1115130 - Output logging metadata from User Timing marks and measures

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[:Eli Perelman]

Decoupled performance testing on Firefox OS currently depends on reading marks and measures metadata from logging to rebuild timelines. Specifically, this is how logging currently takes place from within Gaia (in JS):

```
var message = 'Performance Entry: ' +
  entry.entryType + '|' +
  entry.name + '|' +
  entry.startTime + '|' +
  entry.duration + '|' +
  (entry.time || 0);

console.log(message);
```

When the Gecko implementation lands in bug 782751, we should have access to this same metadata in the logs, although I'm sure the format will change.

Also a note about `entry.time`: for each mark and measure created, we generate a Unix epoch via `Date.now()` in order to correlate markers between processes, e.g. between System, Homescreen, and individual apps. We would also need an epoch timestamp to be output to the logs with the rest of the standard entry metadata.

Feel free to ni? me with any questions.

Comment 1

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

From discussion with Eli on IRC:

Plan is to make the throw a message out via PR_LOG or some other logging mechanism, and it will only do so when a certain pref is set.

Also, it should attach the origin of the window requesting the mark/measure.

Comment 2

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Attachment: Patch 1 (v1) - Add log output for User Timing API

Just adds a pref and a print statement that goes to either stderr or android log, depending on the platform.

Comment 3

[GitHub Autolander Bot]

Attachment: [PullReq] qdot:1115130-user-timing-logging to mozilla-b2g:master

Comment 4

[:Eli Perelman]

Comment on attachment 8559529 [details] [review]
[PullReq] qdot:1115130-user-timing-logging to mozilla-b2g:master

r+ with nit addressed.

Comment 5

[Andrea Marchesini [:baku]]

Comment on attachment 8559519 [details] [diff] [review]
Patch 1 (v1) - Add log output for User Timing API

Review of attachment 8559519 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/base/nsPerformance.cpp
@@ +631,5 @@
>      NS_WARNING("Performance Entry buffer size maximum reached!");
>      return;
>    }
> +  if (aShouldPrint && nsContentUtils::IsUserTimingPrintingEnabled()) {
> +    nsCString uri;

nsAutoCString

@@ +632,5 @@
>      return;
>    }
> +  if (aShouldPrint && nsContentUtils::IsUserTimingPrintingEnabled()) {
> +    nsCString uri;
> +    mWindow->GetDocumentURI()->GetHost(uri);

nsresult rv = ... and check the error code.

@@ +633,5 @@
>    }
> +  if (aShouldPrint && nsContentUtils::IsUserTimingPrintingEnabled()) {
> +    nsCString uri;
> +    mWindow->GetDocumentURI()->GetHost(uri);
> +    LOG("Performance Entry: %s|%s|%s|%f|%f|%lld\n",

can you something else than LOG? I don't like the undef LOG ...

@@ +742,5 @@
>    }
>    nsRefPtr<PerformanceMeasure> performanceMeasure =
>      new PerformanceMeasure(this, aName, startTime, endTime);
> +  InsertPerformanceEntry(performanceMeasure, true);
> +  if (nsContentUtils::IsUserTimingPrintingEnabled()) {

... ?

::: dom/base/nsPerformance.h
@@ +353,4 @@
>    DOMTimeMilliSec GetPerformanceTimingFromString(const nsAString& aTimingName);
>    DOMHighResTimeStamp ConvertDOMMilliSecToHighRes(const DOMTimeMilliSec aTime);
>    void DispatchBufferFullEvent();
> +  void InsertPerformanceEntry(PerformanceEntry* aEntry, bool aShouldPrint);

this should be mozilla::dom::PerformanceEntry right?

Comment 6

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

m-i landing (with nits addressed):

https://hg.mozilla.org/integration/mozilla-inbound/rev/39f991c2bd71

Comment 7

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Gaia landing:

https://github.com/mozilla-b2g/gaia/commit/f1b506f0a708ad0d66e0331dec82256073427bc4

Comment 8

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

(In reply to Andrea Marchesini (:baku) from comment #5)
> this should be mozilla::dom::PerformanceEntry right?

It is. It gets typedef'd to PerformanceEntry in the class definition.

Comment 9

[Ryan VanderMeulen [:RyanVM]]

Backed out for Werror bustage.
https://hg.mozilla.org/integration/mozilla-inbound/rev/9eb78bb0923c

https://treeherder.mozilla.org/logviewer.html#?job_id=6316739&repo=mozilla-inbound

Comment 10

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Oops. Thought I had Werror turned on locally too, guess that wasn't the case. Fixed printf formatting, running try at 

https://tbpl.mozilla.org/?tree=Try&rev=ad41f54afbab

Comment 11

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

After more fun with printf macros and variadic macro formatting, finally passed try:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3dc913df1288
https://tbpl.mozilla.org/?tree=Try&rev=3dc913df1288

Landed to m-i:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8a97a4fd18a9

Comment 12

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/8a97a4fd18a9

Comment 13

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Comment on attachment 8559519 [details] [diff] [review]
Patch 1 (v1) - Add log output for User Timing API

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Bug 782751
User impact if declined: Raptor won't work with user timing API
Testing completed: Been in master for 6 weeks 
Risk to taking this patch (and alternatives if risky): None
String or UUID changes made by this patch: None

Comment 14

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Comment on attachment 8559529 [details] [review]
[PullReq] qdot:1115130-user-timing-logging to mozilla-b2g:master

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Bug 782751
User impact if declined: Raptor won't work with user timing API
Testing completed: Been in master for 6 weeks 
Risk to taking this patch (and alternatives if risky): None
String or UUID changes made by this patch: None

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/92d315086242

v2.2: https://github.com/mozilla-b2g/gaia/commit/a50f961a839fe2f13de951eac674cb5509ccad64