Page MenuHomePhabricator

[ 8 hours ] Spike: Analyze Hovercards and general instrumentation code for potential sources of unexpected data outcomes
Closed, ResolvedPublic

Description

Summary

The results from the hover card A/B test (details below) suggest that the way the data is gathered might be incorrect. Mainly:

  • link interactions (including hover-only interactions) significantly decrease for hover card group (3.71 vs 2.58)
  • hover interactions strangely high for control group - large portion of users hovering for more than 500ms
  • very few link clicks occur in the first 250ms for the experimental group

Details

For background, read the following:

T139319: Analyze results of Hovercards A/B test - Hungarian
T140485: Schema:Popups logs "dwelledButAbandoned" and link open events at the same time

This spike is a request to examine the code for Hovercards and the accompanying instrumentation (Schema:Popups) to potentially identify things in the code that could help explain, at least in part, seemingly unexpected data outcomes.

  1. In T139319#2475143, T139319#2481986, and T139319#2507540 it is noted that the concentration of clicks for Hovecards OFF (the control group) occurs with a lower interaction time than the concentration for Hovercards ON (the test group), and furthermore that the sheer percentage of early clicks is strikingly higher for the control group than the test group. Basically, we have so far failed to understand what happens to the green bump below 250ms in the control group:
    when Hovercards are switched on:
    (@Tbayer still plans to do some deduplication of events that will slightly correct the yellow area in the first chart, but this is highly unlikely influence this part of the data outcomes.) After various tests (T139319#2507540 ) it seems very unlikely that this difference is due to readers "learning" to chance their behavior due to the presence of Hovercards. Hence we are now focusing on the question: Is there something in the code that would cause this? Is the curve merely shifted due to a race condition? Are events potentially being dropped anywhere? Is there something else at play?
  2. As noted in T139319#2507559 duplicate events are being observed in the database. The specific observation here is about click events being more likely to be duplicated for the test groups' outlier usage scenaries, but more generally duplicates have been observed elsewhere. Is there anything that would explain these duplicate events? Is it possible to observe duplicated events at the client? Is there any way to guard against duplicate events? In which case(s) are duplicate events more likely to occur?
  3. Above 250ms as well, there appear to be fewer link interactions in general for the Hovercards ON (test group) case as opposed to the Hovercards OFF (control group). Is there a potential code reason why this might be the case? (n.b., this may be a behavioral difference attributable to the way users mouse around links, but that's a separate conversation.)

This spike is about looking at the client side instrumentation for general code correctness, potential race conditions, duplicate eventing, and so forth. It's okay to describe potential user behaviors and how events may manifest - indeed, that's necessary! - but theories about user learning and behavioral changes have been explored pretty well at this point.

This spike should result in diagnosis of the outcomes pertaining to the questions, and where issues can be rectified, tasks opened for fixes. As fixes, if they're required, guarantee better data quality outcomes in the second A/B test, they should be scheduled for the very next sprint and if time allows in this task's sprint, pulled into this sprint; maybe it will be so easy it can be done right on the spot within the spike time allotment - that would be ideal.

Browsers potentially to consider for exploration if trying to induce eventing:

  • Desktop Firefox
  • Desktop Chrome
  • Desktop Safari
  • Internet Explorer 11
  • Edge

LTR/RTL may be worth exploration, but probably isn't a major component (the results so far have been for huwiki, which is LTR only). Traffic shaping the connection with a router, in-browser settings, on-device filtering, or a utility like Link Conditioner can be handy, too.

Related Objects

Event Timeline

There are a very large number of changes, so older changes are hidden. Show Older Changes
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptAug 2 2016, 8:38 PM

@Tbayer, @JKatzWMF, heads up - feel free to adjust Description if needed.

dr0ptp4kt triaged this task as High priority.Aug 3 2016, 5:13 PM
dr0ptp4kt added a project: Readers-Web-Backlog.
dr0ptp4kt updated the task description. (Show Details)Aug 10 2016, 2:07 PM
dr0ptp4kt updated the task description. (Show Details)Aug 10 2016, 2:29 PM

to be clear the first symptom is the most troubling and important one in terms of obvious impact to the outcome and decision making.

Tbayer updated the task description. (Show Details)Aug 15 2016, 2:12 PM

What I had heard/read was that even for the 0 taps case, the histograms took on a similar form when the head-to-head test started (even with 'error' taken into account). @Tbayer, would you please clarify on that piece?

What I had heard/read was that even for the 0 taps case, the histograms took on a similar form when the head-to-head test started (even with 'error' taken into account). @Tbayer, would you please clarify on that piece?

Does this refer to what I wrote at T139319#2475143 ? "Between 250ms and 500ms (when the card kicks in), user behavior actually looks pretty similar[...]. That's another reason for suspecting that the test group data misses link open events below 250ms."

Assuming "0 taps" refers to link interactions that end without any click, i.e. by the reader moving the mouse away, then that's basically the yellow part of the above histograms (dwelledbutAbandoned).

dr0ptp4kt added a comment.EditedAug 17 2016, 6:08 PM

@Tbayer, thanks. Sorry, I meant to say 0 previews. Language switching on the mind!

But back to Hovercards: what I was wondering about is 0 previews interactions at the beginning of the head to head test (i.e., June 7 and the ensuing days once pages started to fall out of cache). Does that make sense?

Yes, that comment to which you refer it the thing about which I read :)

A simplified description might help folks tackle this:

The hovercards event logging is causing some weird data! Can you look at it and try to understand why certain things are happening? Specifically, there are almost no link clicks recorded in under 250 ms in the experimental group, but we see 40% of all links clicked in the control groupu occur in that time. There are a couple other things, but start there.

ovasileva updated the task description. (Show Details)Aug 18 2016, 12:25 AM
ovasileva updated the task description. (Show Details)
phuedx claimed this task.Aug 18 2016, 1:02 PM
phuedx moved this task from To Do to Doing on the Reading-Web-Sprint-79-Uh-oh board.
phuedx added a subscriber: Jhernandez.

Ping @Jhernandez. You were going to look at this separately, right?

@Tbayer, thanks. Sorry, I meant to say 0 previews. Language switching on the mind!
But back to Hovercards: what I was wondering about is 0 previews interactions at the beginning of the head to head test (i.e., June 7 and the ensuing days once pages started to fall out of cache). Does that make sense?
Yes, that comment to which you refer it the thing about which I read :)

@dr0ptp4kt Ah, OK. See T139319#2507540 for that then. The histogram for the 0 previews case there - reproduced below - was for the timespan of July 15-27. I didn't do another detailed histogram for the early days of the experiment, but instead was looking at the percentage of "fast opens" (link click below 250ms) during that time among the test group, as an ad-hoc metric. The time series [e] there showed that this ratio was different (much lower) in the test group from the beginning of the experiment already. I also just re-did this time series restricted to the 0 previews group (again, this is where we would expect readers to behave identically to the control group during the first 250ms, because they have not been exposed to any different user experience yet). It likewise does not indicate that things were different on June 7 and the subsequent days compared to later in the experiment.

SELECT LEFT(timestamp, 8) AS yearmonthday,
SUM(IF(event_totalInteractionTime <= 250, 1, 0))/SUM(1) AS fast_open_ratio, 
SUM(1) AS all_opens
FROM log.Popups_15597282
WHERE wiki ='huwiki'
AND event_isAnon = 1
AND LEFT(timestamp, 8) < '20160707'
AND event_popupEnabled = 1
AND event_action LIKE 'opened%'
AND event_previewCountBucket = '0 previews'
GROUP BY yearmonthday
ORDER BY yearmonthday;
+--------------+-----------------+-----------+
| yearmonthday | fast_open_ratio | all_opens |
+--------------+-----------------+-----------+
| 20160602     |          0.0000 |         2 |
| 20160603     |          0.0000 |         4 |
| 20160604     |          0.0000 |         3 |
| 20160605     |          0.0000 |         9 |
| 20160606     |          0.2000 |         5 |
| 20160607     |          0.1626 |       203 |
| 20160608     |          0.1489 |       423 |
| 20160609     |          0.1652 |       351 |
| 20160610     |          0.1319 |       273 |
| 20160611     |          0.1795 |       273 |
| 20160612     |          0.1536 |       280 |
| 20160613     |          0.1565 |       294 |
| 20160614     |          0.1214 |       280 |
| 20160615     |          0.1191 |       277 |
| 20160616     |          0.1244 |       217 |
| 20160617     |          0.1538 |       208 |
| 20160618     |          0.1746 |       189 |
| 20160619     |          0.1615 |       192 |
| 20160620     |          0.1378 |       225 |
| 20160621     |          0.1818 |       220 |
| 20160622     |          0.1285 |       179 |
| 20160623     |          0.1495 |       194 |
| 20160624     |          0.1807 |       166 |
| 20160625     |          0.2042 |       142 |
| 20160626     |          0.1942 |       139 |
| 20160627     |          0.1474 |       190 |
| 20160628     |          0.1435 |       209 |
| 20160629     |          0.1807 |       166 |
| 20160630     |          0.1558 |       154 |
| 20160701     |          0.1728 |       162 |
| 20160702     |          0.1964 |       112 |
| 20160703     |          0.1694 |       183 |
| 20160704     |          0.1272 |       173 |
| 20160705     |          0.1707 |       164 |
| 20160706     |          0.1892 |       148 |
+--------------+-----------------+-----------+
35 rows in set (43.77 sec)
Tbayer added a subscriber: ovasileva.EditedAug 18 2016, 2:25 PM

@ovasileva , regarding the first two main points added to the task description yesterday as part of the new "summary":

  • link interactions (including hover-only interactions) significantly decrease for hover card group (3.71 vs 2.58)
  • hover interactions strangely high for control group - large portion of users hovering for more than 500ms

I think we should be clear that these two outcomes are, while somewhat unexpected, not impossible per se. E.g. it could be that people dislike the cards popping up accidentally, and start to deliberately avoid links as they move their mouse along, thus decreasing the number of accidental link interactions. Also, as was already discussed in the context of T139319, it's conceivable that many people in the control group intentionally hover for more than 500ms too - in fact MediaWiki already has feature built specifically for this user behavior (the small black popups with the linked page title that are shown to every reader on any Wikipedia page in the standard view). This task is not about explaining away undesired or unexpected results.

Instead, it's the previously added third point (which @JKatzWMF suggested to use for the summary yesterday, with a different wording T141922#2563079 ) which seems more and more logically impossible, and which is the main "smoking gun" that lead us to believe there is something wrong in the instrumentation.

Thanks @Tbayer. That got me to thinking about making the scope of the analysis only 500ms or less interactions to "compare apples to apples" (which I think you also checked on) and also whittling away the duplicate linkInteractionToken events. Merely for the sake of having the data, here's what it was. Still a major difference between the control and the test groups.

mysql:research@s6-analytics-slave.eqiad.wmnet [log]> select a.yearmonthday,
    -> SUM(IF(a.event_totalInteractionTime <= 250, 1, 0))/SUM(1) AS fast_open_ratio,
    -> SUM(1) as all_opens
    -> from (
    -> select distinct left(timestamp,8) as yearmonthday, event_linkInteractionToken, event_totalInteractionTime
    -> from log.Popups_15597282
    -> WHERE wiki ='huwiki'
    -> AND event_isAnon = 1
    -> AND LEFT(timestamp, 8) < '20160707'
    -> AND event_popupEnabled = 1
    -> AND event_action LIKE 'opened%'
    -> AND event_previewCountBucket = '0 previews'
    -> AND event_totalInteractionTime <= 500
    -> ) a
    -> group by yearmonthday
    -> order by yearmonthday;
+--------------+-----------------+-----------+
| yearmonthday | fast_open_ratio | all_opens |
+--------------+-----------------+-----------+
| 20160602     |          0.0000 |         1 |
| 20160603     |          0.0000 |         3 |
| 20160604     |          0.0000 |         3 |
| 20160605     |          0.0000 |         6 |
| 20160606     |          0.2500 |         4 |
| 20160607     |          0.1854 |       178 |
| 20160608     |          0.1689 |       367 |
| 20160609     |          0.1815 |       314 |
| 20160610     |          0.1506 |       239 |
| 20160611     |          0.2050 |       239 |
| 20160612     |          0.1762 |       244 |
| 20160613     |          0.1833 |       251 |
| 20160614     |          0.1344 |       253 |
| 20160615     |          0.1347 |       245 |
| 20160616     |          0.1378 |       196 |
| 20160617     |          0.1749 |       183 |
| 20160618     |          0.1930 |       171 |
| 20160619     |          0.1962 |       158 |
| 20160620     |          0.1574 |       197 |
| 20160621     |          0.2030 |       197 |
| 20160622     |          0.1386 |       166 |
| 20160623     |          0.1726 |       168 |
| 20160624     |          0.2113 |       142 |
| 20160625     |          0.2266 |       128 |
| 20160626     |          0.2231 |       121 |
| 20160627     |          0.1718 |       163 |
| 20160628     |          0.1587 |       189 |
| 20160629     |          0.2069 |       145 |
| 20160630     |          0.1752 |       137 |
| 20160701     |          0.1905 |       147 |
| 20160702     |          0.2200 |       100 |
| 20160703     |          0.1962 |       158 |
| 20160704     |          0.1507 |       146 |
| 20160705     |          0.1854 |       151 |
| 20160706     |          0.2000 |       140 |
+--------------+-----------------+-----------+
35 rows in set (44.98 sec)

mysql:research@s6-analytics-slave.eqiad.wmnet [log]> select a.yearmonthday,
    -> SUM(IF(a.event_totalInteractionTime <= 250, 1, 0))/SUM(1) AS fast_open_ratio,
    -> SUM(1) as all_opens
    -> from (
    -> select distinct left(timestamp,8) as yearmonthday, event_linkInteractionToken, event_totalInteractionTime
    -> from log.Popups_15597282
    -> WHERE wiki ='huwiki'
    -> AND event_isAnon = 1
    -> AND LEFT(timestamp, 8) < '20160707'
    -> AND event_popupEnabled = false
    -> AND event_action LIKE 'opened%'
    -> AND event_totalInteractionTime <= 500
    -> ) a
    -> group by yearmonthday
    -> order by yearmonthday;
+--------------+-----------------+-----------+
| yearmonthday | fast_open_ratio | all_opens |
+--------------+-----------------+-----------+
| 20160603     |          0.9749 |      6809 |
| 20160604     |          0.9773 |     10483 |
| 20160605     |          0.9729 |     13558 |
| 20160606     |          0.9749 |     11411 |
| 20160607     |          0.9756 |      8450 |
| 20160608     |          0.9810 |      5645 |
| 20160609     |          0.9787 |      5257 |
| 20160610     |          0.9736 |      4921 |
| 20160611     |          0.9750 |      4314 |
| 20160612     |          0.9800 |      6346 |
| 20160613     |          0.9744 |      5148 |
| 20160614     |          0.9806 |      5663 |
| 20160615     |          0.9746 |      5826 |
| 20160616     |          0.9186 |      5356 |
| 20160617     |          0.7229 |      5461 |
| 20160618     |          0.7245 |      5812 |
| 20160619     |          0.7371 |      6867 |
| 20160620     |          0.7221 |      7545 |
| 20160621     |          0.7273 |      7646 |
| 20160622     |          0.7228 |      6515 |
| 20160623     |          0.7274 |      5422 |
| 20160624     |          0.7272 |      6269 |
| 20160625     |          0.7344 |      5241 |
| 20160626     |          0.7404 |      6745 |
| 20160627     |          0.7219 |      8651 |
| 20160628     |          0.7215 |      8248 |
| 20160629     |          0.7134 |      6999 |
| 20160630     |          0.7355 |      6166 |
| 20160701     |          0.7194 |      5902 |
| 20160702     |          0.7219 |      5969 |
| 20160703     |          0.7267 |      6430 |
| 20160704     |          0.7261 |      7109 |
| 20160705     |          0.7392 |      6499 |
| 20160706     |          0.7186 |      6774 |
+--------------+-----------------+-----------+

I've been pairing this morning with @phuedx. Besides his ongoing audit from last week, we've been treating today the system as a black box and started testing the interactions and checking the EL events produced.

For the moment our tests seem to go as expected, so nothing weird.

Here's the etherpad from the session https://etherpad.wikimedia.org/p/hovercards-el

And here's the tests we've run (also in the etherpad) (run both manually and via automated scripts):

Hover and wait for card, then abandon

✅ pageLoaded
✅ dismissed

Quick/accidental hover (✅, produces no events)

Longer quick/accidental hover (+250ms)

✅ dwelledButAbandoned

Longer hover + out + long hover + out

✅ dwelledButAbandoned
✅ dismissed

Note pageLoaded is produced only by the first interaction of the page session. If the tests are run separately they all produce pageLoaded. This is a serial run of those tests.


I'll develop more tests (with click interaction and multi-link interactions too), any suggestions as what other user behaviour to exercise would be appreciated. If you think of any sequence of actions you suspect could cause problems, ping me and I'll make a test for it and run it.


Another issue I've seen is that mw.trackSubscribe doesn't do anything in Firefox, so that's another thing to look at to see if EL is working at all in Firefox.

Another issue I've seen is that mw.trackSubscribe doesn't do anything in Firefox, so that's another thing to look at to see if EL is working at all in Firefox.

Even with Do Not Track disabled? That sounds like a potential culprit if it's generally reproducible. What would the normal expected behavior be?

@Jhernandez @phuedx great approach! Are these checkboxes looking at both experimental and control buckets? I know at least part of the instrumentation is different. For instance, in experimental bucket we don't collect hovers <250ms, but we should be collecting clicks (and don't seem to be). For this reason the click events (<250 ms and above) in both control and experimental are of particular interest.

tl;dr: the wikitext editor's toolbar might be skewing the data for the OFF group. We might be seeing lots of clicks on titles like '#'.


The ON and OFF groups have distinct paths through the Hovercards code for logging click and abandon events, the latter event being represented by either the mouseleave or blur events.

What happens immediately after the user hovers over a link?

In the ON path, a new linkInteractionToken-dwellStartTime pair is generated and the handlers for those events are attached if:

  • the user hasn't just moved their cursor from a hovercard to the link associated with that hovercard,
  • the link has a href of '#' (see 90514356656a for some detail)

I believe that the first filter can be safely ignored. However, in the OFF path, there's no equivalent to the second filter.

AFAICT the hovercards code is loaded and initialised when editing or previewing an edit. There 51 links with an href of '#' in enwiki's wikitext editor [0], most of which are in the editor's toolbar. Might these links be skewing the data for the OFF group?

[0]: $('#mw-content-text').find('a[href="#"]').length

tl;dr: the wikitext editor's toolbar might be skewing the data for the OFF group. We might be seeing lots of clicks on titles like '#'.

Fortunately – or unfortunately, depending on how you're feeling – we can discard this. I've verified that click events aren't logged for the wikitext editor's toolbar buttons.

Even with Do Not Track disabled? That sounds like a potential culprit if it's generally reproducible. What would the normal expected behavior be?

DNT shouldn't affect mw.track. Related pages uses mw.trackSubscribe in the code and it works for me in production.

After some investigation navigation.sendBeacon is undefined for me, so it won't track at all.

So this is not a general problem.

I've been running tests, and if the time between interactions (hover, out, clicking, ...) is smaller than ~500ms then there are certain events that don't get logged. Specially dismissed + dwell as I've seen. It is non deterministic.

As it seems, quick interactions between a link or several links may result in skipping events. Nothing to do with clicks though.

I'll keep digging.

With manual testing I've noticed that sometimes when clicking a link I've seen opened in new tab + a couple of dwell events all at once. I'll investigate some more.

phuedx reassigned this task from phuedx to Jhernandez.EditedAug 24 2016, 7:05 AM
phuedx added a subscriber: phuedx.

