1250290 - Make performance timeline data available via WebDriver

Status: NEW

(Remote Protocol :: Marionette, defect, P3)

Description

[Bobby Holley (:bholley)]

The Angular team does automation testing using WebDriver, and uses the performance data spew to track performance.

A pseudo-spec of the spew can be found at [1]. We should make compatible spew available so that they can run the same tests on Firefox without extra work.

[1] https://sites.google.com/a/chromium.org/chromedriver/logging/performance-log

Comment 1

[David Burns :automatedtester]

I have emailed the Google TL for webdriver for help on how they implemented it. Once I know more I will update.

I suspect that they are doing something that is not specified somewhere so getting parity is going to be a lot of work.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

Also, would be great to know what they actually report in the log.
We collect quite a bit data about GC/CC handling for example and show it in browser console when the relevant pref is on, and also send that as a notification to observer service.
And devtools collect all sorts of stuff when enabled.

Comment 3

[Bobby Holley (:bholley)]

(In reply to David Burns :automatedtester from comment #1)
> I have emailed the Google TL for webdriver for help on how they implemented
> it.

Implemented the platform bits or the stuff in WebDriver? I doubt that the precise details of their data collection machinery is relevant to us, since we would presumably use the existing machinery we use for devtools. That part will take some sorting out, but more likely with overholt/santell.


> Once I know more I will update.
> 
> I suspect that they are doing something that is not specified somewhere so
> getting parity is going to be a lot of work.

I don't follow this. It seems like the log format is somewhat free-form with various self-reported categories of what's going on in the timeline. We just need to mimic the log format with the data that we get from our devtools machinery.

Comment 4

[David Burns :automatedtester]

(In reply to Bobby Holley (busy) from comment #3)
> (In reply to David Burns :automatedtester from comment #1)
> > I have emailed the Google TL for webdriver for help on how they implemented
> > it.
> 
> Implemented the platform bits or the stuff in WebDriver? I doubt that the
> precise details of their data collection machinery is relevant to us, since
> we would presumably use the existing machinery we use for devtools. That
> part will take some sorting out, but more likely with overholt/santell.
> 

The WebDriver pieces. We havent implemented any of the logging stuff and from WebDriver there are potentially differences that we may do. THere are levels etc we need to take into account. While I can try reverse engineer, it would be significantly quicker to be able to "port" what they are doing by looking at their code.

> 
> > Once I know more I will update.
> > 
> > I suspect that they are doing something that is not specified somewhere so
> > getting parity is going to be a lot of work.
> 
> I don't follow this. It seems like the log format is somewhat free-form with
> various self-reported categories of what's going on in the timeline. We just
> need to mimic the log format with the data that we get from our devtools
> machinery.

If its free form, how do we give them an interopable solution or is this something that we don't need to worry about. I have no skin in the game but if we are going to offer them something we should do it in spirit of Webdriver which allows write once and run against multiple browsers.

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

David, have you heard anything back from Google?
What could Gecko platform report here and where should it be reported?

Do you happen to have link to Chrome relevant code?

But anyhow, could our WebDriver use javascript.options.mem.notify and then add observer for
"cycle-collection-statistics" and "garbage-collection-statistics"  ?
That should give json like
{"type":"cycle-collection-statistics","data":{"timestamp":1449097972111,"duration":37,"max_slice_pause":4,"total_slice_pause":7,"max_finish_gc_duration":0,"max_sync_skippable_duration":0,"suspected":106,"visited":{"RCed":1026,"GCed":4042},"collected":{"RCed":80,"GCed":577},"waiting_for_gc":577,"zones_waiting_for_gc":0,"short_living_objects_waiting_for_gc":6,"forced_gc":0,"forget_skippable":{"times_before_cc":8,"min":0,"max":1,"avg":1,"total":8,"removed":601}}}

(of that, max_slice_pause is probably the most interesting bit)

Comment 6

[David Burns :automatedtester]

(In reply to Olli Pettay [:smaug] from comment #5)
> David, have you heard anything back from Google?

I did and sorry for not adding it here.

> What could Gecko platform report here and where should it be reported?

Chrome are reporting a few items described in https://sites.google.com/a/chromium.org/chromedriver/logging/performance-log and was told I could get more details from https://www.chromium.org/developers/how-tos/trace-event-profiling-tool

> 
> Do you happen to have link to Chrome relevant code?

I was just given a link to https://code.google.com/p/chromium/codesearch#chromium/src/chrome/test/chromedriver/performance_logger.cc for the webdriver stuff. I wasnt given more, and havent had time to dive into this more.

> 
> But anyhow, could our WebDriver use javascript.options.mem.notify and then
> add observer for
> "cycle-collection-statistics" and "garbage-collection-statistics"  ?
> That should give json like
> {"type":"cycle-collection-statistics","data":{"timestamp":1449097972111,
> "duration":37,"max_slice_pause":4,"total_slice_pause":7,
> "max_finish_gc_duration":0,"max_sync_skippable_duration":0,"suspected":106,
> "visited":{"RCed":1026,"GCed":4042},"collected":{"RCed":80,"GCed":577},
> "waiting_for_gc":577,"zones_waiting_for_gc":0,
> "short_living_objects_waiting_for_gc":6,"forced_gc":0,"forget_skippable":
> {"times_before_cc":8,"min":0,"max":1,"avg":1,"total":8,"removed":601}}}
> 
> (of that, max_slice_pause is probably the most interesting bit)

This can easily be added and will be added as a new item (if we have timeline, page, network and trace) called gc/cc. All logging, like the chromium implementation, would be turned off by default and would require a capability to turn them on. Sound good?

Comment 7

[David Burns :automatedtester]

Just came across https://docs.google.com/document/d/1QADiFe0ss7Ydq-LUNOPpIf6z4KXGuWs_ygxiJxoMZKo/edit which gives more of an explainer and points to some code.

Comment 8

[David Burns :automatedtester]

so, the missing piece here really is knowing where to get this information or is the item that smaug mentioned in comment 5 enough?

Comment 9

[Bobby Holley (:bholley)]

(In reply to David Burns :automatedtester from comment #8)
> so, the missing piece here really is knowing where to get this information
> or is the item that smaug mentioned in comment 5 enough?

I think we probably want more than that, in particular styling, reflow, and painting.

In the thread "Exposing Performance Timeline Information via WebDriver and JS", Jordan Santell said:

> There are performance APIs[0] similar to the frame timing API mentioned for
> user-created measurements in content, and an extension of that was worked on for
> Firefox OS's perf team for use with Raptor for gecko  -- I thought that landed,
> but looks like it's been dropped[1]. What the goal was to create performance
> markers accessible via content for gecko things like reflow, paint, etc., which
> sounds like it might fit the ticket. I'm sure there's overhead for this, and in
> general, the performance API only stores the most recent 150 entries for that
> reason (IIRC).
>
> For the devtools performance/profiler tools, there is unfortunately some
> overhead due to realtime streaming of the markers to parent process (something
> we've discussed about eliminating for that reason), but this information isn't
> accessible via content. We've looked into ways of scripting performance for CI
> use cases, running a test case and dumping out the profile data to a file for
> post analysis, and if this is something of interest, we can take another look at
> it, and see if maybe a prototype addon can do something like this, but still not
> accessible from content, but if a test could spin up firefox with an addon, then
> we could dump results to a file, run analysis on the profile and use the output
> for regression tracking, etc.. as a pipe dream, provide a CLI for parsing
> devtools perf profiles for this very reason.

It sounds like we probably want some sort of unified processing and marshalling of this information between devtools, the WebDriver stuff, and the future DOM-accessible timeline stuff. It's nontrivial, and so somebody will need to own it.

Comment 10

[Olli Pettay [:smaug][[e-mail]]]

It is hard from platform side to fix this unless we know how WebDriver could get access to the data.
Like, can WebDriver just read stdout or what? Or should one pass the data to some certain network address?

And where did the requirement to access this via content comes from?

Comment 11

[David Burns :automatedtester]

(In reply to Olli Pettay [:smaug] from comment #10)
> It is hard from platform side to fix this unless we know how WebDriver could
> get access to the data.
> Like, can WebDriver just read stdout or what? Or should one pass the data to
> some certain network address?

Webdriver, our implementation is Marionette, has access to XPCOM interfaces so as long as the APIs are available for us to call from that context we can marshall it to something that we can then send over the wire (Devtools protocol) back to a client (Python, Ruby, .NET, Java, JS, <insert any language that can serialize JSON>)

 

> 
> And where did the requirement to access this via content comes from?

Comment 12

[Potch [:potch]]

Seeing additional use-cases for large-scale automation in the wild.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

OK, asking again. Where should the data (and what kind of data) be reported?
Would it be ok to have some generic service running in Gecko process and notify it about various
states and then some callback (implemented by marionette) would get called?
Or perhaps we could use some kind of global PerformanceObserver here? https://www.w3.org/TR/performance-timeline-2/#the-performanceobserver-interface

I'm investigating if PerformanceObserver could be used as the DOM API for this stuff, though, the
non-DOM-API part could have much more precise information, since it doesn't have privacy limitations.

Comment 14

[David Burns :automatedtester]

(In reply to Olli Pettay [:smaug] from comment #13)
> OK, asking again. Where should the data (and what kind of data) be reported?
> Would it be ok to have some generic service running in Gecko process and
> notify it about various
> states and then some callback (implemented by marionette) would get called?
> Or perhaps we could use some kind of global PerformanceObserver here?
> https://www.w3.org/TR/performance-timeline-2/#the-performanceobserver-
> interface
> 

What the user is going to do is in their Selenium/WebDriver test is (in Java, other languages have similar semantics)

DesiredCapabilities cap = DesiredCapabilities.firefox();
LoggingPreferences logPrefs = new LoggingPreferences();
logPrefs.enable(LogType.PERFORMANCE, Level.ALL);
cap.setCapability(CapabilityType.LOGGING_PREFS, logPrefs);
WebDriver driver = new FirefoxDriver(cap)

And then in newSession (https://dxr.mozilla.org/mozilla-central/source/testing/marionette/listener.js#309) we will just check for the logging prefs and enable _some_ observer that someone suggests (be it the performance observer) and then whenever someone calls getLogs() we just pull data from the observer and clear some internal state so we have a clean log for the next getLogs() call.

Comment 15

[:Harald Kirschner :digitarald]

ni? benwa. Should we start with a command line flag that writes gecko performance profiles to disk?

Comment 16

[Andreas Tolfsen ❲:ato❳]

FWIW I don’t think it’s unreasonable to expose something that exposes existing web platform primitives, like what is offered by Performance Timeline (https://www.w3.org/TR/performance-timeline-2/#the-performanceobserver-interface) as an extension command in WebDriver:

    http://w3c.github.io/webdriver/webdriver-spec.html#protocol-extensions

This would practically mean adding an endpoint to GET /session/{session id}/moz/performance (or a better name) in geckodriver (https://github.com/mozilla/geckodriver) adding a new command to Marionette (https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/driver.js#L2733).

Comment 17

[Andreas Tolfsen ❲:ato❳]

My point is that cross browser conformance towards a performance API in WebDriver will not happen before the base specification is complete.  Iterating in the vendor-prefixed realm of the protocol until it is and we have consolidated efforts with other implementations makes some sense.

Comment 18

[David Burns :automatedtester]

(In reply to Andreas Tolfsen ‹:ato› from comment #16)
> FWIW I don’t think it’s unreasonable to expose something that exposes
> existing web platform primitives, like what is offered by Performance
> Timeline
> (https://www.w3.org/TR/performance-timeline-2/#the-performanceobserver-
> interface) as an extension command in WebDriver:
> 
>     http://w3c.github.io/webdriver/webdriver-spec.html#protocol-extensions
> 
> This would practically mean adding an endpoint to GET /session/{session
> id}/moz/performance (or a better name) in geckodriver
> (https://github.com/mozilla/geckodriver) adding a new command to Marionette
> (https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/driver.
> js#L2733).

This doesnt allow us to have any form of interop with ChromeDriver which is using the WebDriver logging API.

Comment 19

[Andreas Tolfsen ❲:ato❳]

(In reply to David Burns :automatedtester from comment #18)
> This doesnt allow us to have any form of interop with ChromeDriver which is
> using the WebDriver logging API.

In fairness, the API you’re referring to is Chrome-specific and not one vendors have reached consensus around.  It sounds like people above are requesting things not currently exposed in that API, and things that are potentially Gecko-specific.

It might be good to clarify if the incentive here is to be Chrome compatible and/or expose an RPC service for arbitrary observers.

Comment 20

[David Burns :automatedtester]

(In reply to Andreas Tolfsen ‹:ato› from comment #19)
> (In reply to David Burns :automatedtester from comment #18)
> > This doesnt allow us to have any form of interop with ChromeDriver which is
> > using the WebDriver logging API.
> 
> In fairness, the API you’re referring to is Chrome-specific and not one
> vendors have reached consensus around.  It sounds like people above are
> requesting things not currently exposed in that API, and things that are
> potentially Gecko-specific.
> 
> It might be good to clarify if the incentive here is to be Chrome compatible
> and/or expose an RPC service for arbitrary observers.

Comment 0 is asking for something compatible so that the angular team can use their current WebDriver tests to get data out of Gecko.

Comment 21

[:Harald Kirschner :digitarald]

> Comment 0 is asking for something compatible so that the angular team can use their current WebDriver tests to get data out of Gecko.

I would not block on that. Facebook said they are fine doing a custom parser for our output. For other use cases don't have specific requirements yet how far we'd need to match Chrome's output, which we can file follow up tasks for.

Comment 22

[Benoit Girard (:BenWa)]

(In reply to Harald Kirschner :digitarald from comment #15)
> ni? benwa. Should we start with a command line flag that writes gecko
> performance profiles to disk?

We can, I'm not sure it would accomplish what this bug is trying to do however. There's value in implementing this to compatible to the ChromeDriver if we can.

Comment 23

[:Harald Kirschner :digitarald]

Vladan for input on what kind of data they'd need.

Comment 24

[:Harald Kirschner :digitarald]

I asked for input on the Facebook-Mozilla mailing list.

Comment 25

[joelb]

We (Facebook) use Chrome's data to give us the exclusive time for different event categories between the start of the request and a console.timeStamp event.

To do this we need data for:
-An event that signals the starting point of the request.
-console.timeStamp events. We use these to mark the events in a page load that we care about.
-start, durations, and parent/child relationships between blocks, and their categories. Example event (doesn't have to follow this format at all; just trying to make it clear what data we're using):
  {
    id: 200,
    title: 'Layout',
    duration: 110,
    start: 5,
    parent_id: 7,
  }

Our result table looks something like this:
| Category                | Request Start->Display Done 
| V8.Execute	          | 562.6774 ms
| V8.ParseLazyMicroSeconds| 128.2143 ms
| UpdateLayoutTree	  | 66.6008 ms
(many more rows)
The important thing here is that all the events (including the timestamps) need to be on the same clock, so we can figure out what comes before/after a timestamp.



Re: whether or not to follow Chrome's format. Chrome's implementation is simply sending down the buffer of events captured using Chrome's tracing tools. (chrome://tracing/ to see this). This is nice, since with only a couple lines of code, we can open up a trace captured with Webdriver in the chrome tracing tool. If Firefox has any tooling built on the current format already, it would be nice to not change the format to match Chrome when sending it via Webdriver. That way we could open up a trace in existing Firefox tools.

Comment 26

[:Harald Kirschner :digitarald]

Bouncing back to Bobby as he has the best overview. This keeps sitting between teams without clear owner. Just to break it down, what would be a tangible next step?

Comment 27

[:Harald Kirschner :digitarald]

Just chatted with Bobby that smoug would be the right person to drive this forward.

:smaug, did the details for the specific use case help or should we try to clarify further?

Comment 28

[:Harald Kirschner :digitarald]

Just to unblock this, would a simple solution be to just start Firefox with an environment flag that triggers writing the profile data to hard drive?

Comment 29

[Benoit Girard (:BenWa)]

This already works:
MOZ_PROFILER_STARTUP=true MOZ_PROFILER_SHUTDOWN=prof.dat /Applications/FirefoxNightly.app/Contents/MacOS/firefox

Excepts that it looks like we have a crash regression that would need to be fixed first: bug 1290199

Comment 30

[:Harald Kirschner :digitarald]

The customer for this is Facebook's project BrowserLab: https://code.facebook.com/posts/1368798036482517/browserlab-automated-regression-detection-for-the-web/

Comment 31

[:Harald Kirschner :digitarald]

fyi, I saw in an email that devtools focusses on Firefox as CI tool. This blocks Facebook and others from getting performance data from Firefox via WebDriver.

Comment 32

[Bryan Clark (DevTools PM) [:clarkbw]]

We are interested in getting Firefox to work better with CI tools.

Adding Greg, who is working on the perf tools these days, any thoughts here?  Or anyone else who could help?

Comment 33

[Greg Tatum [:gregtatum]]

I've been mainly working on the client-side of the performance tools, which means I already have full access to the profiling data. I haven't worked much on the source of the information. However, the perf data comes from the nsIProfiler which has a JS interface. Also I've not played with Marionette or anything in that space, so my knowledge isn't that great for the actual requirements for implementing something like this. But if you can grab access to the nsIProfiler interface from Marionette, you should be able to expose the data as needed.

A good example implementation is the gecko profiler add-on drives the profiler like so:
https://github.com/bgirard/Gecko-Profiler-Addon/blob/master/src/lib/main.js#L348-L507

The devtools' implementation is found here, although it's subject to a lot more complexity due to the remote debugging protocol.
https://dxr.mozilla.org/mozilla-central/source/devtools/server/performance/profiler.js


There might be some additional information you would want that could come from other internal services, but once the basics of the profiler interface was in place, the groundwork should be in place to expose that data.

Comment 34

[Andreas Tolfsen ❲:ato❳]

(In reply to Greg Tatum [:gregtatum] [@gregtatum] from comment #33)
> Also I've not played with Marionette
> or anything in that space, so my knowledge isn't that great for the actual
> requirements for implementing something like this. But if you can grab
> access to the nsIProfiler interface from Marionette, you should be able to
> expose the data as needed.

Marionette is a remote automation protocol over TCP and the implementation is an add-on which lives in chrome space, with full access to Gecko internals.  nsIProfiler is accessible and can be exposed as a service.

You will find the relevant server code under testing/marionette.

Comment 35

[:Harald Kirschner :digitarald]

We just met with another partner who uses ember and their developer tooling and performance regression monitoring uses webdriver + performance traces from Chrome. They can not get that data from Firefox at the moment.

This seems to be blocked on falling between teams. The major and most domain-specific work seems to be adding the feature to webdriver; correct me if I am wrong.

:ato, there are some docs on starting and capturing profiler data: https://github.com/devtools-html/perf.html/blob/master/docs/profile-data.md . :mstange can be also pinged to provide more details.

Comment 36

[David Burns :automatedtester]

Unfortunately, from a Marionette point of view, this is low priority. 

Is there someone you can suggest to do the work, we can easily help mentor to get the work done but we are playing catchup to make sure that we have full webdriver compat. 

Once we have all the pieces to move everyone over to Marionette we can re-evaluate where we are if you can't suggest someone to do the work.

Comment 37

[:Harald Kirschner :digitarald]

I understand that there might be bigger compat work. I don't have the whole picture, but so far have not heard a lot of use cases that are blocked by missing WebDriver support but, as mentioned in the bug, we heard from a few cases that don't include Firefox in their performance regression tests because of this issue.

Comment 38

[David Burns :automatedtester]

(In reply to :Harald Kirschner :digitarald from comment #37)
> I understand that there might be bigger compat work. I don't have the whole
> picture, but so far have not heard a lot of use cases that are blocked by
> missing WebDriver support but, as mentioned in the bug, we heard from a few
> cases that don't include Firefox in their performance regression tests
> because of this issue.

I have been speaking to all the major users of webdriver. The bugs that we are focused on currently are what are stopping them from moving over. I have been speaking to Google, Salesforce and similarly large companies.

I am focused on Google's 20000+ WebDriver tests, not just the angular team. Same with Salesforce and other companies. 

Also, from a look at the Selenium/GeckoDriver issue tracker, the need for this is super low except perhaps for the groups that you speaking to.

When we have finished our keep bits of work I am happy to re-evaluate. If you are able to give me an engineer, we can see about getting this work done sooner.

Comment 39

[Peter Hedenskog]

We (Wikimedia) have in our pipeline (https://phabricator.wikimedia.org/T153069) to implement a Facebook style performance inspector (as described by joelb) for the Chrome trace log and it would be really cool if we also could include Firefox, so we are not dependent on only one vendor.

This will also help us with sitespeed.io to get more useful information out of Firefox (and WebPageTest too I guess) and that would be really nice.

Comment 40

[Greg Tatum [:gregtatum]]

This bug has been around for awhile, so since it's been updated to P1, I'd like to update the current state of our performance tooling. Currently we're in the process of unifying Cleopatra and the devtools perf tool with the perf.html project:

repo: https://github.com/devtools-html/perf.html
UI example: https://perfht.ml/2tpqjE2

The TLDR is that perf.html is definitely interested in helping support this workflow. The data we support comes exclusively from the Gecko Profiler. If this data is dumped from WebDriver, and we can find a process for getting it into the perf.html web app, then we could display that information.

In the future I would also like to provide a programmatic API for asking questions about the profile: https://github.com/devtools-html/perf.html/issues/416

Also I added a tracking issue for any work we need on the perf.html side: https://github.com/devtools-html/perf.html/issues/417

Comment 41

[:Harald Kirschner :digitarald]

Summarizing a chat I had with :dburns during the all hands: just returning the raw results for the Gecko profiler JSON (already symbolicated) is a great initial target.

As most use cases for this are extracting time slices per platform component (JS, Parsing, Styling, etc), Chrome-specific trace processing can be matched with scripts that extract similar information from the profiler JSON.

Comment 42

[Peter Hedenskog]

Any chances this can be prioritized now when Quantum is out? It would really help us to have a better understanding of what's happening when we have a regression in our synthetic testing.

Comment 43

[Henrik Skupin [:whimboo][⌚️UTC+1]]

As long as this isn't baked into the spec and implemented in our tools, you might want to have a look at https://hacks.mozilla.org/2017/11/comparing-browser-page-load-time-an-introduction-to-methodology/. They were using Selenium for that.

Comment 44

[:Harald Kirschner :digitarald]

Their methodology does only read out navigation timing from the page but does not capture platform performance data; which makes performance testing and regression monitoring much more actionable.

Comment 45

[Peter Hedenskog]

Yep, we have nav timings and visual metrics, but it is still hard to actually know what's going on under the hood and our main goal is to find regressions earlier and help developers to know what's going on. 

For Firefox we know when we have a regression in first visual change or Speed Index, but we have no way (as I know of) to go deeper into the problem in an automated way. For Chrome we collect the devtools.timeline data, both so we can graph it and for devs to drag and drop into devtools to deeper understand what's wrong. Would love if we could do the same for Firefox.