1466518 - Save current time as profile creation time during startup if necessary

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[Jan-Erik Rediger [:janerik]]

Bug 1449739 already contained a patch changing the semantics of the recorded profile creation date from using file timestamps in the profile directory to the current time during startup.

However, as the profile creation date has potentially a lot of users in the pipeline already, we will use a less intrusive way first:

We record the startup time as an additional value ("Profile Creation Date v2"), only if not already known.
In the pipeline we can then analyze the different values we see to make a final decision on a final solution eventually.

Comment 1

[Phabricator Automation]

Attachment: Bug 1466518 - Store read timestamp in the correct instance variable.

The rest of the code was using `this._times`, whereas this used a
different variable, leading to the file being read everytime.

MozReview-Commit-ID: FfpTtoQZYxV

Bug 1466518 - Store current timestamp as profile creation date v2 on directory scan.

MozReview-Commit-ID: 6sQW8ffmfAY

Comment 2

[Phabricator Automation]

Attachment: Bug 1466518 - Store read timestamp in the correct instance variable.

The rest of the code was using `this._times`, whereas this used a
different variable, leading to the file being read everytime.

Comment 3

[Phabricator Automation]

Attachment: Bug 1466518 - Store current timestamp as profile directory scan date in a scalar.

Depends on D1577

MozReview-Commit-ID: ADAXwJlIVQN

Comment 4

[Jan-Erik Rediger [:janerik]]

As previously stated already[1], we currently store the profile creation date when a profile is created through normal ways, but not if the profile directory already exists.
In that case we scan the files for creation/modification times and we see the large gap between the assumed creation date and the first appearance in the pipeline.

The idea here is to also store the time we actually initiate such a profile directory scan (these are requested early during startup with a new profile anyway). This is likely also not the real creation date, but gives us another data point to work from.

By using an additional field, we're not changing the current semantics of the profile creation date field.

ni? :mreid, :amiyaguchi, :gfritzsche
Does this make sense? Will this give us a better understanding of profile creations or just shift the error over to the new data point?

[1]: https://bugzilla.mozilla.org/show_bug.cgi?id=1449739#c10

Comment 5

[Mark Reid [:mreid]]

> This is likely also not the real creation date

Can you expand on this a bit? As I understand it, this is expected to be the first-run date of a new profile. When would that be different from the creation date?

Comment 6

[Phabricator Automation]

Comment on attachment 8984067 [details]
Bug 1466518 - Store read timestamp in the correct instance variable.

Chris H-C :chutten has approved the revision.

https://phabricator.services.mozilla.com/D1577

Comment 7

[Jan-Erik Rediger [:janerik]]

:mreid:
This runs when we encounter a missing times.json in the profile directory. We don't know whether that is an actual new profile started with an existing profile directory (containing some old files, whether those are profile file we don't know) or just a very old copied/migrated profile that gets reused.

Comment 8

[Phabricator Automation]

Comment on attachment 8984068 [details]
Bug 1466518 - Store current timestamp as profile directory scan date in a scalar.

Chris H-C :chutten has approved the revision.

https://phabricator.services.mozilla.com/D1578

Comment 9

[Anthony Miyaguchi [:amiyaguchi]]

:janerik We can probably look at the difference between the profile directory scan date and profile creation date, the same way we look at the client and server document timestamps.

Looking at nightly 62 distribution of the PROFILE_DIRECTORY_FILE_AGE [1], this new variable may give us the same information in a more direct way. There's no real way to find out until we look at the data in context. 


[1] https://mzl.la/2H8eibn

Comment 10

[Georg Fritzsche [:gfritzsche]]

