PARA FLIPAR PEPINILLOS


Guido García · @palmerabollo · 2014

QUÉ ES DTRACE

Framework para obtener información de un sistema
(kernel  + userland)
·
Sin parar ni modificar tu aplicación
Listo para producción


"DTrace is a magician that conjures up rainbows, ponies and unicorns — and does it all entirely safely and in production!" – dtrace.org


SONDAS (PROBES)

Son los puntos donde engancharnos "a mirar"

Selectores jerárquicos
provider:module:function:name
Lista de sondas disponibles: dtrace -ln :::
(>180000 en mi mac)

"A probe is a location or activity to which DTrace can bind a request to perform a set of actions, like recording a stack trace or the argument to a function"

UN EJEMPLO SENCILLO

Trazar la ejecución de nuevos procesos
dtrace -n 'proc:::exec-success { trace(execname) }'

CPU     ID                    FUNCTION:NAME
  3   1218        __mac_execve:exec-success   login
  0   1140         posix_spawn:exec-success   mdworker
  1   1218        __mac_execve:exec-success   zsh
  2   1218        __mac_execve:exec-success   git
  2   1218        __mac_execve:exec-success   git
...
Más 

https://google.com/?q=dtrace%20oneliners
http://brendangregg.com/DTrace/dtrace_oneliners.txt
http://solarisinternals.com/wiki/index.php/DTrace_Topics_One_Liner

D SCRIPTING LANGUAGE


BEGIN { inicialización } 
selector_sonda / filtros /
{
   acciones, acceso a información
}

END { terminación }

EJEMPLO

Trazar los ficheros que abre un proceso en tiempo real

syscall::open:entry /pid==$target/
{
    printf("%s", copyinstr(arg0));
}

dtrace -s openfiles.d -p 50026


NODE.JS

unA APLICACIÓN DE EJEMPLO

https://github.com/palmerabollo/test-express-dtrace



versiones utilizadas: nodejs 0.10.x, OSX 10.9.x

SONDAS PROVIDER NODE*

node*:::http-*
node*:::socket-*
node*:::gc-*
Listado de sondas: dtrace -lvn node*:::

http-client-request, http-client-response
http-server-request, http-server-response
gc-start, gc-done
net-server-connection, net-stream-end, net-socket-read, net-socket-write

EJEMPLOS · HTTP-SERVER-REQUEST (I)

Trazar peticiones HTTP recibidas
# dtrace -n 'node*:::http-server-request {printf("%s %s", copyinstr(arg4), copyinstr(arg5))}'

dtrace: description 'node*:::http-server-request' matched 2 probes
CPU     ID                    FUNCTION:NAME
  2   5296 _DTRACE_HTTP_SERVER_REQUEST:http-server-request GET /bubbles
  2   5296 _DTRACE_HTTP_SERVER_REQUEST:http-server-request GET /bubbles
  0   5296 _DTRACE_HTTP_SERVER_REQUEST:http-server-request GET /bubbles
  0   5296 _DTRACE_HTTP_SERVER_REQUEST:http-server-request GET /bubbles
...
Origen de las peticiones HTTP
# dtrace -n 'node*:::http-server-request {@[copyinstr(arg2)] = count()}' 

dtrace: description 'node*:::http-server-request ' matched 1 probe
^C
  10.95.61.78          124
  10.95.61.93           34

EJEMPLOS · HTTP-SERVER-REQUEST (II)

Latencia de peticiones HTTP recibidas

#!/usr/sbin/dtrace -s

node*:::http-server-request
/pid == $target/
{
    ip = copyinstr(arg2);
    rport = arg3;
    reqs[ip, rport] = timestamp;
}

node*:::http-server-response
/reqs[copyinstr(arg1), arg2]/
{
    latency = (timestamp - reqs[copyinstr(arg1), arg2]) / 1000000;
    @result = quantize(latency);
    reqs[copyinstr(arg1), arg2] = 0;
}
 



# dtrace -s nodelatency.d -p 50026
dtrace: script './nodelatency.d' matched 4 probes
^C
    
       value  ------------- Distribution ------------- count    
          64 |                                         0        
         128 |@@                                       7        
         256 |@@@@@@@@@@@                              33       
         512 |@@@@@@@@@@@@@@@@@@@@@@                   65       
        1024 |@@@@@@@@@@@                              32     
        2048 |                                         0
                
            

ver
https://github.com/davepacheco/nhttpsnoop

EJEMPLOS · BUNYAN LOGGER

Crea sus propias sondas en un nuevo provider
Permite mostrar logs no habilitados (de cualquier nivel)

bunyan -p 50026

~
dtrace ... -n 'bunyan*:::log-*' -p 50026

