¿Qué hilo de Java está acaparando la CPU?

Identificar qué Subproceso Java está consumiendo más CPU en el servidor de producción.

La mayoría (si no todos) los sistemas productivos que hacen algo importante usarán más de 1 subproceso java. Y cuando algo se vuelve loco y el uso de la cpu está en 100%, es difícil identificar qué hilo(s) es/están causando esto. O eso pensé. Hasta que alguien más inteligente que yo me mostró cómo se puede hacer. Y aquí te mostraré cómo hacerlo y tú también puedes sorprender a tu familia y amigos con tu friki habilidad.

Una Aplicación De Prueba

Para probar esto, necesitamos una aplicación de prueba. Así que te daré uno. Consta de 3 clases:

• Una clase HeavyThread que hace algo intensivo de CPU (computación de hashes MD5)
• Una clase LightThread que hace algo no tan intensivo en cpu (contando y durmiendo).
• Una clase StartThreads para iniciar 1 cpu intensiva y varios hilos ligeros.

Aquí está el código para estos clases:

import java.security.MessageDigest;
import java.security.NoSuchAlgorithmException;
import java.util.UUID;

/**
 * thread that does some heavy lifting
 *
 * @author srasul
 *
 */
public class HeavyThread implements Runnable {

        private long length;

        public HeavyThread(long length) {
                this.length = length;
                new Thread(this).start();
        }

        @Override
        public void run() {
                while (true) {
                        String data = "";

                        // make some stuff up
                        for (int i = 0; i < length; i++) {
                                data += UUID.randomUUID().toString();
                        }

                        MessageDigest digest;
                        try {
                                digest = MessageDigest.getInstance("MD5");
                        } catch (NoSuchAlgorithmException e) {
                                throw new RuntimeException(e);
                        }

                        // hash the data
                        digest.update(data.getBytes());
                }
        }
}


import java.util.Random;

/**
 * thread that does little work. just count & sleep
 *
 * @author srasul
 *
 */
public class LightThread implements Runnable {

        public LightThread() {
                new Thread(this).start();
        }

        @Override
        public void run() {
                Long l = 0l;
                while(true) {
                        l++;
                        try {
                                Thread.sleep(new Random().nextInt(10));
                        } catch (InterruptedException e) {
                                e.printStackTrace();
                        }
                        if(l == Long.MAX_VALUE) {
                                l = 0l;
                        }
                }
        }
}


/**
 * start it all
 *
 * @author srasul
 *
 */
public class StartThreads {

        public static void main(String[] args) {
                // lets start 1 heavy ...
                new HeavyThread(1000);

                // ... and 3 light threads
                new LightThread();
                new LightThread();
                new LightThread();
        }
}

Suponiendo que nunca ha visto este código, y todo lo que tiene un PID de un proceso Java fuera de control que está ejecutando estas clases y está consumiendo 100% CPU.

Primero comencemos la clase StartThreads.

$ ls
HeavyThread.java  LightThread.java  StartThreads.java
$ javac *
$ java StartThreads &

En esta etapa, un proceso Java que se está ejecutando debería ocupar 100 cpu. En mi parte superior veo:

En la parte superior presione Shift-H que enciende los hilos. La página de manual de top dice:

   -H : Threads toggle
        Starts top with the last remembered 'H' state reversed.  When
        this  toggle is On, all individual threads will be displayed.
        Otherwise, top displays a  summation  of  all  threads  in  a
        process.

Y ahora en mi parte superior con la pantalla de hilos encendida i ver:

Y tengo un proceso java con PID 28294. Vamos a obtener el volcado de pila de este proceso usando jstack:

$ jstack 28924
2010-11-18 13:05:41
Full thread dump Java HotSpot(TM) 64-Bit Server VM (17.0-b16 mixed mode):

"Attach Listener" daemon prio=10 tid=0x0000000040ecb000 nid=0x7150 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"DestroyJavaVM" prio=10 tid=0x00007f9a98027800 nid=0x70fd waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-3" prio=10 tid=0x00007f9a98025800 nid=0x710d waiting on condition [0x00007f9a9d543000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at LightThread.run(LightThread.java:21)
    at java.lang.Thread.run(Thread.java:619)

