It's possible that firstPaint may happen after the load event. Data suggests this could happen up to 5% of the time on mobile for browsers that support firstPaint. Let's find out by watching for last paint timings and reporting them in a new EventLogging schema.
Description
Description
Details
Details
Event Timeline
Comment Actions
Change 488016 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/extensions/NavigationTiming@master] Record late paint timings
Comment Actions
Change 488016 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] Record late paint timings
Comment Actions
No records yet in Hive. Either the code isn't working, or this situation never happens...
Comment Actions
Looking in logstash, we're getting plenty of EventError occurrences with: None is not of type 'integer'
{"dt": "2019-02-25T02:00:35Z", "event": {"pageviewToken": "redacted", "startTime": null}, "ip": "redacted", "recvFrom": "cp5008.eqsin.wmnet", "revision": 18849693, "schema": "PaintTiming", "seqId": 14206806, "userAgent": {"browser_family": "Chrome", "browser_major": "62", "browser_minor": "0", "device_family": "Other", "is_bot": false, "is_mediawiki": false, "os_family": "Mac OS X", "os_major": "10", "os_minor": "13", "wmf_app_version": "-"}, "uuid": "redacted", "webHost": "en.wikipedia.org", "wiki": "enwiki"}So, something in the code isn't right, as "name" is missing altogether and startTime ends up being null...
Comment Actions
Change 492607 had a related patch set uploaded (by Gilles; owner: Gilles):
[mediawiki/extensions/NavigationTiming@master] Fix observePaintTiming for loop
Comment Actions
Change 492607 merged by jenkins-bot:
[mediawiki/extensions/NavigationTiming@master] Fix observePaintTiming for loop
Comment Actions
Data is coming in:
https://grafana.wikimedia.org/d/000000018/eventlogging-schema?orgId=1&var-schema=PaintTiming
Not super common, but it happens. From what I'm seeing glancing in Hive, the values aren't extreme. They seem to be happening shortly after the load event.
This probably won't change the global paint metrics all that much, but for the sake of correctness I think we should switch to collecting paint timing that way, with the "regular" firstPaint collection going to the new schema as well.