feedburner

Lorem ipsum dolor sit amet,
consectetur adipisicing elit,
sed do eiusmod tempor incididunt ut labore
et dolore magna aliqua.

The power of time

Etiquetas:

La instrucción time, usada tal cual, devuelve estadísticas de tiempo invertido en la ejecución del comando que se pase por parámetro. Según man time :

"(...)
La orden time ejecuta el programa orden con los argumentos suministra
dos. Cuando orden finaliza, time escribe un mensaje en la salida
estándar devolviendo estadísticas temporales sobre la ejecución de
este programa. Estas estadísticas están compuestas por (i) el tiempo
real transcurrido entre la llamada y la finalización de orden , (ii)
el tiempo de usuario del procesador (la suma de los valores tms_utime y
tms_cutime en un struct tms tal y como devuelve times(2)), y (iii) el
tiempo de sistema del procesador (la suma de los valores tms_stime y
tms_cstime en un struct tms tal y como devuelve times(2)).
(...)"


Veámos un ejemplo:

dballester@nebuchadnezzar:~$ time scp sqldeveloper-1.1.2.2579-no-jre.zip dballester@localhost:/tmp/prueba2.zip
dballester@localhost's password:
sqldeveloper-1.1.2.2579-no-jre.zip 100% 39MB 38.8MB/s 00:01

real 0m4.963s
user 0m0.688s
sys 0m0.104s
dballester@nebuchadnezzar:~$

Ok, pero si seguimos leyendo el man de time, éste es capaz de darnos muchísima más información. Lo que vemos de real, user y sys es tan solo la salida por defecto y la punta del iceberg.

time nos puede dar estadísticas de ( entre otras ) : el número de veces que el proceso ha sido sacado de la memoria principal, el número de veces que el sistema ha sacado al proceso de ejecución en CPU por haber consumido todo el tiempo asignado para él, número de mensajes ( sockets ) enviados y recibidos...

Todas estas estadísticas ( ver man time ) se pueden obtener indicando un formato de salida determinado a time. Como yo soy, entre muchas otras cosas, vago y con falta de memoria, he montado un script que visualiza todas las estadísticas. No hay magia, solo las muestro pero agrupadas por área. Os dejo el código junto con un ejemplo de ejecución. Para los que nos dedicamos a la consultoría creo que nos irá muy bien tener este script a mano. Está bajo licencia GPL2 así que ya sabéis podéis usarlo, transformarlo y distribuirlo bajo los límites de dicha licencia.

Script time_command.sh disponible en in.solit.us http://in.solit.us/archives/download/23169



Una vez bajado nuestra máquina, hay que darle derechos de ejecucción

chmod 755 time_command.sh


Ejemplo de lanzamiento

Acepta 2 parámetros, el primero debe ser el comando a ejecutar, limitado entre comillas dobles. El segundo es el fichero de log donde se guarda la salida de las estadísticas. Este segundo parámetro es opcional y si no se informa el script generará uno que creará con los datos de la fecha ( fecha/hora hasta los segundos ) del momento de la ejecución, y lo dejará en el mismo directorio donde se ha lanzado el script ( por lo tanto debemos tener derechos de escritura en dicho directorio). Yo recomiendo que dejéis este script en vuestro home y lo lancéis desde ahí


$ ./time_command.sh "scp sqldeveloper-1.1.2.2579-no-jre.zip dballester@localhost:/tmp/prueba2.zip" cp2.log
The authenticity of host 'localhost (127.0.0.1)' can't be established.
RSA key fingerprint is 43:53:7e:71:3a:95:ff:b4:d1:2d:21:dc:c4:1b:ad:1d.
Are you sure you want to continue connecting (yes/no)? yes
Warning: Permanently added 'localhost' (RSA) to the list of known hosts.
dballester@localhost's password:
sqldeveloper-1.1.2.2579-no-jre.zip


Log resultante

$ cat cp2.log
Comand executed scp sqldeveloper-1.1.2.2579-no-jre.zip dballester@localhost:/tmp/prueba2.zip
TIME COMMAND

Elapsed real (wall clock) time used by the process, in [hours:]minutes:seconds 0:06.91
Elapsed real (wall clock) time used by the process in seconds 6.91


CPU STASTISTICS

Percentage of the CPU that this job got(1) 13%
Total number of CPU-seconds used by the system on behalf of the process (in kernel mode), in seconds 0.11
Total number of CPU-seconds that the process used directly (in user mode), in seconds 0.82
Number of times that the program was context-switched voluntarily(2) 5437
Number of times the process was context-switched involuntarily (because the time slice expired) 6024
Number of signals delivered to the process 0


MEMORY STATISTICS

Average amount of shared text in the process, in Kilobytes 0
Average size of the process’s unshared data area, in Kilobytes 0
Average unshared stack size of the process in Kilobytes 0
Average total (data+stack+text) memory use of the process, in Kilobytes 0
Maximum resident set size of the process during its lifetime, in Kilobytes 0
Average resident set size of the process in Kilobytes 0
Number of minor, or recoverable, page faults(3) 1031
Number of times the process was swapped out of main memory 0
System’s page size in bytes(4) 4096


I/O STATISTICS

Number of file system inputs by the process 0
Number of file system outputs by the process 0
Number of major, or I/O-requiring, page faults that occurred while the process was running(5) 1
Number of socket messages received by the process 0
Number of socket messages sent by the process 0




(1) This is just user + system times divided by the total running time
(2) For instance while waiting for an I/O operation to complete
(3)These are pages that are not valid (so they fault)
but which have not yet been claimed by other virtual pages.
Thus the data in the page is still valid but the system tables must be updated.
(4) This is a per-system constant, but varies between systems.
(5) These are faults where the page has actually migrated out of primary memory.












2 comentarios:
gravatar
lasupermarmota dijo...
jueves, 11 de diciembre de 2008, 1:24:00 CET  

tu script ya no ta en insolitus... podias volver a colgarlo?? o si no es muy largo pegarlo directamente en tu blog.. asias!

gravatar
lasupermarmota dijo...
jueves, 11 de diciembre de 2008, 1:25:00 CET  

soy yo otra vez: se me habia olvidado darle a "Enviar por correo electrónico comentarios de seguimiento a"

Publicar un comentario