DTrace en una línea
DTrace es una herramienta que presenta una cantidad infinita de posibilidades, lo demuestra la enorme cantidad de información que se está publicando sobre ella. Pero una de las carácterísticas que me parecen mas interesantes, es que nos puede ayudar a identificar problemas de una forma sencilla y rápida, ya que podemos invocar a DTrace desde la misma línea de comando.
En esta página voy a publicar todos aquellos comandos de dtrace, que creo, pueden ser interesante, solo voy a poner una condición, todos se van a ejecutar en una línea de la shell.
El comando truss
Para comenzar uno sencillo, como utilizar DTrace para emular al comando truss.
# dtrace -q -n 'syscall:::entry
{printf("n%d/%d: %s(0x%x,0x%x,0x%x)",pid,curthread->t_tid,probefunc,arg0,arg1,arg2);}'
- pid, variable con el PID del proceso.
- curthread, es un puntero a la estructura de tipo kthread_t, con la información del thread
- probefunc, variable con el nombre de la función.
- arg0,arg1,arg2, variables con los argumentos de la llamada a sistema.
Procesos entrando en CPU
Con esta línea podemos comprobar, cuales son los procesos que mas veces se les asigna una CPU, se está utilizando la variable execname, aunque una variante interesante es utilizar la variable pid.
root@tcbbdd02-01 # dtrace -q -n 'sched:::on-cpu{ @[execname] = count(); }'
^C
fmd 1
inetd 1
svc.configd 1
svc.startd 1
vxdclid 1
vxesd 1
xprtld 1
pppd 2
CmdServer 5
dtrace 5
fsflush 5
tail 5
xntpd 5
sendmail 6
vxpal 13
sshd 18
nscd 114
prstat 114
oracle 2902
sched 3897
Número de syscall de cada thread
Con la siguiente línea, podemos obtener de forma rápida las llamas a sistemas y la veces que se ejecutan en cada thread del proceso.
root@host # dtrace -q -n 'syscall:::entry / pid == $1 /{@array[tid,execname,probefunc]=count();}' 5560
^C
108 java lwp_cond_wait 1
111 java lwp_cond_signal 1
111 java lwp_cond_wait 1
247 java lwp_cond_signal 1
247 java lwp_cond_wait 1
248 java lwp_cond_wait 1
248 java sendto 1
249 java lwp_cond_signal 1
249 java recvfrom 1
314 java lwp_cond_wait 1
372 java pollsys 1
98 java lwp_cond_wait 2
216 java lwp_cond_signal 2
222 java lwp_cond_wait 2
109 java access 4
109 java lstat64 4
109 java unlink 4
216 java lwp_cond_wait 4
217 java lwp_cond_wait 5
219 java lwp_cond_wait 5
109 java pollsys 6
217 java write 6
219 java write 6
109 java lwp_cond_signal 10
109 java stat64 18
109 java fstat64 21
109 java open64 21
109 java send 21
109 java close 23
106 java pollsys 29
109 java read 1139
109 java write 3031
root@host #
Número de syscall de cada thread, cada segundo
A la línea anterior hemo añadadio el probe profile:::tick-1sec{printa(@array);trunc(@array)}, el cual imprime el contenido del array y posteriormente lo trunca.
root@host # dtrace -q -n 'syscall:::entry / pid == $1 /{@array[tid,probefunc]=count();} profile:::tick-1sec{printa(@array);trunc(@array)}' 7780
98 lwp_cond_wait 1
111 pollsys 1
159 lwp_cond_signal 1
159 lwp_cond_wait 1
164 pollsys 1
226 lwp_cond_signal 1
232 lwp_cond_wait 1
269 pollsys 1
290 lwp_cond_wait 1
290 write 1
302 accept 1
302 setsockopt 1
302 write 1
305 lwp_cond_signal 1
305 write 1
320 pollsys 1
322 pollsys 1
384 lwp_cond_wait 1
384 write 1
386 lwp_cond_wait 1
386 write 1
120 lwp_cond_signal 2
120 lwp_cond_wait 2
159 write 2
164 ioctl 2
164 lwp_cond_wait 2
226 lwp_cond_wait 2
258 lwp_cond_signal 2
258 lwp_cond_wait 2
261 lwp_cond_signal 2
261 recvfrom 2
305 send 2
159 ioctl 3
164 lwp_cond_signal 3
164 write 3
305 lwp_cond_wait 3
159 read 4
164 read 4
305 close 5
305 fcntl 5
103 pollsys 7
388 lwp_cond_wait 9
110 pollsys 17
103 ioctl 192
98 lwp_cond_wait 1
103 lseek 1
103 read 1
111 pollsys 1
117 lwp_cond_wait 1
159 lwp_cond_wait 1
159 pollsys 1
164 lwp_cond_wait 1
164 pollsys 1
225 ioctl 1
225 send 1
226 lwp_cond_signal 1
232 lwp_cond_wait 1
258 lwp_cond_signal 1
258 lwp_cond_wait 1
261 lwp_cond_signal 1
261 recvfrom 1
302 accept 1
302 setsockopt 1
302 write 1
322 pollsys 1
360 lwp_cond_signal 1
402 lwp_cond_signal 1
402 lwp_cond_wait 1
402 lwp_mutex_timedlock 1
421 lwp_cond_wait 1
421 write 1
159 lwp_cond_signal 2
164 ioctl 2
164 lwp_cond_signal 2
164 write 2
225 read 2
226 lwp_cond_wait 2
290 lwp_cond_wait 2
290 write 2
305 lwp_cond_signal 2
305 write 2
360 lwp_cond_wait 2
120 lwp_cond_wait 3
159 ioctl 3
159 write 3
305 ioctl 3
103 pollsys 4
164 read 4
120 lwp_cond_signal 5
159 read 6
305 lwp_cond_wait 6
305 stat64 8
388 lwp_cond_wait 9
110 pollsys 17
305 send 46
358 send 80
305 read 84
358 read 179
98 lwp_cond_wait 1
111 pollsys 1
159 ioctl 1
Tiempo de ejecución de cada thread de un proceso
La siguiente linea de comando, no cumple exactamente el título de la página, pero creo que puede ser útil para todos aquellos que deseen conocer cuanto tiempo emplea un thread en ejecutar las syscall. La primera columna es el thread ID, la siguiente columna en la llamada a sistema y por último está la sumatoria del tiempo empleado por todas las invocaciones a la syscall.
root@host1 # dtrace -q -n 'syscall:::entry
/pid == $1/{
self->time=timestamp; self->tid=tid;
}
:::BEGIN{array[tid,probefunc]=0; inicio=timestamp;}
syscall:::return
/pid== $1 && self->tid==tid/ {
@array[tid,probefunc]=sum((timestamp-self->time));
}:::END{printa(@array);printf("n Time total t %d seg ",(timestamp-inicio)/1000000000);}
' 6272
^C
232 fstat64 12192
235 fstat64 12521
232 getsockname 13290
224 close 13729
235 ioctl 21308
353 lwp_mutex_timedlock 22296
232 ioctl 24054
288 lwp_cond_signal 24163
...
218 lwp_cond_wait 2588508757
217 ioctl 2589616226
536 lwp_cond_wait 2713121947
231 lwp_cond_wait 3019138563
289 lwp_cond_wait 3026488067
225 lwp_cond_wait 3037693553
412 lwp_cond_wait 3453741430
257 lwp_cond_wait 3599322030
260 recvfrom 3610982121
539 lwp_cond_wait 3617181654
301 accept 3956773430
103 pollsys 3958027747
98 lwp_cond_wait 4028218304
111 pollsys 4034147313
334 pollsys 4034569410
118 lwp_cond_wait 4374032786
110 pollsys 4412834997
Time total 4 seg
root@host1 #
Una modificación interesante es eliminar del array asociativo @array el índice probefunc, con este cambio se sumaran todos los tiempos empleados en cada syscall de un thread.
root@host # dtrace -q -n 'syscall:::entry
/pid == $1/{
self->time=timestamp; self->tid=tid;
}
:::BEGIN{array[tid,probefunc]=0; inicio=timestamp;}
syscall:::return
/pid== $1 && self->tid==tid/ {
@array[tid]=sum((timestamp-self->time));
}:::END{printa(@array);printf("n Time total t %d seg ",(timestamp-inicio)/1000000000);}
' 6272
^C
...
98 9077224664
231 9077337905
225 9090857291
103 9267196977
257 9312347666
260 9326818991
538 9339934943
118 10003880308
110 10047955267
Time total 10 seg
Comentarios Recientes
Sobre
Esta plantilla a sido creada con la validacion de CSS y XHTML, por N.Design Studio.Los iconos usados son de Web 2 Mini pack.