Comandos linux útiles para depurar el rendimiento de aplicaciones Java

por | Octubre 9, 2012

Linux es un sistema operativo muy bueno, si nosotros conociéramos las herramientas correctas para “debugear” nuestra tarea sería mas fácil. Algunas veces es bastante difícil encontrar los errores en sistemas que ya han salido a producción, a continuación se detalle algunos comandos que harán que depurar aplicaciones java sobre sistemas opertivos linux sea mas fácil.

1. lsof. Comprueba si existen descriptores de archivos abiertos.

Este comando lista los descriptores de archivos abiertos por un proceso de un sistema Unix. A continuación una breve descripción de la salida del comando man de lsof.

An open file may be a regular file, a directory, a block special file, a character special file, an executing text  reference, a library, a stream or a network file (Internet socket, NFS file or UNIX domain socket.) A specific file or all the files in a file system may be selected by path.

Este comando es bastante útil cuando te enfrentas a problemas relacionados con librerías de terceros y resulta complicado distinguir cual librería está usando tu programa. La salida del comando muestra la ruta absoluta de las librerías que están abiertas. De echo es muy interesante ver que muchas de las librerías no han sido cargadas hasta que tu aplicación las necesita. Un ejemplo de la salida del comando lsof se muestra a continuación:

$ lsof -p 4485
java 4485 alejo 22r REG 8,4 907988 1576751 $JBOSS_HOME/server/default/lib/jboss-remoting.jar

java 4485 alejo 23r REG 8,4 4018512 1576724 $JBOSS_HOME/server/default/lib/richfaces-ui.jar
java 4485 alejo 24r REG 8,4 65046 1576776 $JBOSS_HOME/server/default/lib/jboss-jsr88.jar
java 4485 alejo 25r REG 8,4 3539 1576774 $JBOSS_HOME/server/default/lib/scheduler-plugin-example.jar
java 4485 alejo 26r REG 8,4 111591 1576760 $JBOSS_HOME/server/default/lib/hibernate-entitymanager.jar
java 4485 alejo 27r REG 8,4 15146 1576794 $JBOSS_HOME/server/default/lib/log4j-snmp-appender.jar
java 4485 alejo 28r REG 8,4 398781 1576717 $JBOSS_HOME/server/default/lib/alfresco-web-service-client.jar
java 4485 alejo 29r REG 8,4 1516943 1576738 $JBOSS_HOME/server/default/lib/richfaces-impl.jar
java 4485 alejo 30r REG 8,4 599743 1576735 $JBOSS_HOME/server/default/lib/javassist.jar
java 4485 alejo 31r REG 8,4 167694 1576746 $JBOSS_HOME/server/default/lib/bsf.jar
java 4485 alejo 32r REG 8,4 65358 1576775 $JBOSS_HOME/server/default/lib/jbossws-common.jar
java 4485 alejo 33r REG 8,4 55424 1576722 $JBOSS_HOME/server/default/lib/commons-logging.jar

¿Cómo usarlo?

Si nos fijamos en la salida anterior, este comando muestra detalles exactos de los archivos abiertos por tu aplicación. Si hay un jar que no corresponde a los usados por el programa, puedes descubrir fácilmente cual es mirando su ruta absoluta.

Nota: La salida ha sido modificada, en la ruta de las librerías por seguridad. Para saber el proceso java que esta asignado usamos la siguiente orden: ps -ef | grep java . La segunda columna es el PID.

2. pstack. Comprueba si existen procesos “stack trace”

Este comando es ralmente muy útil si esta depurando algunos errores críticos como deadlock en producción. A continuación de la salida del comando pstack para un proceso java.

$ pstack 4485

Thread 209 (Thread 818031520 (LWP 26203)):
#0 0xb7fe87a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0xb7fd3f7c in pthread_cond_timedwait@@GLIBC_2.3.2 ()
#2 0xb7fd43f5 in pthread_cond_timedwait@GLIBC_2.0 ()
#3 0xb78ee95c in os::Linux::safe_cond_timedwait ()
#4 0xb78d5e41 in Monitor::wait ()
#5 0xb79d1e8b in VMThread::loop ()
#6 0xb79d1af0 in VMThread::run ()
#7 0xb78ef6f8 in _start ()
#8 0xb7fd13cc in start_thread () from /lib/tls/libpthread.so.0
#9 0xb7f6396e in clone () from /lib/tls/libc.so.6

¿Cómo usarlo?

Este comando es bastante útil en el caso en que se esté depurando un programa java con múltiples hilos. Al depurar errores que tienen que ver con consumo de CPU, este comando es de bastante ayuda, se puede comprobar que al tener demasiados procesos haciendo uso del CPU habrá muchos mas que se quedaron a la espera.

3. jstack – Hilos de procesos java stack trace.

Este comando es bastante útil cuando estas depurando errores dificiles de reproducir, como deadlocks, uso exesivo de CPU, etc. A continuación de la salida del comando jstack para un proceso java usando el comando jstack.

