Page MenuHomePhabricator

Verify interaction times are logged correctly with hovercards off and on (with the same actions)
Closed, ResolvedPublic3 Story Points

Description

Lots of tests were done verifying the correctness of the events sent (see T141922#2608525) but the interaction times weren't actually matched.

Perform the hover+click tests with hovercards off and on showing the interaction times and verify that they are roughly of the same order of magnitude to dismiss bugs in link interaction time calculations.

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 14 2016, 5:34 PM
Jhernandez updated the task description. (Show Details)
Jhernandez added a subscriber: ovasileva.

I have the tests and test runner locally, so I'll grab the task or pass the info to someone if I'm not available.

jhobs triaged this task as High priority.
MBinder_WMF set the point value for this task to 3.Sep 19 2016, 4:18 PM
bmansurov moved this task from To Do to Doing on the Reading-Web-Sprint-82-Xpect-Rspec board.

I've manually verified the following scenarios and in all of them the totalInteractionTime recorded correct values except where marked below:

Hovercards on

  • Very short hover over a link (around 300ms)
  • Short hover over a link (around 3 secs)
  • Long hover over a link (around 15 secs)
  • Short hover over a link and click on the link
  • Long hover over a link and click on the link
  • Short hover over a link and click on the hovercard
  • Short hover over a link and click on the hovercard

Hovercards off

  • Very short hover over a link (around 300ms)
  • Short hover over a link (around 3 secs)
  • Long hover over a link (around 15 secs)
  • INCORRECT VALUE: Short hover over a link and click on the link. The recorded value was in milliseconds (less than 100 ms) although I hovered over about 3 seconds before clicking.
  • INCORRECT VALUE: Long hover over a link and click on the link. The recorded value was in milliseconds (less than 100 ms) although I hovered over about 15 seconds before clicking.

I have discovered two bugs with logging the total interaction time and created subtasks to capture the issues. I haven't been able to figure out whey the above two cases are reporting invalid values.

Good news (maybe bad - depends on how you look at it). I cannot re-produce the two issues I've found with the total interaction time anymore. I was using Chrome 51.0.2704.84 (64-bit) on Mac OS 10.11.6 (15G1004) when I noticed the issues. A browser restart must have fixed them.

To sum up my analysis, event logging around totalInteractionTime is correct given we fixe the bugs found in the two subtasks.

Good news (maybe bad - depends on how you look at it). I cannot re-produce the two issues I've found with the total interaction time anymore. I was using Chrome 51.0.2704.84 (64-bit) on Mac OS 10.11.6 (15G1004) when I noticed the issues. A browser restart must have fixed them.

To sum up my analysis, event logging around totalInteractionTime is correct given we fixe the bugs found in the two subtasks.

Too bad - these two issues for the Hovercards OFF case could have helped resolve the "fast opens" paradox ;) If a browser restart fixes these, does that mean that they could still occur for users with long-running browser sessions?

If a browser restart fixes these, does that mean that they could still occur for users with long-running browser sessions?

That's a possibility. I'll keep an eye on the data being sent in case I can come up with clear steps to reproduce.

@Tbayer the bugs addressed here are new and introduced the 23rd of September in https://gerrit.wikimedia.org/r/#/c/311753/

They should have nothing to do with the data captured from hu in july/august and the analysis/debugging we did in the previous task.

I've run my hovercards EL tests again after updating them for the fact that we now log all quick hovers too, and they are mostly fine.

Run results: https://gist.github.com/joakin/3f876fc007758bd8c8f7e5e8bbae84ff

There's a test that fails consistently: Disabled: (Hover link + out)*3 + click. Apparently the opened in same tab seems to be sent twice, not sure of the exact timing.

I've tried reproducing manually on staging by getting a session with HO off, and hovering quickly a link and then clicking it (trackSubscribing before and after the click) but can't see any problem. So I'm not sure if the failure is on the test or on the logging actually.

Just thought I'd write it down here.

bmansurov removed bmansurov as the assignee of this task.
bmansurov added subscribers: phuedx, bmansurov.

@Jhernandez, I cannot manually produce the error either.

@phuedx would you please sign off?

phuedx claimed this task.Oct 7 2016, 8:47 AM

I made sure that the latest version of the Hovercards codebase was on our staging server and verified that all dwelledButAbandoned, dismissed, and opened in new tab events had a totalInteractionTime of a positive integer when Hovercards were enabled and disabled. N.B. that I open links in a new tab while testing to minimise noise.

