Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Generating Timeline metrics with Chrome Trace #43

Closed
haroldtreen opened this issue Sep 16, 2015 · 19 comments
Closed

Generating Timeline metrics with Chrome Trace #43

haroldtreen opened this issue Sep 16, 2015 · 19 comments
Labels
question

Comments

@haroldtreen
Copy link
Contributor

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
Copy link
Owner

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
Copy link
Contributor Author

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
Copy link
Owner

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
Copy link
Contributor Author

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:
image

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
Copy link
Owner

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
Copy link
Contributor Author

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
Copy link
Owner

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Owner

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

@haroldtreen
Copy link
Contributor Author

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
Copy link

hinok commented Oct 24, 2015

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
Copy link
Owner

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.

@malled
Copy link

malled commented Nov 15, 2017

Did it change again? I cannot see any metrics related to js or rendering.

@axemclion
Copy link
Owner

@malled Looks like there was another change in the logs.

@brandonaaron
Copy link
Contributor

@axemclion Could you provide some guidance on making changes necessary to get the metrics back?

@axemclion
Copy link
Owner

@brandonaaron - I think the best way to get started would be to write the metrics to a file by un-commenting this line.

This would list all the raw info, and we should be able to pick up the specific metrics.

@brandonaaron
Copy link
Contributor

brandonaaron commented Feb 9, 2018 •
edited
Loading

@axemclion I see no Tracing related entries in the log output at that point. Only Network and Page entries. If I monitor the log from selenium server I do see Tracing entries.

  bp:index Stating browser with {"browserName":"chrome","chromeOptions":{"perfLoggingPrefs":{"traceCategories":",blink.console,devtools.timeline,disabled-by-default-devtools.timeline,toplevel,disabled-by-default-devtools.timeline.frame,benchmark"},"args":["--enable-gpu-benchmarking","--enable-thread-composting"]},"loggingPrefs":{"performance":"ALL"}} +0ms
  bp:selenium CALL init({"browserName":"chrome","chromeOptions":{"perfLoggingPrefs":{"tra  +2ms
  bp:selenium RESPONSE init({"browserName":"chrome","chromeOptions":{"perfLoggingPrefs":{"tra "0fb1d5f0f898f5d4660d37e247445c37",{"applicationCacheEnabled":false,"r +612ms

@brandonaaron brandonaaron mentioned this issue Feb 12, 2018
Open
@brandonaaron
Copy link
Contributor

I was able to get Tracing entries back into the mix... submitted a pull request.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@brandonaaron @axemclion @hinok @haroldtreen @malled