Generating Timeline metrics with Chrome Trace

[haroldtreen]

Timeline had some really awesome metrics:

https://github.com/axemclion/browser-perf/blob/master/docs/TimelineMetrics.json

Since it's been deprecated, is there a way to generate some of these using the trace data? We're using perfjankie and a bunch of sections aren't getting any data without these stats.

We're using Chrome 45. Any thoughts?

[axemclion]

browser-perf does give continue to pick up timeline metrics from tracing logs - it was done in this commit - 6c01a7b

Are you not able to see timeline metrics ? Can you run browser-perf with DEBUG=* env variable set and send me the logs ?

Note that some of the metrics may be missing because those events may not have occurred.

[haroldtreen]

Thanks for the quick reply!

Here's the logs:

bp:index Selenium is on localhost +0ms
  bp:metrics Initializing Metrics +3ms
  bp:probes Registering probe +203ms PerfLogProbe
  bp:probes:AndroidTracingProbe Initialize +5ms
  bp:probes Registering probe +1ms AndroidTracingProbe
  bp:probes Registering probe +9ms PerfLogProbe
  bp:probes Registering probe +0ms AndroidTracingProbe
  bp:probes Registering probe +3ms RafBenchmarkingProbe
  bp:probes Registering probe +3ms NavTimingProbe
  bp:probes Registering probe +3ms NetworkResourcesProbe
  bp:metrics TimelineMetrics +1ms setup called
  bp:metrics ChromeTracingMetrics +1ms setup called
  bp:metrics NetworkResources +1ms setup called
  bp:probes setup +0ms
  bp:probes PerfLogProbe +1ms setup called
  bp:probes AndroidTracingProbe +0ms setup called
  bp:probes NetworkResourcesProbe +0ms setup called
  bp:index Stating browser with +1ms {"browserName":"chrome","loggingPrefs":{"performance":"ALL"},"version":32,"chromeOptions":{"args":["disable-cache","disk-cache-dir=/dev/null","disk-cache-size=0","incognito","--enable-gpu-benchmarking","--enable-thread-composting"],"perfLoggingPrefs":{"enableNetwork":true,"enablePage":true,"traceCategories":",blink.console,disabled-by-default-devtools.timeline,benchmark"}}}
  bp:selenium CALL +1ms init({"browserName":"chrome","loggingPrefs":{"performance":"ALL"},"ver 
  bp:selenium RESPONSE +2s init({"browserName":"chrome","loggingPrefs":{"performance":"ALL"},"ver "bd005e2d-fe58-42e0-84e9-927adfedf6a2",{"applicationCacheEnabled":fals
  bp:index Session is bd005e2d-fe58-42e0-84e9-927adfedf6a2 +2ms
  bp:index Running Prescript +1ms
  bp:selenium CALL +2ms get("https://preview.mobify.com/?url=http%3A%2F%2Fwww.roadrunnersports 
  bp:selenium RESPONSE +2s get("https://preview.mobify.com/?url=http%3A%2F%2Fwww.roadrunnersports 
  bp:selenium CALL +1ms elementByCssSelector("#authorize") 
  bp:selenium RESPONSE +25ms elementByCssSelector("#authorize") {"ELEMENT":"0"}
  bp:selenium CALL +0ms element.click() 
  bp:selenium RESPONSE +39ms element.click() 
  bp:selenium CALL +1ms get("http://www.roadrunnersports.com/") 
  bp:selenium RESPONSE +4s get("http://www.roadrunnersports.com/") 
  bp:probes start +1ms
  bp:probes PerfLogProbe +1ms start called
  bp:selenium CALL +0ms logTypes() 
  bp:selenium RESPONSE +8ms logTypes() ["performance","browser","driver","client","server"]
  bp:probes:PerfLogProbe Supported log types +1ms [ 'performance', 'browser', 'driver', 'client', 'server' ]
  bp:selenium CALL +3ms log("performance") 
  bp:selenium RESPONSE +906ms log("performance") [{"level":"INFO","message":"{\"message\":{\"method\":\"Network.respons
  bp:probes AndroidTracingProbe +1ms start called
  bp:selenium CALL +0ms sessionCapabilities() 
  bp:selenium RESPONSE +8ms sessionCapabilities() {"applicationCacheEnabled":false,"rotatable":false,"mobileEmulationEna
  bp:probes RafBenchmarkingProbe +1ms start called
  bp:selenium CALL +9ms execute("(function(){var getTimeMs=(function(){if(window.performance)\ 
  bp:selenium RESPONSE +581ms execute("(function(){var getTimeMs=(function(){if(window.performance)\ null
  bp:probes NetworkResourcesProbe +0ms start called
  bp:selenium CALL +1ms execute("(function(){window.__networkResources=(window.performance&&ty 
  bp:actions:scroll Initializing Scroll function +39ms
  bp:selenium CALL +2ms execute("'use strict';(function(){function getBoundingVisibleRect(el){ 
  bp:selenium RESPONSE +22ms execute("(function(){window.__networkResources=(window.performance&&ty null
  bp:selenium CALL +1ms eval("window.__networkResources") 
  bp:selenium RESPONSE +16ms execute("'use strict';(function(){function getBoundingVisibleRect(el){ null
  bp:actions:scroll Waiting for Scrolling to finish +2ms
  bp:selenium CALL +0ms waitFor({"asserter":{},"timeout":600000,"pollFreq":2000}) 
  bp:selenium CALL +1ms eval("(window.__scrollActionDone === true)") 
  bp:selenium RESPONSE +31ms eval("window.__networkResources") [{"entryType":"resource","responseEnd":250.929999980144,"responseStart
  bp:selenium RESPONSE +5ms eval("(window.__scrollActionDone === true)") false
  bp:selenium CALL +2s eval("(window.__scrollActionDone === true)") 
  bp:selenium RESPONSE +12ms eval("(window.__scrollActionDone === true)") true
  bp:selenium RESPONSE +0ms waitFor({"asserter":{},"timeout":600000,"pollFreq":2000}) true
  bp:probes teardown +0ms
  bp:probes PerfLogProbe +0ms teardown called
  bp:probes:PerfLogProbe Getting Performance log +1ms http://localhost:4444/wd/hub/session/bd005e2d-fe58-42e0-84e9-927adfedf6a2/log
  bp:probes AndroidTracingProbe +975ms teardown called
  bp:selenium CALL +0ms sessionCapabilities() 
  bp:selenium RESPONSE +3ms sessionCapabilities() {"applicationCacheEnabled":false,"rotatable":false,"mobileEmulationEna
  bp:probes RafBenchmarkingProbe +1ms teardown called
  bp:probes:RafBenchmarkingProbe Clearing timer Interval +0ms
  bp:selenium CALL +0ms eval("window.__RafRecorder.get()") 
  bp:selenium RESPONSE +9ms eval("window.__RafRecorder.get()") [2264.31900006719,2281.00199997425,2297.68499999773,2314.3680000212,23
  bp:probes NavTimingProbe +1ms teardown called
  bp:selenium CALL +4ms execute("(function(){var requestAnimationFrame=(function(){return wind 
  bp:selenium RESPONSE +7ms execute("(function(){var requestAnimationFrame=(function(){return wind null
  bp:selenium CALL +0ms waitFor({"asserter":{},"timeout":600000,"pollFreq":1000}) 
  bp:selenium CALL +0ms eval("(typeof window.__navTimings !== \"undefined\")") 
  bp:selenium RESPONSE +8ms eval("(typeof window.__navTimings !== \"undefined\")") true
  bp:selenium RESPONSE +1ms waitFor({"asserter":{},"timeout":600000,"pollFreq":1000}) true
  bp:selenium CALL +1ms eval("window.__navTimings") 
  bp:selenium RESPONSE +10ms eval("window.__navTimings") {"firstPaint":263.189792633057,"unloadEventEnd":1442508623825,"respons
  bp:probes NetworkResourcesProbe +1ms teardown called
  bp:selenium CALL +0ms execute("(function(){window.__networkResources=(window.performance&&ty 
  bp:selenium RESPONSE +8ms execute("(function(){window.__networkResources=(window.performance&&ty null
  bp:selenium CALL +1ms eval("window.__networkResources") 
  bp:selenium RESPONSE +31ms eval("window.__networkResources") [{"entryType":"resource","responseEnd":250.929999980144,"responseStart
  bp:metrics Getting Results +1ms
  bp:metrics Getting results from  +0ms TimelineMetrics
  bp:metrics Getting results from  +0ms ChromeTracingMetrics
  bp:metrics:RenderingStats Process ID for render process is  +1ms 21736
  bp:metrics:RenderingStats Timestamp Event name is  +0ms BenchmarkInstrumentation::ImplThreadRenderingStats
  bp:metrics Getting results from  +3ms RafBenchmarkingRenderingStats
  bp:metrics Getting results from  +1ms NetworkTimings
  bp:metrics Getting results from  +0ms NetworkResources
  bp:selenium CALL +1ms quit() 
  bp:selenium RESPONSE +645ms quit() 

And these are the stats that are being returned:

[ 'GPUTask',
  'GPUTask_avg',
  'GPUTask_max',
  'GPUTask_count',
  'UpdateCounters',
  'ScheduleStyleRecalculation',
  'InvalidateLayout',
  'UpdateLayer',
  'UpdateLayer_avg',
  'UpdateLayer_max',
  'UpdateLayer_count',
  'CompositeLayers',
  'CompositeLayers_avg',
  'CompositeLayers_max',
  'CompositeLayers_count',
  'AnalyzeTask',
  'AnalyzeTask_avg',
  'AnalyzeTask_max',
  'AnalyzeTask_count',
  'RasterTask',
  'RasterTask_avg',
  'RasterTask_max',
  'RasterTask_count',
  'ImageDecodeTask',
  'ImageDecodeTask_avg',
  'ImageDecodeTask_max',
  'ImageDecodeTask_count',
  'mean_frame_time',
  'percentage_smooth',
  'frames_per_sec',
  'frame_time_discrepancy',
  'numAnimationFrames',
  'numFramesSentToScreen',
  'droppedFrameCount',
  'meanFrameTime_raf',
  'framesPerSec_raf',
  'firstPaint',
  'unloadEventEnd',
  'responseEnd',
  'responseStart',
  'domInteractive',
  'domainLookupEnd',
  'unloadEventStart',
  'domComplete',
  'domContentLoadedEventStart',
  'domainLookupStart',
  'redirectEnd',
  'redirectStart',
  'connectEnd',
  'connectStart',
  'loadEventStart',
  'navigationStart',
  'requestStart',
  'secureConnectionStart',
  'fetchStart',
  'domContentLoadedEventEnd',
  'domLoading',
  'loadEventEnd',
  'loadTime',
  'domReadyTime',
  'readyStart',
  'redirectTime',
  'appcacheTime',
  'unloadEventTime',
  'domainLookupTime',
  'connectTime',
  'requestTime',
  'initDomTreeTime',
  'loadEventTime',
  'NetworkJs',
  'NetworkJs_avg',
  'NetworkJs_max',
  'NetworkJs_count',
  'NetworkImage',
  'NetworkImage_avg',
  'NetworkImage_max',
  'NetworkImage_count',
  'NetworkCss',
  'NetworkCss_avg',
  'NetworkCss_max',
  'NetworkCss_count',
  'NetworkXhrrequest',
  'NetworkXhrrequest_avg',
  'NetworkXhrrequest_max',
  'NetworkXhrrequest_count',
  'NetworkIframe',
  'NetworkIframe_avg',
  'NetworkIframe_max',
  'NetworkIframe_count',
  '_browserName',
  '_url' ]

It doesn't look like any of the timeline metrics are present :/.

[axemclion]

Actually, things like InvalidateLayout, all stats with _avg/_count, etc are from the timeline. How are you invoking browser-perf ? Are you invoking it from the command line ?

Are there specific stats you are looking for ?

[haroldtreen]

I've used it both in the command line and as a module within a node program.

We're just trying to figure out why so many sections in PerfJankie are empty:

The missing sections are:

• Timer Install
• Timer Fire
• Event Dispatch
• Function Call
• Paint
• Layout
• Recalculate Styles

...And maybe more? Those are just the ones I see in the sidebar that don't have data. Haven't run through all metrics.

[axemclion]

Looks like these metrics do not show up because they do not occur in the timeline. Are you running this on a page that is long enough to scroll ? Can you send me a link to the site you are trying to record ? What action are you performing ?

[haroldtreen]

The page I'm trying to test is long enough to scroll, but it is pretty basic so I wondering the same thing.

But running browser-perf with more complex sites using parallax doesn't seem to generate these events either. Eg. http://islreview.com/

These are the events that site produced:

[ 'UpdateCounters',
  'SetLayerTreeId',
  'ScheduleStyleRecalculation',
  'InvalidateLayout',
  'CompositeLayers',
  'CompositeLayers_avg',
  'CompositeLayers_max',
  'CompositeLayers_count',
  'numAnimationFrames',
  'numFramesSentToScreen',
  'droppedFrameCount',
  'meanFrameTime_raf',
  'framesPerSec_raf',
  'firstPaint',
  'unloadEventEnd',
  'responseEnd',
  'responseStart',
  'domInteractive',
  'domainLookupEnd',
  'unloadEventStart',
  'domComplete',
  'domContentLoadedEventStart',
  'domainLookupStart',
  'redirectEnd',
  'redirectStart',
  'connectEnd',
  'connectStart',
  'loadEventStart',
  'navigationStart',
  'requestStart',
  'secureConnectionStart',
  'fetchStart',
  'domContentLoadedEventEnd',
  'domLoading',
  'loadEventEnd',
  'loadTime',
  'domReadyTime',
  'readyStart',
  'redirectTime',
  'appcacheTime',
  'unloadEventTime',
  'domainLookupTime',
  'connectTime',
  'requestTime',
  'initDomTreeTime',
  'loadEventTime',
  '_browserName',
  '_url' ]

I haven't tried any more complex actions, just scrolling.

[axemclion]

Thanks for the info - looks like I may need more help from you to figure out if this is an issue, and if paint events are infact emitted during the scroll.

Note that by default, the measurements are done after the page has completely loaded. There could be a chance where since there is nothing to draw, all the scroll work is done by the GPU on that page.

One way to be certain is to enable the line that writes perflog to a file and open it to see if there are Paint events - I did not see any on my computer (both Mac and Windows).

To take that a step furthur, we could simply ignore browser-perf and directly open a browser, collect perf log and see what that says. Here is the reduced code that simply collects the timeline.
I actually do not see any paint events - I think that is pretty neat since all that paints is maybe not required during scrolling

https://gist.github.com/axemclion/38265a963f5a863f7a53

[haroldtreen]

Thanks for looking into it! I'll give your tests a try.

I've tried quite a few sites with browser-perf and never seen the "Paint" event, so I'm curious if it's still in use.
I'll give the script a try and see what logs I can get from different sites.

[haroldtreen]

I tried this code: https://gist.github.com/axemclion/38265a963f5a863f7a53

The logs I got showed no sign of the "Paint" event. Instead there was references to things like:

• PaintImage
• ContentLayerDelegate::paintContents
• DeprecatedPaintLayer::updateLayerPositionsAfterLayout

I even got ride of the line where the performance data is flushed after fetching the site and was unable to see any "Paint" events.

So if Chrome is now representing the paint process more granularly with these events, should perfjankie be looking at these events for paint metrics rather then the previous "Paint" event?

[axemclion]

@haroldtreen I think it makes sense. Maybe we should look at ChromeDevTools source and look at how they calculate the paint event now ?

[haroldtreen]

Good idea!

I've just poked around briefly and found this: https://code.google.com/p/chromium/codesearch#chromium/src/out/Debug/gen/devtools/timeline_module.js&q=PaintImage&sq=package:chromium&type=cs&l=315

Although those all look like events from the in browser debug timeline and not the trace logs.

It's interesting because if the timeline data was being shown in the performance logs, you'd expect to see similiar events when running the timeline in the browser vs. looking at performance logs. But many of the events in that file I don't believe I've seen show up in the performance log...

[hinok]

I confirm that I also don't get anymore any metrics related to JavaScript (FunctionCall, EvelauteScript etc.) and rendering events (Paint, Layout etc.).

perfjankie 2.1.0
browser-perf 1.4.1
chromedriver 2.20
selenium-server 2.48.2

Output from https://gist.github.com/axemclion/38265a963f5a863f7a53

Formatted JSON - _perflog.json (10.5 MB)
https://dl.dropboxusercontent.com/u/3487959/_perflog.json

[axemclion]

Yup, looks like the perflog format changed. I will try to see if I can spend some time this week to reconcile the results to a newer format.