Page MenuHomePhabricator
Create Task
Maniphest T167273

pageLoaded events are logged infrequently, if at all
Closed, ResolvedPublic3 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) and then dispatches the BOOT action (synchronous). 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 over the mw.eventLog.Schema class/API.

Related Objects
Search...

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 added a comment.EditedJun 7 2017, 10:57 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 comment.Jun 7 2017, 11:46 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).

gerritbot added a subscriber: gerritbot.Jun 14 2017, 1:04 PM

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

Jdlrobson added a subscriber: Jdlrobson.Jun 14 2017, 5:28 PM

Sam will add SQL query to the task.

• Tbayer added a comment.Jun 14 2017, 5:31 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)
phuedx claimed this task.Jun 15 2017, 10:13 AM
gerritbot added a comment.Jun 20 2017, 9:49 AM

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

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

Jhernandez moved this task from Needs Code Review to Ready for Signoff on the Readers-Web-Kanbanana-Board-Old board.Jun 20 2017, 9:52 AM
Jhernandez added a subscriber: Jhernandez.

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)
pmiazga added a subscriber: pmiazga.Jun 20 2017, 5:37 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.

Jhernandez mentioned this in T168449: event.linkInteractionToken can be undefined.EditedJun 20 2017, 6:31 PM

@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 assigned this task to • Tbayer.Jun 27 2017, 5:10 PM
• Tbayer closed this task as Resolved.Jul 4 2017, 5:22 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)
Content licensed under Creative Commons Attribution-ShareAlike 3.0 (CC-BY-SA) unless otherwise noted; code licensed under GNU General Public License (GPL) or other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL