Diagnosticar problemas comunes de tiempo de ejecución con hprof

Fugas de memoria, interbloqueos y atascos de CPU, ¡oh Dios! Los desarrolladores de aplicaciones Java a menudo se enfrentan a estos problemas de tiempo de ejecución. Pueden ser particularmente desalentadores en una aplicación compleja con múltiples subprocesos que se ejecutan a través de cientos de miles de líneas de código, una aplicación que no puede enviar porque crece en la memoria, se vuelve inactiva o devora más ciclos de CPU de lo que debería.

No es ningún secreto que las herramientas de creación de perfiles de Java han tenido un largo camino para ponerse al día con sus contrapartes de lenguajes alternativos. Ahora existen muchas herramientas poderosas para ayudarnos a localizar a los culpables de esos problemas comunes. Pero, ¿cómo puede desarrollar confianza en su capacidad para utilizar estas herramientas de manera eficaz? Después de todo, está utilizando las herramientas para diagnosticar comportamientos complejos que no comprende. Para agravar su situación, los datos proporcionados por las herramientas son razonablemente complejos y la información que busca o busca no siempre es clara.

Cuando me enfrenté a problemas similares en mi encarnación anterior como físico experimental, creé experimentos de control con resultados predecibles. Esto me ayudó a ganar confianza en el sistema de medición que usé en experimentos que generaron resultados menos predecibles. De manera similar, este artículo utiliza la herramienta de generación de perfiles hprof para examinar tres aplicaciones de control simples que presentan los tres problemas de comportamiento comunes enumerados anteriormente. Aunque no es tan fácil de usar como algunas herramientas comerciales en el mercado, hprof se incluye con Java 2 JDK y, como demostraré, puede diagnosticar eficazmente estos comportamientos.

Ejecutar con hprof

Ejecutar su programa con hprof es fácil. Simplemente invoque el tiempo de ejecución de Java con la siguiente opción de línea de comandos, como se describe en la documentación de la herramienta JDK para el lanzador de aplicaciones Java:

java -Xrunhprof [: ayuda] [: =, ...] MyMainClass 

Una lista de subopciones está disponible con la [:help]opción que se muestra. Generé los ejemplos en este artículo usando el puerto Blackdown del JDK 1.3-RC1 para Linux con el siguiente comando de inicio:

java -classic -Xrunhprof: heap = sites, cpu = samples, depth = 10, monitor = y, thread = y, doe = y MemoryLeak 

La siguiente lista explica la función de cada subopción utilizada en el comando anterior:

  • heap=sites: Le dice a hprof que genere seguimientos de pila indicando dónde se asignó la memoria
  • cpu=samples: Le dice a hprof que use muestreo estadístico para determinar dónde pasa el tiempo la CPU
  • depth=10: Le dice a hprof que muestre los rastros de pila a 10 niveles de profundidad, como máximo
  • monitor=y: Le dice a hprof que genere información sobre los monitores de contención que se utilizan para sincronizar el trabajo de varios subprocesos
  • thread=y: Le dice a hprof que identifique subprocesos en seguimientos de pila
  • doe=y: Le dice a hprof que produzca un volcado de datos de generación de perfiles al salir

Si usa JDK 1.3, debe desactivar el compilador HotSpot predeterminado con la -classicopción. HotSpot tiene su propio generador de perfiles, invocado a través de una -Xprofopción, que usa un formato de salida diferente al que describiré aquí.

Ejecutar su programa con hprof dejará un archivo llamado java.hprof.txten su directorio de trabajo; este archivo contiene la información de creación de perfiles recopilada mientras se ejecuta su programa. También puede generar un volcado en cualquier momento mientras su programa se está ejecutando presionando Ctrl- \ en la ventana de su consola Java en Unix o Ctrl-Break en Windows.

Anatomía de un archivo de salida hprof

Un archivo de salida hprof incluye secciones que describen varias características del programa Java perfilado. Comienza con un encabezado que describe su formato, que según el encabezado está sujeto a cambios sin previo aviso.

Las secciones Thread y Trace del archivo de salida le ayudan a determinar qué subprocesos estaban activos cuando se ejecutó su programa y qué hicieron. La sección Thread proporciona una lista de todos los hilos iniciados y terminados durante la vida del programa. La sección Seguimiento incluye una lista de seguimientos de pila numerados para algunos subprocesos. Estos números de seguimiento de la pila tienen referencias cruzadas en otras secciones de archivos.

Las secciones Heap Dump y Sites le ayudan a analizar el uso de memoria. Dependiendo de la heapsubopción que elija al iniciar la máquina virtual (VM), puede obtener un volcado de todos los objetos activos en el montón de Java ( heap=dump) y / o una lista ordenada de sitios de asignación que identifique los objetos más asignados ( heap=sites).

Las secciones CPU Samples y CPU Time le ayudan a comprender el uso de la CPU; la sección que obtenga depende de su cpusubopción ( cpu=sampleso cpu=time). CPU Samples proporciona un perfil de ejecución estadístico. El tiempo de CPU incluye medidas de cuántas veces se llamó a un método determinado y cuánto tiempo tardó en ejecutarse cada método.

