uftrace for node

1. Download node with --enable-pg option

$ git clone --depth=2 https://github.com/honggyukim/node.git -b build/pg
$ cd node
$ git log --oneline
61dc940 build: add --enable-pg flag to configure
8e3c5b5 test: fix flaky test-vm-timeout-escape-queuemicrotask

2. Build

$ ./configure --enable-pg
$ make -j8
$ nm node | grep mcount
                 U mcount@@GLIBC_2.2.5

3. Test the generated node image

# Pure node doesn't work but it works with uftrace --nop
$ ./node
Profiling timer expired

$ uftrace --nop ./node -e 'console.log("Hello, node!")'
Hello, node!

4. Run node execution with uftrace

$ uftrace -F main -D 1 ./node -e 'console.log("Hello, node!")'
Hello, node!
# DURATION     TID     FUNCTION
            [ 95495] | main() {
 211.551 us [ 95495] |   /* linux:schedule */
  41.444 us [ 95495] |   /* linux:schedule */
   6.162 us [ 95495] |   /* linux:schedule */
  50.181 us [ 95495] |   /* linux:schedule */
  10.235 us [ 95495] |   /* linux:schedule */
 327.448 us [ 95495] |   /* linux:schedule */
 179.879 ms [ 95495] | } /* main */

/* linux:schedule */ can be hidden by using --no-event.

$ uftrace -F main -D 1 --no-event ./node -e 'console.log("Hello, node!")'
Hello, node!
# DURATION     TID     FUNCTION
 433.133 ms [ 95530] | main();

Let's try it with depth 3.

$ uftrace -F main -D 3 --no-event ./node -e 'console.log("Hello, node!")'
Hello, node!
# DURATION     TID     FUNCTION
            [ 95597] | main() {
            [ 95597] |   node::Start() {
  14.611 us [ 95597] |     node::PlatformInit();
   0.178 us [ 95597] |     uv_hrtime();
   1.321 us [ 95597] |     uv_setup_args();
 167.037 us [ 95597] |     node::Init();
   0.087 us [ 95597] |     uv_mutex_lock();
   0.076 us [ 95597] |     uv_mutex_unlock();
   8.167 us [ 95597] |     v8::V8::SetEntropySource();
   7.761 us [ 95597] |     node::tracing::Agent::Agent();
   0.081 us [ 95597] |     node::tracing::TraceEventHelper::SetAgent();
   0.872 us [ 95597] |     v8::platform::tracing::TracingController::AddTraceStateObserver();
   0.069 us [ 95597] |     node::tracing::Agent::DefaultHandle();
   2.863 ms [ 95597] |     node::NodePlatform::NodePlatform();
  43.750 us [ 95597] |     v8::V8::InitializePlatform();
 263.825 us [ 95597] |     v8::V8::Initialize();
   0.342 us [ 95597] |     uv_hrtime();
   0.136 us [ 95597] |     uv_default_loop();
   5.976 ms [ 95597] |     node::NewIsolate();
   0.185 us [ 95597] |     uv_mutex_lock();
   0.100 us [ 95597] |     uv_mutex_unlock();
   2.519 us [ 95597] |     v8::Locker::Initialize();
   0.549 us [ 95597] |     v8::Isolate::Enter();
   0.287 us [ 95597] |     v8::HandleScope::HandleScope();
 231.842 us [ 95597] |     node::IsolateData::IsolateData();
 168.294 ms [ 95597] |     node::Start();
   1.212 us [ 95597] |     node::IsolateData::~IsolateData();
   0.294 us [ 95597] |     v8::HandleScope::~HandleScope();
   0.329 us [ 95597] |     v8::Isolate::Exit();
   1.529 us [ 95597] |     v8::Locker::~Locker();
   0.169 us [ 95597] |     uv_mutex_lock();
   0.080 us [ 95597] |     uv_mutex_unlock();
 430.770 us [ 95597] |     v8::Isolate::Dispose();
   4.458 us [ 95597] |     node::NodePlatform::UnregisterIsolate();
   0.127 us [ 95597] |     node::ArrayBufferAllocator::~ArrayBufferAllocator();
   0.109 us [ 95597] |     node::tracing::Agent::Disconnect();
  28.440 us [ 95597] |     v8::V8::Dispose();
 269.844 us [ 95597] |     node::NodePlatform::Shutdown();
   1.718 us [ 95597] |     std::_Sp_counted_deleter::_M_dispose();
   0.132 us [ 95597] |     std::_Sp_counted_deleter::_M_destroy();
   0.121 us [ 95597] |     uv_mutex_destroy();
  20.815 us [ 95597] |     node::tracing::Agent::~Agent();
 178.667 ms [ 95597] |   } /* node::Start */
 178.668 ms [ 95597] | } /* main */

5. Visualized trace output of gcc

• chrome: https://uftrace.github.io/dump/node-marked.html
• flame-graph: https://uftrace.github.io/dump/node-marked.svg