Profiling Node Programs on Mac OS X

I’ve had a lot of trouble finding decent instructions on how to do this. Once I eventually found the information I needed, I thought I should share.

These instructions are based on:

  • Mac OS X 10.7.3
  • Node 0.6.11

The Why

When you want to make a program faster, profiling is the best way to get started — it gives you empirical data on what your program is actually doing — in particular, where the “hot spots” are — i.e. which “tasks” are taking more time than others.

When I recently wanted to profile a Node program, my initial Web searches yielded the false impression that it’d be super-easy — “just add --prof to the command-line” was the common refrain. And so I did, expecting it to just work — how naïve of me! After I ran my program, lo, there was indeed a shiny new file in my directory: v8.log. But all was not good.

Disappointingly to me, the file was full of stuff like this:

code-creation,KeyedLoadIC,0x10569e400,122,"error"
code-creation,Stub,0x10569e480,349,"CompareICStub"
code-creation,LazyCompile,0x10569e5e0,832,"indexOf native string.js:115",0x1055ca1f0,~
code-creation,Stub,0x10569e920,176,"CompareICStub"
tick,0x100e31be1,0x7fff6084e670,0,0x7fff6084e6d8,0,0x10565c323,0x105661909
code-creation,Stub,0x10569e9e0,349,"CompareICStub"
code-creation,Stub,0x10569eb40,137,"ToBooleanStub_String"
code-creation,Script,0x10569ebe0,164,"path.js",0x1257c75a8,
tick,0x100da996b,0x7fff6084cd10,0,0x2183,2,0x105660efa,0x1056609cc,0x10565c5ec,0x105661909
code-creation,Stub,0x10569eca0,217,"FastNewContextStub"
code-creation,Function,0x10569ed80,776,"normalizeArray path.js:30",0x1257c7748,~
code-creation,Function,0x10569f0a0,812,"splitPath path.js:68",0x1257c7858,~
code-creation,Function,0x10569f3e0,148,"f path.js:148",0x1257c7930,~
code-creation,Function,0x10569f480,2344,"exports.resolve path.js:83",0x1257c7a60,~
code-creation,Function,0x10569fdc0,148," path.js:169",0x1257c7b38,~
code-creation,Function,0x1056a0040,1248,"exports.normalize path.js:160",0x1257c7c40,~
code-creation,Function,0x1056a0520,192,"f path.js:185",0x1257c7d18,~
code-creation,Function,0x1056a05e0,880,"exports.join path.js:184",0x1257c7e08,~

…which meant nothing to me.

I figured there had to be some way to turn the above into something meaningful, and it didn’t take long before I got wind of a tool named mac-tick-processor, which ships with V8. Great! Problem solved — or so I thought. I had a lot of trouble figuring out how to actually use the tool — I found a lot of casual mentions of scons and d8 but I struggled to put it all together.

The How

After much searching, I finally found what I needed: a comment on a GitHub issue by Spyro7. The following steps incorporate and expand on Spyro7’s instructions.

  1. Download the Node source to your system using your preferred method — zip file, git clone, etc.
  2. Build Node: configure && make
  3. Move into the v8 directory: cd deps/v8
  4. Build d8: scons d8
  5. Add d8 to your path: export D8_PATH=/your_node_dir/deps/v8/
  6. Move to the directory which contains your program
  7. Run your program, passing the switch --prof to Node. The file v8.log will be created in the current directory.
  8. Run mac-tick-processor on the file: `locate mac-tick-processor` v8.log

The Result

Voila! You should now have some actually useful information, something along these lines:

Statistical profiling result from v8.log, (7673 ticks, 143 unaccounted, 0 excluded).

 [Unknown]:
   ticks  total  nonlib   name
	143    1.9%

 [Shared libraries]:
   ticks  total  nonlib   name
   6588   85.9%    0.0%  /usr/local/bin/node

 [JavaScript]:
   ticks  total  nonlib   name
	146    1.9%   13.5%  LazyCompile: *ArrayConcat native array.js:457
	 23    0.3%    2.1%  LazyCompile: WeekDays native date.js:398
	 22    0.3%    2.0%  RegExp: \[(\d{2})\/(\w{3})\/(\d{4}):(\d{2}):(\d{2}):(\d{2})\s([-+]\d{4})\]
	 19    0.2%    1.8%  Function: emit /Users/avi/Dev/rollups/coffee-script/node_modules/linestream/LineStream.js:156
	 18    0.2%    1.7%  LazyCompile: COMPARE native runtime.js:120
	 17    0.2%    1.6%  LazyCompile: *forEach native array.js:1019
	 15    0.2%    1.4%  Stub: StringAddStub
	 14    0.2%    1.3%  LazyCompile: *BuildResultFromMatchInfo native regexp.js:126
	 13    0.2%    1.2%  Stub: SubStringStub
	 12    0.2%    1.1%  Stub: CompareICStub
	 12    0.2%    1.1%  LazyCompile: APPLY_PREPARE native runtime.js:449
	 11    0.1%    1.0%  LazyCompile: DefaultNumber native runtime.js:637
	 11    0.1%    1.0%  LazyCompile: *rollup /Users/avi/Dev/rollups/coffee-script/rollup.js:141
	 11    0.1%    1.0%  LazyCompile: *MakeTime native date.js:279
	 11    0.1%    1.0%  LazyCompile: *LocalTimeNoCheck native date.js:248
	 10    0.1%    0.9%  Stub: CallFunctionStub_Args1_Implicit
	 10    0.1%    0.9%  LazyCompile: *exec native regexp.js:167
	  9    0.1%    0.8%  Stub: RegExpExecStub
	  9    0.1%    0.8%  LazyCompile: *EventEmitter.emit events.js:40
	  8    0.1%    0.7%  Stub: JSEntryStub
	  8    0.1%    0.7%  Stub: CompareStub_GE
	  8    0.1%    0.7%  LazyCompile: *parse native date.js:534
	  8    0.1%    0.7%  LazyCompile: *extractDate /Users/avi/Dev/rollups/coffee-script/rollup.js:24
	  8    0.1%    0.7%  LazyCompile: * /Users/avi/Dev/rollups/coffee-script/rollup.js:184
	  [redacted]

 [C++]:
   ticks  total  nonlib   name
	137    1.8%   12.6%  _setpgrp
	 93    1.2%    8.6%  _bsd_signal
	 42    0.5%    3.9%  _setruid
	 29    0.4%    2.7%  _chmod
	 24    0.3%    2.2%  __asl_server_prune
	 20    0.3%    1.8%  _sethostid
	 14    0.2%    1.3%  _setrgid
	 [redacted]

 [GC]:
   ticks  total  nonlib   name
	152    2.0%

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
   6588   85.9%  /usr/local/bin/node
   6005   91.2%    LazyCompile: *ArrayConcat native array.js:457
   5995   99.8%      LazyCompile: *rollup /Users/avi/Dev/rollups/coffee-script/rollup.js:141
   5995  100.0%        LazyCompile: * /Users/avi/Dev/rollups/coffee-script/rollup.js:184
   5995  100.0%          LazyCompile: *EventEmitter.emit events.js:40
   5995  100.0%            Function: emit /Users/avi/Dev/rollups/coffee-script/node_modules/linestream/LineStream.js:156
	172    2.6%    LazyCompile: *rollup /Users/avi/Dev/rollups/coffee-script/rollup.js:141
	172  100.0%      LazyCompile: * /Users/avi/Dev/rollups/coffee-script/rollup.js:184
	172  100.0%        LazyCompile: *EventEmitter.emit events.js:40
	172  100.0%          Function: emit /Users/avi/Dev/rollups/coffee-script/node_modules/linestream/LineStream.js:156
	172  100.0%            LazyCompile: *emitLineWithoutFilter /Users/avi/Dev/rollups/coffee-script/node_modules/linestream/LineStream.js:183

Bonus: CoffeeScript

It’s not hard to find this Stack Overflow answer on how to profile a CoffeeScript Node program without an interim compilation step, but I figured it couldn’t hurt to share. I’m a big fan of this little language and I’d love to see it become more popular.

To enable profiling of your CoffeeScript program, just invoke coffee with these parameters: --nodejs --prof e.g.: coffee --nodejs --prof myprogram.coffee. The file v8.log will be produced, just as when invoking Node directly to profile a JavaScript program. You can then process v8.log with mac-tick-processor using the instructions above.

The End

I hope this was helpful!