(In reply to Anthony Miyaguchi [:amiyaguchi] from comment #9)
> Looking at nightly 62 distribution of the PROFILE_DIRECTORY_FILE_AGE [1],
> this new variable may give us the same information in a more direct way.
> There's no real way to find out until we look at the data in context. 
> 
> 
> [1] https://mzl.la/2H8eibn

This is a prerelease probe.
Is data from Beta instead of Release sufficient to use this for diagnosis?

Comment 11

[Jan-Erik Rediger [:janerik]]

Even though PROFILE_DIRECTORY_FILE_AGE is only prerelease, it already shows that we indeed see old files (and thus the code is doing what we expect it to do).
With the proposed patch we get the profile scan date in all pings (as it is not a scalar and thus not enabled/disabled based on prerelease/release). Should we change that and make it a proper scalar instead (then making it a release probe)?

Comment 12

[Jan-Erik Rediger [:janerik]]

Attachment: data-review-request-1466518.txt

Comment 13

[Chris H-C :chutten]

Comment on attachment 8987053 [details]
data-review-request-1466518.txt

DATA COLLECTION REVIEW RESPONSE:

    Is there or will there be documentation that describes the schema for the ultimate data set available publicly, complete and accurate?

Yes, the in-tree docs are being updated in this patch and will live here: https://firefox-source-docs.mozilla.org/toolkit/components/telemetry/telemetry/data/environment.html

    Is there a control mechanism that allows the user to turn the data collection on and off? 

Yes, standard Telemetry mechanisms apply.

    If the request is for permanent data collection, is there someone who will monitor the data over time?

Yes, jan-erik.

    Using the category system of data types on the Mozilla wiki, what collection type of data do the requested measurements fall under?

Category 1

    Is the data collection request for default-on or default-off?

Default on

    Does the instrumentation include the addition of any new identifiers (whether anonymous or otherwise; e.g., username, random IDs, etc. See the appendix for more details)?

No.

    Is the data collection covered by the existing Firefox privacy notice? 

Yes.

    Does there need to be a check-in in the future to determine whether to renew the data? 

No. Though all permanent data collection should be under annual Data Stewardship review.

---
Result: datareview+

Comment 14

[Mark Reid [:mreid]]

(In reply to Jan-Erik Rediger [:janerik] from comment #7)
> :mreid:
> This runs when we encounter a missing times.json in the profile directory.
> We don't know whether that is an actual new profile started with an existing
> profile directory (containing some old files, whether those are profile file
> we don't know) or just a very old copied/migrated profile that gets reused.

Ah, ok. This makes sense to me!

Comment 15

[Chris H-C :chutten]

(In reply to Jan-Erik Rediger [:janerik] from comment #11)
> Even though PROFILE_DIRECTORY_FILE_AGE is only prerelease, it already shows
> that we indeed see old files (and thus the code is doing what we expect it
> to do).
> With the proposed patch we get the profile scan date in all pings (as it is
> not a scalar and thus not enabled/disabled based on prerelease/release).
> Should we change that and make it a proper scalar instead (then making it a
> release probe)?

(( summarized from conversations we had on IRC and during the packing meeting ))

It depends on how you see this being used. If this, or something very similar to this, is likely to be a long-term supplement to profileCreationDate, then we can put it in the environment because pings with environments want to say how old the profile is. If the scan date is important information about that, it should be there.

If we're not sure just yet, consider using a Scalar instead (with a short expiry. Great or Dead) to mark only the subsessions in which a directory scan occurred. With some data collected via this scalar we can analyse the incidences where the dates differ and decide how to proceed (maybe even overwriting profileCreationDate itself, if it proves -that- useful).

Sound like a plan?

Also, before shipping this collection it might be prudent to run some analysis on the existing collections. We're seeing up to 8 profile dir scans per subsession from a small number of clients: https://mzl.la/2Kcctjs. It might be nice to explore what we can learn from existing collection first.

Comment 16

[Jan-Erik Rediger [:janerik]]

I went ahead and changed the code to use an expiring scalar to record the scan date (and adjust the docs accordingly).

I did some analysis on the available nightly data. In 1600 pings containing the PROFILE_DIRECTORY_FILE_AGE histogram with some values, 31 of them were duplicated (by client id), that's 1.9%. These 31 duplicated pings are from 13 distinct client ids. 

The data collection review should still apply. ni?chutten to confirm

Comment 17

[Jan-Erik Rediger [:janerik]]

Re multiple profile dir scans: These can happen on a single session when the profile age is requested at multiple locations asynchronously at the same time. `ProfileAge` will scan the directory multiple times, the `times.json` might be written multiple times as well (but never be in an invalid state because it's atomically written). This should not be a problem in general (scans should be at roughly the same time, so the time frame for new files with old timestamps to occur should be small)

Re analysis: I see wildly different values for the PROFILE_DIRECTORY_FILE_AGE histogram for pings with the same client ids. This could mean that a client id is indeed reused across different profiles (e.g. cloned profiles) with different profile directories.
(I also see some pings without a profile creation date in the data)

Comment 18

[Chris H-C :chutten]

The data collection review may apply, yes, with the following amendment:

---

The collection is no longer permanent, so :janerik will be responsible for removing or renewing the probe before it expires in 64.

---

...which means reviewing that within the next few weeks, since we're already on 63. I'm not even sure we'll send you an email warning you that it's going to expire.

Comment 19

[Jan-Erik Rediger [:janerik]]

You are right. Would it makes sense to extend it to 65 right away?
I'd like this to also get uplifted to beta soon, so we can collect a bit more data to work with.

Comment 20

[Chris H-C :chutten]

65's fine. "current version + 5" is typical for temporary collections... but if you don't need 6 months of data, then shorter terms are even better.

Comment 21

[Jan-Erik Rediger [:janerik]]

I'd like to see a much quicker decision here, so I'm going with 65 for now.

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4342f08ca495
Store read timestamp in the correct instance variable. r=chutten

Comment 23

[Cristina Coroiu [:ccoroiu]]

https://hg.mozilla.org/mozilla-central/rev/4342f08ca495

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d2afa568a6ba
Store current timestamp as profile directory scan date in a scalar. r=chutten

Comment 25

[Tiberius Oros[:tiberius_oros]]

Backed out changeset d2afa568a6ba (bug 1466518) for linting opt failure

Backout: https://hg.mozilla.org/integration/autoland/rev/b99d3e57ea6fad840498914eda94f6bec4b2b12f
Push with failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=d2afa568a6baab6c7b41041697922080b6c725d4
Failure log file: https://treeherder.mozilla.org/logviewer.html#?job_id=185728656&repo=autoland&lineNumber=262

Snippet with the failure:
[task 2018-06-30T10:18:39.714Z] x86_64-linux-gnu-gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -Wdate-time -D_FORTIFY_SOURCE=2 -g -fstack-protector-strong -Wformat -Werror=format-security -Wl,-Bsymbolic-functions -Wl,-z,relro -Wdate-time -D_FORTIFY_SOURCE=2 -g -fstack-protector-strong -Wformat -Werror=format-security build/temp.linux-x86_64-2.7/psutil/_psutil_common.o build/temp.linux-x86_64-2.7/psutil/_psutil_posix.o -o build/lib.linux-x86_64-2.7/psutil/_psutil_posix.so
[task 2018-06-30T10:18:39.714Z] copying build/lib.linux-x86_64-2.7/psutil/_psutil_linux.so -> psutil
[task 2018-06-30T10:18:39.714Z] copying build/lib.linux-x86_64-2.7/psutil/_psutil_posix.so -> psutil
[task 2018-06-30T10:18:39.714Z] 
[task 2018-06-30T10:18:39.714Z] Error processing command. Ignoring because optional. (optional:packages.txt:comm/build/virtualenv_packages.txt)
[task 2018-06-30T10:23:51.881Z] TEST-UNEXPECTED-ERROR | /builds/worker/checkouts/gecko/toolkit/modules/ProfileAge.jsm:123:55 | Missing semicolon. (semi)
[taskcluster 2018-06-30 10:23:52.170Z] === Task Finished ===
[taskcluster 2018-06-30 10:23:52.170Z] Unsuccessful task run with exit code: 1 completed in 576.534 seconds

Comment 26

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d7beba7d8251
Store current timestamp as profile directory scan date in a scalar. r=chutten

Comment 27

[Bogdan Tara[:bogdan_tara | bogdant]]

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

Comment 28

[Jan-Erik Rediger [:janerik]]

Comment on attachment 8984067 [details]
Bug 1466518 - Store read timestamp in the correct instance variable.

Approval Request Comment
[Feature/Bug causing the regression]: 
This bug (larger issue: 1449739)
[User impact if declined]: 
None, but we wouldn't get enough data to act on the underlying problem
[Is this code covered by automated tests?]:
Yes, as part of Telemetry tests
[Has the fix been verified in Nightly?]: 
Yes
[Needs manual test from QE? If yes, steps to reproduce]: 
No
[List of other uplifts needed for the feature/fix]: 
Next patch in this bug
[Is the change risky?]: 
No
[Why is the change risky/not risky?]: 
Only a rename of a variable. The old code is doing work more often than necessary.
[String changes made/needed]:
No

Comment 29

[Jan-Erik Rediger [:janerik]]

Comment on attachment 8984068 [details]
Bug 1466518 - Store current timestamp as profile directory scan date in a scalar.

Approval Request Comment
[Feature/Bug causing the regression]:
This bug (larger issue: 1449739)
[User impact if declined]:
None, but we wouldn't get enough data to act on the underlying problem
[Is this code covered by automated tests?]:
Yes, as part of Telemetry tests
[Has the fix been verified in Nightly?]:
Yes
[Needs manual test from QE? If yes, steps to reproduce]: 
No
[List of other uplifts needed for the feature/fix]:
See above
[Is the change risky?]:
No
[Why is the change risky/not risky?]:
Not risky as it only records a single new scalar probe
[String changes made/needed]:
No

Comment 30

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8984067 [details]
Bug 1466518 - Store read timestamp in the correct instance variable.

Sounds like this has worked out well in nightly, and should get the team data more quickly while potentially improving performance. OK to uplift to beta 10.

Comment 31

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/releases/mozilla-beta/rev/1b0329d27c8e
https://hg.mozilla.org/releases/mozilla-beta/rev/8ed08150ff29