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?