Attaching to process ID 24776, please wait...

Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_16-b02
Thread 25010: (state = IN_NATIVE)
- java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) @bci=0 (Compiled frame; information may be imprecise)
- java.net.SocketInputStream.read(byte[], int, int) @bci=84, line=129 (Compiled frame)
- com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(com.sun.net.ssl.internal.ssl.InputRecord, boolean) @bci=44, line=782 (Interpreted frame)
- com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(com.sun.net.ssl.internal.ssl.InputRecord) @bci=15, line=739 (Interpreted frame)
- com.sun.net.ssl.internal.ssl.AppInputStream.read(byte[], int, int) @bci=30, line=75 (Interpreted frame)
- org.apache.coyote.http11.InternalInputBuffer.fill() @bci=59, line=738 (Interpreted frame)
- org.apache.coyote.http11.InternalInputBuffer.parseRequestLine() @bci=16, line=399 (Compiled frame)
- org.apache.coyote.http11.Http11Processor.process(java.io.InputStream, java.io.OutputStream) @bci=327, line=828 (Compiled frame)

¿Cómo usarlo?

Este comando es bastante útil ya que te permite saber exactamente el nombre de la  clase o del método como una traza de error. Si estás depurando el uso excesivo de CPU, toma dos o tres capturas de este log y revisa que método o clase se repite en cada captura y el hilo que se está comiendo mas ciclos de la CPU.

4. ps con la opción “-L”

Este comando es bastante usado, más no su opción -L. Esta opción lista los procesos mas “ligeros” de un sistema operativo Linux. La salida de este comando puede ser combinado con la salida del comando jstack para un análisis más detallado. A continuación de la salida simple del comando ps -L.

ps -aefL | grep java | more
host 10258 1 10258 0 94 Dec23 ? 00:00:25 /usr/java/jdk/bin/java -Xms1024M -Xmx1536M -XX:-UseParallelGC -Djava.util.logging.manager=org.apac
he.juli.ClassLoaderLogManager -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.endorsed.dirs=/usr/local/tomcat/common/endorse
d -classpath :/usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/commons-logging-api.jar -Dcatalina.base=/usr/local/tomcat -Dcatalina.home=/usr/local/
tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp org.apache.catalina.startup.Bootstrap start
host 10258 1 10259 0 94 Dec23 ? 00:03:15 /usr/java/jdk/bin/java -Xms1024M -Xmx1536M -XX:-UseParallelGC -Djava.util.logging.manager=org.apac
he.juli.ClassLoaderLogManager -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.endorsed.dirs=/usr/local/tomcat/common/endorse
d -classpath :/usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/commons-logging-api.jar -Dcatalina.base=/usr/local/tomcat -Dcatalina.home=/usr/local/
tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp org.apache.catalina.startup.Bootstrap start

¿Cómo usarlo?

Este comando puede ser usando en combinación de los comandos  pstack & jstack. Los comandos pstack y jstack usan el ID del hilo del proceso en su salida y usando el comando “ps -L” se puede ver los procesos ligeros (hilos unix) para tu proceso java. Esto puede ayudarte a apuntar al hilo exacto que está causando problemas.

5. jmap – Controlar la asignación de almacenamiento dinámico de Java

El comando jmap es parte del JDK 5, puede ser usado para conectarse a un proceso java “vivo”. Al igual que el comando jstack este comando se puede usar en procesos que ya están corriendo para obtener los detalles del uso de memoria(detalles de la asignacion de la JVM). El uso de este comando es: jpam [pid]. A continuación la salida de este comando.

$ /usr/java/jdk/bin/jmap 4485
Attaching to process ID 4485, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.5.0_16-b02
0x08048000 62K /usr/java/jdk1.5.0_16/bin/java
0x477ae000 343K /usr/java/jdk1.5.0_16/jre/lib/i386/libcmm.so
0x4923b000 77K /lib/libresolv-2.3.4.so
0x4924e000 21K /lib/libnss_dns-2.3.4.so
0x49257000 22K /usr/java/jdk1.5.0_16/jre/lib/i386/libmanagement.so
0x4b9ed000 71K /usr/java/jdk1.5.0_16/jre/lib/i386/libnet.so
0x4c310000 156K /usr/java/jdk1.5.0_16/jre/lib/i386/libjpeg.so
0xb741e000 63K /usr/java/jdk1.5.0_16/jre/lib/i386/libzip.so
0xb742f000 133K /usr/java/jdk1.5.0_16/jre/lib/i386/libjava.so
0xb7452000 47K /usr/java/jdk1.5.0_16/jre/lib/i386/libverify.so
0xb745e000 46K /lib/libnss_files-2.3.4.so
0xb7469000 97K /lib/libnsl-2.3.4.so
0xb748a000 206K /lib/tls/libm-2.3.4.so
0xb74ae000 26K /usr/java/jdk1.5.0_16/jre/lib/i386/native_threads/libhpi.so
0xb74b7000 7275K /usr/java/jdk1.5.0_16/jre/lib/i386/server/libjvm.so
0xb7e98000 1502K /lib/tls/libc-2.3.4.so
0xb7fc7000 14K /lib/libdl-2.3.4.so
0xb7fcc000 103K /lib/tls/libpthread-2.3.4.so
0xb7fe8000 108K /lib/ld-2.3.4.so

¿Cómo usarlo?

Este comando es bastante útil al depurar “issues” en procesos java OutOfMemory. Para más detalles referir a los comandos del JDK en el siguiente enlace. Troubleshooting Java SE.

En PID(ID del proceso) usado para los ejemplos(4485) es el id del proceso de mi máquina. Para saber cual es id del proceso java de tu máquina puedes emplear el siguiente comando:

$ ps -ef  |  grep java

Para más información y detalles referir a la fuente: http://www.fromdev.com/2008/12/debugging-java-on-unixlinux-my-favorite.html