Node.JS: need help or more detailed documentation, think I broke it

[jokeyrhyme]

I'm having some real problems getting any sort of useful trace capture out of the NPM module. I installed it with npm -g install tracing-framework and attempted to run: wtf-trace index.js in the working directory for my project. That JavaScript file is here.

goals

• instrument my app while it is running
• instrument my code whilst unit tests (run through grunt) are running

problem 1

wtf-trace doesn't seem like it is supposed to work with normal Node.JS files.

wtf-trace bombs out with this:

/usr/local/lib/node_modules/tracing-framework/bin/trace-runner.js:83
vm.runInThisContext(code, filename);
^
Error: Cannot find module 'q'
at Function.Module._resolveFilename (module.js:338:15)
at Function.Module._load (module.js:280:25)
at Module.require (module.js:364:17)
at require (module.js:380:17)
at global.require (/usr/local/lib/node_modules/tracing-framework/bin/trace-runner.js:76:10)
at /Users/ron/Projects/cdn-sync/index.js:13:5
at Object. (/usr/local/lib/node_modules/tracing-framework/bin/trace-runner.js:83:4)
at Module._compile (module.js:456:26)
at Object.Module._extensions..js (module.js:474:10)
at Module.load (module.js:356:32)

It would appear that I'm not allowed to use __dirname, and all my require calls for locally-installed modules need to be replaced with explicit paths.

problem 2

wtf-trace doesn't capture anything useful for asynchronous Node.JS apps

After I fix my index.js to not use any standard but mysteriously missing Node.JS features, wtf-trace index.js no longer bombs out, my code runs, and a trace is generated. Hooray!

However, this is what I see when I run wtf-dump index-....wtf-trace:

1776ms [ Script ] window#setTimeout {"delay":1,"timeoutId":0}
1776ms [ Script ] wtf.flow#branch {"id":1,"parentId":0,"name":"window#setTimeout","value":null}
1778ms [ Script ] window#setTimeout:callback {"timeoutId":0}
1778ms [ Script ] wtf.flow#extend {"id":1,"name":"callback","value":null}
1785ms [ Script ] wtf.flow#terminate {"id":1,"value":null}
1785ms [ Script ] wtf.scope#leave
1992ms [ Script ] window#setTimeout {"delay":1,"timeoutId":0}
1992ms [ Script ] wtf.flow#branch {"id":2,"parentId":0,"name":"window#setTimeout","value":null}
1993ms [ Script ] window#setTimeout:callback {"timeoutId":0}
1993ms [ Script ] wtf.flow#extend {"id":2,"name":"callback","value":null}
2001ms [ Script ] wtf.flow#terminate {"id":2,"value":null}
2001ms [ Script ] wtf.scope#leave
2296ms [ Script ] window#setTimeout {"delay":1,"timeoutId":0}
2296ms [ Script ] wtf.flow#branch {"id":3,"parentId":0,"name":"window#setTimeout","value":null}
2298ms [ Script ] window#setTimeout:callback {"timeoutId":0}
2298ms [ Script ] wtf.flow#extend {"id":3,"name":"callback","value":null}

This is completely generic output, not featuring a single project-specific call from my code.

the plea

I realise this is a Chrome-focused project, but there are a few paragraphs about Node.JS support on the site. I just have no clue what I'm doing wrong. I get similar results to the above when I attempt to use the module programmatically.

Is there a command-line parameter that I'm missing? Is there a specific sort of file that this is designed for use with?

I would be grateful for any suggestions, and absolutely will be as helpful as possible in diagnosing this further.

[deepak1556]

http://nodejs.org/docs/latest/api/vm.html
https://npmjs.org/package/contextify

@jokeyrhyme you will get an idea so as why it didnt work as you expected.

[jokeyrhyme]

Intriguing. So vm.runInThisContext is used by wtf-trace to run my code, and my code is not provided access to the local variables within the module that called it. Does this explain why things like __dirname and basic require behaviour is different?

[deepak1556]

Yep the V8 global context is hidden when run in vm.runInThisContext but to expose some desired global context objects we can use vm.runInContext where we provide the sandbox context of global objects for the code to run with.

// Object containing global context for VM
var sandbox = {
  require: global.require,
  console: console,
  module: module
},
context = vm.createContext(sandbox);

vm.runInContext(code, context, filename);

but as for require and __dirname goes even if you pass them via the sandbox container you will still face the error "Module Not Found" coz in the vm runtime the cwd will be different from where your code might be actually present, the cwd will be referring to the code which is executing the vm. So as to avoid this problem @benvanik provided a mock of require in bin/trace-runner.js

// Make require relative to the input file.
var targetPath = path.dirname(filename);
var originalRequire = require;
global.require = function(name) {
  var relativePath = path.join(targetPath, name);
  try {
    return originalRequire(relativePath);
  } catch (e) {
  }
  return originalRequire(name);
};

#429

[benvanik]

@jokeyrhyme: I just submitted a fix that should solve problem 1, though I honestly need more tests to see if it really does. Right now the node functionality is kind of barebones and used primarily for unit testing on Travis, but has been working in other projects too.

As for problem 2, that's expected. The Tracing Framework does not automatically instrument your code - what you're seeing are the platform events (timeout/etc) that are built into the library, but otherwise you must instrument your code as documented here: http://google.github.io/tracing-framework/instrumenting-code.html
Since node support is still early there aren't many instrumented platform features (mainly just timing functions), but I'd be interested in having more.

@deepak1556: thanks for the tips!

[jokeyrhyme]

Thanks heaps. When I return to my profiling work, I'll be sure to instrument as suggested. Cheers!