"Thread-2" prio=10 tid=0x00007f9a98023800 nid=0x710c waiting on condition [0x00007f9a9d644000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at LightThread.run(LightThread.java:21)
    at java.lang.Thread.run(Thread.java:619)

"Thread-1" prio=10 tid=0x00007f9a98021800 nid=0x710b waiting on condition [0x00007f9a9d745000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at LightThread.run(LightThread.java:21)
    at java.lang.Thread.run(Thread.java:619)

"Thread-0" prio=10 tid=0x00007f9a98020000 nid=0x710a runnable [0x00007f9a9d846000]
   java.lang.Thread.State: RUNNABLE
    at sun.security.provider.DigestBase.engineReset(DigestBase.java:139)
    at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:104)
    at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:538)
    at java.security.MessageDigest.update(MessageDigest.java:293)
    at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:197)
    - locked <0x00007f9aa457e400> (a sun.security.provider.SecureRandom)
    at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:257)
    - locked <0x00007f9aa457e708> (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$200(NativePRNG.java:108)
    at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
    - locked <0x00007f9aa4582fc8> (a java.security.SecureRandom)
    at java.util.UUID.randomUUID(UUID.java:162)
    at HeavyThread.run(HeavyThread.java:27)
    at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x00007f9a98006800 nid=0x7108 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x00007f9a98004000 nid=0x7107 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x00007f9a98001000 nid=0x7106 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0000000040de4000 nid=0x7105 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0000000040dc4800 nid=0x7104 in Object.wait() [0x00007f9a97ffe000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00007f9aa45506b0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    - locked <0x00007f9aa45506b0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x0000000040dbd000 nid=0x7103 in Object.wait() [0x00007f9a9de92000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00007f9aa4550318> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:485)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
    - locked <0x00007f9aa4550318> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0000000040db8800 nid=0x7102 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000040d6e800 nid=0x70fe runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000040d70800 nid=0x70ff runnable 

"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000040d72000 nid=0x7100 runnable 

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000040d74000 nid=0x7101 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f9a98011800 nid=0x7109 waiting on condition 

JNI global references: 910

Desde mi parte superior veo que el PID del hilo superior es 28938. Y 28938 en hexadecimal es 0x710A. Observe que en el volcado de pila, cada hilo tiene un nid que se muestra en hexadecimal. Y resulta que 0x710A es el id del hilo:

"Thread-0" prio=10 tid=0x00007f9a98020000 nid=0x710a runnable [0x00007f9a9d846000]
   java.lang.Thread.State: RUNNABLE
    at sun.security.provider.DigestBase.engineReset(DigestBase.java:139)
    at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:104)
    at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:538)
    at java.security.MessageDigest.update(MessageDigest.java:293)
    at sun.security.provider.SecureRandom.engineNextBytes(SecureRandom.java:197)
    - locked <0x00007f9aa457e400> (a sun.security.provider.SecureRandom)
    at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:257)
    - locked <0x00007f9aa457e708> (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$200(NativePRNG.java:108)
    at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:97)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:433)
    - locked <0x00007f9aa4582fc8> (a java.security.SecureRandom)
    at java.util.UUID.randomUUID(UUID.java:162)
    at HeavyThread.run(HeavyThread.java:27)
    at java.lang.Thread.run(Thread.java:619)

Y así puedes confirmar que el hilo que está ejecutando la clase HeavyThread está consumiendo más CPU.

En situaciones de mundo de lectura, probablemente será un montón de subprocesos que consumen alguna porción de CPU y estos subprocesos juntos conducirán al proceso Java utilizando 100% CPU.

Resumen

• Run top
• Presione Shift-H para habilitar la vista de hilos
• Obtiene el PID del subproceso con la CPU más alta
• Convertir PID a HEXADECIMAL
• Get stack dump of java process
• Busque el hilo con el PID hexadecimal correspondiente.

Jvmtop puede mostrarte los hilos consumidores principales:

    TID NAME                                 STATE     CPU    TOTALCPU
     25 http-8080-Processor13                RUNNABLE  4.55%     1.60%
 128022 RMI TCP Connection(18)-10.101.       RUNNABLE  1.82%     0.02%
  36578 http-8080-Processor164               RUNNABLE  0.91%     2.35%
 128026 JMX server connection timeout   TIMED_WAITING  0.00%     0.00%

Simplemente ejecute JVisualVM, conéctese a su aplicación y use la vista de subprocesos. El que permanece continuamente activo es su culpable más probable.

Echa un vistazo al complemento Top Threads para JConsole.

Si se está ejecutando bajo Windows, pruebe Process Explorer. Abra el diálogo propiedades para su proceso, luego seleccione la pestaña Hilos.

Tome un volcado de hilo. Espera 10 segundos. Haz otro volcado de hilo. Repite una vez más. Inspeccione los volcados de hilos y vea qué hilos están atascados en el mismo lugar o procesando la misma solicitud. Esta es una forma manual de hacerlo, pero a menudo útil.

¿Está ejecutando Java 6 en un equipo multinúcleo?

Lo más probable es que usted está sufriendo de un problema que acabo de describir en un artículo sobre el hambre hilo.

Ver Sincronizado vs.Bloqueo vs. bloqueo justo.

Yo recomendaría echar un vistazo a Arthas herramienta de código abierto de Alibaba.

Contiene un montón de comandos útiles que pueden ayudarlo a depurar su código de producción:

• Dashboard : Descripción general de su Proceso Java
• SC : Clase de búsqueda Cargada por Su JVM
• Jad : Descompilar La Clase En Código Fuente
• Watch : Ver Entrada y Resultados de Invocación del Método
• Trace : Encuentra el Cuello de botella de Tu Invocación del método
• Monitor : Ver Estadísticas de Invocación del Método
• Stack : Ver la pila de llamadas del Método
• Tt : Túnel Temporal de Invocaciones de Métodos

Ejemplo del dashboard:

Esta es una especie de manera hackeada, pero parece que podría encender la aplicación en un depurador, y luego suspender todos los hilos, y pasar por el código y averiguar cuál no está bloqueando un bloqueo o una llamada de E/S en algún tipo de bucle. ¿O es esto como lo que ya has probado?

Una opción que podría considerar es consultar sus hilos para la respuesta desde dentro de la aplicación. A través de ThreadMXBean puede consultar el uso de la CPU de los subprocesos desde su aplicación Java y consultar los rastros de la pila del subproceso ofensivo.

La opción ThreadMXBean le permite construir este tipo de monitoreo en su aplicación en vivo. Tiene un impacto insignificante y tiene la ventaja única de que usted puede hacer que haga exactamente lo que desea.

Si sospecha que VisualVM es una buena herramienta, pruébela (porque hace esto) Averigüe que los subprocesos solo le ayudan en la dirección general de por qué está consumiendo tanta CPU.

Sin embargo, si es tan obvio, iría directamente a usar un generador de perfiles para averiguar por qué está consumiendo tanta CPU.