[nodejs] failing to get decent profiles with prof_lazy and profiler module

On Fri, Oct 26, 2012 at 7:59 PM, Andrew Spyker wrote:
Not sure if this is the best place to post this, but given I'm 80% certain
this isn't a profiler module issue given it seems to be an issue with the v8
log file itself when trying to lazy start profiling, I think this is the
right place to post.

Please see the attached zip for my test case.

I'm trying to profile a node server app, but want to avoid profiling
startup. Therefore, I'm trying to use the prof_lazy support in node/v8. If
I use the --prof support, the profiler works as expected. If I instead use
the --prof_lazy --prof and --log_all, the v8.log is written to, but it ends
up being non-parseable by nprof (from profiler module). It looks like the
problem is that with --prof_lazy node isn't writing out the code that is
loaded until I call profiler.resume() which means all the symbols that
should have been known are not.

I would love for someone to hack the attached test case and driver script
(test.sh) to make the v8-lazystartprofiling.nprof.txt look clean instead of
all the unknown command log entries and get the unaccounted ticks to be
zero. Note the comparable log file v8-standardprofiling.nprof.txt is clean
in these two areas (no unknown commands and all ticks accounted for).

If I can get this working, I will likely throw this up as an example
somewhere. Maybe I'm missing something basic, but I haven't been able to
find a single place that puts all the pieces together in a single example
like this.

Andrew Spyker

On Friday, October 26, 2012 4:13:30 PM UTC-4, Ben Noordhuis wrote:
It's caused by what I suspect is a bug in V8. I'd been meaning to
bring it up with the V8 guys but I admit I forgot all about it. [1]
is a patch (for node.js) that should address it. Try it and let me
know if it works for you.

[1] https://gist.github.com/fdcbcb16594e699cffe3

diff --git a/deps/v8/src/log.cc b/deps/v8/src/log.cc
index b049ffe..662916e 100644
--- a/deps/v8/src/log.cc
+++ b/deps/v8/src/log.cc
@@ -283,11 +283,7 @@ void Profiler::Engage() {
if (engaged_) return;
engaged_ = true;

- // TODO(mnaganov): This is actually "Chromium" mode. Flags need to
be revised.
- // http://code.google.com/p/v8/issues/detail?id=487
- if (!FLAG_prof_lazy) {
- OS::LogSharedLibraryAddresses();
- }
+ OS::LogSharedLibraryAddresses();

// Start thread processing the profiler buffer.
running_ = true;

On Fri, Oct 26, 2012 at 10:29 PM, Andrew Spyker wrote:
One other question, should I be running with --log or --log_all or some
other version of --log? I'm assuming which I want to run with depends on
what I'm trying to profile, but for now I'm trying to get CPU burn.

On Friday, October 26, 2012 5:23:24 PM UTC-4, Ben Noordhuis wrote:
--log and --log-all are not mutually exclusive, they log (mostly?)
separate events.

--log-all is probably most relevant to C++ programmers - V8 developers
in particular :-) - because it logs things that are not user-visible,
like C++ API calls. nprof and tick-processor simply ignore those
events.

On Fri, Oct 26, 2012 at 11:31 PM, Andrew Spyker wrote:
Just re-ran with --log instead of --log-all and as you suggested, it didn't
change much about nprof. Results:

v8-lazystartprofiling-ganode.nprof.txt:Statistical profiling result from
v8-lazystartprofiling-ganode.log, (9781 ticks, 7212 unaccounted, 0
excluded).
v8-lazystartprofiling-patchednode.nprof.txt:Statistical profiling result
from v8-lazystartprofiling-patchednode.log, (8799 ticks, 3398 unaccounted, 0
excluded).
v8-standardprofiling.nprof.txt:Statistical profiling result from
v8-standardprofiling.log, (18120 ticks, 0 unaccounted, 0 excluded).

On Friday, October 26, 2012 1:59:45 PM UTC-4, Andrew Spyker wrote:

Not sure if this is the best place to post this, but given I'm 80% certain
this isn't a profiler module issue given it seems to be an issue with the
v8 log file itself when trying to lazy start profiling, I think this is the
right place to post.

Please see the attached zip for my test case.

I'm trying to profile a node server app, but want to avoid profiling
startup. Therefore, I'm trying to use the prof_lazy support in node/v8.
If I use the --prof support, the profiler works as expected. If I instead
use the --prof_lazy --prof and --log_all, the v8.log is written to, but it
ends up being non-parseable by nprof (from profiler module). It looks like
the problem is that with --prof_lazy node isn't writing out the code that
is loaded until I call profiler.resume() which means all the symbols that
should have been known are not.

I would love for someone to hack the attached test case and driver script
(test.sh) to make the v8-lazystartprofiling.nprof.txt look clean instead of
all the unknown command log entries and get the unaccounted ticks to be
zero. Note the comparable log file v8-standardprofiling.nprof.txt is clean
in these two areas (no unknown commands and all ticks accounted for).

If I can get this working, I will likely throw this up as an example
somewhere. Maybe I'm missing something basic, but I haven't been able to
find a single place that puts all the pieces together in a single example
like this.

Andrew Spyker

On Sat, Oct 27, 2012 at 4:23 AM, Andrew Spyker wrote:
Attached is a third zip of logs based on both patches (and using --log). I
assume the logs help you validate which ticks are coming back as unresolved.

The second patch doesn't seem to help much more than the first. Still
hovering around 39% of all ticks unrecognized.

[idcuser@xxxx test-profiling]$ grep Statistical *nprof*
v8-lazystartprofiling-ganode.nprof.txt:Statistical profiling result from
v8-lazystartprofiling-ganode.log, (9667 ticks, 7054 unaccounted, 0
excluded).
v8-lazystartprofiling-patchednode.nprof.txt:Statistical profiling result
from v8-lazystartprofiling-patchednode.log, (8664 ticks, 3419 unaccounted, 0
excluded).
v8-standardprofiling.nprof.txt:Statistical profiling result from
v8-standardprofiling.log, (17834 ticks, 0 unaccounted, 0 excluded).

I guess I should have mentioned, but doubt it matters, that this is on a
cloud instances in the IBM smart cloud, so everything is being run
virtualized (vs. on the metal). Would be interested if someone could repeat
these tests on the metal to see if it skews the numbers at all.

On Monday, October 29, 2012 5:28:05 PM UTC-4, Andrew Spyker wrote:

Ben,

Thanks for driving this.

To likely confirm what you already know, I did the following and it
"worked". I profiled without lazy start (--prof) and put a call to new
Date().toGMTString() right where I would have called profiler.resume(). I
did this knowing that toGMTString isn't called at all in the real
application. I then was able to grep for the line number in the log file:

#[idcuser@xxxx test-profiler]$ grep -n toGMT v8.log
#10525:code-creation,LazyCompile,0x8ad2fd20,260,"toGMTString native
date.js:747",0xa331bbc0,~

I then wrote a trim script to rip out all ticks that happened before this:

head -n 10525 v8.log |grep -v "^tick," > v8-trimmed.log
tail -n +10526 v8.log >> v8-trimmed.log

Then I ran nprof and saw:

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

Pretty hacky approach as all that data needs to be written during warmup.
But it likely proves that if --prof_lazy did exactly what --prof was doing
(with the exception of writing tick specific log entries until
V8:ResumeProfiler was called) we'd be working as expected.

I'm gonna try this on the full blown node app next. Hoping all that data
being written during a longer warmup doesn't break this approach.