1386186 - Record firstPaint timestamp into a scalar

Status: RESOLVED FIXED

(Toolkit :: Telemetry, enhancement, P2)

Description

[Georg Fritzsche [:gfritzsche]]

The firstPaint timestamp is recorded here:
https://dxr.mozilla.org/mozilla-central/rev/36f95aeb4c77f7cf3b3366583008cd6e4b6b1dba/view/nsViewManager.cpp#362

We should also record it into a scalar.

As we will migrate other timestamps to scalars as well, we can in Scalars.yaml:
- introduce a new category "timestamps" or "timeline"
- add the new "first_paint" scalar under it

Comment 1

[Georg Fritzsche [:gfritzsche]]

As far as i know we don't have any test coverage for firstPaint yet.
We can possibly add a basic sanity check to some mochitest.

Comment 2

[Georg Fritzsche [:gfritzsche]]

We already have an existing browser test for Telemetry GC: toolkit/components/telemetry/tests/browser/browser_TelemetryGC.js
We could add a test next to it for this, say browser_TelemetryTimestamps.js.

Comment 3

[Georg Fritzsche [:gfritzsche]]

Rebecca, do you know who would own the firstPaint measurement now?

Comment 4

[[e-mail]]

No, I do not.  Consider asking :digitarald?

Comment 5

[:Harald Kirschner :digitarald]

I can own this.

Georg: Can you please clarify the request? Is this about adding tests about the firstNonBlankPaint heuristics implemented in bug 1307242?

Comment 6

[Georg Fritzsche [:gfritzsche]]

