resueltos - La ejecución de código Java produce diferentes resultados en depuración sin puntos de interrupción y ejecución normal. ¿ExecutorService está roto?
pool de hilos java (1)
TL: DR ExecutorService executorService = Executors.newFixedThreadPool(8); en depuración se ejecuta simultáneamente, pero en el tiempo de ejecución normal se inicia simultáneamente, pero luego se ejecuta en un solo subproceso.
Tengo un código donde empiezo 4 tareas diferentes en ExecutorService . Dos de esas tareas deberían terminar casi al instante, las otras dos deberían ejecutarse por un tiempo.
Esas tareas devuelven el tiempo de ejecución en segundos en Future<Double> .
Este código es responsable de la ejecución y medición de la tarea:
public Future<Double> measure(int[] arr, ProcessIntArray processIntArray, ExecutorService es) {
Callable<Double> task = () -> {
long start = System.nanoTime();
processIntArray.process(arr);
long end = System.nanoTime();
return (end - start) / 1000000000.0;
};
return es.submit(task);
}
Más adelante, después de comenzar esas tareas, las imprimo en el orden del tiempo de ejecución de las ejecuciones anteriores para el mismo tamaño de entrada.
Future<Double> bubbleSortTime = measure(bubbleSortArray, Solution::bubbleSort, executorService);
Future<Double> insertionSortTime = measure(insertionSortArray, Solution::insertionSort, executorService);
Future<Double> quickSortTime = measure(quickSortArray, Solution::quickSort, executorService);
Future<Double> mergeSortTime = measure(mergeSortArray, Solution::mergeSort, executorService);
System.out.println();
System.out.println("array size: " + size);
System.out.println("quick sort: " + quickSortTime.get() + "s");
System.out.println("merge sort: " + mergeSortTime.get() + "s");
System.out.println("insertion sort: " + insertionSortTime.get() + "s");
System.out.println("bubble sort: " + bubbleSortTime.get() + "s");
Cuando ejecuto el código en modo de depuración, 2 resultados se imprimen inmediatamente, y tengo que esperar un tiempo para el 3er resultado (no me molesto en esperar el 4to).
Después de comenzar a depurar (correcto y esperado):
array size: 1000000 quick sort: 0.186892839s merge sort: 0.291950604s insertion sort: 344.534256723s
La ejecución normal es diferente, parece que en el método measure long start = System.nanoTime(); se ejecuta, luego el hilo se queda dormido, y después de insertionSort, quickSort vuelve a estar en ejecución, lo que da como resultado:
array size: 1000000 quick sort: 345.893922141s merge sort: 345.944023095s insertion sort: 345.871908569s
Cuál está mal. Todos estos hilos deberían estar ejecutándose al mismo tiempo, como desde newFixedThreadPool javadoc.
/**
* Creates a thread pool that reuses a fixed number of threads
* operating off a shared unbounded queue. At any point, at most
* {@code nThreads} threads will be active processing tasks.
* If additional tasks are submitted when all threads are active,
* they will wait in the queue until a thread is available.
* If any thread terminates due to a failure during execution
* prior to shutdown, a new one will take its place if needed to
* execute subsequent tasks. The threads in the pool will exist
* until it is explicitly {@link ExecutorService#shutdown shutdown}.
*
* @param nThreads the number of threads in the pool
* @return the newly created thread pool
* @throws IllegalArgumentException if {@code nThreads <= 0}
*/
public static ExecutorService newFixedThreadPool(int nThreads)
Adjunto el código fuente:
import java.util.Arrays;
import java.util.Random;
import java.util.concurrent.*;
class ThreadedSortingComparsion {
Random random = new Random(System.currentTimeMillis());
void popul(int[] array) {
for (int i = 0; i < array.length; i++) {
array[i] = random.nextInt();
}
}
interface ArraySorter {
void sort(int[] array);
}
public Future<Double> measureTime(int[] array, ArraySorter arraySorter, ExecutorService executorService) {
Callable<Double> task = () -> {
long start = System.nanoTime();
arraySorter.sort(array);
long end = System.nanoTime();
return (end - start) / 1000000000.0;
};
return executorService.submit(task);
}
public void start() throws ExecutionException, InterruptedException {
ExecutorService executorService = Executors.newFixedThreadPool(8);
int size = 1000 * 1000;
int[] quickSortArray = new int[size];
popul(quickSortArray);
int[] bubbleSortArray = Arrays.copyOf(quickSortArray, quickSortArray.length);
int[] mergeSortArray = Arrays.copyOf(quickSortArray, quickSortArray.length);
int[] originalArray = Arrays.copyOf(quickSortArray, quickSortArray.length);
int[] insertionSortArray = Arrays.copyOf(quickSortArray, quickSortArray.length);
Future<Double> bubbleSortTime = measureTime(bubbleSortArray, ThreadedSortingComparsion::bubbleSort, executorService);
Future<Double> insertionSortTime = measureTime(insertionSortArray, ThreadedSortingComparsion::insertionSort, executorService);
Future<Double> quickSortTime = measureTime(quickSortArray, ThreadedSortingComparsion::quickSort, executorService);
Future<Double> mergeSortTime = measureTime(mergeSortArray, ThreadedSortingComparsion::mergeSort, executorService);
System.out.println();
System.out.println("array size: " + size);
System.out.println("quick sort: " + quickSortTime.get() + "s");
System.out.println("merge sort: " + mergeSortTime.get() + "s");
System.out.println("insertion sort: " + insertionSortTime.get() + "s");
System.out.println("bubble sort: " + bubbleSortTime.get() + "s");
executorService.shutdown();
for (int i = 0; i < quickSortArray.length; i++) {
if (quickSortArray[i] != bubbleSortArray[i] || quickSortArray[i] != mergeSortArray[i] || quickSortArray[i] != insertionSortArray[i]) {
throw new RuntimeException(Arrays.toString(originalArray));
}
}
}
public static void mergeSort(int[] ar) {
if (ar.length < 5) {
bubbleSort(ar);
return;
}
int middle = ar.length / 2;
int[] arrayLeft = new int[middle];
int[] arrayRight = new int[ar.length - middle];
for (int i = 0; i < ar.length; i++) {
if (i < middle) {
arrayLeft[i] = ar[i];
} else {
arrayRight[i - middle] = ar[i];
}
}
mergeSort(arrayLeft);
mergeSort(arrayRight);
int indexLeft = 0;
int indexRight = 0;
int inputArrayIndex = 0;
while (true) {
int whatToPutInAR = 0;
if (indexLeft != arrayLeft.length && indexRight != arrayRight.length) {
if (arrayLeft[indexLeft] < arrayRight[indexRight]) {
whatToPutInAR = arrayLeft[indexLeft];
indexLeft++;
} else {
whatToPutInAR = arrayRight[indexRight];
indexRight++;
}
} else if (indexLeft != arrayLeft.length) {
whatToPutInAR = arrayLeft[indexLeft];
indexLeft++;
} else if (indexRight != arrayRight.length) {
whatToPutInAR = arrayRight[indexRight];
indexRight++;
}
if (inputArrayIndex == ar.length) return;
ar[inputArrayIndex++] = whatToPutInAR;
}
}
private static void quickSort(int[] ar) {
quickSort(ar, 0, ar.length);
}
static public void quickSort(int[] array, int start, int end) {
boolean changed = false;
if (end == 0) return;
int pivot = array[end - 1];
int partitionCandidate = start;
for (int i = start; i < end; i++) {
if (array[i] < pivot) {
swap(array, partitionCandidate++, i);
changed = true;
} else if (pivot < array[i]) {
swap(array, end - 1, i);
changed = true;
}
}
if (start < partitionCandidate) {
quickSort(array, start, partitionCandidate);
}
if (partitionCandidate < end) {
if (partitionCandidate != start || changed) quickSort(array, partitionCandidate, end);
}
}
public static void swap(int[] ar, int from, int to) {
int old = ar[from];
ar[from] = ar[to];
ar[to] = old;
}
public static void bubbleSort(int[] array) {
for (int i = 0; i < array.length; i++) {
for (int j = 0; j < array.length - 1; j++) {
if (array[j] > array[j + 1]) {
swap(array, j + 1, j);
}
}
}
}
private static void insertionSort(int[] ar) {
for (int i = 0; i < ar.length; i++) {
for (int j = i; j >= 1; j--) {
boolean breaker = true;
if (ar[j] < ar[j - 1]) {
breaker = false;
swap(ar, j - 1, j);
}
if (breaker) break;
}
}
}
public static void main(String[] args) throws ExecutionException, InterruptedException {
ThreadedSortingComparsion s = new ThreadedSortingComparsion();
s.start();
}
}
Editar: cuando lo ejecuto en Ideone, el código funciona bien. http://ideone.com/1E8C51 Ideone tiene la versión de Java 1.8.0_51 1.8.0_91 en 1.8.0_91 , 1.8.0_92 . Y 1.8.0_45 . ¿Por qué funciona en ideone, pero no en otras 2 PC que probé?
Cuando hago un volcado de subprocesos, mientras ejecuto no en la depuración, luego espero un rato, y después de que se imprime el volcado de subprocesos, también se imprimen los resultados. Entonces, el volcado de hilo se realiza después de terminar la ordenación por inserción.
"C:/Program Files/Java/jdk1.8.0_45/bin/java" -Xmx8G -Xss1G -Didea.launcher.port=7533 "-Didea.launcher.bin.path=C:/Program Files (x86)/JetBrains/IntelliJ IDEA Community Edition 2016.1.3/bin" -Dfile.encoding=UTF-8 -classpath "C:/Program Files/Java/jdk1.8.0_45/jre/lib/charsets.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/deploy.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/access-bridge-64.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/cldrdata.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/dnsns.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/jaccess.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/jfxrt.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/localedata.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/nashorn.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/sunec.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/sunjce_provider.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/sunmscapi.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/sunpkcs11.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/ext/zipfs.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/javaws.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/jce.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/jfr.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/jfxswt.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/jsse.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/management-agent.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/plugin.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/resources.jar;C:/Program Files/Java/jdk1.8.0_45/jre/lib/rt.jar;C:/Users/Tomasz_Mielczarski/IdeaProjects/untitled/out/production/untitled;C:/Program Files (x86)/JetBrains/IntelliJ IDEA Community Edition 2016.1.3/lib/idea_rt.jar" com.intellij.rt.execution.application.AppMain ThreadedSortingComparsion
array size: 1000000
2016-07-15 13:45:22
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode):
"pool-1-thread-4" #15 prio=5 os_prio=0 tid=0x00000000696bd000 nid=0x560 runnable [0x00000002fffee000]
java.lang.Thread.State: RUNNABLE
at ThreadedSortingComparsion.mergeSort(ThreadedSortingComparsion.java:77)
at ThreadedSortingComparsion.mergeSort(ThreadedSortingComparsion.java:78)
at ThreadedSortingComparsion.mergeSort(ThreadedSortingComparsion.java:78)
at ThreadedSortingComparsion.mergeSort(ThreadedSortingComparsion.java:78)
at ThreadedSortingComparsion.mergeSort(ThreadedSortingComparsion.java:77)
at ThreadedSortingComparsion$$Lambda$5/81628611.sort(Unknown Source)
at ThreadedSortingComparsion.lambda$measureTime$0(ThreadedSortingComparsion.java:21)
at ThreadedSortingComparsion$$Lambda$2/1023892928.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"pool-1-thread-3" #14 prio=5 os_prio=0 tid=0x00000000696bb800 nid=0x2634 runnable [0x00000002bffee000]
java.lang.Thread.State: RUNNABLE
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:123)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:126)
at ThreadedSortingComparsion.quickSort(ThreadedSortingComparsion.java:105)
at ThreadedSortingComparsion$$Lambda$4/1989780873.sort(Unknown Source)
at ThreadedSortingComparsion.lambda$measureTime$0(ThreadedSortingComparsion.java:21)
at ThreadedSortingComparsion$$Lambda$2/1023892928.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"pool-1-thread-2" #13 prio=5 os_prio=0 tid=0x00000000696b7800 nid=0x1c70 waiting on condition [0x000000027ffef000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000719d72480> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"pool-1-thread-1" #12 prio=5 os_prio=0 tid=0x00000000696b6800 nid=0x478 runnable [0x000000023ffee000]
java.lang.Thread.State: RUNNABLE
at ThreadedSortingComparsion.bubbleSort(ThreadedSortingComparsion.java:139)
at ThreadedSortingComparsion$$Lambda$1/990368553.sort(Unknown Source)
at ThreadedSortingComparsion.lambda$measureTime$0(ThreadedSortingComparsion.java:21)
at ThreadedSortingComparsion$$Lambda$2/1023892928.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"Monitor Ctrl-Break" #11 daemon prio=5 os_prio=0 tid=0x0000000068d3d000 nid=0x2f3c runnable [0x00000001fffee000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
- locked <0x00000007156892b8> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at java.io.BufferedReader.fill(BufferedReader.java:161)
at java.io.BufferedReader.readLine(BufferedReader.java:324)
- locked <0x00000007156892b8> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:389)
at com.intellij.rt.execution.application.AppMain$1.run(AppMain.java:93)
at java.lang.Thread.run(Thread.java:745)
"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x0000000068c81000 nid=0x2d6c runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread3" #9 daemon prio=9 os_prio=2 tid=0x0000000068bea800 nid=0x1ad0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x0000000068be4000 nid=0x17d0 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x0000000068bdd800 nid=0x3238 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x0000000068bda000 nid=0x1824 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x0000000068bd8800 nid=0x910 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x0000000068bd7800 nid=0x31f8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x0000000043229800 nid=0x2810 in Object.wait() [0x00000000fffee000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000719d707e0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked <0x0000000719d707e0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000043223000 nid=0xd48 in Object.wait() [0x00000000bffef000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000719d78370> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
- locked <0x0000000719d78370> (a java.lang.ref.Reference$Lock)
"main" #1 prio=5 os_prio=0 tid=0x000000000311d800 nid=0x2ed0 waiting on condition [0x000000004311e000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000719d58fe0> (a java.util.concurrent.FutureTask)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
at java.util.concurrent.FutureTask.get(FutureTask.java:191)
at ThreadedSortingComparsion.start(ThreadedSortingComparsion.java:48)
at ThreadedSortingComparsion.main(ThreadedSortingComparsion.java:162)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)
"VM Thread" os_prio=2 tid=0x0000000056348800 nid=0x2984 runnable
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000043147000 nid=0x27e0 runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000043148800 nid=0x20b4 runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x000000004314a000 nid=0x1da4 runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x000000004314c000 nid=0x29e0 runnable
"GC task thread#4 (ParallelGC)" os_prio=0 tid=0x000000004314e000 nid=0xa04 runnable
"GC task thread#5 (ParallelGC)" os_prio=0 tid=0x0000000043150000 nid=0x14b8 runnable
"GC task thread#6 (ParallelGC)" os_prio=0 tid=0x0000000043153800 nid=0xf00 runnable
"GC task thread#7 (ParallelGC)" os_prio=0 tid=0x0000000043154800 nid=0x243c runnable
"VM Periodic Task Thread" os_prio=2 tid=0x0000000068c82000 nid=0x22d8 waiting on condition
JNI global references: 224
Heap
PSYoungGen total 76288K, used 13755K [0x0000000715580000, 0x000000071aa80000, 0x00000007c0000000)
eden space 65536K, 4% used [0x0000000715580000,0x0000000715874910,0x0000000719580000)
from space 10752K, 99% used [0x0000000719580000,0x0000000719ffa348,0x000000071a000000)
to space 10752K, 0% used [0x000000071a000000,0x000000071a000000,0x000000071aa80000)
ParOldGen total 175104K, used 33211K [0x00000005c0000000, 0x00000005cab00000, 0x0000000715580000)
object space 175104K, 18% used [0x00000005c0000000,0x00000005c206ed30,0x00000005cab00000)
Metaspace used 4277K, capacity 4790K, committed 4992K, reserved 1056768K
class space used 484K, capacity 535K, committed 640K, reserved 1048576K
quick sort: 355.579434803s
merge sort: 355.629940032s
insertion sort: 355.532578023s
TL; DR HotSpot La optimización JIT para eliminar las comprobaciones de puntos de seguridad en los bucles contados es una broma pesada.
Esta es una pregunta muy interesante: una simple prueba de Java revela un problema no trivial en el interior de JVM.
El hecho de que un volcado de subprocesos no haya aparecido inmediatamente indica que el problema no está en el código de Java, sino que de alguna manera está relacionado con JVM. Los volcados de subprocesos se imprimen en puntos de seguridad. La demora significa que VM no pudo alcanzar un punto seguro en poco tiempo.
Fondo
Algunas operaciones de VM (GC, Deoptimization, Thread dump y algunas otras ) se ejecutan en pausas Stop-the-World cuando no se están ejecutando subprocesos de Java. Pero los hilos de Java no se podían detener en ningún punto arbitrario, solo pueden detenerse en ciertos lugares llamados puntos de seguridad . En el código compilado JIT, los puntos de seguridad generalmente se colocan en las salidas del método y en las ramas hacia atrás, es decir, dentro de los bucles.
Los controles de puntos de seguridad son relativamente baratos en términos de rendimiento, pero no gratuitos. Es por eso que el compilador JIT intenta reducir el número de puntos de seguridad donde sea posible. Una optimización de este tipo consiste en eliminar las comprobaciones de puntos de seguridad en los bucles contados, es decir, bucles con un contador entero que se sabe que tienen un número finito de iteraciones.
Verificar la teoría
Regresemos a nuestra prueba y verifiquemos si los puntos de seguridad se alcanzan a tiempo.
Agregue -XX:+SafepointTimeout -XX:SafepointTimeoutDelay=1000 opciones de JVM. Esto debería imprimir un mensaje de depuración siempre que la VM no llegue a un punto seguro en 1000 ms.
# SafepointSynchronize::begin: Timeout detected:
# SafepointSynchronize::begin: Timed out while spinning to reach a safepoint.
# SafepointSynchronize::begin: Threads which did not reach the safepoint:
# "pool-1-thread-2" #12 prio=5 os_prio=0 tid=0x0000000019004800 nid=0x1480 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
# SafepointSynchronize::begin: (End of list)
Sí, imprimió que el subproceso pool-1-thread-2 no podía detenerse en 1000 ms. Este es el segundo hilo del grupo de ejecutores, que debería ejecutar el algoritmo insertionSort .
insertionSort tiene dos bucles contados anidados muy largos, y parece que JVM ha eliminado las comprobaciones de safepoint dentro de ellos. Entonces, si este método se ejecuta en modo compilado, JVM no puede detenerlo hasta que el método finalice. Si se solicita una pausa stop-the-world mientras se ejecuta el método, todos los demás hilos también esperarán.
¿Qué hacer?
Este problema se conoce desde hace mucho tiempo. Aquí está el error JVM relacionado: JDK-5014723 . No es uno de alta prioridad, ya que el problema rara vez aparece en las aplicaciones de la vida real.
Apareció una nueva marca JVM en JDK 8u92 para solucionar el problema.
-XX:+UseCountedLoopSafepoints siempre colocará puntos seguros dentro de los bucles.
Otra solución sería transformar un bucle largo contado en uno genérico modificando una variable contraria dentro del bucle.
Por ejemplo, si reemplaza if (breaker) break; con if (breaker) j = 0; el problema también desaparecerá
¿Por qué funciona en modo de depuración entonces?
Cuando se inicia JVM con el depurador activado, algunas optimizaciones de JIT se desactivan para que la información de depuración esté disponible. En este caso, el código compilado tiene todas las comprobaciones de safepoint.