Closed Bug 1115130 Opened 6 years ago Closed 6 years ago

Output logging metadata from User Timing marks and measures

Categories

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

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla38
Tracking Status
firefox36 --- wontfix
firefox37 --- wontfix
firefox38 --- fixed
b2g-v2.2 --- fixed
b2g-master --- fixed

People

(Reporter: Eli, Assigned: qdot)

References

Details

(Keywords: dev-doc-needed, Whiteboard: [systemsfe])

Attachments

(2 files)

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.
Whiteboard: [systemsfe]
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.
Blocks: 1129687
Just adds a pref and a print statement that goes to either stderr or android log, depending on the platform.
Attachment #8559519 - Flags: review?(amarchesini)
Attachment #8559529 - Flags: review?(eperelman)
Comment on attachment 8559529 [details] [review]
[PullReq] qdot:1115130-user-timing-logging to mozilla-b2g:master

r+ with nit addressed.
Attachment #8559529 - Flags: review?(eperelman) → review+
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?
Attachment #8559519 - Flags: review?(amarchesini) → review+
(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.
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
https://hg.mozilla.org/mozilla-central/rev/8a97a4fd18a9
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla38
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
Attachment #8559519 - Flags: approval-mozilla-b2g37?
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
Attachment #8559529 - Flags: approval-mozilla-b2g37?
Attachment #8559519 - Flags: approval-mozilla-b2g37? → approval-mozilla-b2g37+
Attachment #8559529 - Flags: approval-mozilla-b2g37? → approval-mozilla-b2g37+
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.