Passing the baton to @Jhernandez (although I'm sticking around for a while…)

Jhernandez added a subscriber: HaeB.EditedAug 24 2016, 10:59 AM

We (@Jhernandez and @phuedx) think we've found something important.

What

In the hovercards OFF case, when the user clicks a link that has been hovered multiple times, then multiple click events are logged with different linkInteractionTokens. Events have a decreasing totalInteractionTime, e.g. in the automated tests that were run we saw one event with a totalInteractionTime on the order of 100ms and one on the order of 10ms (in real data this will depend on the user's actions and their timing).

Correcting analysis

These events can be de-duplicated by grouping click events by pageTitleHover and by pageToken but only for action: 'opened in same tab' (opened in new tab can send multiple click events legitimately, so no fix for that). The event with the lowest totalInteractionTime should be accepted (as it should be the last one) and all others rejected.

With such grouping we should see fewer click events on the OFF case.

Why

When preview is disabled a click event is bound in every hover that is never unbound, which doesn't happen when preview is enabled. As @phuedx mentioned in T141922#2574587, binding click events follows different code paths for the OFF and ON groups.

In source


Tests run

test('Enabled: Hover link + click', [
  visit(staging),
  hover(testLink),
  wait(150),
  hoverout(testLink),
  wait(150),
  hover(testLink),
  click(testLink)
], [
  'pageLoaded',
  'opened in same tab',
  'pageLoaded'
])

test('Disabled: Hover link + click', [
  visit(staging, {disabled: true}),
  hover(testLink),
  wait(150),
  hoverout(testLink),
  wait(150),
  hover(testLink),
  click(testLink)
], [
  'pageLoaded',
  'opened in same tab',
  'pageLoaded'
])

test('Disabled: Hover link + click', [
  visit(staging, {disabled: true}),
  hover(testLink),
  wait(150),
  hoverout(testLink),
  wait(150),
  hover(testLink),
  wait(150),
  hoverout(testLink),
  wait(150),
  hover(testLink),
  wait(150),
  hoverout(testLink),
  wait(150),
  hover(testLink),
  click(testLink)
], [
  'pageLoaded',
  'opened in same tab',
  'pageLoaded'
])

Results

Enabled: Hover link + click

✅  pageLoaded
✅  opened in same tab
✅  pageLoaded
Events
{ action: 'pageLoaded',
  totalInteractionTime: undefined,
  sessionToken: '39b6d31c19fd6717',
  linkInteractionToken: undefined }
{ action: 'opened in same tab',
  totalInteractionTime: 4,
  sessionToken: '39b6d31c19fd6717',
  linkInteractionToken: '6b37444918c073691472034318220' }
{ action: 'pageLoaded',
  totalInteractionTime: undefined,
  sessionToken: '39b6d31c19fd6717',
  linkInteractionToken: undefined }

Disabled: Hover link + click

✅  pageLoaded
✅  opened in same tab
❌  expected pageLoaded, got opened in same tab
❌  expected undefined, got pageLoaded
Events
{ action: 'pageLoaded',
  totalInteractionTime: undefined,
  sessionToken: 'afe778deea20e74c',
  linkInteractionToken: undefined }
{ action: 'opened in same tab',
  totalInteractionTime: 326,
  sessionToken: 'afe778deea20e74c',
  linkInteractionToken: 'cf3605b17c7409701472034323265' }
{ action: 'opened in same tab',
  totalInteractionTime: 6,
  sessionToken: 'afe778deea20e74c',
  linkInteractionToken: '2fa633833201904a1472034323587' }
{ action: 'pageLoaded',
  totalInteractionTime: undefined,
  sessionToken: 'afe778deea20e74c',
  linkInteractionToken: undefined }

Disabled: Hover link + click

✅  pageLoaded
✅  opened in same tab
❌  expected pageLoaded, got opened in same tab
❌  expected undefined, got opened in same tab
❌  expected undefined, got opened in same tab
❌  expected undefined, got pageLoaded
Events
{ action: 'pageLoaded',
  totalInteractionTime: undefined,
  sessionToken: '0b4ca4de3b9f5044',
  linkInteractionToken: undefined }
{ action: 'opened in same tab',
  totalInteractionTime: 959,
  sessionToken: '0b4ca4de3b9f5044',
  linkInteractionToken: 'fe8b4369a461a9ac1472035435603' }
{ action: 'opened in same tab',
  totalInteractionTime: 640,
  sessionToken: '0b4ca4de3b9f5044',
  linkInteractionToken: 'bd55c9e95ae0f6061472035435924' }
{ action: 'opened in same tab',
  totalInteractionTime: 325,
  sessionToken: '0b4ca4de3b9f5044',
  linkInteractionToken: 'ef6d79c8f15ecd601472035436240' }
{ action: 'opened in same tab',
  totalInteractionTime: 7,
  sessionToken: '0b4ca4de3b9f5044',
  linkInteractionToken: 'f7874abeed2b1f811472035436559' }
{ action: 'pageLoaded',
  totalInteractionTime: undefined,
  sessionToken: '0b4ca4de3b9f5044',
  linkInteractionToken: undefined }

cc/ @dr0ptp4kt @HaeB

@phuedx @Jhernandez nice find! I did some preliminary analysis and it looks like there is a big impact. When I group all links by pageTitleHover (ignoring the fact that in both enabled and disabled there are legitimate multiple events per link), the enabled group goes from having 27% fewer link interactions (distinct event_linkInteractionTokens) per page to having 3% fewer. Rough query below: Tilman will do a better check against this when he gets back. Earlier we found that many click interactions also seemed to create a duplicate hoverAbandon event, that we were removing. Strange that it didn't show up here, but maybe it was already fixed.

One thing I am specifically curious about and I am not sure you have tested. Have you been able to confirm that a click within 250 ms of a hover in the enabled group triggers? It might be that it's simply humanly impossible and the ones we are seeing in the disabled group are from the weirdness you mention in the comment above.

with no control for noise:
SELECT	count(DISTINCT event_pageToken), count(DISTINCT event_linkInteractionToken),	count(DISTINCT event_sessionToken), event_popupEnabled
FROM Popups_15777589						
WHERE wiki ='huwiki'					
AND  event_isAnon = 1				
GROUP BY event_popupEnabled;
grouping multiple interactions per link
SELECT count(DISTINCT event_pageToken), count(DISTINCT event_linkInteractionToken), count(DISTINCT event_sessionToken), event_popupEnabled
FROM	
(
	SELECT *, count(*) AS num_events
	FROM Popups_15777589						
	WHERE	wiki	='huwiki'					
	AND	event_isAnon	=	1				
	GROUP	BY	event_pageTitleHover, event_pageToken
) AS t1
GROUP BY event_popupEnabled;

@JKatzWMF Nice, thanks.

Earlier we found that many click interactions also seemed to create a duplicate hoverAbandon event, that we were removing. Strange that it didn't show up here, but maybe it was already fixed.

Regarding duplicate hoverAbandon I've seen that in my manual tests, but I haven't been able to get a reproducible test that creates that. Mouse interactions in the browser when leaving the page can get messy.

One thing I am specifically curious about and I am not sure you have tested. Have you been able to confirm that a click within 250 ms of a hover in the enabled group triggers? It might be that it's simply humanly impossible and the ones we are seeing in the disabled group are from the weirdness you mention in the comment above.

Yep, first tests we've run were those hoping there was an easy to spot problem. They all work fine both immediately and with bigger delays like 150ms (but still <250ms) and the results are correct always.

I'll re-run the whole test suite again later and post a gist with the source and the results so that it is more visible what it has been tested (a bunch of things!)

You can see in T141922#2576067 that that test was tested that time too and passed, source and the results.

Any other tests or interactions you want to test or suspect tell me and I'll run them!

Tbayer removed a subscriber: HaeB.Aug 29 2016, 11:22 AM

As promised here's the full list of tests freshly run with the steps:

We (@Jhernandez and @phuedx) think we've found something important.

What

In the hovercards OFF case, when the user clicks a link that has been hovered multiple times, then multiple click events are logged with different linkInteractionTokens. Events have a decreasing totalInteractionTime, e.g. in the automated tests that were run we saw one event with a totalInteractionTime on the order of 100ms and one on the order of 10ms (in real data this will depend on the user's actions and their timing).

Correcting analysis

These events can be de-duplicated by grouping click events by pageTitleHover and by pageToken but only for action: 'opened in same tab' (opened in new tab can send multiple click events legitimately, so no fix for that). The event with the lowest totalInteractionTime should be accepted (as it should be the last one) and all others rejected.

Great find! So, before filtering these duplicates out, I first tried to get a better understanding of how often they happen in the wild.

Amazingly, it seems that this duplication is the norm rather than the exception: Less than 3% of 'opened in same tab'events per day are not the duplicate of another such event.[a] (Defined as having the same values for browser session, source and target page. Usually link interaction token and interaction time differ, but the timestamp will be the same too; per inspection of a hour-long sample: P3905.) In contrast, with Hovercards ON this percentage is consistently >90% (as expected from the code difference explained above).[a] Removing such duplicate events would decrease the number of measured 'opened in same tab' by between 58% and 62% for each day in the past month for Hovercards OFF, but only by 1-5% for Hovercards ON.[b] In other words, the impact of this correction on the comparison of links clicked would be even bigger than in Jon's first approximation above (T141922#2579299, regarding all links interactions).

Do we have an explanation for this result too? I.e. why multiple click events are logged, with different linkInteractionToken, even when there aren't multiple hovers.

[a]
SELECT singletonsperday.popupEnabled, singletonsperday.yearmonthday, ROUND(100*singletons/totalevents,2) AS singletons_percentage FROM
	(SELECT popupEnabled, yearmonthday, SUM(1) AS singletons FROM
		(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
		event_sessionToken, event_pageIdSource, event_pageTitleHover,
		COUNT(*) AS copies
		FROM log.Popups_15777589 
		WHERE wiki ='huwiki' AND event_isAnon = 1
		AND LEFT(timestamp, 8) < '20160828'
		AND event_action = 'opened in same tab'
		GROUP BY popupEnabled, yearmonthday,
		event_sessionToken, event_pageIdSource, event_pageTitleHover
		HAVING copies=1) AS singletons
	GROUP BY popupEnabled, yearmonthday) AS singletonsperday
JOIN
	(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
	COUNT(*) AS totalevents
	FROM log.Popups_15777589 
	WHERE wiki ='huwiki' AND event_isAnon = 1
	AND LEFT(timestamp, 8) < '20160828'
	AND event_action = 'opened in same tab'
	GROUP BY popupEnabled, yearmonthday) AS totaleventsperday
ON singletonsperday.popupEnabled = totaleventsperday.popupEnabled
AND singletonsperday.yearmonthday = totaleventsperday.yearmonthday
ORDER BY popupEnabled, yearmonthday;


+--------------+--------------+-----------------------+
| popupEnabled | yearmonthday | singletons_percentage |
+--------------+--------------+-----------------------+
|            0 | 20160728     |                  0.17 |
|            0 | 20160729     |                  0.11 |
|            0 | 20160730     |                  0.34 |
|            0 | 20160731     |                  0.09 |
|            0 | 20160801     |                  0.18 |
|            0 | 20160802     |                  0.14 |
|            0 | 20160803     |                  0.23 |
|            0 | 20160804     |                  0.20 |
|            0 | 20160805     |                  0.12 |
|            0 | 20160806     |                  0.19 |
|            0 | 20160807     |                  0.17 |
|            0 | 20160808     |                  0.18 |
|            0 | 20160809     |                  0.17 |
|            0 | 20160810     |                  0.20 |
|            0 | 20160811     |                  0.22 |
|            0 | 20160812     |                  0.23 |
|            0 | 20160813     |                  0.26 |
|            0 | 20160814     |                  0.25 |
|            0 | 20160815     |                  0.19 |
|            0 | 20160816     |                  0.14 |
|            0 | 20160817     |                  0.12 |
|            0 | 20160818     |                  1.73 |
|            0 | 20160819     |                  2.43 |
|            0 | 20160820     |                  2.39 |
|            0 | 20160821     |                  2.43 |
|            0 | 20160822     |                  2.36 |
|            0 | 20160823     |                  2.36 |
|            0 | 20160824     |                  2.31 |
|            0 | 20160825     |                  2.25 |
|            0 | 20160826     |                  2.36 |
|            0 | 20160827     |                  2.65 |
|            1 | 20160728     |                 96.73 |
|            1 | 20160729     |                 95.72 |
|            1 | 20160730     |                 96.11 |
|            1 | 20160731     |                 94.19 |
|            1 | 20160801     |                 95.36 |
|            1 | 20160802     |                 94.93 |
|            1 | 20160803     |                 92.72 |
|            1 | 20160804     |                 94.86 |
|            1 | 20160805     |                 95.08 |
|            1 | 20160806     |                 95.11 |
|            1 | 20160807     |                 95.82 |
|            1 | 20160808     |                 94.75 |
|            1 | 20160809     |                 95.04 |
|            1 | 20160810     |                 94.70 |
|            1 | 20160811     |                 92.95 |
|            1 | 20160812     |                 94.72 |
|            1 | 20160813     |                 94.52 |
|            1 | 20160814     |                 92.30 |
|            1 | 20160815     |                 94.36 |
|            1 | 20160816     |                 95.30 |
|            1 | 20160817     |                 95.77 |
|            1 | 20160818     |                 93.99 |
|            1 | 20160819     |                 93.31 |
|            1 | 20160820     |                 93.66 |
|            1 | 20160821     |                 93.42 |
|            1 | 20160822     |                 95.72 |
|            1 | 20160823     |                 96.06 |
|            1 | 20160824     |                 94.24 |
|            1 | 20160825     |                 95.93 |
|            1 | 20160826     |                 94.49 |
|            1 | 20160827     |                 95.52 |
+--------------+--------------+-----------------------+
62 rows in set (1 min 0.18 sec)

(BTW, something must have happened on August 18, increasing this percentage in the control group by a factor of more than 10.)

[b]
# determine ratio of duplicate opens, i.e. same source page and same linked page 
# during the same browser session (not necessarily the same page session)
SELECT dupesperday.popupEnabled, dupesperday.yearmonthday, ROUND(100*dupes/totalevents,2) AS dupes_percentage FROM
	(SELECT popupEnabled, yearmonthday, SUM(copies-1) AS dupes FROM
		(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
		event_sessionToken, event_pageIdSource, event_pageTitleHover,
		COUNT(*) AS copies
		FROM log.Popups_15777589 
		WHERE wiki ='huwiki' AND event_isAnon = 1
		AND LEFT(timestamp, 8) < '20160828'
		AND event_action = 'opened in same tab'
		GROUP BY popupEnabled, yearmonthday,
		event_sessionToken, event_pageIdSource, event_pageTitleHover
		HAVING copies>1) AS dupeslist
	GROUP BY popupEnabled, yearmonthday) AS dupesperday
	JOIN
	(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
	COUNT(*) AS totalevents
	FROM log.Popups_15777589 
	WHERE wiki ='huwiki' AND event_isAnon = 1
	AND LEFT(timestamp, 8) < '20160828'
	AND event_action = 'opened in same tab'
	GROUP BY popupEnabled, yearmonthday) AS totaleventsperday
	ON dupesperday.popupEnabled = totaleventsperday.popupEnabled
	AND dupesperday.yearmonthday = totaleventsperday.yearmonthday
ORDER BY popupEnabled, yearmonthday;
+--------------+--------------+------------------+
| popupEnabled | yearmonthday | dupes_percentage |
+--------------+--------------+------------------+
|            0 | 20160728     |            59.93 |
|            0 | 20160729     |            60.72 |
|            0 | 20160730     |            60.42 |
|            0 | 20160731     |            60.81 |
|            0 | 20160801     |            60.39 |
|            0 | 20160802     |            61.50 |
|            0 | 20160803     |            61.99 |
|            0 | 20160804     |            61.18 |
|            0 | 20160805     |            62.33 |
|            0 | 20160806     |            61.96 |
|            0 | 20160807     |            60.69 |
|            0 | 20160808     |            61.37 |
|            0 | 20160809     |            61.37 |
|            0 | 20160810     |            60.77 |
|            0 | 20160811     |            61.17 |
|            0 | 20160812     |            60.47 |
|            0 | 20160813     |            60.95 |
|            0 | 20160814     |            58.82 |
|            0 | 20160815     |            61.13 |
|            0 | 20160816     |            61.07 |
|            0 | 20160817     |            61.17 |
|            0 | 20160818     |            60.34 |
|            0 | 20160819     |            59.96 |
|            0 | 20160820     |            59.65 |
|            0 | 20160821     |            59.68 |
|            0 | 20160822     |            59.56 |
|            0 | 20160823     |            59.42 |
|            0 | 20160824     |            59.63 |
|            0 | 20160825     |            60.21 |
|            0 | 20160826     |            59.11 |
|            0 | 20160827     |            58.64 |
|            1 | 20160728     |             1.79 |
|            1 | 20160729     |             2.21 |
|            1 | 20160730     |             2.08 |
|            1 | 20160731     |             3.03 |
|            1 | 20160801     |             2.49 |
|            1 | 20160802     |             2.79 |
|            1 | 20160803     |             3.70 |
|            1 | 20160804     |             2.70 |
|            1 | 20160805     |             2.63 |
|            1 | 20160806     |             2.54 |
|            1 | 20160807     |             2.19 |
|            1 | 20160808     |             2.85 |
|            1 | 20160809     |             2.58 |
|            1 | 20160810     |             2.83 |
|            1 | 20160811     |             3.91 |
|            1 | 20160812     |             2.77 |
|            1 | 20160813     |             3.08 |
|            1 | 20160814     |             4.21 |
|            1 | 20160815     |             2.97 |
|            1 | 20160816     |             2.49 |
|            1 | 20160817     |             2.21 |
|            1 | 20160818     |             3.14 |
|            1 | 20160819     |             3.51 |
|            1 | 20160820     |             3.46 |
|            1 | 20160821     |             3.57 |
|            1 | 20160822     |             2.19 |
|            1 | 20160823     |             2.05 |
|            1 | 20160824     |             3.07 |
|            1 | 20160825     |             2.14 |
|            1 | 20160826     |             3.03 |
|            1 | 20160827     |             2.58 |
+--------------+--------------+------------------+
62 rows in set (1 min 4.89 sec)

Great results, @Tbayer

Do we have an explanation for this result too? I.e. why multiple click events are logged, with different linkInteractionToken, even when there aren't multiple hovers.

I don't understand even when there aren't multiple hovers.. If there are different linkInteractionTokens, I think then there have been multiple hovers. Can you expand on that?

(BTW, something must have happened on August 18, increasing this percentage in the control group by a factor of more than 10.)

That's very weird, I don't recall any config changes, and I've had a look and it seems like the experiment config hasn't changed since the 6th of june (https://github.com/wikimedia/operations-mediawiki-config/blob/master/wmf-config/InitialiseSettings.php#L12748-L12766).

How should we follow up on this?


Queries

I'm not exactly sure the queries are accurate regarding what we're looking for, (I may be misunderstanding something) given we're grouping with sessionToken.

In a session, you can have multiple legitimate clicks to the same link (by clicking, going back later and clicking it again) so grouping by that may be eliminating valid clicks and raising the duplicates % (AFAIK sessionToken survives page loads).

As we mentioned above:

These events can be de-duplicated by grouping click events by pageTitleHover and by pageToken

The reason we suggest grouping by pageToken instead is because it should be unique per visit and page. So for each unique visit and page there should be at most one valid opened in same tab event (because the browser leaves the page, if it comes back pageToken should be different) so the remaining events are duplicate.

@Jhernandez

(BTW, something must have happened on August 18, increasing this percentage in the control group by a factor of more than 10.)

That's very weird, I don't recall any config changes, and I've had a look and it seems like the experiment config hasn't changed since the 6th of june (https://github.com/wikimedia/operations-mediawiki-config/blob/master/wmf-config/InitialiseSettings.php#L12748-L12766).
How should we follow up on this?

It seems this could be a good point for investigation. Can you think of any other changes that could cause this/any other place to look?

Peter added a subscriber: Peter.Aug 31 2016, 2:12 PM

Great results, @Tbayer

Do we have an explanation for this result too? I.e. why multiple click events are logged, with different linkInteractionToken, even when there aren't multiple hovers.

I don't understand even when there aren't multiple hovers.. If there are different linkInteractionTokens, I think then there have been multiple hovers. Can you expand on that?

This was based on the assumption that multiple hovers over the same link will occur only in a minority of cases (or at least not in the vast majority of link interactions where the link is opened in the same tab). I.e. that most of the time, the user will hover over the same link only once. I think this is a very plausible assumption.

In other words, one would have expected that the bug which you found causes duplicate events only in a minority of cases. I.e. it does not yet explain what we are seeing in P3905 and these singleton/duplicate percentages. Could there be another mechanism which causes this kind of behavior (more than one "opened in same tab" event sent) even when there has only been a single hover?

(BTW, something must have happened on August 18, increasing this percentage in the control group by a factor of more than 10.)

That's very weird, I don't recall any config changes, and I've had a look and it seems like the experiment config hasn't changed since the 6th of june (https://github.com/wikimedia/operations-mediawiki-config/blob/master/wmf-config/InitialiseSettings.php#L12748-L12766).
How should we follow up on this?

Thanks for checking! Strange - no software deployments either on August 18? (I could try to narrow the time of the change down to the hour on that day if that is helpful.)


Queries

I'm not exactly sure the queries are accurate regarding what we're looking for, (I may be misunderstanding something) given we're grouping with sessionToken.
In a session, you can have multiple legitimate clicks to the same link (by clicking, going back later and clicking it again) so grouping by that may be eliminating valid clicks and raising the duplicates % (AFAIK sessionToken survives page loads).
As we mentioned above:

These events can be de-duplicated by grouping click events by pageTitleHover and by pageToken

The reason we suggest grouping by pageToken instead is because it should be unique per visit and page. So for each unique visit and page there should be at most one valid opened in same tab event (because the browser leaves the page, if it comes back pageToken should be different) so the remaining events are duplicate.

Yes, I saw your advice to group by pageToken and have been planning to follow it for the calculation of the overall results. However, as I wrote, "before filtering these duplicates out, I first tried to get a better understanding of how often they happen in the wild" - i.e. how many (and which kind of) events we will be discarding by this. That's what the queries [a] and [b] and P3905 were about.

"so grouping by [sessionToken] may be eliminating valid clicks and raising the duplicates %" - no, not in this kind of calculation ;) On the contrary, I added grouping by sessionToken in the above queries to increase accuracy, because otherwise events from different users (sessions) that happened to share the same source and target page would be counted as duplicates. (Note that those queries already grouped by other fields. Once you already have a GROUP BY clause in your query, adding more terms to that clause will increase the number of rows resulting from the query, rather than eliminating rows.)

In summary, given that there are still many more duplicates (as defined in T141922#2590553) than can be explained by the bug identified in T141922#2578626, I do not think we can trust the data yet.

From @phuedx and myself (pairing):

This was based on the assumption that multiple hovers over the same link will occur only in a minority of cases (or at least not in the vast majority of link interactions where the link is opened in the same tab). I.e. that most of the time, the user will hover over the same link only once. I think this is a very plausible assumption.

This assumption seems to be false from what we see on the data.

That there are "duplicate" events that don't have the same linkInteractionToken means that users are hovering over a link more than once before they click it (and with the bug sending multiple click events).

From what we've seen, both code paths hovercards off and on should behave properly now (with the exception of weird browser behaviors with hovers).

We have re-run the tests against staging, now that Baha's fix for the bug has been merged into the codebase and the duplicate hovers behavior is fixed now in master: https://gist.github.com/joakin/c832f08a14987bd12e6730de837bda20#disabled-hover-link--click-3

Maybe we need to re-run the A/B test.

From @phuedx and myself (pairing):

Related to the bump the 18th August

August 18th was group 2 wiki deployment day. It doesn't seem that there were also any config changes in general that could affect this.

We're going to find out which deployment branch was released on 18th 1.28.0-wmf.15 – and check EventLogging to see if anything was changed that week.

From @phuedx and myself (pairing):

On the contrary, I added grouping by sessionToken in the above queries to increase accuracy, because otherwise events from different users (sessions) that happened to share the same source and target page would be counted as duplicates.

Yes we understand not grouping by any token would result in miscounting events to the same link from different users.

sessionToken is unique per user and survives page loads – if you visit a page you get sessionToken A, click a link, then go back and click the same link, you still get sessionToken A. pageToken is unique per user per page load and doesn't survive page loads – if you visit a page, you get pageToken A, click a link, then go back and click the same link, you get pageToken B.

Our worry is that in in [b] with popupsEnabled=1, those 2% of duplicate clicks could represent valid user behaviour.

If any of the assumptions are wrong please correct us, otherwise we think it would be interesting to re-run [a] and [b] grouping by pageToken, or with pageToken and sessionToken.

In summary, given that there are still many more duplicates (as defined in T141922#2590553) than can be explained by the bug identified in T141922#2578626, I do not think we can trust the data yet.

We're still not sure there's a way to make this data set completely valid by amending which queries we run, so it maybe the case that we need to repeat the experiment now that the bug (T141922#2578626) has been fixed to get more trustworthy data.

phuedx added a comment.EditedSep 1 2016, 11:18 AM

Here's the list of changes to relevant codebases that were deployed on Thurdsay, August 18th. It is feasible that some code would affect the numbers given huwiki is in group 2 that get's the new code on Thursdays.

I think all changes can be discarded immediately, apart from 0ad88a24 which removes the jQuery.jStorage shim from the Popups code.

If a user had enabled Popups, then the shim would migrate that setting out of the old settings storage area into the new – from jQuery.jStorage to mw.storage – and then clean up. This would only happen once. This shim was in production for approximately two months before it was removed, in which time all settings for all users should have been migrated leaving the shim effectively doing nothing.

I can't see how this change could've affected the experiment or, specifically, reduced the number of duplicate clicks per session in the OFF condition.

Maybe we need to re-run the A/B test.

Once the code goes to production, it will be interesting to see what the data now say. I think we're assuming there will be a correction that will no longer require tuning parameters.

Assuming consultation goes well, an A/B test or two of Hovercards are tentatively planned for the latter part of Reading-Web-Sprint-81-We-suck-at-coming-up-with-sprint-names, a sprint that starts 12-September-2016. @ovasileva is tracking on the consultation piece.

@Jhernandez @phuedx -

Suppose a user's mouse glances over link A for 150ms, then within the same page session the user's mouse goes to link B and clicks link B. Would that generate two events with different link interaction tokens bearing duplicate fields?...other than, obviously, the session token and page token.

We're still not sure there's a way to make this data set completely valid by amending which queries we run, so it maybe the case that we need to repeat the experiment now that the bug (T141922#2578626) has been fixed to get more trustworthy data.

We should look at the data since the fix and see what we're getting now. In addition, the next two A/B tests are scheduled for the end of next sprint, which will give us an additional basis for comparison.

From @phuedx and myself (pairing):

On the contrary, I added grouping by sessionToken in the above queries to increase accuracy, because otherwise events from different users (sessions) that happened to share the same source and target page would be counted as duplicates.

Yes we understand not grouping by any token would result in miscounting events to the same link from different users.

I feel we may still be talking past each other here. Again, the purpose of these queries [a] and [b] was not yet to actually count events for the end result, but to assess how often the duplication bug happens before filtering these events out.

sessionToken is unique per user and survives page loads – if you visit a page you get sessionToken A, click a link, then go back and click the same link, you still get sessionToken A. pageToken is unique per user per page load and doesn't survive page loads – if you visit a page, you get pageToken A, click a link, then go back and click the same link, you get pageToken B.

Yes, I know this ;)

Our worry is that in in [b] with popupsEnabled=1, those 2% of duplicate clicks could represent valid user behaviour.
If any of the assumptions are wrong please correct us, otherwise we think it would be interesting to re-run [a] and [b] grouping by pageToken, or with pageToken and sessionToken.

OK, I *think* your concern may be that when counting singletons/duplicates in queries [a] and [b], clicks on the same link by the same user (session) during separate views of the same source page may have been erroneously counted as duplicates, correct? It is true that not grouping by pageToken (only by pageIdSource) was a bit of a shortcut. It was a deliberate decision which was also clearly spelled out in the comment to [b] ("not necessarily the same page session"). I had already included a check for identical source page titles and timestamps, and expected that adding the page token would not impact the result meaningfully for our purposes.
In any case, per your suggestion, I have re-run [a] and [b] with grouping by pageToken as well. As expected, the takeaway is the same, see [a*] and [b*] below. E.g. on the first day (July 28), [a*] measures still only 0.17% singletons for hovercards off, same as [a], with some slight differences on later days. The conclusion remains that for hovercards off, the overwhelming majority of 'opened in same tab' events (>99.5% until Aug 17, >97% after Aug 18) forms part of a multiple, redundant set of events that appears to have resulted from the same user action.

In summary, given that there are still many more duplicates (as defined in T141922#2590553) than can be explained by the bug identified in T141922#2578626, I do not think we can trust the data yet.

We're still not sure there's a way to make this data set completely valid by amending which queries we run, so it maybe the case that we need to repeat the experiment now that the bug (T141922#2578626) has been fixed to get more trustworthy data.

When did / will the fix go live?

[a*]
# repeat https://phabricator.wikimedia.org/T141922#2590553 [a] with event_pageToken added (and for all dates)
SELECT singletonsperday.popupEnabled, singletonsperday.yearmonthday, ROUND(100*singletons/totalevents,2) AS singletons_percentage FROM
	(SELECT popupEnabled, yearmonthday, SUM(1) AS singletons FROM
		(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
		event_sessionToken, event_pageToken, event_pageIdSource, event_pageTitleHover,
		COUNT(*) AS copies
		FROM log.Popups_15777589 
		WHERE wiki ='huwiki' AND event_isAnon = 1
		AND event_action = 'opened in same tab'
		GROUP BY popupEnabled, yearmonthday,
		event_sessionToken, event_pageToken, event_pageIdSource, event_pageTitleHover
		HAVING copies=1) AS singletons
	GROUP BY popupEnabled, yearmonthday) AS singletonsperday
JOIN
	(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
	COUNT(*) AS totalevents
	FROM log.Popups_15777589 
	WHERE wiki ='huwiki' AND event_isAnon = 1
	AND event_action = 'opened in same tab'
	GROUP BY popupEnabled, yearmonthday) AS totaleventsperday
ON singletonsperday.popupEnabled = totaleventsperday.popupEnabled
AND singletonsperday.yearmonthday = totaleventsperday.yearmonthday
ORDER BY popupEnabled, yearmonthday;

+--------------+--------------+-----------------------+
| popupEnabled | yearmonthday | singletons_percentage |
+--------------+--------------+-----------------------+
|            0 | 20160728     |                  0.17 |
|            0 | 20160729     |                  0.12 |
|            0 | 20160730     |                  0.43 |
|            0 | 20160731     |                  0.09 |
|            0 | 20160801     |                  0.18 |
|            0 | 20160802     |                  0.21 |
|            0 | 20160803     |                  0.26 |
|            0 | 20160804     |                  0.24 |
|            0 | 20160805     |                  0.12 |
|            0 | 20160806     |                  0.24 |
|            0 | 20160807     |                  0.21 |
|            0 | 20160808     |                  0.19 |
|            0 | 20160809     |                  0.24 |
|            0 | 20160810     |                  0.23 |
|            0 | 20160811     |                  0.22 |
|            0 | 20160812     |                  0.27 |
|            0 | 20160813     |                  0.29 |
|            0 | 20160814     |                  0.26 |
|            0 | 20160815     |                  0.21 |
|            0 | 20160816     |                  0.15 |
|            0 | 20160817     |                  0.12 |
|            0 | 20160818     |                  1.88 |
|            0 | 20160819     |                  2.67 |
|            0 | 20160820     |                  2.56 |
|            0 | 20160821     |                  2.79 |
|            0 | 20160822     |                  2.52 |
|            0 | 20160823     |                  2.50 |
|            0 | 20160824     |                  2.41 |
|            0 | 20160825     |                  2.40 |
|            0 | 20160826     |                  2.50 |
|            0 | 20160827     |                  2.83 |
|            0 | 20160828     |                  2.86 |
|            0 | 20160829     |                  2.21 |
|            0 | 20160830     |                  2.43 |
|            0 | 20160831     |                  2.58 |
|            0 | 20160901     |                  2.16 |
|            1 | 20160728     |                 98.63 |
|            1 | 20160729     |                 99.38 |
|            1 | 20160730     |                 98.96 |
|            1 | 20160731     |                 98.84 |
|            1 | 20160801     |                 99.52 |
|            1 | 20160802     |                 99.20 |
|            1 | 20160803     |                 96.92 |
|            1 | 20160804     |                 98.35 |
|            1 | 20160805     |                 99.14 |
|            1 | 20160806     |                 98.72 |
|            1 | 20160807     |                 98.93 |
|            1 | 20160808     |                 98.91 |
|            1 | 20160809     |                 98.75 |
|            1 | 20160810     |                 98.27 |
|            1 | 20160811     |                 98.17 |
|            1 | 20160812     |                 98.51 |
|            1 | 20160813     |                 97.70 |
|            1 | 20160814     |                 99.12 |
|            1 | 20160815     |                 98.36 |
|            1 | 20160816     |                 99.08 |
|            1 | 20160817     |                 99.15 |
|            1 | 20160818     |                 99.42 |
|            1 | 20160819     |                 98.49 |
|            1 | 20160820     |                 97.70 |
|            1 | 20160821     |                 99.16 |
|            1 | 20160822     |                 99.14 |
|            1 | 20160823     |                 99.18 |
|            1 | 20160824     |                 98.86 |
|            1 | 20160825     |                 99.13 |
|            1 | 20160826     |                 99.19 |
|            1 | 20160827     |                 98.86 |
|            1 | 20160828     |                 99.46 |
|            1 | 20160829     |                 98.74 |
|            1 | 20160830     |                 99.25 |
|            1 | 20160831     |                 98.93 |
|            1 | 20160901     |                 98.54 |
+--------------+--------------+-----------------------+
72 rows in set (1 min 18.43 sec)
[b*]
# repeat https://phabricator.wikimedia.org/T141922#2590553 [b] with event_pageToken added (and for all dates)
# determine ratio of duplicate opens, i.e. same source page and same linked page 
# during the same browser session and pageview session
SELECT dupesperday.popupEnabled, dupesperday.yearmonthday, ROUND(100*dupes/totalevents,2) AS dupes_percentage FROM
	(SELECT popupEnabled, yearmonthday, SUM(copies-1) AS dupes FROM
		(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
		event_sessionToken, event_pageToken, event_pageIdSource, event_pageTitleHover,
		COUNT(*) AS copies
		FROM log.Popups_15777589 
		WHERE wiki ='huwiki' AND event_isAnon = 1
		AND event_action = 'opened in same tab'
		GROUP BY popupEnabled, yearmonthday,
		event_sessionToken, event_pageToken, event_pageIdSource, event_pageTitleHover
		HAVING copies>1) AS dupeslist
	GROUP BY popupEnabled, yearmonthday) AS dupesperday
	JOIN
	(SELECT event_popupEnabled AS popupEnabled, LEFT(timestamp, 8) AS yearmonthday,
	COUNT(*) AS totalevents
	FROM log.Popups_15777589 
	WHERE wiki ='huwiki' AND event_isAnon = 1
	AND event_action = 'opened in same tab'
	GROUP BY popupEnabled, yearmonthday) AS totaleventsperday
	ON dupesperday.popupEnabled = totaleventsperday.popupEnabled
	AND dupesperday.yearmonthday = totaleventsperday.yearmonthday
ORDER BY popupEnabled, yearmonthday;

+--------------+--------------+------------------+
| popupEnabled | yearmonthday | dupes_percentage |
+--------------+--------------+------------------+
|            0 | 20160728     |            59.10 |
|            0 | 20160729     |            59.54 |
|            0 | 20160730     |            58.71 |
|            0 | 20160731     |            59.78 |
|            0 | 20160801     |            59.14 |
|            0 | 20160802     |            59.80 |
|            0 | 20160803     |            59.97 |
|            0 | 20160804     |            59.79 |
|            0 | 20160805     |            59.75 |
|            0 | 20160806     |            59.77 |
|            0 | 20160807     |            59.48 |
|            0 | 20160808     |            60.21 |
|            0 | 20160809     |            59.56 |
|            0 | 20160810     |            59.46 |
|            0 | 20160811     |            59.43 |
|            0 | 20160812     |            59.28 |
|            0 | 20160813     |            59.43 |
|            0 | 20160814     |            57.94 |
|            0 | 20160815     |            59.66 |
|            0 | 20160816     |            59.44 |
|            0 | 20160817     |            59.98 |
|            0 | 20160818     |            58.52 |
|            0 | 20160819     |            57.82 |
|            0 | 20160820     |            57.89 |
|            0 | 20160821     |            57.13 |
|            0 | 20160822     |            58.30 |
|            0 | 20160823     |            57.94 |
|            0 | 20160824     |            58.04 |
|            0 | 20160825     |            58.48 |
|            0 | 20160826     |            57.96 |
|            0 | 20160827     |            57.42 |
|            0 | 20160828     |            57.38 |
|            0 | 20160829     |            58.42 |
|            0 | 20160830     |            58.99 |
|            0 | 20160831     |            57.94 |
|            0 | 20160901     |            58.90 |
|            1 | 20160728     |             0.74 |
|            1 | 20160729     |             0.31 |
|            1 | 20160730     |             0.56 |
|            1 | 20160731     |             0.65 |
|            1 | 20160801     |             0.25 |
|            1 | 20160802     |             0.41 |
|            1 | 20160803     |             1.58 |
|            1 | 20160804     |             0.88 |
|            1 | 20160805     |             0.45 |
|            1 | 20160806     |             0.68 |
|            1 | 20160807     |             0.56 |
|            1 | 20160808     |             0.63 |
|            1 | 20160809     |             0.67 |
|            1 | 20160810     |             0.97 |
|            1 | 20160811     |             0.94 |
|            1 | 20160812     |             0.83 |
|            1 | 20160813     |             1.47 |
|            1 | 20160814     |             0.48 |
|            1 | 20160815     |             0.89 |
|            1 | 20160816     |             0.47 |
|            1 | 20160817     |             0.43 |
|            1 | 20160818     |             0.31 |
|            1 | 20160819     |             0.78 |
|            1 | 20160820     |             1.31 |
|            1 | 20160821     |             0.45 |
|            1 | 20160822     |             0.45 |
|            1 | 20160823     |             0.47 |
|            1 | 20160824     |             0.57 |
|            1 | 20160825     |             0.48 |
|            1 | 20160826     |             0.42 |
|            1 | 20160827     |             0.70 |
|            1 | 20160828     |             0.27 |
|            1 | 20160829     |             0.67 |
|            1 | 20160830     |             0.39 |
|            1 | 20160831     |             0.57 |
|            1 | 20160901     |             0.82 |
+--------------+--------------+------------------+
72 rows in set (1 min 7.28 sec)

PS: Perhaps it's more instructive to simply look at the concrete event log excerpt P3905 (instead of discussing the duplicate-counting queries [a] and [b]).

It demonstrates directly that for hovercards off, an 'opened in same tab' event almost never comes by itself, but is almost always accompanied by one or more duplicates that have the same timestamp but different totalInteractionTime.

Following the above discussion I have regenerated to also include pageToken. As expected, its value is identical among the previously identified duplicates, meaning that we did not accidentally lump together link interactions from different views of the page.

SELECT event_sessionToken AS sessionToken, event_pageTitleSource AS pageTitleSource, event_pageTitleHover AS pageTitleHover, 
  CONCAT(MID(timestamp,11,2),':',RIGHT(timestamp, 2)) AS mm_ss, event_totalInteractionTime AS tIaTime, event_pageToken as pageToken
FROM log.Popups_15777589 
WHERE wiki ='huwiki'
AND event_isAnon = 1
AND timestamp LIKE '201608DDHH%' # replace "DDHH" with exact day and hour to reproduce result below
AND event_popupEnabled = 0
AND event_action = 'opened in same tab'
ORDER BY event_sessionToken, event_pageTitleSource, event_pageTitleHover, timestamp;

+------------------+-----------------------------------------+-----------------------------------------------+-------+---------+-----------------------------------------------+
| sessionToken     | pageTitleSource                         | pageTitleHover                                | mm_ss | tIaTime | pageToken                                     |
+------------------+-----------------------------------------+-----------------------------------------------+-------+---------+-----------------------------------------------+
| 0a76e80a6252b361 | James Bond                              | George Lazenby                                | 06:28 |    1883 | c237619583dd94f41472169918769db9bfbcdae8f8772 |
| 0a76e80a6252b361 | James Bond                              | George Lazenby                                | 06:28 |     259 | c237619583dd94f41472169918769db9bfbcdae8f8772 |
| 0a76e80a6252b361 | James Bond                              | Sean Connery                                  | 06:47 |     194 | c3b2635f60ac1aae147217001073957d10c432a24fdc0 |
| 0a76e80a6252b361 | James Bond                              | Sean Connery                                  | 06:47 |     592 | c3b2635f60ac1aae147217001073957d10c432a24fdc0 |
| 0a76e80a6252b361 | James Bond                              | Timothy Dalton                                | 06:41 |    1307 | 5b06503dd9b48b1e147217000283225899648d6667dfa |
| 0a76e80a6252b361 | James Bond                              | Timothy Dalton                                | 06:41 |     208 | 5b06503dd9b48b1e147217000283225899648d6667dfa |
| 45e707635d33a4ee | Hidegháború                             | Második világháború                           | 09:53 |     130 | b1eddf16f17993b914721700308118b82c398294aff24 |
| 45e707635d33a4ee | Hidegháború                             | Második világháború                           | 09:53 |      74 | b1eddf16f17993b914721700308118b82c398294aff24 |
| 4a8aea93a63b7ad5 | Higgs-bozon                             | Peter Higgs                                   | 59:27 |     735 | d4b4d0672b42e0651472172250772b2d50d195efe08fc |
| 4a8aea93a63b7ad5 | Higgs-bozon                             | Peter Higgs                                   | 59:27 |     877 | d4b4d0672b42e0651472172250772b2d50d195efe08fc |
| 4bae0575026331db | A holokauszt áldozatai                  | Arany Dániel                                  | 04:56 |     719 | 844772a0230d27e9147209017045340dcb8a332709f7d |
| 4bae0575026331db | Judik Etel                              | Karinthy Frigyes                              | 04:04 |     109 | 45610c80fce3815d14720900959366e18ebbc55ff19a5 |
| 4bae0575026331db | Judik Etel                              | Karinthy Frigyes                              | 04:04 |    1266 | 45610c80fce3815d14720900959366e18ebbc55ff19a5 |
| 4bae0575026331db | Karinthy Frigyes                        | Böhm Aranka                                   | 04:15 |     969 | cda81c45f039fa491472090131172bb7b0a2032ccde55 |
| 4bae0575026331db | Karinthy Frigyes                        | Böhm Aranka                                   | 04:15 |     109 | cda81c45f039fa491472090131172bb7b0a2032ccde55 |
| 4bae0575026331db | Karinthy Gábor                          | Judik Etel                                    | 03:30 |     609 | 94a8f76fcdb81ddb14720900771725a212c6d3735b872 |
| 4bae0575026331db | Karinthy Gábor                          | Judik Etel                                    | 03:30 |     125 | 94a8f76fcdb81ddb14720900771725a212c6d3735b872 |
| 4bae0575026331db | Karinthy Márton                         | Karinthy Gábor                                | 03:11 |     531 | 65dd852e1ae08a2a14720900361569fce4ae8114519ea |
| 4bae0575026331db | Magyar LMBT költők, írók                | Karinthy Márton                               | 02:30 |     610 | 092579b0cf9a2cc614720900306407131ee0c958d1b35 |
| 4bae0575026331db | Magyar LMBT költők, írók                | Karinthy Márton                               | 02:30 |     125 | 092579b0cf9a2cc614720900306407131ee0c958d1b35 |
| 4bae0575026331db | Magyar LMBT költők, írók                | Lovas Nagy Anna                               | 02:11 |      94 | 4f3909bb40bd0aa71472089999015261cf331461daf62 |
| 4bae0575026331db | Magyar LMBT költők, írók                | Lovas Nagy Anna                               | 02:11 |     469 | 4f3909bb40bd0aa71472089999015261cf331461daf62 |
| 4bae0575026331db | Magyar LMBT színészek                   | Steiner Kristóf                               | 01:05 |     625 | bc218b8d47092a6414720899385933716453f786e5a93 |
| 4bae0575026331db | Magyar LMBT színészek                   | Steiner Kristóf                               | 01:05 |     125 | bc218b8d47092a6414720899385933716453f786e5a93 |
| 508d3e5cf1d06a19 | Jókai Mór                               | Szeretve mind a vérpadig                      | 58:31 |    2116 | e06c027d609fb2ba147216784672471e9a4b1e904eb75 |
| 508d3e5cf1d06a19 | Jókai Mór                               | Szeretve mind a vérpadig                      | 58:31 |     840 | e06c027d609fb2ba147216784672471e9a4b1e904eb75 |
| 508d3e5cf1d06a19 | Jókai Mór                               | Szeretve mind a vérpadig                      | 58:31 |     186 | e06c027d609fb2ba147216784672471e9a4b1e904eb75 |
| 5ebd6f3b87a55ed4 | Peller Anna                             | Gór Nagy Mária                                | 34:59 |     703 | 2d7753f6d9a0512714721709063681e4cee426fb3a371 |
| 5ebd6f3b87a55ed4 | Peller Anna                             | Gór Nagy Mária                                | 34:59 |     278 | 2d7753f6d9a0512714721709063681e4cee426fb3a371 |
| 5ebd6f3b87a55ed4 | Peller Anna                             | Gór Nagy Mária                                | 34:59 |      78 | 2d7753f6d9a0512714721709063681e4cee426fb3a371 |
| 5ebd6f3b87a55ed4 | Peller Mariann (egyértelműsítő lap)     | Peller Mariann (műsorvezető)                  | 21:30 |     316 | 039df2ef57b9c96d1472170895205b42f7dcf0f0fc1d3 |
| 5ebd6f3b87a55ed4 | Peller Mariann (egyértelműsítő lap)     | Peller Mariann (műsorvezető)                  | 21:30 |     109 | 039df2ef57b9c96d1472170895205b42f7dcf0f0fc1d3 |
| 5ebd6f3b87a55ed4 | Váci egyházmegye                        | Beer Miklós                                   | 16:34 |     688 | f48fb972aabcd47814721705961884132413fc842ed5c |
| 5ebd6f3b87a55ed4 | Váci egyházmegye                        | Beer Miklós                                   | 16:34 |      68 | f48fb972aabcd47814721705961884132413fc842ed5c |
| 8e6323bdcb720659 | J. R. R. Tolkien                        | Christopher Tolkien                           | 02:00 |     882 | a8426a46968ba280147216969631597dd71b3976e9c98 |
| 8e6323bdcb720659 | J. R. R. Tolkien                        | Christopher Tolkien                           | 02:00 |      75 | a8426a46968ba280147216969631597dd71b3976e9c98 |
| 9377e6bbf5e58daf | Széll Kálmán (politikus)                | Moszkva tér                                   | 00:27 |     202 | d8cbed157b3b14191472169470389346c899134a2e1fc |
| 9377e6bbf5e58daf | Széll Kálmán (politikus)                | Moszkva tér                                   | 00:27 |    2709 | d8cbed157b3b14191472169470389346c899134a2e1fc |
| a4bf8b22b43cc596 | Carl Gustav Jung                        | Mircea Eliade                                 | 55:26 |     655 | 64ab1842424cbcb514721724482043a0c15a04c2e5c25 |
| a4bf8b22b43cc596 | Carl Gustav Jung                        | Mircea Eliade                                 | 55:26 |     266 | 64ab1842424cbcb514721724482043a0c15a04c2e5c25 |
| a4bf8b22b43cc596 | Mircea Eliade                           | Vasgárda                                      | 57:32 |     234 | 548cfadb6053b97c14721729234752b633a6aa89cb8e7 |
| a4bf8b22b43cc596 | Mircea Eliade                           | Vasgárda                                      | 57:32 |    1466 | 548cfadb6053b97c14721729234752b633a6aa89cb8e7 |
| a4bf8b22b43cc596 | Mircea Eliade                           | Vasgárda                                      | 57:32 |    4274 | 548cfadb6053b97c14721729234752b633a6aa89cb8e7 |
| b359fd31be154ec0 | Az olimpiai játékok éremtáblázata       | Olimpiai játékok                              | 05:18 |     883 | 0ac8d9b50e4f69581472169903864b5f3b668da576bc6 |
| b359fd31be154ec0 | Az olimpiai játékok éremtáblázata       | Olimpiai játékok                              | 05:18 |       4 | 0ac8d9b50e4f69581472169903864b5f3b668da576bc6 |
| b359fd31be154ec0 | Olimpiai játékok                        | Többszörös olimpiai aranyérmesek listája      | 06:37 |     875 | 67383f7cc7f589a714721699165820d649c2ce64b1cba |
| b359fd31be154ec0 | Olimpiai játékok                        | Többszörös olimpiai aranyérmesek listája      | 06:37 |      12 | 67383f7cc7f589a714721699165820d649c2ce64b1cba |
| d4f83f4722d1b0d8 | Váradi Júlia                            | Preisich Gábor                                | 52:32 |     132 | a33d364771a366fb147217272030008ba4953fba6b596 |
| d4f83f4722d1b0d8 | Váradi Júlia                            | Preisich Gábor                                | 52:32 |    2980 | a33d364771a366fb147217272030008ba4953fba6b596 |
| d4f83f4722d1b0d8 | Váradi Júlia                            | Preisich Gábor                                | 52:32 |    1669 | a33d364771a366fb147217272030008ba4953fba6b596 |
| dec3fe98a7069196 | Gombamérgek                             | Aflatoxin                                     | 09:56 |     118 | 5a0b7a9502b3b27514721701918026b7ff34b9393227c |
| dec3fe98a7069196 | Gombamérgek                             | Aflatoxin                                     | 09:56 |     273 | 5a0b7a9502b3b27514721701918026b7ff34b9393227c |
| dec3fe98a7069196 | Gombamérgek                             | Citrinin                                      | 10:16 |      66 | 894463a0f349891e147217021616303abe5d3fee4b03d |
| dec3fe98a7069196 | Gombamérgek                             | Citrinin                                      | 10:16 |     445 | 894463a0f349891e147217021616303abe5d3fee4b03d |
| dec3fe98a7069196 | Gombamérgek                             | Patulin                                       | 11:00 |     296 | 2ba8aeabc2007043147217025778859541fbfda75e743 |
| dec3fe98a7069196 | Gombamérgek                             | Patulin                                       | 11:00 |      91 | 2ba8aeabc2007043147217025778859541fbfda75e743 |
| dec3fe98a7069196 | Gombamérgek                             | Pszilocin                                     | 11:26 |     246 | 45375f93120e30d4147217028545064083aae611b8af6 |
| dec3fe98a7069196 | Gombamérgek                             | Pszilocin                                     | 11:26 |     539 | 45375f93120e30d4147217028545064083aae611b8af6 |
| dec3fe98a7069196 | Gombamérgek                             | Pszilocin                                     | 11:26 |     122 | 45375f93120e30d4147217028545064083aae611b8af6 |
| dec3fe98a7069196 | Gombamérgek                             | Tenuazonsav                                   | 11:40 |     269 | 04f5d6057b46ca591472170298768b881897466855c3e |
| dec3fe98a7069196 | Gombamérgek                             | Tenuazonsav                                   | 11:40 |     110 | 04f5d6057b46ca591472170298768b881897466855c3e |
| dec3fe98a7069196 | Gombamérgek                             | Vomitoxin                                     | 12:09 |     284 | 33798893093d8e7b14721703289672c4cfb7c8f9e33aa |
| dec3fe98a7069196 | Gombamérgek                             | Vomitoxin                                     | 12:09 |     117 | 33798893093d8e7b14721703289672c4cfb7c8f9e33aa |
| dec3fe98a7069196 | Hegyes badargomba                       | Pszilocibin                                   | 03:11 |     341 | 9244c3d080524cec1472169758751e18ffccf0630fb18 |
| dec3fe98a7069196 | Hegyes badargomba                       | Pszilocibin                                   | 03:11 |      79 | 9244c3d080524cec1472169758751e18ffccf0630fb18 |
| dec3fe98a7069196 | Iboténsav                               | Gamma-amino-vajsav                            | 06:51 |      97 | 91622081f8e39cdb1472170007021fec065a2787bb46f |
| dec3fe98a7069196 | Iboténsav                               | Gamma-amino-vajsav                            | 06:51 |     397 | 91622081f8e39cdb1472170007021fec065a2787bb46f |
| dec3fe98a7069196 | Keresés                                 | Kutyatej                                      | 12:43 |      97 | c53d84212f28e4d61472170361190de9f6952f44937f9 |
| dec3fe98a7069196 | Keresés                                 | Szobanövények                                 | 12:54 |     301 | 1fe78ab0b9c2b60f14721703678232e1dc4cb061db915 |
| dec3fe98a7069196 | Keresés                                 | Szobanövények                                 | 12:54 |     879 | 1fe78ab0b9c2b60f14721703678232e1dc4cb061db915 |
| dec3fe98a7069196 | Keresés                                 | Szobanövények                                 | 12:54 |      97 | 1fe78ab0b9c2b60f14721703678232e1dc4cb061db915 |
| dec3fe98a7069196 | Kígyógomba                              | Muszkarin                                     | 04:49 |     311 | 4be7d9cde3e339201472169870659b13a41863690a108 |
| dec3fe98a7069196 | Kígyógomba                              | Muszkarin                                     | 04:49 |      70 | 4be7d9cde3e339201472169870659b13a41863690a108 |
| dec3fe98a7069196 | Légyölő galóca                          | Iboténsav                                     | 06:45 |     973 | caddcfa15289f6b214721700001412fcaaa5118ac3cb9 |
| dec3fe98a7069196 | Légyölő galóca                          | Iboténsav                                     | 06:45 |     110 | caddcfa15289f6b214721700001412fcaaa5118ac3cb9 |
| dec3fe98a7069196 | Muszkarin                               | Atropin                                       | 05:53 |    6946 | 78049c9233ad22561472169890515aafee6c623fd5dae |
| dec3fe98a7069196 | Muszkarin                               | Atropin                                       | 05:53 |     113 | 78049c9233ad22561472169890515aafee6c623fd5dae |
| dec3fe98a7069196 | Muszkarin                               | Atropin                                       | 05:53 |     257 | 78049c9233ad22561472169890515aafee6c623fd5dae |
| dec3fe98a7069196 | Muszkarin                               | Atropin                                       | 05:53 |   19959 | 78049c9233ad22561472169890515aafee6c623fd5dae |
| dec3fe98a7069196 | Mérgező gombák                          | Cifra korallgomba                             | 00:55 |      68 | 0c3135dbafb562e4147216965382276946f9f5c1671b1 |
| dec3fe98a7069196 | Mérgező gombák                          | Cifra korallgomba                             | 00:55 |     556 | 0c3135dbafb562e4147216965382276946f9f5c1671b1 |
| dec3fe98a7069196 | Mérgező gombák                          | Fehér galóca                                  | 01:15 |    2695 | 97f43a5a0a93fff31472169672267ccebb003b084c658 |
| dec3fe98a7069196 | Mérgező gombák                          | Fehér galóca                                  | 01:15 |     124 | 97f43a5a0a93fff31472169672267ccebb003b084c658 |
| dec3fe98a7069196 | Mérgező gombák                          | Fehér galóca                                  | 01:15 |     414 | 97f43a5a0a93fff31472169672267ccebb003b084c658 |
| dec3fe98a7069196 | Mérgező gombák                          | Feketedő nedűgomba                            | 01:24 |      97 | 8e959c5310e7dc4b14721696833644c4035e5dffcff20 |
| dec3fe98a7069196 | Mérgező gombák                          | Feketedő nedűgomba                            | 01:24 |     670 | 8e959c5310e7dc4b14721696833644c4035e5dffcff20 |
| dec3fe98a7069196 | Mérgező gombák                          | Fenolszagú csiperke                           | 01:45 |    1431 | 01dd2dbc0cfafb5f147216970328166cdc965d0fd18ad |
| dec3fe98a7069196 | Mérgező gombák                          | Fenolszagú csiperke                           | 01:45 |     130 | 01dd2dbc0cfafb5f147216970328166cdc965d0fd18ad |
| dec3fe98a7069196 | Mérgező gombák                          | Hagymatönkű pókhálósgomba                     | 02:08 |    2227 | dff7c190a3e13a74147216972566282b2927ad159665d |
| dec3fe98a7069196 | Mérgező gombák                          | Hagymatönkű pókhálósgomba                     | 02:08 |     131 | dff7c190a3e13a74147216972566282b2927ad159665d |
| dec3fe98a7069196 | Mérgező gombák                          | Hegyes badargomba                             | 02:37 |     660 | bca5a54da8ab4c561472169756659ef3d40770b52bba2 |
| dec3fe98a7069196 | Mérgező gombák                          | Hegyes badargomba                             | 02:37 |     124 | bca5a54da8ab4c561472169756659ef3d40770b52bba2 |
| dec3fe98a7069196 | Mérgező gombák                          | Hegyeskalapú galóca                           | 04:18 |     103 | cf5f08edcfd4bc1914721698582216fe59dbf277967d4 |
| dec3fe98a7069196 | Mérgező gombák                          | Hegyeskalapú galóca                           | 04:18 |     547 | cf5f08edcfd4bc1914721698582216fe59dbf277967d4 |
| dec3fe98a7069196 | Mérgező gombák                          | Hánytató galambgomba                          | 02:25 |      52 | 7eb5a7ca79711d9514721697446896b17465669bdd99e |
| dec3fe98a7069196 | Mérgező gombák                          | Hánytató galambgomba                          | 02:25 |     816 | 7eb5a7ca79711d9514721697446896b17465669bdd99e |
| dec3fe98a7069196 | Mérgező gombák                          | Kubai badargomba                              | 06:10 |     327 | 3b64afff695a37891472169959614622468e0e5abdad0 |
| dec3fe98a7069196 | Mérgező gombák                          | Kubai badargomba                              | 06:10 |     128 | 3b64afff695a37891472169959614622468e0e5abdad0 |
| dec3fe98a7069196 | Mérgező gombák                          | Kígyógomba                                    | 04:29 |     160 | 4ac52fc131193149147216986773593baf7a8e20a4b1c |
| dec3fe98a7069196 | Mérgező gombák                          | Kígyógomba                                    | 04:29 |     483 | 4ac52fc131193149147216986773593baf7a8e20a4b1c |
| dec3fe98a7069196 | Mérgező gombák                          | Légyölő galóca                                | 06:38 |      93 | 686cadc0a0abfc841472169997983c15b3963a88a46ea |
| dec3fe98a7069196 | Mérgező gombák                          | Légyölő galóca                                | 06:38 |     212 | 686cadc0a0abfc841472169997983c15b3963a88a46ea |
| dec3fe98a7069196 | Mérgező gombák                          | Nagy döggomba                                 | 07:03 |     215 | 99739c85c1c603111472170021571e2e3d6ee6778dc90 |
| dec3fe98a7069196 | Mérgező gombák                          | Nagy döggomba                                 | 07:03 |     125 | 99739c85c1c603111472170021571e2e3d6ee6778dc90 |
| dec3fe98a7069196 | Mérgező gombák                          | Párducgalóca                                  | 07:19 |     100 | 5d4dd1013bb4246c1472170038502de1cf301b4fbd0bc |
| dec3fe98a7069196 | Mérgező gombák                          | Párducgalóca                                  | 07:19 |     344 | 5d4dd1013bb4246c1472170038502de1cf301b4fbd0bc |
| dec3fe98a7069196 | Mérgező gombák                          | Redős papsapkagomba                           | 07:35 |    2779 | f97eaec60a69225f1472170049077579eb4afeaaffa62 |
| dec3fe98a7069196 | Mérgező gombák                          | Redős papsapkagomba                           | 07:35 |      79 | f97eaec60a69225f1472170049077579eb4afeaaffa62 |
| dec3fe98a7069196 | Mérgező gombák                          | Retekszagú kígyógomba                         | 08:17 |     129 | fa3db50a620793e614721700964220d98a843f987d731 |
| dec3fe98a7069196 | Mérgező gombák                          | Retekszagú kígyógomba                         | 08:17 |    1067 | fa3db50a620793e614721700964220d98a843f987d731 |
| dec3fe98a7069196 | Mérgező gombák                          | Retekszagú kígyógomba                         | 08:17 |     419 | fa3db50a620793e614721700964220d98a843f987d731 |
| dec3fe98a7069196 | Mérgező gombák                          | Sárga galóca                                  | 08:40 |      93 | b3be89b36294017b147217012058865994284219e7047 |
| dec3fe98a7069196 | Mérgező gombák                          | Sárga galóca                                  | 08:40 |     360 | b3be89b36294017b147217012058865994284219e7047 |
| dec3fe98a7069196 | Mérgező gombák                          | Sárga kénvirággomba                           | 08:59 |      89 | cc44a3eb6d95c1df147217013700203dab6c3f5b3ad5c |
| dec3fe98a7069196 | Mérgező gombák                          | Sárga kénvirággomba                           | 08:59 |    1411 | cc44a3eb6d95c1df147217013700203dab6c3f5b3ad5c |
| dec3fe98a7069196 | Mérgező gombák                          | Sárga kénvirággomba                           | 08:59 |    1975 | cc44a3eb6d95c1df147217013700203dab6c3f5b3ad5c |
| dec3fe98a7069196 | Mérgező gombák                          | Sárga kénvirággomba                           | 08:59 |     296 | cc44a3eb6d95c1df147217013700203dab6c3f5b3ad5c |
| dec3fe98a7069196 | Mérgező gombák                          | Sátántinóru                                   | 09:24 |      97 | e0fbb4d3b6bc97b814721701540077514c964d843c81a |
| dec3fe98a7069196 | Mérgező gombák                          | Sátántinóru                                   | 09:24 |     293 | e0fbb4d3b6bc97b814721701540077514c964d843c81a |
| dec3fe98a7069196 | Mérgező gombák                          | Tulipán csészegomba                           | 09:36 |     338 | df2f4821663c50dd1472170174679ad83dbfff59883f6 |
| dec3fe98a7069196 | Mérgező gombák                          | Tulipán csészegomba                           | 09:36 |      63 | df2f4821663c50dd1472170174679ad83dbfff59883f6 |
| dec3fe98a7069196 | Mérgező gombák                          | Tulipán csészegomba                           | 09:36 |     974 | df2f4821663c50dd1472170174679ad83dbfff59883f6 |
| dfadfd5132fc4221 | Gábor Dénes Főiskola                    | Angster Erzsébet                              | 15:18 |     127 | c234c2c157737f4a1472080943324c793306a16ebb333 |
| dfadfd5132fc4221 | Gábor Dénes Főiskola                    | Angster Erzsébet                              | 15:18 |     876 | c234c2c157737f4a1472080943324c793306a16ebb333 |
| e6c53bb05fc2ea12 | Domain Name System                      | HTTP                                          | 46:59 |     846 | 4ebe4928d69604ee147217241953260494bc3c6d64d6e |
| e6c53bb05fc2ea12 | Domain Name System                      | HTTP                                          | 46:59 |     121 | 4ebe4928d69604ee147217241953260494bc3c6d64d6e |
| f3a04c25a9193d19 | Facundo Arana                           | Te vagy az életem                             | 36:00 |     119 | be435628f004765b1472171339849fff80e61f4401480 |
| f3a04c25a9193d19 | Facundo Arana                           | Te vagy az életem                             | 36:00 |     819 | be435628f004765b1472171339849fff80e61f4401480 |
+------------------+-----------------------------------------+-----------------------------------------------+-------+---------+-----------------------------------------------+
128 rows in set (0.07 sec)

PPS:

From @phuedx and myself (pairing):

This was based on the assumption that multiple hovers over the same link will occur only in a minority of cases (or at least not in the vast majority of link interactions where the link is opened in the same tab). I.e. that most of the time, the user will hover over the same link only once. I think this is a very plausible assumption.

This assumption seems to be false from what we see on the data.

True, but the whole point here is to assess whether the data is likely to be correct ;) And isn't it a plausible assumption? I for one rarely open a link on a website by moving my mouse over it, moving the mouse away, moving back and only then clicking the link.

PPPS:

From @phuedx and myself (pairing):

...

Our worry is that in in [b] with popupsEnabled=1, those 2% of duplicate clicks could represent valid user behaviour.

In the refined query [b*] that ratio is actually lower now - e.g. for July 28 0.74% instead of 1.79% in [b], and for most days below 1%. (Also, as described in T142667, there appears to be a persistent EventLogging problem affecting multiple schemas where sometimes duplicate (spurious) events are recorded in the table, which would need to be subtracted here.) So I don't think this will be a huge problem.
But yes, if the remaining small percentage represents actual duplicate user actions, there is a good chance that these occur in the control group too, i.e. that we would be discarding some valid user actions under your proposed correction method. Again though I would not expect this to be a major issue.

When did / will the fix go live?

The fix will be deployed on Thursday, 8th September.

OK, I *think* your concern may be that when counting singletons/duplicates in queries [a] and [b], clicks on the same link by the same user (session) during separate views of the same source page may have been erroneously counted as duplicates, correct?

Yeah that's what we were worried about, but it is not that important for what we were diagnosing. Sorry @Tbayer if we confused you.

It is true that not grouping by pageToken (only by pageIdSource) was a bit of a shortcut. It was a deliberate decision which was also clearly spelled out in the comment to [b] ("not necessarily the same page session"). I had already included a check for identical source page titles and timestamps, and expected that adding the page token would not impact the result meaningfully for our purposes.
In any case, per your suggestion, I have re-run [a] and [b] with grouping by pageToken as well. As expected, the takeaway is the same, see [a*] and [b*] below. E.g. on the first day (July 28), [a*] measures still only 0.17% singletons for hovercards off, same as [a], with some slight differences on later days. The conclusion remains that for hovercards off, the overwhelming majority of 'opened in same tab' events (>99.5% until Aug 17, >97% after Aug 18) forms part of a multiple, redundant set of events that appears to have resulted from the same user action.

Right, I see. Good to know anyway, thanks for re-running them.


PS: Perhaps it's more instructive to simply look at the concrete event log excerpt P3905 (instead of discussing the duplicate-counting queries [a] and [b]).
It demonstrates directly that for hovercards off, an 'opened in same tab' event almost never comes by itself, but is almost always accompanied by one or more duplicates that have the same timestamp but different totalInteractionTime.
Following the above discussion I have regenerated to also include pageToken. As expected, its value is identical among the previously identified duplicates, meaning that we did not accidentally lump together link interactions from different views of the page.

Yeah, we see. We've looked very hard and couldn't find anything wrong other than this bug, that seems to explain it all really well if the users hover multiple times a link quickly before clicking it.

It is a weird assumption, but it is known how innacurate the mouse is and it may be that people when moving towards a target tend to fail and correct position to click which would explain the multiple hovers. It is all guessing, of course.

Since we don't log hovers before 250ms we can't really confirm this theory with neither hovercards OFF or ON with this data.

But yes, if the remaining small percentage represents actual duplicate user actions, there is a good chance that these occur in the control group too, i.e. that we would be discarding some valid user actions under your proposed correction method. Again though I would not expect this to be a major issue.

Nice.

I'm looking forward to the data after the deployment, because we couldn't see any other problems with the code, and I'm very curious to know if after this fix the data will make more sense (and what story it will tell).


As last steps (unless there are other questions) I'm going to be running some more browser tests related to interactions clicking the hovercards (instead of the links) to verify the correctness of those actions.

Will post updated test log and results when I'm done with it.

I've added clicking hovercards instead of links to the tests, everything seems fine. Same behavior as when clicking the links.

I believe we're almost done now. Anything else we can do @Tbayer @dr0ptp4kt?

Moving to signoff.

ovasileva closed this task as Resolved.Sep 7 2016, 7:08 PM

I believe we're almost done now. Anything else we can do @Tbayer @dr0ptp4kt?
Moving to signoff.

@Jhernandez and @phuedx: Cool, I'm glad we're on the same page now regarding these duplicates, and thanks for running the additional tests. I think we also agree that we remain in a quite frustrating situation, where there's either a still undetected bug in the instrumentation or we have stumbled upon a surprising insight about web users' behavior in general, somthing that would need some confirmation before one would be comfortable relying on it. Let's call it the "shaky mouse hypothesis" ;)

Nevertheless, when @ovasileva and I talked about this task on Tuesday, we agreed that it should be closed now, considering that we seem to have reached the end of what can be done with a reasonable amount of code debugging work, and that we will see what the new (post-fix) data from after today will bring. I'm also going to go ahead and regenerate the histogram from the task description with the duplicate correction applied, let's see what this shows. After this, we should make the call on whether we can rely on the corrected data.

...

I'm also going to go ahead and regenerate the histogram from the task description with the duplicate correction applied, let's see what this shows.

See below for the result, compared with the analogous histogram posted earlier for Hovercards ON and for Hovercards OFF without this duplicate correction.

To recap, this implements the correction method proposed T141922#2578626 (for multiple opened in same tab events over the same link during the same pageview, keep only the one with the lowest totalInteractionTime). Not surprisingly, this exacerbates rather than resolves the discrepancy that was a main motivation for doubting the veracity of the link interaction timing data, and thus this task: Namely, that there are so many more "fast opens" below 250ms for Hovercard off than for Hovercards on, even though the user experience is the same up to that point. By discarding the later open events and keeping the earliest ones, the correction actually increases the fast open ratio even more, reducing the green area right of 250ms.

Hovercards off, corrected:


Hovercards off, uncorrected:

Hovercards on:

(For direct comparability with the uncorrected version, this is for the previously examined timespan; I may redo this later for the data after the various fixes - including the one that rolled out on September 8, although that is not expected to change the takeaway described above.)

Data source:

SELECT FLOOR(event_totalInteractionTime/10) AS bucket, event_action AS action, COUNT(*) AS frequency
FROM log.Popups_15597282
WHERE wiki ='huwiki'
AND event_isAnon = 1
AND LEFT(timestamp, 8) > '20160607'
AND LEFT(timestamp, 8) < '20160707'
AND event_popupEnabled = 0
AND event_action != 'opened in same tab'
AND event_linkInteractionToken IS NOT NULL
GROUP BY bucket, action

UNION

SELECT FLOOR(mtIaTime/10) AS bucket, event_action AS action, COUNT(*) AS frequency
FROM
	(SELECT event_sessionToken AS sessionToken, event_pageToken, timestamp, event_pageTitleHover,
	 event_action, MIN(event_totalInteractionTime) AS mtIaTime
	FROM
	log.Popups_15597282
	WHERE wiki ='huwiki'
	AND event_isAnon = 1
	AND LEFT(timestamp, 8) > '20160607'
	AND LEFT(timestamp, 8) < '20160707'
	AND event_popupEnabled = 0
	AND event_linkInteractionToken IS NOT NULL
	AND event_action = 'opened in same tab'
	GROUP BY event_sessionToken, event_pageToken, timestamp, event_pageTitleHover
	) AS deduplicated_events
GROUP BY bucket, action

ORDER BY bucket, action;

(see T139319#2475143 and T139319#2481986 for the data sources of the second and third chart)

...

Yeah, we see. We've looked very hard and couldn't find anything wrong other than this bug, that seems to explain it all really well if the users hover multiple times a link quickly before clicking it.
It is a weird assumption, but it is known how innacurate the mouse is and it may be that people when moving towards a target tend to fail and correct position to click which would explain the multiple hovers. It is all guessing, of course.
Since we don't log hovers before 250ms we can't really confirm this theory with neither hovercards OFF or ON with this data.

(To clarify, this refers to not logging dwelledButAbandonedevents before 250ms - other kinds of events are logged, in particular the "fast opens" discussed here.)

BTW does anyone recall why we excluded these? (Can't quite find a discussion of this in T131315, maybe it was out of concern of miscounting cases where the user passes over a link accidentally while moving to a different target - but these could still be excluded in the query afterwards. ) Per your remark above, we should consider removing that restriction for the upcoming tests, as this should help validating (or disproving) the "shaky mouse hypothesis" that we are now relying on.

Another PS: Let's also not forget that T140485: Schema:Popups logs "dwelledButAbandoned" and link open events at the same time is still open. We resolved to not regard it as a blocker for the analysis because these extraneous events can be filtered out in the analysis, but it's probably worth keeping in mind that the instrumentation still contains other unexplained or at least unresolved bugs.