FAQ
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

--
Job Board: http://jobs.nodejs.org/
Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
You received this message because you are subscribed to the Google
Groups "nodejs" group.
To post to this group, send email to nodejs@googlegroups.com
To unsubscribe from this group, send email to
nodejs+unsubscribe@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/nodejs?hl=en?hl=en

Search Discussions

  • Ben Noordhuis at Oct 26, 2012 at 9:13 pm

    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
    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;

    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Andrew Spyker at Oct 26, 2012 at 8:36 pm
    Haven't built Node from source before, but starting on it now.

    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 4:13:30 PM UTC-4, Ben Noordhuis wrote:
    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
    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;
    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Ben Noordhuis at Oct 26, 2012 at 11:18 pm

    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.
    --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.

    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Andrew Spyker at Oct 27, 2012 at 10:38 pm
    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 5:23:24 PM UTC-4, Ben Noordhuis wrote:
    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.
    --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.
    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Ben Noordhuis at Oct 27, 2012 at 5:10 am

    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).
    Okay, unaccounted ticks need some explaining.

    The profiler takes samples at 1000 Hz, meaning it logs the instruction
    pointer every millisecond. The tick processor takes those samples and
    tries to match them to C/C++ or (compiled) JS code. When no matching
    function is found, the tick is unaccounted for.

    The unknown addresses nearly always correspond with the slabs of
    executable memory where V8 stores generated code. (I say "nearly"
    because stack trampolines, for example, also cause unaccounted ticks -
    but those are rare.)

    What happens is that --prof_lazy disables some crucial log events that
    the tick processor needs. The problem is that I haven't quite figured
    out yet what those events are. :-) The patch below improves but
    doesn't quite fix the situation.

    diff --git a/deps/v8/src/log.h b/deps/v8/src/log.h
    index 33f359a..5c64136 100644
    --- a/deps/v8/src/log.h
    +++ b/deps/v8/src/log.h
    @@ -284,7 +284,7 @@ class Logger {
    void LogRuntime(Vector<const char> format, JSArray* args);

    bool is_logging() {
    - return logging_nesting_ > 0;
    + return logging_nesting_ > 0 || FLAG_prof_lazy;
    }

    bool is_logging_code_events() {

    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Andrew Spyker at Oct 27, 2012 at 3:14 am
    Better, but still quite of bit of problems in the resulting files. check
    out the new zip file for all the logs.

    you can see that it did get better:

    [idcuser@xxx test-profiling]$ grep Statistical *nprof*
    v8-lazystartprofiling-ganode.nprof.txt:Statistical profiling result from
    v8-lazystartprofiling-ganode.log, (11925 ticks, 7714 unaccounted, 0
    excluded).
    v8-lazystartprofiling-patchednode.nprof.txt:Statistical profiling result
    from v8-lazystartprofiling-patchednode.log, (8492 ticks, 3297 unaccounted,
    0 excluded).
    v8-standardprofiling.nprof.txt:Statistical profiling result from
    v8-standardprofiling.log, (18028 ticks, 0 unaccounted, 0 excluded).

    So non-lazy profiling got 0% unaccounted, lazy start with no patch 65%,
    lazy start with patch 39%. Ran it a second time and got very similar
    results.

    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Andrew Spyker at Oct 26, 2012 at 10:08 pm
    Should have included versions:

    node --version = v0.8.14
    profiler version is whatever downloads current from 'npm install profiler'

    uname -a
    Linux vhost4145 2.6.32-220.17.1.el6.i686 #1 SMP Thu Apr 26 13:37:46 EDT
    2012 i686 i686 i386 GNU/Linux

    Redhat Enterprise Linux Server Release 6.2 (Santiago)

    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Andrew Spyker at Oct 27, 2012 at 3:25 am
    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 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
    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Ben Noordhuis at Oct 29, 2012 at 1:16 pm

    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.
    Here is the tracking issue in case you want to follow it:

    https://github.com/joyent/node/issues/4209

    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Andrew Spyker at Oct 29, 2012 at 10:33 pm
    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.

    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en
  • Andrew Spyker at Oct 30, 2012 at 5:12 am
    same approach worked well in full node server app
    Statistical profiling result from v8-trimmed.log, (183523 ticks, 190
    unaccounted, 0 excluded).

    This was after trimming 3 minutes of warmup followed by 3 minutes of
    "profiled" code after the call to getGMTString() using the below trimming
    approach.
    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.
    --
    Job Board: http://jobs.nodejs.org/
    Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
    You received this message because you are subscribed to the Google
    Groups "nodejs" group.
    To post to this group, send email to nodejs@googlegroups.com
    To unsubscribe from this group, send email to
    nodejs+unsubscribe@googlegroups.com
    For more options, visit this group at
    http://groups.google.com/group/nodejs?hl=en?hl=en

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupnodejs @
categoriesnodejs
postedOct 26, '12 at 8:36p
activeOct 30, '12 at 5:12a
posts12
users2
websitenodejs.org
irc#node.js

2 users in discussion

Andrew Spyker: 8 posts Ben Noordhuis: 4 posts

People

Translate

site design / logo © 2022 Grokbase