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