OpenSolaris: Java y Dtrace.
Introducción
Como administrador de sistemas nunca he tenido un especial cariño a las aplicaciones java, la Virtual Machine (VM) se suele arrancar con unos parámetros de memoria bastante generosos, esta se queda mapeada en el kernel de forma que el gestor del sistema operativo queda de facto anulado para esas páginas. A nivel de procesos la cosa es compleja, suele haber un único proceso con muchos, digo muchísimos hilos, lo que a la práctica significa que tratar de tracearlo con las herramientas del tipo truss o dtruss es prácticamente inviable y identificar el hilo que está generando más carga es complicado. A cada nueva versión de la máquina virtual de sun (aka hotspot) los desarrolladores han hecho un esfuerzo para que sea cada vez más observable paliando en gran medida los problemas descritos. Desde las primeras versiones que eran bastantes opacas hasta la 1.5, que incluye bastantes herramientas para el diagnóstico, ha mejorado bastante en este aspecto. En la última versión (java 1.6 SE) se ha incluido un provider para Dtrace, de forma que podemos observar el comportamiento de aplicaciones vivas de forma totalmente dinámica ... y se han ganado mi corazón. :) ¡¡Algunas de estas pruebas generan bastante carga al sistema!! sed cautelosos. Por eso motivo debemos habilitarlas al arrancar nuestra VM con los flags: -XX:+DTraceAllocProbes-XX:+DTraceMethodProbes
-XX:+DTraceMonitorProbes
-XX:+ExtendedDTraceProbes O bien cambiarlos dinámicamente con el comando
jinfo
El provider HotSpot
El provider hotspot se carga dinámicamente cuando se arranca un proceso java, viene identificado por hotspot+(pid).root@opensolaris:~# dtrace -ln 'hotspot*:::' | more ID PROVIDER MODULE FUNCTION NAME 4762 hotspot2688 libjvm.so __1l[...]s_b_v_ class-loaded 4763 hotspot2688 libjvm.so __1c[...]anceKlass__v_ class-unloaded 4764 hotspot2688 libjvm.so __1cH[...]dbFpost_c compiled-method-load [...]
Este provider nos proporciona probes para comprobar muchos aspectos de la máquina virtual java. Podéis encontrar una descripción completa de todas ellas en la documentación de sun. A grandes rasgos podremos tracear objetos, métodos, clases, monitores y la actividad del Garbage Collector.¿Que debemos mirar?
Hay varios elementos que impactan sustancialmente en el rendimiento de la VM y que son susceptibles de mejora, en general las acciones correctivas siempre se tendrán que hacer por parte del equipo de desarrollo o por el de administradores de los servidores de aplicaciones, sin embargo nosotros les podemos proporcionar datos útiles para su toma de decisiones. El Garbage Colector Se conoce como garbage colector a un conjunto de hilos responsables de gestionar la memoria asignada a la VM. Esta se encuentra dividida en generaciones, los objetos que sobreviven a una generación son copiados a la siguiente. A modo práctico y sin entrar en detalles, si el tamaño de las distintas generaciones no está dimensionado correctamente puede provocar que los hilos del garbage colector se ejecuten demasiado frecuentemente, que se ejecuten muy pocas veces pero que el proceso se prolongue demasiado en el tiempo, que quede parte de la memoria sin usarse nunca e incluso en el peor de los casos que tengamos un out of memory aun cuando hay parte de la memoria sin usar. Ajustar el tamaño de las distintas generaciones es complejo y debería hacerse en preproducción ya que puede tener un impacto negativo en el rendimiento mientras se realiza. Normalmente suele llevarlo acabo la gente de adminstración de los servidores de aplicaciones. Sin embargo podemos colaborar con ellos proporcionándoles información sobre la actividad de los distintos hilos del Garbage colector. Monitores Para entendernos, un monitor es a Java lo que un bloqueo es al kernel, es decir, se utilizan para sincronizar el acceso a los datos por parte de los distintos threads. Nosotros podemos ver que hilos se quedan esperando en los monitores, durante cuanto tiempo, etc. Datos que los desarrolladores agradecerán. Objetos y reserva de memoria Cuando se crea un nuevo objeto este ocupa una parte de memoria, es interesante saber cuales son los objetos más grandes, cuales se crean con más frecuencia, etc. Si los desarrolladores pueden optimizar el uso de los objetos y su tamaño es posible ahorrar considerable memoria. Métodos Podemos también analizar cuales son los métodos más ejecutados, en informática suele ser buena idea optimizar las operaciones más frecuentes aunque implique penalizar las ocasionales. Con estos datos los desarrolladores pueden centrar sus esfuerzos en ellas.Ejemplos prácticos, obteniendo los datos.
Garbage Collector Este script nos mostrará datos acerca el garbage collector global, concretamentne cuantas veces se ha ejecutado durante la muestra y cuanto dura su ejecución.root@opensolaris:~# ./garbage-colector.d 2688 3 value ------------- Distribution ------------- count 1048576 | 0 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 4194304 | 0
En este ejemplo podemos ver que se ha ejecutado tres veces y hs tardado 209152 nanosegundos, a modo de curiosidad también nos indica que el GC es el thread 3 del proceso. Este otro script es similar al anterior pero, simplificando un poco, tracea los Pararel Garbage Colectors responsables de la gestión de las distintas generaciones de memoria por separado.root@opensolaris:~# ./garbage-colector-pool.d 2688 Code Cache value ------------- Distribution ------------- count 1048576 | 0 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 4194304 | 0 Eden Space value ------------- Distribution ------------- count 2097152 | 0 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 8388608 | 0 Survivor Space value ------------- Distribution ------------- count 2097152 | 0 4194304 |@@@@@@@@@@ 1 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 16777216 | 0 Perm Gen value ------------- Distribution ------------- count 4194304 | 0 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 16777216 | 0 Tenured Gen value ------------- Distribution ------------- count 4194304 | 0 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 16777216 | 0
La información es parecida al anterior salvo que está dividida por cada una de los Pararel Garbage Collector, Tenured, Perm, Survivor, Eden y Code. Objetos Para tracear los objetos podemos usar unos simples one-liners que nos proporcionarán información bastante interesante, veamos unos ejemplos.root@opensolaris:~# ps -ef | grep java root 2688 2680 0 jul 01 console 1236:26 java -Dprogram.name=run.sh -server -XX:+ExtendedDTraceProbes -Xms128m -Xmx512m ############ thread y objeto allocado dtrace -qn 'hotspot2688:::object-alloc { printf("thread %d new %s \n",arg0, stringof(copyin(arg1,arg2))); }' stringof(copyin(arg1,arg2))); }' thread 23 new [Ljava/lang/String; thread 23 new java/io/FileString; thread 23 new java/lang/StringBuffer thread 23 new [C thread 23 new [C thread 23 new [C thread 23 new java/lang/String [...] ############ Tamaño reservado por objetos dtrace -qn 'hotspot2688:::object-alloc { @[stringof(copyin(arg1,arg2))] = sum(arg3); }' rjuna/ats/arjuna/coordinator/CheckedActionore/AtomicActionmple 8 com/arjuna/ats/arjuna/[...]/AtomicActionmpleonEventListener$TransactionSynchronization 8 java/lang/Objectnalizerommon/[...]/arjunacore/AtomicActionmple 8 java/lang/Objectnalizerommon/[...]AtomicActionmpleonEventListener$TransactionSynchronization 8 [...] [Cva/lang/StringBufferoggingEventctQueuedSynchronizer$Node 15528 ############ Numero de veces que se ha reservado un objeto dtrace -qn 'hotspot2688:::object-alloc { @[stringof(copyin(arg1,arg2))] = quantize(arg0); }' java/lang/Stringp$Entrybean/DescriptorSupportteInforployedURL value ------------- Distribution ------------- count 4 | 0 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 164 16 | 0 [Cva/lang/StringBuilderbean/DescriptorSupportteInforployedURL value ------------- Distribution ------------- count 4 | 0 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 205 16 | 0 [Cva/lang/StringBuffer value ------------- Distribution ------------- count 32 | 0 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 29 128 | 0 [...]
Monitores Como antes os comentaba, los monitores de java son usados por sincronizar el acceso a los recursos, si un monitor está ocupado, el thread pretendiente debe esperar que se libere, con este script podremos ver que threads se quedan esperando en monitores y durante cuanto tiempo.root@opensolaris:~# ./monitor-wait.d 2688 dtrace: script './monitor-wait.d' matched 2 probes ^C 69 value ------------- Distribution ------------- count 8388608 | 0 16777216 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 3554432 | 0
Métodos En este primer ejemplo contamos el número de veces que se ejecuta cada método.
root@opensolaris:~# ./method.d
Tracing... Hit Ctrl-C to end.
^C
EDU/oswego/cs/dl/util/concurrent/ConcurrentHashMap.put 1
[...]
java/lang/System.currentTimeMillis 209
java/lang/Object.
java/util/PriorityQueue offer value ------------- Distribution ------------- count 32768 | 0 65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 131072 | 0 java/util/PriorityQueue poll value ------------- Distribution ------------- count 32768 | 0 65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 131072 | 0 [...] java/lang/Object wait value ------------- Distribution ------------- count 268435456 | 0 536870912 |@@@@@@@@@@@@ 5 1073741824 | 0 2147483648 | 0 4294967296 | 0 8589934592 | 0 17179869184 | 0 34359738368 | 0 68719476736 | 0 137438953472 | 0 274877906944 | 0 549755813888 | 0 1099511627776 | 0 2199023255552 | 0 4398046511104 | 0 8796093022208 | 0 17592186044416 | 0 35184372088832 | 0 70368744177664 | 0 140737488355328 | 0 281474976710656 | 0 562949953421312 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12 1125899906842624 | 0 < /p>
