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

http://dtrace.org/blogs/dap/2013/10/14/stopping-a-broken-program-in-its-tracks/

hacer el mal http://felinemenace.org/~nemo/dtrace-infiltrate.pdf

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