(In reply to :Harald Kirschner :digitarald from comment #5)
> Georg: Can you please clarify the request? Is this about adding tests about
> the firstNonBlankPaint heuristics implemented in bug 1307242?

For historic reasons, we have a few important measurements in sections of our "main" ping that are not well suited for automatic support.

We are currently duplicating some of these, like the timestamp for first paint, to the scalars we record, to make it easier to handle them in the future.
Note that we are not touching the current/old probe for firstPaint yet, so there is no disruption for its users (we will figure out proper migration later).

For this new firstPaint scalar we need an owner that we can list in Scalars.yaml.

Does that clear it up?

Comment 7

[Vanessa Gutierrez]

Attachment: firstPaint scalar added, equal to SM on local build. No tests, WIP

Comment 8

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 9

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8894549 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

::: toolkit/components/telemetry/Scalars.yaml
@@ +818,5 @@
> +  first_paint:
> +    bug_numbers:
> +      - 1386186
> +    description: >
> +     Load time duration for first content window paint, in milliseconds.

"Record the timestamp of the first ..."

::: toolkit/components/telemetry/tests/browser/browser.ini
@@ +2,5 @@
>  # License, v. 2.0. If a copy of the MPL was not distributed with this
>  # file, You can obtain one at http://mozilla.org/MPL/2.0/.
>  
>  [browser_TelemetryGC.js]
> +[browser_Telemetry_timestamp_test.js]

You didn't add the actual test file to this patch.

::: view/nsViewManager.cpp
@@ +367,5 @@
> +      static bool recorded = false;
> +      if(!recorded){
> +        uint32_t firstPaintTime = (int) (((TimeStamp::Now()) - TimeStamp::ProcessCreation(&error)).ToMilliseconds());
> +        if(!error){
> +          Telemetry::ScalarSet(Telemetry::ScalarID::TIMESTAMPS_FIRST_PAINT, firstPaintTime);

Ok, i think now that this is better done inside StartupTimeline.cpp:
- move RecordOnce() into StartupTimeline.cpp
- inside this function, if the event id is FIRST_PAINT, record the timestamp into this scalar

Comment 10

[Vanessa Gutierrez]

(In reply to Georg Fritzsche [:gfritzsche] from comment #9)
> ::: view/nsViewManager.cpp
> @@ +367,5 @@
> > +      static bool recorded = false;
> > +      if(!recorded){
> > +        uint32_t firstPaintTime = (int) (((TimeStamp::Now()) - TimeStamp::ProcessCreation(&error)).ToMilliseconds());
> > +        if(!error){
> > +          Telemetry::ScalarSet(Telemetry::ScalarID::TIMESTAMPS_FIRST_PAINT, firstPaintTime);
> 
> Ok, i think now that this is better done inside StartupTimeline.cpp:
> - move RecordOnce() into StartupTimeline.cpp
> - inside this function, if the event id is FIRST_PAINT, record the timestamp
> into this scalar

Do you mean move RecordOnce from StartUpTimeline.h to StartUpTimeline.cpp? Or should I check for the event id and record the timestamp to the scalar in the RecordOnce in StartUpTimeline.h?

Comment 11

[Georg Fritzsche [:gfritzsche]]

(In reply to Vanessa Gutierrez from comment #10)
> (In reply to Georg Fritzsche [:gfritzsche] from comment #9)
> > ::: view/nsViewManager.cpp
> > @@ +367,5 @@
> > > +      static bool recorded = false;
> > > +      if(!recorded){
> > > +        uint32_t firstPaintTime = (int) (((TimeStamp::Now()) - TimeStamp::ProcessCreation(&error)).ToMilliseconds());
> > > +        if(!error){
> > > +          Telemetry::ScalarSet(Telemetry::ScalarID::TIMESTAMPS_FIRST_PAINT, firstPaintTime);
> > 
> > Ok, i think now that this is better done inside StartupTimeline.cpp:
> > - move RecordOnce() into StartupTimeline.cpp
> > - inside this function, if the event id is FIRST_PAINT, record the timestamp
> > into this scalar
> 
> Do you mean move RecordOnce from StartUpTimeline.h to StartUpTimeline.cpp?

Yes.
Adding this code to `RecordOnce()` means that you have to add some include, which we should not add to StartupTimeline.h (and all its users).
To avoid this, we should move the implementation into the .cpp.

Comment 12

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 13

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8897165 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

::: toolkit/components/startup/StartupTimeline.cpp
@@ +36,5 @@
>  }
> +
> +void StartupTimeline::RecordOnce(Event ev){
> +  if (!HasRecord(ev))
> +    Record(ev);

This is already a branch for "is this the first time we are recording this.
Lets turn this into an early return if we already recorded this:
if (HasRecord(ev)) {
  return;
}

... then the rest of the function becomes much simpler.

@@ +38,5 @@
> +void StartupTimeline::RecordOnce(Event ev){
> +  if (!HasRecord(ev))
> +    Record(ev);
> +  //Record Scalar first_paint
> +  if(StartupTimeline::Describe(ev) == "firstPaint"){

Currently you would record this value more than once.
Instead of doing string comparisons here, you can directly do `ev == FIRST_PAINT` (see the definitions in StartupTimeline.h).

A more general note here:
When doing string comparisons in C++, "==" does probably not do what you expect.
It would end up comparing pointers, not the actual string values.

And a more general style note:
We use spacing between braces etc., i.e. "if (...) {" instead of "if(...){".
https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Coding_Style#Control_Structures

::: toolkit/components/telemetry/Scalars.yaml
@@ +812,5 @@
>      release_channel_collection: opt-out
>      record_in_processes:
>        - 'main'
>  
> +#The following section contains time scalars.

Nits:
- space after the "#".
- "contains probes that record timestamps."

::: toolkit/components/telemetry/tests/browser/browser_Telemetry_timestamp_test.js
@@ +18,5 @@
> +
> +const {GCTelemetry} = Cu.import("resource://gre/modules/GCTelemetry.jsm", {});
> +
> +add_task(async function test() {
> +  //Save start time.

General style comment: Add a space after "//" for all comments.

@@ +91,5 @@
> +  //Calculate browser test runtime.
> +  var endTime = new Date().getTime();
> +  var startUpTime = endTime - startTime;
> +
> +  let payload = TelemetrySession.getPayload("main");

All the code before this line seems unrelated to what we want to test.
You should remove that other code.

@@ +99,5 @@
> +    "first_paint scalar greater than 0: " + payload.processes.parent.scalars["timestamps.first_paint"]);
> +  //Check browser startup time greater than 0.
> +  ok(startUpTime > 0, "Browser test runtime is greater than zero: " + startUpTime);
> +  //Check first_paint scalar less than browser start up time.
> +  ok(payload.processes.parent.scalars["timestamps.first_paint"] < startUpTime,

I don't think `startUpTime` is what you think it is.
What this measures is how much time we spent inside the test, not how long it took to get here from browser startup.
There is a lot of initialization work happening before any of this tests code ever runs - currently that time is ignored.

We can compare this instead to `Services.telemetry.msSinceProcessStart()`.
Save the value of that as the first thing in the test - i assume this that happens to run after the first content paint.

::: view/nsViewManager.cpp
@@ +25,5 @@
>  #include "Layers.h"
>  #include "gfxPlatform.h"
>  #include "gfxPrefs.h"
>  #include "nsIDocument.h"
> +#include "mozilla/Telemetry.h"

Remove this, this is no longer needed.

@@ +358,5 @@
>        if (nsLayoutUtils::InvalidationDebuggingIsEnabled()) {
>          printf_stderr("--ENDCOMPOSITE--\n");
>        }
>  #endif
> +      //Record SimpleMeasurement firstPaint

Lets drop that comment, i don't think it adds anything here.

Comment 14

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 15

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8898046 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

Getting close!
The below are basically all style / consistency / readability comments.

::: toolkit/components/startup/StartupTimeline.cpp
@@ +38,5 @@
> +void StartupTimeline::RecordOnce(Event ev) {
> +  if (HasRecord(ev)) {
> +    return;
> +  }
> +    Record(ev);

Indentation here is off.
Style/readability: Add an empty line before this.

@@ +39,5 @@
> +  if (HasRecord(ev)) {
> +    return;
> +  }
> +    Record(ev);
> +  // Record Scalar first_paint

Style/readability: Add an empty line before this.

@@ +42,5 @@
> +    Record(ev);
> +  // Record Scalar first_paint
> +  if (ev == FIRST_PAINT) {
> +    bool error = false;
> +    uint32_t firstPaintTime = (int) (((Get(ev)) - TimeStamp::ProcessCreation(&error)).ToMilliseconds());

Some things here:
- Lets drop some parantheses, at least the ones around Get(ev).
- Why convert to int, that assign to uint32_t? If you need an explicit conversion, convert directly to uint32_t.

@@ +44,5 @@
> +  if (ev == FIRST_PAINT) {
> +    bool error = false;
> +    uint32_t firstPaintTime = (int) (((Get(ev)) - TimeStamp::ProcessCreation(&error)).ToMilliseconds());
> +    if (!error)
> +      Telemetry::ScalarSet(Telemetry::ScalarID::TIMESTAMPS_FIRST_PAINT, firstPaintTime);

Style:
Always add (curly) braces around the body of a control structure:
https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Coding_Style#Control_Structures

::: toolkit/components/telemetry/Scalars.yaml
@@ +812,5 @@
>      release_channel_collection: opt-out
>      record_in_processes:
>        - 'main'
>  
> +#The following section contains time scalars.

Nit: Missing space after #.

::: toolkit/components/telemetry/tests/browser/browser_Telemetry_timestamp_test.js
@@ +1,4 @@
> +"use strict";
> +
> +/*
> + *********************************************************************************

This whole comment block doesn't apply to this test, lets remove it.

@@ +16,5 @@
> +Cu.import("resource://gre/modules/TelemetryController.jsm", this);
> +Cu.import("resource://gre/modules/TelemetrySession.jsm", this);
> +
> +add_task(async function test() {
> +  let startUpTime = Services.telemetry.msSinceProcessStart();

Just call it "now", that seems more clear?

@@ +19,5 @@
> +add_task(async function test() {
> +  let startUpTime = Services.telemetry.msSinceProcessStart();
> +  let payload = TelemetrySession.getPayload("main");
> +
> +  // Check first_paint scalar present.

Nit: Lets avoid shortened english in the comments please and use full sentences.

@@ +21,5 @@
> +  let payload = TelemetrySession.getPayload("main");
> +
> +  // Check first_paint scalar present.
> +  ok(payload.processes.parent.scalars["timestamps.first_paint"] > 0,
> +    "first_paint scalar greater than 0: " + payload.processes.parent.scalars["timestamps.first_paint"]);

Lets do additional checks:
- "scalars" in payload.processes.parent
- "timestamp.first_paint" in ...
Without this, if this test fails later it will be harder to understand why: Is the scalar missing? Or is the value wrong?

Also, we have specific test functions for specific logical conditions. So lets use:
greater(...first_paint, 0, "message ...");

That will also already print the value if it fails, so you don't need to add it to the message.
See: https://developer.mozilla.org/en/docs/Mozilla/JavaScript_code_modules/Assert.jsm

Similarly use right functions instead of ok() below.

Comment 16

[Georg Fritzsche [:gfritzsche]]

One last thing that i missed before:
I see that there are startup browser tests already in toolkit/components/startup/tests/browser.
Lets move our test there, that is a better place.

Comment 17

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8898046 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

::: toolkit/components/telemetry/Scalars.yaml
@@ +818,5 @@
> +  first_paint:
> +    bug_numbers:
> +      - 1386186
> +    description: >
> +     Record the timestamp of the first content window paint, in milliseconds.

Digging through startup/ code i realize we need to be more clear here:
"Record the timestamp of the first content window paint, in milliseconds since process start."

Comment 18

[Vanessa Gutierrez]

(In reply to Georg Fritzsche [:gfritzsche] from comment #16)
> One last thing that i missed before:
> I see that there are startup browser tests already in
> toolkit/components/startup/tests/browser.
> Lets move our test there, that is a better place.

Do you mean move the test file into the directory or move the code into one of the files in toolkit/components/startup/tests/browser?

Comment 19

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 20

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 21

[Vanessa Gutierrez]

(In reply to Vanessa Gutierrez from comment #18)
> (In reply to Georg Fritzsche [:gfritzsche] from comment #16)
> > One last thing that i missed before:
> > I see that there are startup browser tests already in
> > toolkit/components/startup/tests/browser.
> > Lets move our test there, that is a better place.
> 
> Do you mean move the test file into the directory or move the code into one
> of the files in toolkit/components/startup/tests/browser?

I think you mean move the test file, so I've done that in the latest submit.

Comment 22

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8898535 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

::: toolkit/components/startup/StartupTimeline.cpp
@@ +42,5 @@
> +  }
> +
> +  Record(ev);
> +
> +  // Record Scalar first_paint

This should also be a full sentence.
E.g. "// Record first paint timestamp as a scalar."

::: toolkit/components/startup/tests/browser/browser_Telemetry_timestamp_test.js
@@ +6,5 @@
> +add_task(async function test() {
> +  let now = Services.telemetry.msSinceProcessStart();
> +  let payload = TelemetrySession.getPayload("main");
> +
> +  // Check that the first_paint scalar is present.

How about we make this comment into "// Check the first_paint scalar.".
That one comment would cover all the next checks.

@@ +8,5 @@
> +  let payload = TelemetrySession.getPayload("main");
> +
> +  // Check that the first_paint scalar is present.
> +  "scalars" in payload.processes.parent
> +  "timestamp.first_paint" in payload.processes.parent

Those should be expressions that you use with ok(), e.g. `ok("scalars" in ..., "Some message...")`.
I just kept it short in the comment.

@@ +11,5 @@
> +  "scalars" in payload.processes.parent
> +  "timestamp.first_paint" in payload.processes.parent
> +  greater(payload.processes.parent.scalars["timestamps.first_paint"], 0,
> +    "first_paint scalar is greater than 0.");
> +  // Check that the browser start up time is greater than 0.

This comment just repeats what the test message says, lets drop it.

@@ +13,5 @@
> +  greater(payload.processes.parent.scalars["timestamps.first_paint"], 0,
> +    "first_paint scalar is greater than 0.");
> +  // Check that the browser start up time is greater than 0.
> +  greater(now, 0, "Browser test runtime is greater than zero.");
> +  // Check that the first_paint scalar is less than the browser start up time.

"... less than the current time."
This is clear, while "start up time" is not exactly clear (and probably is understood to mean something else).

::: toolkit/components/telemetry/tests/browser/browser.ini
@@ +2,5 @@
>  # License, v. 2.0. If a copy of the MPL was not distributed with this
>  # file, You can obtain one at http://mozilla.org/MPL/2.0/.
>  
>  [browser_TelemetryGC.js]
> +[browser_Telemetry_timestamp_test.js]

You will need to undo this change and update toolkit/components/startup/tests/browser/browser.ini.

Comment 23

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 24

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 25

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8898954 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

::: toolkit/components/startup/StartupTimeline.cpp
@@ +42,5 @@
> +  }
> +
> +  Record(ev);
> +
> +  // Record first paint timestamp as a scalar. 

Nit: Trailing whitespace.

::: toolkit/components/startup/tests/browser/browser_Telemetry_timestamp_test.js
@@ +8,5 @@
> +  let payload = TelemetrySession.getPayload("main");
> +
> +  // Check the first_paint scalar.
> +  ok("scalars" in payload.processes.parent, "Scalars are present in the payload.");
> +  ok("timestamps.first_paint" in payload.processes.parent.scalars, "The first_paint timestamp is present in the payload." + payload.processes.parent.scalars);

- What is the `+ payload ...` for? Please drop it.
- This line is still pretty long, put the second argument on a new line (aligned with "timestamps...").

Comment 26

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8898954 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

Nathan, this is getting into shape now.
Do you have any concerns here or is the approach fine?

Comment 27

[Nathan Froyd [:froydnj]]

Comment on attachment 8898954 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

The StartupTimeline changes look fine.  The tests look OK, though I did not look at them closely.

Comment 28

[Georg Fritzsche [:gfritzsche]]

Per comment 5 and a clarification i gave to Harald on Slack, ownership should be settled.

Comment 29

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 30

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8898968 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

This looks good!
One whitespace fix needed.
Then you should update to the latest mozilla-central, rebase the patch and upload the new version here.
After that we can get it landed.

::: toolkit/components/startup/tests/browser/browser_Telemetry_timestamp_test.js
@@ +8,5 @@
> +  let payload = TelemetrySession.getPayload("main");
> +
> +  // Check the first_paint scalar.
> +  ok("scalars" in payload.processes.parent, "Scalars are present in the payload.");
> +  ok("timestamps.first_paint" in payload.processes.parent.scalars, 

Trailing whitespace here.

Comment 31

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 32

[Georg Fritzsche [:gfritzsche]]

Comment on attachment 8899555 [details] [diff] [review]
Added firstPaint scalar, timestamps scalar section, and tests

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

Looks good, lets push this to try.

Comment 33

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 34

[Vanessa Gutierrez]

Attachment: Added firstPaint scalar, timestamps scalar section, and tests

Comment 35

[Chris H-C :chutten]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=dd84137972f41a7a40dcfd24bbdf01a97fcb5753

Comment 36

[Vanessa Gutierrez]

(In reply to Chris H-C :chutten from comment #35)
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=dd84137972f41a7a40dcfd24bbdf01a97fcb5753

There are 11 oranges, and 5 red B's. I've looked at all the error messages, and I don't recognize any of them, nor do any seem related to the changes I made. Georg, can you take a look to be sure?

Comment 37

[Georg Fritzsche [:gfritzsche]]

Chris, can you take a look?

Comment 38

[Chris H-C :chutten]

All appear to be intermittents unrelated to the code changed in the patch.

Comment 39

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b23d59dbab75
Added firstPaint scalar, timestamps scalar section, and tests. r=gfritzsche

Comment 40

[Ryan VanderMeulen [:RyanVM]]

In the future, please make sure your patches include all necessary commit information, including name & email.

Comment 41

[Vanessa Gutierrez]

(In reply to Ryan VanderMeulen [:RyanVM] from comment #40)
> In the future, please make sure your patches include all necessary commit
> information, including name & email.

Will do! Sorry about that and thanks for the heads up.

Comment 42

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b23d59dbab75