There remains one event whose totalInteractionTime is positive but extraordinarily low: opened in new tab with Hovercards disabled. I repeatedly saw a totalInteractionTime on the order of 10 ms rather than the expected 100 or 1000 ms.

phuedx removed phuedx as the assignee of this task.Oct 10 2016, 9:22 AM

There remains one event whose totalInteractionTime is positive but extraordinarily low: opened in new tab with Hovercards disabled. I repeatedly saw a totalInteractionTime on the order of 10 ms rather than the expected 100 or 1000 ms.

This may be specific to Chrome – I'm using Chrome (53.0.2785.143) – but ⌘-clicking a link will trigger a focus DOM event whereas right-clicking the link and selecting "Open Link in New Tab" won't. This focus event zeroes the timing data for this link interaction.

ovasileva added a comment.EditedOct 10 2016, 6:10 PM

@phuedx: I guess we should look into this further - should we make a new card or keep it under this one?

I also think this is a bug with Chrome which happened to me (see T145665#2675674 towards the bottom). I was not able to reproduce the bug after a restart of Chrome. @phuedx can you check if you are able to reproduce the bug after restarting Chrome?

@phuedx: I guess we should look into this further - should we make a new card or keep it under this one?

I think we've achieved what the task asked for. We should create a new task to capture the problem with Chrome.

I also think this is a bug with Chrome which happened to me (see T145665#2675674 towards the bottom). I was not able to reproduce the bug after a restart of Chrome. @phuedx can you check if you are able to reproduce the bug after restarting Chrome?

@bmansurov: I can reproduce this on our staging server after restarting Chrome.

I went to pick this up since it's in the sprint and unclaimed, but after reading the comment thread, it appears this should've been closed since appropriate subtasks were created. Can someone confirm?

/cc @phuedx @bmansurov @ovasileva

P.S. I believe the created task: T147846: opened in new tab events logged incorrectly for hovercards off group in chrome, is unnecessary as there are known problems with Hovercards and the focus event, thus I think it should be merged into T142723. I will comment with this info on that task as well.

@jhobs - it seems we should close this after the subtasks are closed? Although, I agree that that would be confusing as well.

@ovasileva are we going to do that task ? We are going to rewrite this feature anyway.

Dumping what I said in standup here:
"Would be great if someone who is not Sam or I can look at the evaluating the hovercards work (Verify interaction times are logged correctly with hovercards off and on (with the same actions), https://phabricator.wikimedia.org/T145665) since fresh eyes would be valuable for that task."

In the sync this morning, there was the impression that @bmansurov was working on this as part of sign off for T147846. Is that the case?

I did verify some events, but not everything. This task should be tackled separately.

bmansurov claimed this task.Nov 3 2016, 3:12 PM
bmansurov moved this task from To Do to Doing on the Reading-Web-Sprint-84-Zero-minutes-left board.

I've manually verified the following scenarios and in all of them the totalInteractionTime recorded correct values. However I've discovered 3 other bugs that I captured in T149947.

Browser: Chrome 53.0.2785.143 (64-bit)
OS: Mac OS 10.11.6 (15G1004)

Hovercards on

  • Very short hover over a link (around 300ms)
  • Short hover over a link (around 3 secs)
  • Long hover over a link (around 15 secs)
  • Short hover over a link and click on the link
  • Long hover over a link and click on the link
  • Short hover over a link and click on the hovercard
  • Short hover over a link and click on the hovercard

Hovercards off

  • Very short hover over a link (around 300ms)
  • Short hover over a link (around 3 secs)
  • Long hover over a link (around 15 secs)
  • Short hover over a link and click on the link. The recorded value was in milliseconds (less than 100 ms) although I hovered over about 3 seconds before clicking.
  • Long hover over a link and click on the link. The recorded value was in milliseconds (less than 100 ms) although I hovered over about 15 seconds before clicking.

I'm moving the task to "Ready for Signoff" as no code review is needed.

@jhobs @Jdlrobson, @phuedx @pmiazga can someone please see if T145665#2769762 looks reasonable and sign off on the task if it's OK.

jhobs closed this task as Resolved.Nov 3 2016, 8:48 PM

Given the unlikeliness that a user will run into the bugs @bmansurov logged in T149947, and the fact that they are most likely new since the creation of this task, I'm calling this signed off per T145665#2769762.

bmansurov removed bmansurov as the assignee of this task.Nov 3 2016, 9:13 PM