¿Cómo se ve el volcado de subprocesos cuando JVM pasó tiempo en GC?

Question

Al crear perfiles de aplicaciones Java, noto un dato interesante.Cuando la JVM está en la espiral de GC, el volcado del hilo de la muerte se ve así:

"1304802943@qtp-393978767-9985" prio=10 tid=0x00007f3ed02dd000 nid=0x74e7 in Object.wait() [0x000000004febb000]
 java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
    - locked <0x00000007aed40048> (a org.mortbay.thread.QueuedThreadPool$PoolThread)

"26774405@qtp-393978767-9984" prio=10 tid=0x00007f3ee4b37000 nid=0x74e6 in Object.wait() [0x0000000045d1a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
    - locked <0x00000007aed83aa0> (a org.mortbay.thread.QueuedThreadPool$PoolThread)

"764808089@qtp-393978767-9983" prio=10 tid=0x00007f3ee4c50000 nid=0x74e5 in Object.wait() [0x000000004ad6a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
    - locked <0x00000007aed5c448> (a org.mortbay.thread.QueuedThreadPool$PoolThread)

Entonces, hay muchos subprocesos en el estado TIMED_WAITING.En teoría, esta situación podría encontrarse fácilmente en una aplicación que funciona normalmente (la aplicación simplemente no tiene solicitudes entrantes en este momento), pero no puedo encontrar ni un solo hilo de envío de solicitudes que haga algo útil (la tasa de aciertos nominal es de aproximadamente 100 hps).

¿Este comportamiento tiene algo que ver con GC o es solo una coincidencia?

Answer 1

Respondiendo solo al título de la pregunta:

¿Cómo se ve el volcado de subprocesos cuando JVM pasó tiempo en GC?

La respuesta es: no tiene medios para obtener tal volcado (de la manera habitual).

JVM procesa la solicitud de volcado de subprocesos solo después de alcanzar safepoint que simplemente no puede suceder mientras estás en GC.

Pero hay una forma engañosa de obtener el volcado de subprocesos de GC activo con la ayuda de la función JVMTI no documentada AsyncGetCallTrace que se menciona en esta publicación:

http://jeremymanson.blogspot.com/ 2010/07 / por qué-muchos-perfiladores-tienen-en-serio.html

También sugiere que Oracle Solaris Studio puede ser usado para tomar tales volcados de subprocesos nativos / java mixtos.

Answer 2

Pruebe un jmap -histo: en vivo a lo largo del tiempo, puede comparar la salida y ver qué tipos de objetos están creciendo.

Necesita tener el JDK instalado para jmap. http://docs.oracle.com/javase/6/docs/technotes/tools/share/jmap.html

Una advertencia, jmap es intensivo, detendrá todos los subprocesos mientras se está ejecutando, lo que debería ser solo unos segundos.Los procesos pueden volcar el núcleo porque es intensivo, generalmente es rápido y seguro, pero lo he visto bloquear o eliminar aplicaciones grandes, montones de varios gigas.

Answer 3

Supongo que tiene un grupo de subprocesos que está esperando algo que hacer.Si su proceso es eficiente y tiene incluso 100 solicitudes por segundo, es posible que tenga problemas para detectar incluso un hilo haciendo algo.Le sugiero que mire la carga de CPU de su proceso.Si es del 50%, tiene un 50% de posibilidades de encontrar un hilo (posiblemente no un hilo de solicitud) haciendo algo.

Si desea ver lo que su servidor dedica su tiempo a hacer, probaría con un generador de perfiles como VisualVM, o un generador de perfiles comercial como YourKit.

Al hacer una búsqueda en Google de su código, encontré una versión diferente http://grepcode.com/file/repo1.maven.org/maven2/org.mortbay.jetty/jetty-util/7.0.0.pre5 / org / mortbay / thread / QueuedThreadPool.java sin embargo sospecho que sus hilos son TIMED_WAIT en este bloque en el método run ()

                // We are idle
                // wait for a dispatched job
                synchronized (this)
                {
                    if (_job==null)
                        this.wait(getMaxIdleTimeMs());
                    job=_job;
                    _job=null;
                }