# bunyan -p 50026
...
[2014-06-12T08:15:16] DEBUG: myapp/50026 on tizona: run cleanup 1 bubbles
[2014-06-12T08:15:46] DEBUG: myapp/50026 on tizona: run cleanup 0 bubbles
...
https://github.com/trentm/node-bunyan
npm install bunyan -g

MÓDULO dtrace-provider

Facilita la creación de tus propios providers y sondas
https://github.com/chrisa/node-dtrace-provider

Ejemplo

myprovider:::myprobe

var dtrace = require('dtrace-provider');
var provider = dtrace.createDTraceProvider('myprovider');
var probe = provider.addProbe('myprobe', 'int', 'char *');provider.enable();

...
probe.fire(function () { return [1, 'foo'] });

5 LOC

EJEMPLO · RECOLECTOR DE BASURA

Latencia del recolector de basura
#!/usr/sbin/dtrace -s

node*:::gc-start{
    trace("gc start");
    self->ts = timestamp;
}

node*:::gc-done
/self->ts/
{
    @result = quantize((timestamp - self->ts) / 1000);
    self->ts = 0;
} 

Desviación típica:
    @sd = stddev((timestamp - self->ts) / 1000);


# sudo dtrace -s gc.d
dtrace: script 'gc.d' matched 4 probes

CPU     ID                    FUNCTION:NAME
  3   4485 _dtrace_gc_start_GCCallbackFlagsE:gc-start   gc start   
  ...
^C
           value  ------------- Distribution ------------- count    
             256 |                                         0
             512 |@                                        1
            1024 |@@@@@@@@@@@@@@@@                         12
            2048 |@@@@@@@@@@@@@@@                          11
            4096 |@@@@@                                    4
            8192 |@                                        1
           16384 |                                         0
    
Truco para exponer las llamadas al recolector de basura
# node --expose-gc
> global.gc()

EJEMPLO · LATENCIA ADDONS C/C++


Latencia en llamadas asíncronas a addons
http://www.joyent.com/blog/tracing-node-js-add-on-latency

pid$target::uv_queue_work:entry
...

Este no lo voy a hacer

EJEMPLO · MUESTRAS PERIÓDICAS

No sólo podemos esperar eventos. Podemos muestrear.
Ejemplo 1: Número de llamadas al sistema cada 5 segundos:
syscall:::entry
/execname == "node"/
{ @[probefunc] = count() }
tick-5sec
{ printa(@); clear(@); }

Ejemplo 2: Stacktrace cada milisegundo:
dtrace -n 'profile-1001  /pid == $target/  { @[ustack()] = count(); }' -p 50026
ver http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html

EJEMPLO · MODO DESTRUCTIVO

Habilitar el modo destructivo: dtrace -w

Enviar SIGABRT al proceso node que no encuentre un fichero
syscall::open:return
/execname == "node" && errno == ENOENT/ 
{ trace(pid); raise(SIGABRT); exit(0); }
Tomar un coredump del proceso que reciba una señal SIGSEGV
proc:::signal-send
/args[2] == SIGSEGV/
{ trace(pid); system("gcore %d", pid); exit(0); }
En OSX se puede instalar gcore con: brew install gcore


Más

BONUS EXAMPLE · MYSQL

dtrace -ln mysql*:::

dtrace -n 'mysql*:::query-start{ trace(copyinstr(arg0)) }'

...
0  30046 _enum_server_command:query-start
         select * from Configuration where name like 'mail%'
0  30046 _enum_server_command:query-start
         SHOW FULL COLUMNS FROM `Configuration` FROM `BillyDB`
0  30046 _enum_server_command:query-start
         drop table Configuration

Otras posibilidades: latencia, consultas fallidas

Más
http://dev.mysql.com/doc/refman/5.5/en/dba-dtrace-mysqld-ref.html


Ejemplo: trazar sólo las sentencias fallidas
:::query-start
{
  self->query = arg0
}
:::query-done
/self->query && arg0 == 1/
{
  trace(copyinstr(self->query));
  self->query = NULL
}

ALGUNAS IDEAS

Incluir sondas en librerías de TDAF
  • therror
  • tdaf-node-logger
  • tdaf-node-boilerplate ?

Probar dtrace4linux en Centos y RH

Visualizaciones en tiempo real

    MÁS RECURSOS ONLINE

    cheatsheet
    http://www.oracle.com/technetwork/server-storage/solaris11/documentation/dtrace-cheatsheet-1930738.pdf


    providers https://wikis.oracle.com/display/DTrace/Providers

    http://joyent.com/developers/node/debug

    http://blog.nodejs.org/2012/04/25/profiling-node-js/

    http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Overhead

    http://dtrace.org/blogs/brendan/2011/02/18/dtrace-pid-provider-overhead/

    http://joyent.com/blog/understanding-dtrace-ustack-helpers

    Y MÁS

    http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Intro
    http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Quick_Wins