pageLoaded events are logged infrequently, if at all
Closed, ResolvedPublic3 Estimated Story Points
Actions

Description

Symptom

There were 5 pageLoaded Popups events logged Sunday, 4th June 2017. This is drastically low.

Cause

As the Page Previews (PP) application boots it [loads the ext.eventLogging.Schema module (asynchronous)](https://github.com/wikimedia/mediawiki-extensions-Popups/blob/master/src/index.js#L146-L150) and then [dispatches the BOOT action (synchronous)](https://github.com/wikimedia/mediawiki-extensions-Popups/blob/master/src/index.js#L152). As part of reducing the action, we create and queue a pageLoaded event for logging. The event is only logged if the eventLogging change listener is registered. Unfortunately, the change listener is registered when the module has loaded, which, if the module has been loaded from the ResourceLoader's cache, will be in the next tick of the JavaScript event loop.

This is an instance of the late subscriber problem.

Possible fix

As I suggested in T158999#3087132 and T158999#3110621, rely on [the event. mw.track protocol defined by the EventLogging extension](https://github.com/wikimedia/mediawiki-extensions-EventLogging/blob/master/modules/ext.eventLogging.subscriber.js) over the mw.eventLog.Schema class/API.

Details

	Project	Branch	Lines +/-	Subject
	mediawiki/extensions/Popups	master	+164 -93	i13n: Log EL events with mw.track

Customize query in gerrit

Related Objects
Search...

Status	Assigned	Task
Resolved	Dereckson	T68374 Enable Hovercards on se.wikimedia.org (Swedish chapter wiki)
Resolved	Jdlrobson	T70860 [GOAL] Graduate Page Previews feature (Popups extension) out of Beta Feature
Resolved	ovasileva	T154635 [EPIC] Deploy page previews to English and German Wikipedia
Resolved	ovasileva	T162672 Deploy page previews to 90% of users on all wikis but English and German
Resolved	• Tbayer	T158172 Analyze results of stage 0 page previews test
Resolved	• Tbayer	T167273 pageLoaded events are logged infrequently, if at all
Resolved	phuedx	T173422 Investigate the increase in the number of requests to Swift after the Page Previews deploy

Event Timeline

phuedx created this task.Jun 7 2017, 10:44 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 7 2017, 10:44 AM

phuedx mentioned this in T164256: pageTitleHover not set correctly in Popups schema.Jun 7 2017, 10:44 AM

ovasileva added a subscriber: ovasileva.Jun 7 2017, 10:51 AM

@ovasileva: This should probably be tackled in the next ~~sprint~~ thing.

ovasileva triaged this task as High priority.Jun 7 2017, 11:01 AM

ovasileva added a project: Readers-Web-Backlog.

ovasileva moved this task from Incoming to Upcoming on the Readers-Web-Backlog board.

phuedx updated the task description. (Show Details)Jun 7 2017, 4:16 PM

ovasileva set the point value for this task to 3.Jun 7 2017, 4:18 PM

Jhernandez updated the task description. (Show Details)Jun 7 2017, 4:18 PM

Jhernandez removed the point value for this task.

Jhernandez set the point value for this task to 3.

• Tbayer added a parent task: T158172: Analyze results of stage 0 page previews test.Jun 7 2017, 10:58 PM

Good catch! This might explain last week's observation at T165461#3305090 that the number of link interactions per pageview in the current schema (>3 in both test and control) seems much higher than the corresponding result from old instrumentation (around 1).

• Tbayer mentioned this in T165461: Various sanity checks for data from the rewritten Popups instrumentation.Jun 7 2017, 11:47 PM

ovasileva added a project: Readers-Web-Kanbanana-Board-Old.Jun 13 2017, 12:09 PM

Jdlrobson moved this task from Upcoming to 2016-17 Q4 on the Readers-Web-Backlog board.Jun 14 2017, 3:55 AM

Change 358957 had a related patch set uploaded (by Phuedx; owner: Phuedx):
[mediawiki/extensions/Popups@master] i13n: Log EL events with mw.track

https://gerrit.wikimedia.org/r/358957

gerritbot added a project: Patch-For-Review.Jun 14 2017, 1:04 PM

Sam will add SQL query to the task.

Jdlrobson moved this task from To Do to Doing on the Readers-Web-Kanbanana-Board-Old board.Jun 14 2017, 5:28 PM

ovasileva moved this task from Doing to Needs Code Review on the Readers-Web-Kanbanana-Board-Old board.Jun 14 2017, 5:29 PM

A count by date and Hovercards on/off condition:

SELECT DATE(timestamp) AS date, 
event_popupEnabled, COUNT(*)
FROM log.Popups_16364296 
WHERE MONTH(timestamp) >= 6 
AND event_action = 'pageLoaded' 
GROUP BY date, event_popupEnabled
ORDER BY date, event_popupEnabled;

+------------+--------------------+----------+
| date       | event_popupEnabled | COUNT(*) |
+------------+--------------------+----------+
| 2017-06-01 |                  1 |        3 |
| 2017-06-02 |                  0 |        2 |
| 2017-06-02 |                  1 |        3 |
| 2017-06-03 |                  0 |        4 |
| 2017-06-04 |                  0 |        3 |
| 2017-06-04 |                  1 |        2 |
| 2017-06-05 |                  0 |        2 |
| 2017-06-05 |                  1 |        2 |
| 2017-06-06 |                  0 |        1 |
| 2017-06-06 |                  1 |        1 |
| 2017-06-07 |                  0 |        1 |
| 2017-06-07 |                  1 |        3 |
| 2017-06-08 |                  0 |        2 |
| 2017-06-08 |                  1 |        4 |
| 2017-06-09 |                  0 |        2 |
| 2017-06-09 |                  1 |        2 |
| 2017-06-10 |                  0 |        1 |
| 2017-06-10 |                  1 |        1 |
| 2017-06-11 |                  0 |        2 |
| 2017-06-12 |                  0 |        3 |
| 2017-06-12 |                  1 |        3 |
| 2017-06-13 |                  0 |        2 |
| 2017-06-14 |                  0 |        2 |
| 2017-06-14 |                  1 |        4 |
+------------+--------------------+----------+
24 rows in set (13.22 sec)

Jdlrobson moved this task from Needs Code Review to Needs More Work on the Readers-Web-Kanbanana-Board-Old board.Jun 14 2017, 8:05 PM

phuedx claimed this task.Jun 15 2017, 10:13 AM

phuedx moved this task from Needs More Work to Needs Code Review on the Readers-Web-Kanbanana-Board-Old board.Jun 15 2017, 3:08 PM

@Jdlrobson: I've rebased rEPOPb972b8378b20: i13n: Log EL events with mw.track…

Change 358957 merged by jenkins-bot:
[mediawiki/extensions/Popups@master] i13n: Log EL events with mw.track

https://gerrit.wikimedia.org/r/358957

Needs technical signoff.

Verify that:

pageload events are consistently logged when you are bucketed in (see mw.trackSubscribe('event.Popups', console.log)
bucketing works per session based on sampling rate on the environment you test (subsequent page visits on the same visit, should yield events if trackSubscribe did)

Jhernandez mentioned this in T168371: eventLogging exception in Popups "Value "undefined previews" for property "previewCountBucket" is not one of ...".Jun 20 2017, 9:53 AM

ReleaseTaggerBot added a project: MW-1.30-release-notes (WMF-deploy-2017-06-20_(1.30.0-wmf.6)).Jun 20 2017, 10:00 AM

ovasileva moved this task from Backlog to In Development on the Page-Previews board.Jun 20 2017, 1:05 PM

@phuedx - there is one tiny issue with tracking PageLoaded events.

We create a pageLoaded event here - https://github.com/wikimedia/mediawiki-extensions-Popups/blob/master/src/reducers/eventLogging.js#L170 - event doesn't contain linkInteractionToken property.

Then in https://github.com/wikimedia/mediawiki-extensions-Popups/blob/master/src/changeListeners/eventLogging.js#L71 we read linkInteractionToken which is undefined.

It would be nice to fix it so our code is consistent.

@pmiazga Nice catch!, but unrelated to this task, and affects probably other events like the settings cog one.

I've created T168449: event.linkInteractionToken can be undefined, next time create it yourself! 😉👍

phuedx removed phuedx as the assignee of this task.Jun 22 2017, 8:47 AM

phuedx removed a project: Patch-For-Review.Jun 23 2017, 1:17 PM

phuedx assigned this task to • Tbayer.Jun 27 2017, 5:10 PM

Repeating the above query, these events are being sent in numbers now. (We can now go back to T148850 and do a rough check on whether they are consistent with the overall pageview numbers and defined sampling rates, but that's another task.)

SELECT DATE(timestamp) AS date, 
event_popupEnabled, COUNT(*)
FROM log.Popups_16364296 
WHERE MONTH(timestamp) >= 6 
AND event_action = 'pageLoaded' 
GROUP BY date, event_popupEnabled
ORDER BY date, event_popupEnabled;

+------------+--------------------+----------+
| date       | event_popupEnabled | COUNT(*) |
+------------+--------------------+----------+
| 2017-06-01 |                  1 |        3 |
| 2017-06-02 |                  0 |        2 |
| 2017-06-02 |                  1 |        3 |
| 2017-06-03 |                  0 |        4 |
| 2017-06-04 |                  0 |        3 |
| 2017-06-04 |                  1 |        2 |
| 2017-06-05 |                  0 |        2 |
| 2017-06-05 |                  1 |        2 |
| 2017-06-06 |                  0 |        1 |
| 2017-06-06 |                  1 |        1 |
| 2017-06-07 |                  0 |        1 |
| 2017-06-07 |                  1 |        3 |
| 2017-06-08 |                  0 |        2 |
| 2017-06-08 |                  1 |        4 |
| 2017-06-09 |                  0 |        2 |
| 2017-06-09 |                  1 |        2 |
| 2017-06-10 |                  0 |        1 |
| 2017-06-10 |                  1 |        1 |
| 2017-06-11 |                  0 |        2 |
| 2017-06-12 |                  0 |        3 |
| 2017-06-12 |                  1 |        3 |
| 2017-06-13 |                  0 |        2 |
| 2017-06-14 |                  0 |        5 |
| 2017-06-14 |                  1 |        9 |
| 2017-06-15 |                  0 |        2 |
| 2017-06-15 |                  1 |        4 |
| 2017-06-16 |                  0 |        2 |
| 2017-06-16 |                  1 |        2 |
| 2017-06-17 |                  0 |        1 |
| 2017-06-17 |                  1 |        1 |
| 2017-06-18 |                  1 |        5 |
| 2017-06-19 |                  0 |        2 |
| 2017-06-19 |                  1 |        6 |
| 2017-06-20 |                  0 |        2 |
| 2017-06-20 |                  1 |       15 |
| 2017-06-21 |                  0 |        4 |
| 2017-06-21 |                  1 |       24 |
| 2017-06-22 |                  0 |       41 |
| 2017-06-22 |                  1 |      293 |
| 2017-06-23 |                  0 |       36 |
| 2017-06-23 |                  1 |      278 |
| 2017-06-24 |                  0 |       23 |
| 2017-06-24 |                  1 |      216 |
| 2017-06-25 |                  0 |       50 |
| 2017-06-25 |                  1 |      316 |
| 2017-06-26 |                  0 |      299 |
| 2017-06-26 |                  1 |     2001 |
| 2017-06-27 |                  0 |     1108 |
| 2017-06-27 |                  1 |     7914 |
| 2017-06-28 |                  0 |     1032 |
| 2017-06-28 |                  1 |     7240 |
| 2017-06-29 |                  0 |      966 |
| 2017-06-29 |                  1 |     7195 |
| 2017-06-30 |                  0 |     1292 |
| 2017-06-30 |                  1 |     7366 |
| 2017-07-01 |                  0 |      764 |
| 2017-07-01 |                  1 |     5557 |
| 2017-07-02 |                  0 |      992 |
| 2017-07-02 |                  1 |     5786 |
| 2017-07-03 |                  0 |      992 |
| 2017-07-03 |                  1 |     7155 |
| 2017-07-04 |                  0 |      754 |
| 2017-07-04 |                  1 |     5184 |
+------------+--------------------+----------+
63 rows in set (16.56 sec)

• Tbayer mentioned this in T148850: Sampling sanity check for Schema:Popups pageview events.Jul 12 2017, 5:56 PM

MBinder_WMF moved this task from 2016-17 Q4 to 2017-18 Q1 on the Readers-Web-Backlog board.Mar 6 2018, 6:51 PM

pageLoaded events are logged infrequently, if at allClosed, ResolvedPublic3 Estimated Story PointsActions