Log node.js http server response times and output it's distribution on exit.

output

[root@market1 ~]# ./request_time.d 
Request took 275 ms to complete /users/ubf4a1949-bb12-484a-80c5-ef7d079933e8/entitlement/edf627d85-f6bc-485c-a387-65b32bf4d231/token 
Request took 278 ms to complete /users/ubf4a1949-bb12-484a-80c5-ef7d079933e8/entitlement/edf627d85-f6bc-485c-a387-65b32bf4d231/token 
Request took 286 ms to complete /users/u07edf558-8f50-4963-992a-728f56e49590/entitlement/e3afec1f9-ed01-4444-b7b9-6e90cf573e17/token 
Request took 163 ms to complete /users/u7716cbc1-e0b9-4fab-b705-43d74aad9541/entitlement/ed89cf626-28c3-48ee-84d0-964726a9caef/token 
Request took 1 ms to complete /organization/oz/catchup/content/26cf243fda948f68430942993257746b 
Request took 3 ms to complete /organization/oz/catchup/content/26cf243fda948f68430942993257746b 
Request took 0 ms to complete /organization/oz/catchup/content/a61d78c15d3aecf8982e097ff8f74d2f 
Request took 2 ms to complete /organization/oz/catchup/content/a61d78c15d3aecf8982e097ff8f74d2f 
Request took 3 ms to complete /organization/oz/catchup/content/a61d78c15d3aecf8982e097ff8f74d2f 
Request took 1 ms to complete /organization/oz/catchup/content/26cf243fda948f684309429932588229 
Request took 2 ms to complete /organization/oz/catchup/content/7ce0e55f01a21bf9128f4152467d5594 
Request took 1 ms to complete /organization/oz/catchup/content/bb7afe745922e3546569f5d3685bbd3e 
Request took 2 ms to complete /organization/oz/catchup/content/bb7afe745922e3546569f5d3685bbd3e 
Request took 1 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151c34eff 
Request took 0 ms to complete /organization/oz/catchup/content/543e02b84b09d16436ba7eba9025cd60 
Request took 1 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 3 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 4 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 6 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 11 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 12 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 13 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 14 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 15 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 15 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 17 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 18 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 19 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 31 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 32 ms to complete /organization/oz/catchup/content/0a0e5775c4a127572691b6d151ac518e 
Request took 194 ms to complete /users/u07edf558-8f50-4963-992a-728f56e49590/entitlement/e0e89b850-86a4-4252-acf1-7f720213256b/token 
Request took 240 ms to complete /users/u07edf558-8f50-4963-992a-728f56e49590/entitlement/e0e89b850-86a4-4252-acf1-7f720213256b/token 
^X^C


           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@                                       2        
               1 |@@@@                                     5        
               2 |@@@@@                                    6        
               4 |@@                                       2        
               8 |@@@@@                                    6        
              16 |@@@@@@@@@@@@@@@@                         18       
              32 |@                                        1        
              64 |                                         0        
             128 |@@@                                      3        
             256 |@@@                                      3        
             512 |                                         0        

request_time.d

#!/usr/sbin/dtrace -Cs
#pragma D option quiet

node*:::http-server-request {
    latency[args[1]->fd] = timestamp;
    url[args[1]->fd] = args[0]->url;
}

node*:::http-server-response {
    printf("Request took %d ms to complete %s \n",
        (timestamp - latency[args[0]->fd]) / 1048576,
        url[args[0]->fd]
    );
    @ = quantize( (timestamp - latency[args[0]->fd]) / 1048576 );
}