Node 0.10.3 Keep getting entries: unknown code state: undefined

[antitoxic]

When parsing the log with nprof i am simply getting giant volume of :

...
line 3565: unknown code state: undefined
line 3566: unknown code state: undefined
line 3594: unknown code state: undefined
line 3595: unknown code state: undefined
line 3596: unknown code state: undefined
line 3598: unknown code state: undefined
line 3599: unknown code state: undefined
line 3600: unknown code state: undefined
line 3602: unknown code state: undefined
...

And then:

 [Unknown]:
   ticks  total  nonlib   name
    503    0.4%

 [Shared libraries]:
   ticks  total  nonlib   name
  125191   99.5%    0.0%  /usr/lib/libc-2.17.so
     61    0.0%    0.0%  /usr/bin/node
     29    0.0%    0.0%  /usr/lib/libpthread-2.17.so

 [JavaScript]:
   ticks  total  nonlib   name

 [C++]:
   ticks  total  nonlib   name

 [GC]:
   ticks  total  nonlib   name
      0    0.0%

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
  125191   99.5%  /usr/lib/libc-2.17.so

[skeggse]

Similar problem--I get a surge of line [0-9]+: unknown code state: undefined.

It looks like nprof is tripping up on this line:

code-creation,Script,0x33382ed13fe0,844,"native runtime.js",0x10691041aa98,~

But I don't understand the v8.log format, so I don't understand what it should do.

[bnoordhuis]

It's on my TODO list. The issue is that the v8.log file layout changes between V8 releases.

My plan is to bundle tick processors from all major releases and select the appropriate one based on the value of process.versions.v8. (Which is not foolproof when the log file was generated with a different node.js/V8 version, of course. A command line override is planned.)

[hunterloftis]

What's the best way to get a tick processor from the latest version of v8? I'm having issues like:

node --prof --prof_lazy app
doesn't output anything to v8.log

node --prof --prof_lazy --log_code app
doesn't output anything to v8.log

node --prof --prof_lazy --log_all app
seems to work? at least, it outputs something - I don't know if it's profiling information. but nprof and my old node-tick-processor give back gibberish

I'm not sure that profiler.pause() and profiler.resume() are doing anything... it's hard to tell without being able to analyze the output. It's suspicious that --prof_lazy which is supposed to imply log_code doesn't actually output anything.

[bnoordhuis]

What's the best way to get a tick processor from the latest version of v8?

From the top-level directory of the node.js tarball or git checkout, cd into deps/v8 and run make -j8 native. When that's done, you can run tools/linux-tick-processor or whatever the appropriate tick processor is for your platform on the v8.log.

By the way, you don't want the latest version of V8 - you want the version that generated the log file, i.e. the version of V8 that's bundled with node.js.

[hunterloftis]

Thanks for the detailed explanation. It's amazing how hard it is to find that answer online (lots of answers, all wrong/outdated).

Gotcha with the version - what I should have said was, I have the latest version, so I need to figure out how to build the latest tick processor.

[hunterloftis]

Do you have any insights on which flags to use to get the best profiling? So far I've had zero success with anything other than node --prof app.

[bnoordhuis]

--prof --log should be all you need.

[hunterloftis]

Cool, I was hoping to start with the profiler disabled (prof_lazy) but in that mode no output is recorded.

make -j8 native gives me make: *** No rule to make targettest/cctest/cctest.gyp', needed by out/Makefile.native'. Stop. with the v0.10.13 tarball.

[bnoordhuis]

Oh, it's possible the tarball doesn't contain deps/v8/test - in that case try cloning the git repo.

BTW, --prof_lazy is often broken.

[hunterloftis]

Aha, thanks for the heads up. It didn't seem to really do anything. Instead I'm just running profiler.pause() immediately.

In case someone else runs into this problem, I'm going to start debugging here if the git repo doesn't help:
https://groups.google.com/forum/#!msg/nodejs/4NMoiPd2K6s/Neql-TtgHf4J

[mark-hahn]

I switched to v 0.10.5 to match Pull Request #12: Updated to v8 version 3.14.5.8 included with 0.10.5 and I still have the problem. Is this expected?

Oh, I just noticed the last update was seven months ago. So the pull hasn't been done yet?

[mark-hahn]

Sorry to be a pain, but i finally looked at the pull request page and I see that I have to add a dependency to the package.json. I did this copying the json provided there. I tried the following and got an unmet dependency. Can someone help me?

 > npm rebuild profiler  --unsafe-perm true
npm WARN unmet dependency /ri/node_modules/profiler requires profiler@'wolfeidau/node-profiler#updated_v8_to_3.14.5.8' but will load
npm WARN unmet dependency /ri/node_modules/profiler,
npm WARN unmet dependency which is version 1.2.1

[mark-hahn]

What old version of node should I run to make this work without using the pull request?

[linbo]

May I know which version of V8 and Node can work with node-profiler?

[jfirebaugh]

I cloned the repository and tried make -j8 native:

~/Development/node/deps/v8 $ make -j8 native
GYP_GENERATORS=make \
    build/gyp/gyp --generator-output="out" build/all.gyp \
                  -Ibuild/standalone.gypi --depth=. -S.native  -Dv8_can_use_vfp3_instructions=true
/bin/sh: build/gyp/gyp: No such file or directory
make: *** [out/Makefile.native] Error 127

[bnoordhuis]

You need to have gyp installed and symlink it in build/gyp. You can use the gyp that ships with node in tools/gyp.

[jfirebaugh]

I ran into compile errors after that and gave up. However, copying deps/v8/tools/tickprocessor.js into place in a node-profiler checkout and rerunning build-nprof gave me a working nprof.

[netpoetica]

Are there any updates on this? I am experiencing this type of output from tick-processor (mac-tick-processor from v8 source) and profviz on Mac OSX 10.9.5, node v0.10.33, V8 version 3.31.0

[bnoordhuis]

See nodejs/node#158. I think this would be best solved by shipping a known-good tick profiler script with every io.js / node.js release.

I'm going to prepare a patch that adds version information to the v8.log file, to make it possible to discriminate between log files from different V8 versions.

[netpoetica]

Edit: forgot that I was on your personal repo and not in joyent/node. Will try to find appropriate place there to say the same thing.

@bnoordhuis Good to see there are some ideas around this! It's cool that iojs may host a solution to profiling, but I do think @joyent ought to be concerned with CPU profiling as not everyone is going to be willing to host on SmartOS or illuminos-based OSes w/ DTrace to profile their applications.

My personal applications usually don't have to support the kind of volume my employers do, so normally I'm not profiling (even though of course I should be), but when asked "Why is this call blocking?"/ "Why are we at 100% CPU consistently for this request?" we definitely need to be able to understand where the bottleneck is on whatever OS they are using (especially common ones like Ubuntu, CentOS & other Amazon AWS instances) and best-case-scenario local dev machines (Mac OSX, Windows)

[sidorares]

I'm going to prepare a patch that adds version information to the v8.log file, to make it possible to discriminate between log files from different V8 versions.

that would be very useful. node-tick-processor currently tries to guess format based on first occurrence of version-specific entry but it's not very reliable

[bnoordhuis]

https://codereview.chromium.org/800293002/

[andre487]

I have this issue in all the versions of Node.js where I try to extract a profile information from the v8.log: 0.10.0, 0.10.3, 0.10.4, 0.10.36, 0.10.37.

In all cases I have line \d+: unknown code state: undefined

On which version and with which params and which tick-processor can it works?