Skip to content

Benchpress is over-reporting in Chrome 45 #4011

Closed

Description

@goderbauer

When running the treeUpdate benchmark in Chrome 45, benchpress reports scriptTimes and pureScriptTimes that are higher than what was reported in previous versions of chrome:

Chrome 45: ~19ms
Chrome 44: ~9ms

Looking at the browser timeline in chrome 45, the script time should be around 11ms. I am assuming that benchpress is over-reporting in chrome 45.

Note: Chrome Team changed a bunch of event names in Chrome 45, which benchpress depends on. Benchpress has been adapted to those new names (see #3411), but maybe more than just names changed. Further investigation is required.

Activity

  1. goderbauer commented on Sep 5, 2015

    @goderbauer
    ContributorAuthor

    I just looked at the FunctionCall events produced by Chrome 45 compared to Chrome 44. Looks like Chrome 45 is producing more of them (the extra ones do not have scriptName set) which probably results in the over-reporting. Need to find out what those additional FunctionCalls are and if it is save to just ignore them since they seem to be included in the FunctionCall events with scriptName.

    Chrome 45:

    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 120, name: FunctionCall, ph: X, pid: 798817, tdur: 116, tid: 798817, ts: 384961574250.0, tts: 1950001}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 4217, name: FunctionCall, ph: X, pid: 798817, tdur: 4146, tid: 798817, ts: 384961576126.0, tts: 1950694}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 143, name: FunctionCall, ph: X, pid: 798817, tdur: 141, tid: 798817, ts: 384961580196.0, tts: 1954696}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 229, name: FunctionCall, ph: X, pid: 798817, tdur: 227, tid: 798817, ts: 384961581758.0, tts: 1955316}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 63, name: FunctionCall, ph: X, pid: 798817, tdur: 60, tid: 798817, ts: 384961582615.0, tts: 1955809}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 165, name: FunctionCall, ph: X, pid: 798817, tdur: 160, tid: 798817, ts: 384961592619.0, tts: 1957622}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 312, name: FunctionCall, ph: X, pid: 798817, tdur: 299, tid: 798817, ts: 384961594401.0, tts: 1958409}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 248, name: FunctionCall, ph: X, pid: 798817, tdur: 232, tid: 798817, ts: 384961596096.0, tts: 1959189}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 2102, name: FunctionCall, ph: X, pid: 798817, tdur: 2015, tid: 798817, ts: 384961599428.0, tts: 1960301}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 336, name: FunctionCall, ph: X, pid: 798817, tdur: 326, tid: 798817, ts: 384961603196.0, tts: 1962883}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1668, name: FunctionCall, ph: X, pid: 798817, tdur: 1598, tid: 798817, ts: 384961605820.0, tts: 1963903}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 932, name: FunctionCall, ph: X, pid: 798817, tdur: 921, tid: 798817, ts: 384961609190.0, tts: 1966094}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 11319, name: FunctionCall, ph: X, pid: 798817, tdur: 11196, tid: 798817, ts: 384961612989.0, tts: 1969160}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 95, name: FunctionCall, ph: X, pid: 798817, tdur: 94, tid: 798817, ts: 384961624582.0, tts: 1980632}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 118, name: FunctionCall, ph: X, pid: 798817, tdur: 113, tid: 798817, ts: 384961660138.0, tts: 1991396}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1202, name: FunctionCall, ph: X, pid: 798817, tdur: 1192, tid: 798817, ts: 384961662062.0, tts: 1991993}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 102, name: FunctionCall, ph: X, pid: 798817, tdur: 99, tid: 798817, ts: 384961663159.0, tts: 1993082}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 271, name: FunctionCall, ph: X, pid: 798817, tdur: 258, tid: 798817, ts: 384961664793.0, tts: 1993589}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 77, name: FunctionCall, ph: X, pid: 798817, tdur: 74, tid: 798817, ts: 384961665999.0, tts: 1994066}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 118, name: FunctionCall, ph: X, pid: 798817, tdur: 112, tid: 798817, ts: 384961674946.0, tts: 1994487}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1839, name: FunctionCall, ph: X, pid: 798817, tdur: 1820, tid: 798817, ts: 384961676410.0, tts: 1995070}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 88, name: FunctionCall, ph: X, pid: 798817, tdur: 85, tid: 798817, ts: 384961678911.0, tts: 1997199}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 115, name: FunctionCall, ph: X, pid: 798817, tdur: 104, tid: 798817, ts: 384961715221.0, tts: 1997567}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1808, name: FunctionCall, ph: X, pid: 798817, tdur: 1746, tid: 798817, ts: 384961717059.0, tts: 1998237}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 109, name: FunctionCall, ph: X, pid: 798817, tdur: 105, tid: 798817, ts: 384961718755.0, tts: 1999874}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 246, name: FunctionCall, ph: X, pid: 798817, tdur: 237, tid: 798817, ts: 384961720677.0, tts: 2000462}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 82, name: FunctionCall, ph: X, pid: 798817, tdur: 76, tid: 798817, ts: 384961721713.0, tts: 2001039}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 126, name: FunctionCall, ph: X, pid: 798817, tdur: 108, tid: 798817, ts: 384961730280.0, tts: 2001382}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 203, name: FunctionCall, ph: X, pid: 798817, tdur: 199, tid: 798817, ts: 384961731580.0, tts: 2001896}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 77, name: FunctionCall, ph: X, pid: 798817, tdur: 66, tid: 798817, ts: 384961732523.0, tts: 2002351}
    

    Chrome 44:

    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 87, name: FunctionCall, ph: X, pid: 280056, tdur: 85, tid: 280056, ts: 720815084703.0, tts: 1471547}
    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 11797, name: FunctionCall, ph: X, pid: 280056, tdur: 11710, tid: 280056, ts: 720815119161.0, tts: 1481839}
    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 94, name: FunctionCall, ph: X, pid: 280056, tdur: 92, tid: 280056, ts: 720815169782.0, tts: 1505669}
    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 115, name: FunctionCall, ph: X, pid: 280056, tdur: 112, tid: 280056, ts: 720815216374.0, tts: 1509758}
    
  2. tbosch commented on Sep 5, 2015

    @tbosch
    Contributor

    Michael, could we add a logic to not count FunctionCalls that are nested
    inside of others in general?
    On Fri, Sep 4, 2015 at 8:31 PM Michael Goderbauer [email protected]
    wrote:

    I just looked at the FunctionCall events produced by Chrome 45 compared to
    Chrome 44. Looks like Chrome 45 is producing more of them (the extra ones
    do not have scriptName set) which probably results in the over-reporting.
    Need to find out what those additional FunctionCalls are and if it is save
    to just ignore them since they seem to be included in the FunctionCall
    events with scriptName.

    Chrome 45:

    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 120, name: FunctionCall, ph: X, pid: 798817, tdur: 116, tid: 798817, ts: 384961574250.0, tts: 1950001}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 4217, name: FunctionCall, ph: X, pid: 798817, tdur: 4146, tid: 798817, ts: 384961576126.0, tts: 1950694}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 143, name: FunctionCall, ph: X, pid: 798817, tdur: 141, tid: 798817, ts: 384961580196.0, tts: 1954696}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 229, name: FunctionCall, ph: X, pid: 798817, tdur: 227, tid: 798817, ts: 384961581758.0, tts: 1955316}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 63, name: FunctionCall, ph: X, pid: 798817, tdur: 60, tid: 798817, ts: 384961582615.0, tts: 1955809}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 165, name: FunctionCall, ph: X, pid: 798817, tdur: 160, tid: 798817, ts: 384961592619.0, tts: 1957622}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 312, name: FunctionCall, ph: X, pid: 798817, tdur: 299, tid: 798817, ts: 384961594401.0, tts: 1958409}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 248, name: FunctionCall, ph: X, pid: 798817, tdur: 232, tid: 798817, ts: 384961596096.0, tts: 1959189}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 2102, name: FunctionCall, ph: X, pid: 798817, tdur: 2015, tid: 798817, ts: 384961599428.0, tts: 1960301}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 336, name: FunctionCall, ph: X, pid: 798817, tdur: 326, tid: 798817, ts: 384961603196.0, tts: 1962883}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1668, name: FunctionCall, ph: X, pid: 798817, tdur: 1598, tid: 798817, ts: 384961605820.0, tts: 1963903}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 932, name: FunctionCall, ph: X, pid: 798817, tdur: 921, tid: 798817, ts: 384961609190.0, tts: 1966094}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 11319, name: FunctionCall, ph: X, pid: 798817, tdur: 11196, tid: 798817, ts: 384961612989.0, tts: 1969160}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 95, name: FunctionCall, ph: X, pid: 798817, tdur: 94, tid: 798817, ts: 384961624582.0, tts: 1980632}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 118, name: FunctionCall, ph: X, pid: 798817, tdur: 113, tid: 798817, ts: 384961660138.0, tts: 1991396}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1202, name: FunctionCall, ph: X, pid: 798817, tdur: 1192, tid: 798817, ts: 384961662062.0, tts: 1991993}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 102, name: FunctionCall, ph: X, pid: 798817, tdur: 99, tid: 798817, ts: 384961663159.0, tts: 1993082}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 271, name: FunctionCall, ph: X, pid: 798817, tdur: 258, tid: 798817, ts: 384961664793.0, tts: 1993589}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 77, name: FunctionCall, ph: X, pid: 798817, tdur: 74, tid: 798817, ts: 384961665999.0, tts: 1994066}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 118, name: FunctionCall, ph: X, pid: 798817, tdur: 112, tid: 798817, ts: 384961674946.0, tts: 1994487}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1839, name: FunctionCall, ph: X, pid: 798817, tdur: 1820, tid: 798817, ts: 384961676410.0, tts: 1995070}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 88, name: FunctionCall, ph: X, pid: 798817, tdur: 85, tid: 798817, ts: 384961678911.0, tts: 1997199}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 115, name: FunctionCall, ph: X, pid: 798817, tdur: 104, tid: 798817, ts: 384961715221.0, tts: 1997567}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 1808, name: FunctionCall, ph: X, pid: 798817, tdur: 1746, tid: 798817, ts: 384961717059.0, tts: 1998237}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 44, scriptLine: 3501, scriptName: http://ioen80.prod.google.com:27834/src/tree/tree_benchmark.dart.js}}, cat: devtools.timeline,v8, dur: 109, name: FunctionCall, ph: X, pid: 798817, tdur: 105, tid: 798817, ts: 384961718755.0, tts: 1999874}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 246, name: FunctionCall, ph: X, pid: 798817, tdur: 237, tid: 798817, ts: 384961720677.0, tts: 2000462}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 82, name: FunctionCall, ph: X, pid: 798817, tdur: 76, tid: 798817, ts: 384961721713.0, tts: 2001039}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 126, name: FunctionCall, ph: X, pid: 798817, tdur: 108, tid: 798817, ts: 384961730280.0, tts: 2001382}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 203, name: FunctionCall, ph: X, pid: 798817, tdur: 199, tid: 798817, ts: 384961731580.0, tts: 2001896}
    R {args: {data: {frame: 0x2d03342c2c0, scriptId: 39, scriptLine: 1, scriptName: }}, cat: devtools.timeline,v8, dur: 77, name: FunctionCall, ph: X, pid: 798817, tdur: 66, tid: 798817, ts: 384961732523.0, tts: 2002351}

    Chrome 44:

    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 87, name: FunctionCall, ph: X, pid: 280056, tdur: 85, tid: 280056, ts: 720815084703.0, tts: 1471547}
    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 11797, name: FunctionCall, ph: X, pid: 280056, tdur: 11710, tid: 280056, ts: 720815119161.0, tts: 1481839}
    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 94, name: FunctionCall, ph: X, pid: 280056, tdur: 92, tid: 280056, ts: 720815169782.0, tts: 1505669}
    R {args: {data: {frame: 0x3d90f9680000, scriptId: 35, scriptLine: 3501, scriptName: http://ioih17.prod.google.com:19374/src/tree/tree_benchmark.dart.js}}, cat: disabled-by-default-devtools.timeline, dur: 115, name: FunctionCall, ph: X, pid: 280056, tdur: 112, tid: 280056, ts: 720815216374.0, tts: 1509758}

    —
    Reply to this email directly or view it on GitHub
    #4011 (comment).

  3. goderbauer commented on Sep 9, 2015

    @goderbauer
    ContributorAuthor

    As discussed offline: These events are not nested. Also, that logic already exists:
    https://github.com/angular/angular/blob/master/modules/benchpress/src/metric/perflog_metric.ts#L251

  4. angular-automatic-lock-bot commented on Sep 7, 2019

    @angular-automatic-lock-bot

    This issue has been automatically locked due to inactivity.
    Please file a new issue if you are encountering a similar or related problem.

    Read more about our automatic conversation locking policy.

    This action has been performed automatically by a bot.

  5. locked and limited conversation to collaborators on Sep 7, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions