{"id":92,"date":"2011-03-01T14:50:55","date_gmt":"2011-03-01T22:50:55","guid":{"rendered":"http:\/\/dtrace.org\/blogs\/rm\/?p=92"},"modified":"2011-03-01T14:50:55","modified_gmt":"2011-03-01T22:50:55","slug":"dtrace-probes-for-node-v0-4-x","status":"publish","type":"post","link":"https:\/\/rm.dtrace.org\/2011\/03\/01\/dtrace-probes-for-node-v0-4-x\/","title":{"rendered":"DTrace probes for Node v0.4.x"},"content":{"rendered":"<p>\nAs a part of the work for <a href=\"http:\/\/dtrace.org\/blogs\/brendan\/2011\/01\/24\/cloud-analytics-first-video\/\">Cloud Analytics<\/a> that <a href=\"http:\/\/dtrace.org\/blogs\/dap\">Dave<\/a>, <a href=\"http:\/\/dtrace.org\/blogs\/bmc\">Bryan<\/a>, <a href=\"http:\/\/dtrace.org\/blogs\/brendan\">Brendan<\/a>, and I been doing, we&#8217;ve added several <a href=\"http:\/\/dtrace.org\/blogs\/ahl\/2006\/05\/08\/user-land-tracing-gets-better-and-better\/\">USDT<\/a> probes to <a href=\"http:\/\/nodejs.org\">Node<\/a>. As I&#8217;ve been doing a lot of the integration work and working with <a href=\"https:\/\/twitter.com\/ryah\">Ryan Dahl<\/a> to get them into Node itself, I thought that I would document what we&#8217;ve added and talk a bit about what information we can get from the probes. Dave has a <a href=\"http:\/\/dtrace.org\/blogs\/dap\/2011\/03\/01\/welcome-to-cloud-analytics\/\">blog entry<\/a> that explains how you can use these probes and Cloud Analytics to understand what&#8217;s going on with your application.\n<\/p>\n<p>\nCurrently Node has probes that let us track the following events:\n<\/p>\n<ul>\n<li><a href=\"#httpd\">HTTP Server Requests and Responses<\/a><\/li>\n<li><a href=\"#httpc\">HTTP Client Requests and Responses<\/a><\/li>\n<li><a href=\"#socket\">Socket Operations<\/a><\/li>\n<li><a href=\"#gc\">Garbage Collection<\/a><\/li>\n<\/ul>\n<p>Before we jump too far ahead of ourselves, we should talk a bit about how to enable DTrace USDT probes with node. To get the DTrace probes in node, you can pass the option &#8211;with-dtrace to configure. This flag will fail on systems that aren&#8217;t SunOS (i.e. <a href=\"http:\/\/illumos.org\/\">Illumos<\/a> and OpenSolaris). Now, OS X and FreeBSD do have DTrace. You can certainly hack the wscript for node to get the probes compiled into OS X and FreeBSD; however, they have not been tested. On OS X you can get the probes to fire; however, the translator does not currently work on OS X, which limits their power.  I have not tested this on FreeBSD 9 which added support for the <a href=\"http:\/\/wiki.freebsd.org\/DTrace\/userland\">USDT provider<\/a>. So, let&#8217;s build node with support for DTrace!<\/p>\n<pre>$ <b>.\/configure --with-dtrace && make && make install<\/b><\/pre>\n<p>So, now we can go ahead and list all of the probes that DTrace has for node. To do this we need to fire up our newly compiled node and then run the following DTrace command to see all the probes that we have:<\/p>\n<pre>rm@devel ~ $ <b>dtrace -l -n node*:::<\/b>\n   ID   PROVIDER            MODULE                          FUNCTION NAME\n 4331  node12090              node _ZN4node14dtrace_gc_doneEN2v86GCTypeENS0_15GCCallbackFlagsE gc-done\n 4332  node12090              node _ZN4node15dtrace_gc_startEN2v86GCTypeENS0_15GCCallbackFlagsE gc-start\n 4333  node12090              node _ZN4node26DTRACE_HTTP_CLIENT_REQUESTERKN2v89ArgumentsE http-client-request\n 4334  node12090              node _ZN4node27DTRACE_HTTP_CLIENT_RESPONSEERKN2v89ArgumentsE http-client-response\n 4335  node12090              node _ZN4node26DTRACE_HTTP_SERVER_REQUESTERKN2v89ArgumentsE http-server-request\n 4336  node12090              node _ZN4node27DTRACE_HTTP_SERVER_RESPONSEERKN2v89ArgumentsE http-server-response\n 4337  node12090              node _ZN4node28DTRACE_NET_SERVER_CONNECTIONERKN2v89ArgumentsE net-server-connection\n 4338  node12090              node _ZN4node22DTRACE_NET_SOCKET_READERKN2v89ArgumentsE net-socket-read\n 4339  node12090              node _ZN4node23DTRACE_NET_SOCKET_WRITEERKN2v89ArgumentsE net-socket-write\n 4340  node12090              node _ZN4node21DTRACE_NET_STREAM_ENDERKN2v89ArgumentsE net-stream-end<\/pre>\n<p>As we can see there are several probes here, for this entry we&#8217;re going to leave out net-stream-end and net-server-connection. If we include the path to the node.d file, we can even view all the arguments of the probe. The node.d file is a translator that is installed into $PREFIX\/lib\/dtrace. As long as you have the <a href=\"http:\/\/dtrace.org\/blogs\/rm\/2011\/02\/18\/fixing-dtrace-libdir-dependency-resolution\/\">libdir patch<\/a> (or move the file into \/usr\/lib\/dtrace) then you should be all set and we can run:<\/p>\n<pre>rm@devel ~ $ <b>dtrace -L $PREFIX\/lib\/dtrace -v -n node*:::<\/b>\n   ID   PROVIDER            MODULE                          FUNCTION NAME\n 4331  node12090              node _ZN4node14dtrace_gc_doneEN2v86GCTypeENS0_15GCCallbackFlagsE gc-done\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: int\n                args[1]: int\n\n 4332  node12090              node _ZN4node15dtrace_gc_startEN2v86GCTypeENS0_15GCCallbackFlagsE gc-start\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: int\n                args[1]: int\n\n 4333  node12090              node _ZN4node26DTRACE_HTTP_CLIENT_REQUESTERKN2v89ArgumentsE http-client-request\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: node_http_request_t *\n                args[1]: node_connection_t *\n 4334  node12090              node _ZN4node27DTRACE_HTTP_CLIENT_RESPONSEERKN2v89ArgumentsE http-client-response\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: node_connection_t *\n\n 4335  node12090              node _ZN4node26DTRACE_HTTP_SERVER_REQUESTERKN2v89ArgumentsE http-server-request\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: node_http_request_t *\n                args[1]: node_connection_t *\n\n 4336  node12090              node _ZN4node27DTRACE_HTTP_SERVER_RESPONSEERKN2v89ArgumentsE http-server-response\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: node_connection_t *\n\n 4338  node12090              node _ZN4node22DTRACE_NET_SOCKET_READERKN2v89ArgumentsE net-socket-read\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: node_connection_t *\n                args[1]: int\n\n 4339  node12090              node _ZN4node23DTRACE_NET_SOCKET_WRITEERKN2v89ArgumentsE net-socket-write\n\n        Probe Description Attributes\n                Identifier Names: Private\n                Data Semantics:   Private\n                Dependency Class: Unknown\n\n        Argument Attributes\n                Identifier Names: Evolving\n                Data Semantics:   Evolving\n                Dependency Class: ISA\n\n        Argument Types\n                args[0]: node_connection_t *\n                args[1]: int\n\n\n<\/pre>\n<p>For the rest of this entry we&#8217;ll go over the different probes and their arguments. I&#8217;ll detail what they are and how you can get some useful information from them. In a future entry I&#8217;ll discuss how you can use this information.<\/p>\n<h3><a name=\"httpd\">HTTP Server Probes<\/a><\/h3>\n<p>When an HTTP request comes in it will fire the http-server-request probe. The probe is fired once node receives all of the HTTP headers for the incoming connection. Thus the probe fires right before the HTTP socket emits the event &#8216;request&#8217;. The http-server-request probe has two arguments. The first argument tells us information about the HTTP request. We can use it to get the method and url requested. The second argument tells us information about who is connecting to our HTTP server. We can view all this information with the following DTrace snippet:<\/p>\n<pre>\n# <b>cat -n \/tmp\/node-httpd-request.d<\/b>\n     1  #pragma D option quiet\n     2\n     3  node21291:::http-server-request\n     4  {\n     5          printf(\"Connection from %s:%d on fd %d - Request %s: %s\\n\",\n     6              args[1]->remoteAddress, args[1]->remotePort, args[1]->fd,\n     7              args[0]->method, args[0]->url);\n     8  }\n# <b>dtrace -L$PREFIX\/lib\/dtrace -s node-httpd-request.d<\/b>\nConnection from 10.99.99.254:63486 on fd 7 - Request GET: \/\nConnection from 10.99.99.254:63487 on fd 7 - Request GET: \/\nConnection from 10.99.99.254:63488 on fd 7 - Request GET: \/\nConnection from 10.99.99.254:63489 on fd 7 - Request GET: \/\nConnection from 10.99.99.254:63490 on fd 7 - Request GET: \/\n^C\n<\/pre>\n<p>The corresponding probe, http-server-response, will fire once we have finished sending all the data in our response to the client. This probe no longer has the information on the incoming HTTP request, but does have all of the information about who we are talking to. Here&#8217;s all the information that we have:<\/p>\n<pre>\n# cat node-http-response.d\n     1  #pragma D option quiet\n     2\n     3  node*:::http-server-response\n     4  {\n     5          printf(\"Connection from %s:%d on fd %d\\n\",\n     6              args[0]->remoteAddress, args[0]->remotePort, args[0]->fd);\n     7  }\n# <b>dtrace -L$PREFIX\/lib\/dtrace -s node-http-response.d<\/b>\nConnection from 127.0.0.1:59149 on fd 8\nConnection from 127.0.0.1:39130 on fd 9\nConnection from 10.99.99.254:63691 on fd 7\nConnection from 10.99.99.254:55004 on fd 19\nConnection from 10.99.99.254:55000 on fd 14\nConnection from 10.99.99.254:55276 on fd 16\nConnection from 10.99.99.254:54977 on fd 11\n<\/pre>\n<p>Now, if we want to track the time that has elapsed, we have to be a little smarter. In node we could have multiple connections going on at the same time, and these are all going to occur in the same thread. This means that we cannot use the traditional thread-local variables that we might do via self->foo. So, how do we actually correlate one http-server-request probe with its http-server-response probe? Each connection is using a separate socket and each socket has its own file descriptor. There is a one to one correlation between sockets and file descriptors. A file descriptor will only be reused if the socket it was previously associated with was closed. So if we wanted to track the latency we can use the file descriptor to correlate events and write a small script that looks something like:<\/p>\n<pre>\nrm@devel ~ $ <b>cat  -n\/tmp\/httpd-lat.d<\/b>\n     1  #pragma D option quiet\n     2\n     3  node*:::http-server-request\n     4  {\n     5          latency[args[1]->fd] = timestamp;\n     6  }\n     7\n     8  node*:::http-server-response\n     9  {\n    10          printf(\"Request took %d nanoseconds to complete\\n\",\n    11              timestamp - latency[args[0]->fd]);\n    12  }\nrm@devel ~ $ <b>dtrace -L$PREFIX\/lib\/dtrace -s \/tmp\/httpd-lat.d<\/b>\nRequest took 444589 nanoseconds to complete\nRequest took 939339 nanoseconds to complete\nRequest took 353588 nanoseconds to complete\nRequest took 1431926 nanoseconds to complete\nRequest took 334404 nanoseconds to complete\n^C\n<\/pre>\n<p>Now, if we run this with the sample Node &#8216;Hello, world!&#8217; HTTP server we certainly can get some rather interesting data. But the value comes from being able to visualize this data, something that <a href=\"http:\/\/dtrace.org\/blogs\/brendan\">Brendan<\/a> has looked at <a href=\"http:\/\/queue.acm.org\/detail.cfm?id=1809426\">extensively.<\/a><\/p>\n<h3><a name=\"httpc\">HTTP Client Probes<\/a><\/h3>\n<p>The HTTP Client probes have been designed to correspond to their HTTP Server counterparts. There are both http-client-request and http-client-response probes. The http-client-request gets fired when an outgoing request is made and the http-client response probe is fired when we have received the response. In terms of arguments, the HTTP Client probes work identically to their server counterparts. The http-client-request has information about what the underlying connection and the HTTP resource we have asked for. The http-client-response probe only has information on the underlying socket.<\/p>\n<p>Let&#8217;s look at the same information as we did with the HTTP Server probes, but this time with the client:<\/p>\n<pre># <b>cat -n \/tmp\/node-httpc-request.d<\/b>\n     1  #pragma D option quiet\n     2\n     3  node*:::http-client-request\n     4  {\n     5          printf(\"Connection to %s:%d on fd %d - Request %s: %s\\n\",\n     6              args[1]->remoteAddress, args[1]->remotePort, args[1]->fd,\n     7              args[0]->method, args[0]->url);\n     8  }\n# <b>dtrace -L$PREFIX\/lib\/dtrace -s \/tmp\/node-httpc-request.d<\/b>\nConnection to 127.0.0.1:23184 on fd 10 - Request GET: \/ca\/instrumentations\/1\/value\/raw?start_time=1298733995\nConnection to 127.0.0.1:23185 on fd 12 - Request GET: \/ca\/instrumentations\/4\/value\/raw?start_time=1298733995\nConnection to 127.0.0.1:23184 on fd 10 - Request GET: \/ca\/instrumentations\/1\/value\/raw?start_time=1298733997\nConnection to 127.0.0.1:23184 on fd 13 - Request GET: \/ca\/instrumentations\/5\/value\/raw?start_time=1298733997\nConnection to 127.0.0.1:23185 on fd 12 - Request GET: \/ca\/instrumentations\/4\/value\/raw?start_time=1298733997\n^C\n<\/pre>\n<p>Again, we can do a similar thing for the response:<\/p>\n<pre># <b>cat -n \/tmp\/node-httpc-response.d<\/b>\n     1  #pragma D option quiet\n     2\n     3  node*:::http-client-response\n     4  {\n     5          printf(\"Connection to %s:%d on fd %d\\n\",\n     6              args[0]->remoteAddress, args[0]->remotePort, args[0]->fd);\n     7  }\n# <b>dtrace -L$PREFIX\/lib\/dtrace -s \/tmp\/node-httpc-response.d<\/b>\nConnection to 127.0.0.1:23185 on fd 15\nConnection to 127.0.0.1:23185 on fd 13\nConnection to 127.0.0.1:23184 on fd 18\nConnection to 127.0.0.1:23184 on fd 12\nConnection to 127.0.0.1:23184 on fd 10\n^C\n<\/pre>\n<p>With all of this information we can gather a lot of useful information. Because both probes have the file descriptor, we can link them together to get the latency, as we did previously. Because a node program may be making several HTTP requests to external services, having the ability to know <b>which<\/b> request is inducing <b>how much<\/b> latency is quite valuable.<\/p>\n<h3><a name=\"socket\">Socket Read\/Write Probes<\/a><\/h3>\n<p>This next set of probes is in fact two different probes, one which fires on every <a href=\"http:\/\/nodejs.org\/docs\/v0.4.1\/api\/net.html#event_data_\">read<\/a> from a <a href=\"http:\/\/nodejs.org\/docs\/v0.4.1\/api\/net.html#net.Socket\">socket<\/a> and one that fires on every <a href=\"http:\/\/nodejs.org\/docs\/v0.4.1\/api\/net.html#socket.write\">write<\/a> to a socket. In addition to the information about the socket itself, we get two very useful numbers: the <b>size<\/b> of the data and the amount <b>buffered<\/b>. Whenever node does a write to a socket, it attempts to write all of it to the kernel at once. However, if the write would block, node stores the data in userland and will write it out a bit later. When this happens, the call to write returns <b>false<\/b>. If you aren&#8217;t careful or checking the return value from write that buffer can grow quite quickly in userland and eat up a lot of memory.  Let&#8217;s look at how we can use these two probes:<\/p>\n<pre># <b>cat -n socket.d<\/b>\n     1  #pragma D option quiet\n     2\n     3  node*:::net-socket-read,\n     4  node*:::net-socket-write\n     5  {\n     6          printf(\"%s:%d -- %d bytes -- %d buffered\\n\", args[0]->remoteAddress,\n     7              args[0]->remotePort, arg1, args[0]->bufferSize);\n     8  }\n# <b>dtrace -L$PREFIX\/lib\/dtrace -s \/tmp\/socket.d<\/b>\n10.99.99.254:55000 -- 314 bytes -- 0 buffered\n10.99.99.254:55000 -- 2740 bytes -- 0 buffered\n10.99.99.254:55000 -- 2 bytes -- 0 buffered\n10.99.99.254:55000 -- 5 bytes -- 0 buffered\n^C\n<\/pre>\n<h3><a name=\"gc\">Garbage Collection Probes<\/a><\/h3>\n<p>Javascript is a language where you don&#8217;t have to explicitly manage memory like you do in C. Instead, the runtime uses various techniques to allocate and later determine what memory can be freed. This technique is known as <a href=\"https:\/\/secure.wikimedia.org\/wikipedia\/en\/wiki\/Garbage_collection_(computer_science)\">garbage collection<\/a>. Node is using <a href=\"https:\/\/code.google.com\/p\/v8\/\">v8<\/a> under the hood to do this work. v8 gives us the ability to be notified right before garbage collection starts and ends. We have two pieces of information from the garbage collection process: the <b>type<\/b> of garbage collection and various <b>flags<\/b>.<\/p>\n<p>To understand the different types, we have to dive into the v8 header file. Node v0.4.0 is currently using v8 version v3.1. If we open up \/usr\/include\/v8.h we see the following for valid garbage collection types:<\/p>\n<pre>\n2472 enum GCType {\n2473   kGCTypeScavenge = 1 << 0,\n2474   kGCTypeMarkSweepCompact = 1 << 1,\n2475   kGCTypeAll = kGCTypeScavenge | kGCTypeMarkSweepCompact\n2476 };\n<\/pre>\n<p>From this we can see that v8 supports two different kinds of garbage collection. To help understand the differences, it's important to know that v8 uses the notion of generations. Generational garbage collection makes the observation that objects fall into two camps: those that come and go rather quickly and those that stick around for a while. Mark and Sweep compaction is a traditional form of garbage collection which works well for older objects, but takes much longer. The Scavenge algorithm works well for short lived objects and is generally much quicker than Mark and Sweep. <a href=\"http:\/\/dtrace.org\/blogs\/dap\">Dave<\/a> helps explain <b>why<\/b> we care about GC.<\/p>\n<p>The other argument to our GC probes are a series of flags. Currently this looks like:<\/p>\n<pre>\n2478 enum GCCallbackFlags {\n2479   kNoGCCallbackFlags = 0,\n2480   kGCCallbackFlagCompacted = 1 << 0\n2481 };\n<\/pre>\n<p>When using the probes, there are a few useful things to know. When GC occurs, nothing else is going to run. Furthermore, v8 uses the same thread to call the GC prologue and epilogue handlers. These callbacks are respectively fired immediately before and immediately after the GC operation. Because we have the same thread calling it, we can use a thread local variable in D to keep track of and answer the question of <b>how<\/b> much latency was due to garbage collection. We can do this with the following D script:<\/p>\n<pre># <b>cat -n \/tmp\/node-gc.d<\/b>\n     1  #pragma D option quiet\n     2\n     3  node*:::gc-start\n     4  {\n     5          self->ts = timestamp;\n     6  }\n     7\n     8  node*:::gc-done\n     9  {\n    10          printf(\"Spent %d nanoseconds doing Garbage Collection\\n\",\n    11              timestamp - self->ts);\n    12          self->ts = 0\n    13  }\n# <b>dtrace -s \/tmp\/node-gc.d<\/b>\nSpent 780604 nanoseconds doing Garbage Collection\nSpent 50416942 nanoseconds doing Garbage Collection\nSpent 33276517 nanoseconds doing Garbage Collection\nSpent 14498463 nanoseconds doing Garbage Collection\nSpent 3847561 nanoseconds doing Garbage Collection\n^C\n<\/pre>\n<p>Those are all the probes that we have currently added to node. All of them are available in the stock node src that you can download and compile yourself. The idea behind all of the probes that we added is to be able to answer a question directly related to <b>what<\/b> your application is doing and to be able to understand <b>why<\/b> and <b>where<\/b> issues are coming from.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>As a part of the work for Cloud Analytics that Dave, Bryan, Brendan, and I been doing, we&#8217;ve added several USDT probes to Node. As I&#8217;ve been doing a lot of the integration work and working with Ryan Dahl to get them into Node itself, I thought that I would document what we&#8217;ve added and [&hellip;]<\/p>\n","protected":false},"author":3,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[3],"tags":[12,14],"_links":{"self":[{"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/posts\/92"}],"collection":[{"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/users\/3"}],"replies":[{"embeddable":true,"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/comments?post=92"}],"version-history":[{"count":0,"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/posts\/92\/revisions"}],"wp:attachment":[{"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/media?parent=92"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/categories?post=92"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/rm.dtrace.org\/wp-json\/wp\/v2\/tags?post=92"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}