Blind spots profiling node
Kenneth Gunn
Hi!
My team is developing a service in node. We are experiencing high CPU utilization and are attempting to profile, but are having a hard time getting a sufficient picture of what’s going on. We have experience profiling in various other environments, but this is our first crack at node.
We've tried a few different tools (including nodetime.com, which has been useful for some things), and have spent most of our time with the v8 profiler. The main problem is that our viewable results only cover a small portion of the program runtime. More than 80% of the time is spent in libc.so, and that time isn't rolled up by function or caller in the node program. Also, the C++ section, which I would expect to contain events in the v8 interpreter itself, is empty. (Below, I'm including an abbreviated output from the v8 tick processor.)
We're aware that the v8 profiling output changes frequently, and we've managed to figure out how to get the right tick processor version that corresponds to the node version we are using. (Our steps are here: https://gist.github.com/kennethgunn/6770664 ) We've seen very similar results with versions of node ranging from v0.8.9 to v0.10.18.
Is libc actually responsible for 80+% of the CPU time? If so, how do we roll that up to the the higher level code leading to those calls? Does it sound like we're missing something here, or is there another set of tools we should consider using? Your help is greatly appreciated!
-Ken
------
[Shared libraries]:
ticks total nonlib name
369080 84.3% 0.0% /lib/x86_64-linux-gnu/libc-2.15.so
45389 10.4% 0.0% /opt/nvm/v0.10.15/bin/node
3624 0.8% 0.0% /lib/x86_64-linux-gnu/libpthread-2.15.so
150 0.0% 0.0% /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.16
94 0.0% 0.0% 7fffeddff000-7fffede00000
68 0.0% 0.0% /lib/x86_64-linux-gnu/libm-2.15.so
23 0.0% 0.0% /lib/x86_64-linux-gnu/librt-2.15.so
. . .
[JavaScript]:
ticks total nonlib name
1185 0.3% 6.1% LazyCompile: BSON.deserialize /mnt/nomic/api/node_modules/mongodb/node_modules/bson/lib/bson/bson.js:1129
544 0.1% 2.8% KeyedLoadIC: A keyed load IC from the snapshot
403 0.1% 2.1% LazyCompile: *Buffer.toString buffer.js:392
363 0.1% 1.9% Stub: CEntryStub
270 0.1% 1.4% LazyCompile: CallSiteGetMethodName native messages.js:8
. . .
[C++]:
ticks total nonlib name
[GC]:
ticks total nonlib name
3494 0.8%
[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
369080 84.3% /lib/x86_64-linux-gnu/libc-2.15.so
45389 10.4% /opt/nvm/v0.10.15/bin/node
11117 24.5% LazyCompile: *createWriteReq net.js:656
11089 99.7% LazyCompile: *Socket._write net.js:617
11076 99.9% LazyCompile: *Writable.write _stream_writable.js:160
11076 100.0% LazyCompile: *Socket.write net.js:610
8431 76.1% LazyCompile: obj.(anonymous function) /mnt/nomic/api/node_modules/nodetime/lib/core/proxy.js:37
1022 9.2% LazyCompile: *Connection.flush /mnt/nomic/api/node_modules/pg/lib/connection.js:246
1001 9.0% LazyCompile: ~OutgoingMessage.end http.js:855
307 2.8% LazyCompile: *Connection.sync /mnt/nomic/api/node_mod
. . .
Ben Noordhuis
> Hi!
>
>
> My team is developing a service in node. We are experiencing high CPU
> utilization and are attempting to profile, but are having a hard time
> getting a sufficient picture of what’s going on. We have experience
> profiling in various other environments, but this is our first crack at
> node.
>
>
> We've tried a few different tools (including nodetime.com, which has been
> useful for some things), and have spent most of our time with the v8
> profiler. The main problem is that our viewable results only cover a small
> portion of the program runtime. More than 80% of the time is spent in
> libc.so, and that time isn't rolled up by function or caller in the node
> program. Also, the C++ section, which I would expect to contain events in
> the v8 interpreter itself, is empty. (Below, I'm including an abbreviated
> output from the v8 tick processor.)
uses `nm` to map addresses to symbol.
Small nomenclature nit: V8 is a just-in-time compiler, not an interpreter.
> We're aware that the v8 profiling output changes frequently, and we've
> managed to figure out how to get the right tick processor version that
> corresponds to the node version we are using. (Our steps are here:
> https://gist.github.com/kennethgunn/6770664 ) We've seen very similar
> results with versions of node ranging from v0.8.9 to v0.10.18.
>
>
> Is libc actually responsible for 80+% of the CPU time? If so, how do we
> roll that up to the the higher level code leading to those calls? Does it
> sound like we're missing something here, or is there another set of tools we
> should consider using? Your help is greatly appreciated!
Future versions of node.js will filter out such ticks but right now
that's not possible, you have to keep your application busy when
profiling.
Ben Noordhuis
time by passing -j or --js to the tick processor. That filters out
samples that aren't accountable to JS land.
