node prof produce nothing: tool/linux-tick-processor v8.log

[xlpiao]

git clone https://github.com/joyent/node.git 
./configure 
make 
sudo make install 
cd node/deps/v8/ 
make dependencies 
make native 
vim test.js 
node --prof test.js 
tools/linux-tick-processor v8.log

The results are:

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

Test on ubuntu 12.04 with node version v0.11.14-pre and v8 version is 3.26.33

[indutny]

What does test.js contain? The profiler is randomly interrupting main thread to gather some stack traces. If test.js is too short - none frames could be collected.

[xlpiao]

It is google-chrome.js from jsbench, jsbench can be checkedout from http://code.google.com/p/jsbench/source/checkout.

[indutny]

Could you please gist the file?

[xlpiao]

I tried lots of js files and it produce the same results.

one of them is:

var sys = require('sys');

// simple timeout exapmle
var start_time = new Date();
sys.puts('String 2 second timer');

setTimeout(function(){
var end_time = new Date();
var difference = end_time.getTime() - start_time.getTime();
sys.puts('Stopped timer after : ' +
Math.round(difference / 1000) + 'seconds');

cleartimeout_example();
}, 2000);


function cleartimeout_example(){
var start_time = new Date();
sys.puts('\nStarting 30 second timer and stopping it immediately without triggering callback');

var timeout = setTimeout(function(){
var end_time = new Date();
var difference = end_time.getTime() - start_time.getTime();
sys.puts('Stoped timer after ' + Math.round(difference / 1000) + ' seconds');
}, 3000);
clearTimeout(timeout);
interval_example();
}


function interval_example(){
var start_time = new Date();
sys.puts('\nString 2 second interval, stopped after 5th tick');

var count = 1;
var interval = setInterval(function(){
if(count == 5) clearInterval(this);
var end_time = new Date();
var diffrence = end_time.getTime() -
start_time.getTime();
sys.puts('Tick no.' + count + 'after ' + Math.round(diffrence / 1000) + ' second');
count ++;
}, 2000);
}

[indutny]

Hm... indeed, it isn't writing any ticks to the file. Thanks for a heads up! cc @trevnorris

[trevnorris]

On my list. Thanks for the report.

[bnoordhuis]

FWIW, V8's SIGPROF signal handler bails out because v8::Isolate::IsInUse() returns false. That normally means the isolate hasn't been entered but I don't see how that can happen, there's a Isolate::Scope instance a few stack frames down. Needs further investigation.

EDIT: The hack below makes V8 start logging tick events again. I still don't understand why it thinks the isolate is not in use...

diff --git a/deps/v8/src/sampler.cc b/deps/v8/src/sampler.cc
index 3cb0b74..380d6a3 100644
--- a/deps/v8/src/sampler.cc
+++ b/deps/v8/src/sampler.cc
@@ -332,7 +332,7 @@ void SignalHandler::HandleProfilerSignal(int signal, siginfo_t* info,
   USE(info);
   if (signal != SIGPROF) return;
   Isolate* isolate = Isolate::UncheckedCurrent();
-  if (isolate == NULL || !isolate->IsInitialized() || !isolate->IsInUse()) {
+  if (isolate == NULL || !isolate->IsInitialized()) {
     // We require a fully initialized and entered isolate.
     return;
   }

[trevnorris]

@bnoordhuis sounds more like this is a bug in how Node starts up?

For example int Start() (in src/node.cc) has a couple flaws. One is that calling V8::Initialize() where it does is pointless. It has been automatically run by that point anyways. Also, no where does Node use an Isolate::Scope. Instead using Locker.

[bnoordhuis]

Oh, that's it. The patch below trivially fixes it. Odd, I'm reasonably sure there was an Isolate::Scope there before.

diff --git a/src/node.cc b/src/node.cc
index f3409dc..b50ecdc 100644
--- a/src/node.cc
+++ b/src/node.cc
@@ -3610,6 +3610,7 @@ int Start(int argc, char** argv) {
   V8::Initialize();
   {
     Locker locker(node_isolate);
+    Isolate::Scope isolate_scope(node_isolate);
     HandleScope handle_scope(node_isolate);
     Local<Context> context = Context::New(node_isolate);
     Environment* env = CreateEnvironment(

[xlpiao]

Thank you~! It works now !

[trevnorris]

Thanks @bnoordhuis. Fix committed 437c2f4, Ben as the author.