Incorrect source file names in time profiles in Node 8

[nolanmar511]

For the sample application, a time profile indicated that the function 'fill' was located within the source file below, when it should be marked as within 'buffer.js'. This is likely a problem with serialization, and since much of the serialization code is shared, heap profiles may also be impacted.

const profiler = require('@google-cloud/profiler')

let count = 0;
function additionFunction() {
    let a = 0
          for (var i = 0; i < 10000; i++) {
                a = a + 3;
                a = a * a;
                a = Math.sqrt(a);
                  }
      setImmediate(additionFunction);
}

function fillBuffer() {
    var buffer = new Buffer(500);
    for (var k = 0; k < 1e2; k++)
      buffer.fill(0);
    setImmediate(fillBuffer);
}

profiler.start({
    projectId: 'nolanmar-testappstandard',
      logLevel: 5,
        serviceContext: {
              service: 'app-std',
                  version: '0'
                        },
});

additionFunction();
fillBuffer();

[nolanmar511]

I'm less certain that this is a problem with serialization.
I printed out the profile prior to serialization and saw this as part of the profile:

{
                    "name": "fillBuffer",
                    "scriptName": "/path/to/server.js",
                    "scriptId": 71,
                    "lineNumber": 15,
                    "columnNumber": 20,
                    "hitCount": 50,
                    "children": [
                      {
                        "name": "fill",
                        "scriptName": "/path/to/server.js",
                        "scriptId": 24,
                        "lineNumber": 0,
                        "columnNumber": 0,
                        "hitCount": 129,
                        "children": [
                          {
                            "name": "fill",
                            "scriptName": "",
                            "scriptId": 0,
                            "lineNumber": 0,
                            "columnNumber": 0,
                            "hitCount": 501,
                            "children": []
                          }
                        ]
                      },
...

The function 'fill' is listed as having server.js as the file it is in.

[nolanmar511]

Ran with Node 6, saw this in the profile before serialization:

{
    "name": "fillBuffer",
    "scriptName": "/path/to/server.js",
    "scriptId": 61,
    "lineNumber": 15,
    "columnNumber": 20,
    "hitCount": 90,
    "children": [
      {
        "name": "fill",
        "scriptName": "buffer.js",
        "scriptId": 38,
        "lineNumber": 662,
        "columnNumber": 38,
        "hitCount": 243,
        "children": [
          {
            "name": "fill",
            "scriptName": "",
            "scriptId": 0,
            "lineNumber": 0,
            "columnNumber": 0,
            "hitCount": 481,
            "children": []
          }
        ]
      },

[nolanmar511]

Buffer seems to have the correct source file with node 8, though, and the wrong source file with node 6.

With node 6:

{
                        "name": "Buffer",
                        "scriptName": "/path/to/server.js",
                        "scriptId": 38,
                        "lineNumber": 0,
                        "columnNumber": 0,
                        "hitCount": 0,
                        "children": [

With Node 8:

{
                        "name": "Buffer",
                        "scriptName": "buffer.js",
                        "scriptId": 24,
                        "lineNumber": 147,
                        "columnNumber": 16,
                        "hitCount": 2,
                        "children": [

[aalexand]

Just to clarify, are you looking at the fill() branch or Buffer() constructor branch? Your previous comments talk about fill() but the last one seems to talk about Buffer()? Just want to make sure we keep looking at the same data.

[nolanmar511]

Yes, I am talking about that section of the flame chart.
In node 6, the filename for fill is Buffer.js, and the filename for Buffer is /path/to/server.js.
In node 8, the filename for fill is path/to/server.js, and the filename for Buffer is Buffer.js.

So basically, both node 6 and node 8 seem to have problems with the filenames in the profiles, but the problems are different.

[aalexand]

I wonder if this happen to depend on how the inlining works.

…

On Tue, Dec 12, 2017 at 8:38 AM, Margaret Nolan ***@***.***> wrote: Yes, I am talking about that section of the flame chart. In node 6, the filename for fill is Buffer.js, and the filename for Buffer is /path/to/server.js. In node 8, the filename for fill is path/to/server.js, and the filename for Buffer is Buffer.js. So basically, both node 6 and node 8 seem to have problems with the filenames in the profiles, but the problems are different. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#89 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABctwKxbuD1WCXCh05cHKeHwEC-H3Qeqks5s_qwPgaJpZM4Q70jY> .

-- Alex

[ofrobots]

I think it is quite likely due to inlining. /cc @bmeurer @hashseed

[bmeurer]

If you're essentially using --prof then it's very likely that this is due to inlining, yes.

[ofrobots]

This uses the CPU Profiler (cpu-profiler.h) which is based on timer based statistical sampling. I think that's what prof does as well.

I think https://crbug.com/v8/6239 is supposed to be the tracking bug for this issue in V8.

[bmeurer]

That tracking bug was about something else. I created v8:7203 for this specifically now.

[aalexand]

As a workaround on the profiler side I guess we could pretend the source file is empty when the line number is zero. But I'd rather prefer the profiler do that for us (or put the right source file name).

[nolanmar511]

@hashseed -- we'd mentioned this problem earlier.
Is this behavior expected? Can it be fixed?

[bmeurer]

@nolanmar511 Yes. We'll be working on supporting that as well.

[aalexand]

@nolanmar511 @bmeurer @hashseed Who should own this issue?

[hashseed]

@fhinkel do you want to take a look?

[fhinkel]

Yes, I'll check

[fhinkel]

Is there an easy way to run this locally? I don't have auth credentials for GCP.

Using the --inspect flag, DevTools shows buffer.js as source for both fill and Buffer (for Node 6 and Node 8). There's a second fill, not attributed to any file, I'm assuming that's because it was inlined. Is that maybe misattributed in @google-cloud/profiler?

Edit: The recorded profile changes once I kill the Node process: and a bunch of file attributions change to server.js. (Start recording, stop recording, see correct buffer.js, stop Node, DevTools automatically disconnects, server.js attributions change to buffer.js attributions

Gist, just run node --inspect server.js.

[aalexand]

@nolanmar Can you give instructions on running locally?

[nolanmar511]

@fhinkel -- PR #95 will make it so that profiles are written out when starting the profile with .startLocal(). So, you can replace .start() with .startLocal(), if you get the code from that PR.

To see profiles before they are serialized, you can add console.log(result) after this line. The only processing done to result between the call to the profile and this point happens in this file.
I don't know that this code uses the same profiler which is used by inspect.

[fhinkel]

Here's my V8 patch that fixes the wrong file attribution for the cloud profiler and DevTools. We can probably backport it to Node master (and later to 8) after a few days of Canary coverage.

[aalexand]

@nolanmar511 assigned to you for the verification.

[fhinkel]

Merged to 6.4, should get picked up in this PR and land in Node master on January 23rd.

[ofrobots]

Opened back port PR for current version of V8 in Node: nodejs/node#18298. Even if 6.4 gets merged before my PR, this is needed in older versions of node.

[aalexand]

@nolanmar511 Please verify that this is fixed and close issue if so.

[nolanmar511]

This seems fixed.
I ran the script in description of this issue with node 8, inspected the flame graph of a profile and saw this:

The fill() function is attributed to the script from which it is called.

I then installed the nightly release from today (2-13-18), and ran with that release. The flame graph correctly attributed the fill() function to buffer.js