davidmarkclements / 0x

🔥 single-command flamegraph profiling 🔥
MIT License
3.21k stars 103 forks source link

fix: Missing ticks data #231

Closed ovhemert closed 4 years ago

ovhemert commented 4 years ago

In the following simple code example, the pbkdf2Sync is blocking the event loop and is taking >90% of total ticks.

const express = require('express')
const crypto = require('crypto')

const app = express()
app.get('/', async (req, res) => {
 const salt = crypto.randomBytes(128).toString('base64')
 crypto.pbkdf2Sync('test', salt, 10000, 512, 'sha512')
 res.status(200).send('hello world')
})

app.listen(3000)

But this function is not marked as "hot" in the flame chart and only visible as a small block. Running Node.js with the --prof-process flag on the isolate-log that was generated through 0x, does show the issue.

 [C++]:
   ticks  total  nonlib   name
   8459   95.2%   95.4%  T node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
    165    1.9%    1.9%  t __ZN2v88internal15IsCompiledScopeC2ENS0_18SharedFunctionInfoEPNS0_7IsolateE
     40    0.5%    0.5%  T node::native_module::NativeModuleEnv::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
     31    0.3%    0.3%  t node::fs::Open(v8::FunctionCallbackInfo<v8::Value> const&)
     31    0.3%    0.3%  T __kernelrpc_thread_policy_set
     19    0.2%    0.2%  T ___ulock_wait

The line T node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&) seems to appear in the JSON generated from 0x, but it's not resolved from the ticks data. Also, running 0x with the --tree-debug flag does not show a matching result in the stacks.###.json output.

The code block that is generating the JSON from the LOG using the --preprocess flag, passes an extra -j flag (Show only ticks from JS VM state). Without this flag, the ticks data is correctly added to the JSON by the Node.js runtime and the heavy crypto function correctly shows up in the Flame chart.

Unless there is a specific reason for this flag, it can be removed to make sure all ticks data is being processed.