Las secciones Monitor Time y Monitor Dump le ayudan a comprender cómo la sincronización afecta el rendimiento de su programa. Monitor Time muestra cuánto tiempo sus hilos experimentan contención por recursos bloqueados. Monitor Dump es una instantánea de los monitores actualmente en uso. Como verá, Monitor Dump es útil para encontrar puntos muertos.

Diagnosticar una pérdida de memoria

En Java, defino una fuga de memoria como una falla (generalmente) no intencional para desreferenciar objetos descartados para que el recolector de basura no pueda reclamar la memoria que usan. El MemoryLeakprograma del Listado 1 es simple:

Listado 1. Programa MemoryLeak

01 import java.util.Vector; 02 03 clase pública MemoryLeak {04 05 public static void main (String [] args) {06 07 int MAX_CONSUMERS = 10000; 08 int SLEEP_BETWEEN_ALLOCS = 5; 09 10 ConsumerContainer objectHolder = new ConsumerContainer (); 11 12 while (objectHolder.size () <MAX_CONSUMERS) {13 System.out.println ("Asignar objeto" + 14 Integer.toString (objectHolder.size ()) 15); 16 objectHolder.add (nuevo MemoryConsumer ()); 17 intente {18 Thread.currentThread (). Sleep (SLEEP_BETWEEN_ALLOCS); 19} catch (InterruptedException ie) {20 // No hacer nada. 21} 22} // mientras. 23} // principal. 24 25} // Fin de MemoryLeak. 26 27 / ** Clase contenedor con nombre para contener referencias a objetos. * / 28 clase ConsumerContainer extiende Vector {} 29 30 / ** Clase que consume una cantidad fija de memoria. * / 31 clase MemoryConsumer {32 public static final int MEMORY_BLOCK = 1024;33 bytes públicos [] memoryHoldingArray; 34 35 MemoryConsumer () {36 memoryHoldingArray = nuevo byte [MEMORY_BLOCK]; 37} 38} // Finalizar MemoryConsumer.

Cuando el programa se ejecuta, crea un ConsumerContainerobjeto, luego comienza a crear y agregar MemoryConsumerobjetos de al menos 1 KB de tamaño a ese ConsumerContainerobjeto. Mantener los objetos accesibles hace que no estén disponibles para la recolección de basura, simulando una pérdida de memoria.

Veamos partes seleccionadas del archivo de perfil. Las primeras líneas de la sección Sitios muestran claramente lo que está sucediendo:

SITIOS COMIENZAN (ordenados por bytes en vivo) Lunes 3 de septiembre 19:16:29 2001 porcentaje en vivo asignado clase de pila rango bytes de acumulación propia objs bytes objs nombre de rastreo 1 97.31% 97.31% 10280000 10000 10280000 10000 1995 [B 2 0.39% 97.69% 40964 1 81880 10 1996 [L; 3 0,38% 98,07% 40000 10000 40000 10000 1994 Consumidor de memoria 4 0,16% 98,23% 16388 1 16388 1 1295 [C 5 0,16% 98,38% 16388 1 16388 1 1304 [C ...

Hay 10,000 objetos de tipo byte[]( [Ben lenguaje virtual), así como 10,000 MemoryConsumerobjetos. Las matrices de bytes ocupan 10,280,000 bytes, por lo que aparentemente hay una sobrecarga justo por encima de los bytes sin procesar que consume cada matriz. Dado que la cantidad de objetos asignados es igual a la cantidad de objetos activos, podemos concluir que ninguno de estos objetos podría ser recolectado como basura. Esto es consistente con nuestras expectativas.

Otro punto interesante: la memoria reportada como consumida por los MemoryConsumerobjetos no incluye la memoria consumida por las matrices de bytes. Esto muestra que nuestra herramienta de creación de perfiles no expone las relaciones de contención jerárquica, sino más bien estadísticas clase por clase. Es importante comprender esto cuando se usa hprof para identificar una pérdida de memoria.

Ahora, ¿de dónde provienen esas matrices de bytes con fugas? Observe que los MemoryConsumerobjetos y las matrices de bytes hacen referencia a trazas 1994y 1995en la siguiente sección Trazas. He aquí que estos rastros nos dicen que los MemoryConsumerobjetos fueron creados en el método de la MemoryLeakclase main()y que las matrices de bytes fueron creadas en el constructor ( ()método en VM-speak). Hemos encontrado nuestra pérdida de memoria, números de línea y todo:

TRACE 1994: (hilo = 1) MemoryLeak.main (MemoryLeak.java:16) TRACE 1995: (hilo = 1) MemoryConsumer. (MemoryLeak.java:36) MemoryLeak.main (MemoryLeak.java:16) 

Diagnosticar un consumidor de CPU

En el Listado 2, una BusyWorkclase hace que cada subproceso llame a un método que regula cuánto funciona el subproceso variando su tiempo de reposo entre episodios de realización de cálculos intensivos en CPU:

Listing 2. CPUHog program

01 /** Main class for control test. */ 02 public class CPUHog { 03 public static void main(String[] args) { 04 05 Thread slouch, workingStiff, workaholic; 06 slouch = new Slouch(); 07 workingStiff = new WorkingStiff(); 08 workaholic = new Workaholic(); 09 10 slouch.start(); 11 workingStiff.start(); 12 workaholic.start(); 13 } 14 } 15 16 /** Low CPU utilization thread. */ 17 class Slouch extends Thread { 18 public Slouch() { 19 super("Slouch"); 20 } 21 public void run() { 22 BusyWork.slouch(); 23 } 24 } 25 26 /** Medium CPU utilization thread. */ 27 class WorkingStiff extends Thread { 28 public WorkingStiff() { 29 super("WorkingStiff"); 30 } 31 public void run() { 32 BusyWork.workNormally(); 33 } 34 } 35 36 /** High CPU utilization thread. */ 37 class Workaholic extends Thread { 38 public Workaholic() { 39 super("Workaholic"); 40 } 41 public void run() { 42 BusyWork.workTillYouDrop(); 43 } 44 } 45 46 /** Class with static methods to consume varying amounts 47 * of CPU time. */ 48 class BusyWork { 49 50 public static int callCount = 0; 51 52 public static void slouch() { 53 int SLEEP_INTERVAL = 1000; 54 computeAndSleepLoop(SLEEP_INTERVAL); 55 } 56 57 public static void workNormally() { 58 int SLEEP_INTERVAL = 100; 59 computeAndSleepLoop(SLEEP_INTERVAL); 60 } 61 62 public static void workTillYouDrop() { 63 int SLEEP_INTERVAL = 10; 64 computeAndSleepLoop(SLEEP_INTERVAL); 65 } 66 67 private static void computeAndSleepLoop(int sleepInterval) { 68 int MAX_CALLS = 10000; 69 while (callCount < MAX_CALLS) { 70 computeAndSleep(sleepInterval); 71 } 72 } 73 74 private static void computeAndSleep(int sleepInterval) { 75 int COMPUTATIONS = 1000; 76 double result; 77 78 // Compute. 79 callCount++; 80 for (int i = 0; i < COMPUTATIONS; i++) { 81 result = Math.atan(callCount * Math.random()); 82 } 83 84 // Sleep. 85 try { 86 Thread.currentThread().sleep(sleepInterval); 87 } catch (InterruptedException ie) { 88 // Do nothing. 89 } 90 91 } // End computeAndSleep. 92 } // End BusyWork. 

There are three threads -- Workaholic, WorkingStiff, and Slouch -- whose work ethics vary by orders of magnitude, judging by the work they choose to do. Examine the profile's CPU Samples section shown below. The three highest ranked traces show that the CPU spent most of its time calculating random numbers and arc tangents, as we would expect:

CPU SAMPLES BEGIN (total = 935) Tue Sep 4 20:44:49 2001 rank self accum count trace method 1 39.04% 39.04% 365 2040 java/util/Random.next 2 26.84% 65.88% 251 2042 java/util/Random.nextDouble 3 10.91% 76.79% 102 2041 java/lang/StrictMath.atan 4 8.13% 84.92% 76 2046 BusyWork.computeAndSleep 5 4.28% 89.20% 40 2050 java/lang/Math.atan 6 3.21% 92.41% 30 2045 java/lang/Math.random 7 2.25% 94.65% 21 2051 java/lang/Math.random 8 1.82% 96.47% 17 2044 java/util/Random.next 9 1.50% 97.97% 14 2043 java/util/Random.nextDouble 10 0.43% 98.40% 4 2047 BusyWork.computeAndSleep 11 0.21% 98.61% 2 2048 java/lang/StrictMath.atan 12 0.11% 98.72% 1 1578 java/io/BufferedReader.readLine 13 0.11% 98.82% 1 2054 java/lang/Thread.sleep 14 0.11% 98.93% 1 1956 java/security/PermissionCollection.setReadOnly 15 0.11% 99.04% 1 2055 java/lang/Thread.sleep 16 0.11% 99.14% 1 1593 java/lang/String.valueOf 17 0.11% 99.25% 1 2052 java/lang/Math.random 18 0.11% 99.36% 1 2049 java/util/Random.nextDouble 19 0.11% 99.47% 1 2031 BusyWork.computeAndSleep 20 0.11% 99.57% 1 1530 sun/io/CharToByteISO8859_1.convert ... 

Tenga en cuenta que las llamadas al BusyWork.computeAndSleep()método ocupan 8,13 por ciento, 0,43 por ciento y 0,11 por ciento para los Workaholic, WorkingStiffy Slouchlas discusiones, respectivamente. Podemos saber qué subprocesos son examinando las trazas a las que se hace referencia en la columna de trazas de la sección Muestras de CPU anterior (rangos 4, 10 y 19) en la siguiente sección de Trazas: