Normalmente la máquina virtual de Java (JVM o Java Virtual Machine) hace un trabajo bastante razonable cuando corremos una aplicación en terminos de velocidad y uso de recursos; Sin embargo la única forma de saber eso por seguro es observando como se porta nuestro programa a través del tiempo.
la JVM cuenta con parametros que afectan su comportamiento, veamos que podemos hacer para mejorar la ejecución de nuestro programa; Suponga por ejemplo que usted escribió un programa para hacer reportes desde la base de datos de ‘Bugzilla‘ en formato XML y que llama a su aplicación en Java así (sólo le muestro el fragmento de código que nos interesa). El programa es un simple programa que corre por la línea de comandos:
SYSTEM_PROPERTIES=”-DBugzillaReport.startdate=${ARGUMENTS[0]} -DBugzillaReport.enddate=${ARGUMENTS[1]} -DBugzillaReport.outputFile=${ARGUMENTS[2]} -DBugzillaReport.configFile=${ARGUMENTS[3]}”
COMMAND=”${JAVA_HOME}/bin/java ${SYSTEM_PROPERTIES} -classpath ${CLASSPATH} com.XXXX.bugzilla.report.CronReporter”
exec $COMMAND
OK, vamos a ver ahora como alterar la llamada del programa para obtener información. Primero veamos cuanto tarda el programa en correr usando la herramienta ‘time’.
COMMAND=”/usr/bin/time -p ${JAVA_HOME}/bin/java ${SYSTEM_PROPERTIES} -classpath ${CLASSPATH} com.XXXX.bugzilla.report.CronReporter”
Corriendolo tenemos:
[josevnz@god josevnz]$ ./BugzillaReport.bsh -s 2004-08-01 -e 2004-11-24 -c /home/josevnz/.BugzillaReport -f test.xml
real 7.04
user 2.80
sys 2.42
¿Que significa todo esto? ‘real‘ es cuanto se tardó el programa en realidad (7.04 segundos), ‘user‘ es cuanto tiempo pasó haciendo trabajo útil mientras que ‘sys‘ es cuanto pasó utilizando recursos del sistema (todo esto es a MUY groso modo). La herramienta ‘time’ nos dá mucha información útil, y le hemos pedido que nos muestre esa información en el formato (p)ortable (POSIX).
Vamos a jugar ahora con las estádisticas del recolector de basura (Garbage Collector). La salida es muy dependiente de la version del JDK que usted esté utilizando:
[josevnz@god josevnz]$ java -version
java version “1.4.2_04”
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2_04-b05)
Java HotSpot(TM) Client VM (build 1.4.2_04-b05, mixed mode)
[josevnz@god josevnz]$
Modificando el script:
SYSTEM_PROPERTIES=”-DBugzillaReport.startdate=${ARGUMENTS[0]} -DBugzillaReport.enddate=${ARGUMENTS[1]} -DBugzillaReport.outputFile=${ARGUMENTS[2]} -DBugzillaReport.configFile=${ARGUMENTS[3]} -verbosegc“
Corriendo el programa tenemos:
[josevnz@god josevnz]$ ./BugzillaReport.bsh -s 2004-08-01 -e 2004-11-24 -c /home/josevnz/.BugzillaReport -f test.xml
[GC 478K->128K(1984K), 0.0123790 secs]
[GC 578K->198K(1984K), 0.0096410 secs]
….
[Full GC 2222K->2162K(2892K), 0.0603210 secs]
[GC 2674K->2162K(4180K), 0.0070220 secs]
[GC 2672K->2165K(4180K), 0.0068920 secs]
[GC 2677K->2163K(4180K), 0.0063560 secs]
[GC 2667K->2171K(4180K), 0.0072510 secs]
[GC 2681K->2168K(4180K), 0.0008050 secs]
real 9.61
user 2.92
sys 2.49
El número en rojo es cuanto había antes de correr el GC (Garbage Collector), el número azul es cuanto habia después, el verde es la diferencia entre esos dos valores y el purpura es cuanto tiempo tardó liberando la memoria.
Idealmente deberíamos usar un programita para parsear el archivo, algo como esto:
1:#!/usr/bin/perl
2:# This program parses the GC log file of a JDK 1.4.2 and generates some stats
3:# Author: Jose V Nunez Zuleta (josevnz@yahoo.com)
4:my %stats;
5:my $count=0.0;
6:open(LOG, $ARGV[0]) || die "$!";
7:while(<LOG>) {
8: $_ =~ /\[GC (.*)K->(.*)K\((.*)K\), (.*) secs\]/;
9: $stats{bytes_freed}+=$3;
10: $stats{time_used}=$4;
11: $count++;
12:}
13:close(LOG);
14:my $average = $stats{bytes_freed} / $count;
15:print ("Bytes freed: $stats{bytes_freed}K ($average)K, Time used in GC: $stats{time_used} secs\n");
La salida sería also asi:
[josevnz@god josevnz]$ tmp/parse_gc_jdk142.pl gc.log
Bytes freed: 65872K (2744.66666666667)K, Time used in GC: 0.0008050 secs
[josevnz@god josevnz]$
Idealmente la JVM debería pasar menos de %5 haciendo GC, %15 y más alla ya es un problema. En nuestro ejemplo: (0.0008050 * %100.0) / 7.2 =~ %0.011181, estamos bien.
Esta aplicación en particular corre muy rápido, además de que no usa casi memoria en la pile (heap) asi que en teoría podríamos decirle a Java que reserve menos memoria al principio y que demore las operaciones del GC lo más posible:
SYSTEM_PROPERTIES=”-DBugzillaReport.startdate=${ARGUMENTS[0]} -DBugzillaReport.enddate=${ARGUMENTS[1]} -DBugzillaReport.outputFile=${ARGUMENTS[2]} -DBugzillaReport.configFile=${ARGUMENTS[3]} -Xms10m -XX:NewSize=5m -Xincgc
“
Ahora veamos el resultado final:
[josevnz@god josevnz]$ ./BugzillaReport.bsh -s 2004-08-01 -e 2004-11-24 -c /home/josevnz/.BugzillaReport -f test.xml
real 3.73
user 1.93
sys 1.33
[josevnz@god josevnz]$
Nada mal, ¡la mitad del tiempo, sólo con cambiar unos parámetros!
Tenga en cuenta que usted deberá experimentar mucho con su aplicación para obtener estadísticas valederas y que este pequeño articulo es muy informal como para ser tomado en serio (pero si espero haber despertado su curiosidad). Si quiere saber más acerca de este tópico, entonces lea este articulo.
Add to Address Book
