50

The Boardgames Stack Exchange question How would an instant or sorcery with an effect that targets work with Feather? became a Hot Network Question three times, according to its timeline:

timeline showing three 'became hot network question' events

All three events have the exact timestamp (19:14:39 UTC - shown when you click the 'toggle format' link or upon hovering) so it's probably a race condition or something.

It's not a unique case; this SEDE query finds instances on a single site, and this cross-site query lists all occurrences in the network (currently 448). The current record holders, with 44 HNQ entry events, are

enter image description here

  • It could be that the question dropped on and off the list, but I didn't think that this was supposed to leave an entry (see the announcement). – Laurel May 7 '19 at 20:46
  • 3
    @Laurel Nah, that only happens every 15 minutes, so it'd have different time stamps. These are all the same. It's more obvious if you "toggle format" to get the precise time rather than the relative time. The thing I find curious is that they aren't considered simultaneous. – Catija May 7 '19 at 20:52
  • I wonder if three events could have sequentially checked if it was on the list and seeing that it wasn't checked for the particular tested attribute, seeing that the condition had been met it added it and fired off a message, a rare occurance? - is there a SEDE query to check for superheated HNQs? (is that how this was discovered). – Rob May 8 '19 at 0:53
  • 1
    Same thing here, but just twice. Maybe the bug is on its way to being fixed (thrice to twice)? – Rand al'Thor May 9 '19 at 16:23
  • 1
    Few more examples 1, 2 – Arulkumar Jun 11 '19 at 8:16
  • 9
    Another example with 23 occurrences within three seconds – Sam Onela Jun 22 at 16:10
  • 1
    We got one with 25 occurrences: data.stackexchange.com/materials/query/1232023/… – user1271772 Jun 28 at 3:21
  • 5
    43 occurrences in four seconds. – Eliah Kagan Jul 13 at 16:28
  • 1
    This one had 15 occurrences over a period of 4 seconds. – John Omielan Aug 24 at 4:59
  • 3
    @ShadowWizardWearingMask Perhaps it's too hot to touch – Asteroids With Wings Sep 13 at 15:18
  • 1
    @ShadowWizardWearingMask Very low since it doesn't appear to affect actual functionality. – Adam Lear Sep 14 at 14:24
  • 1
    @AdamLear sure, but it clutters the timeline and doesn't look good. :/ – Shadow Wizard Wearing Mask Sep 14 at 15:18
  • 1
    SciFi question w/ 26 occurrenceS: scifi.meta.stackexchange.com/questions/13136/… - perhaps the priority should be upped a notch since it is clearly happening with some frequency still and is happening network wide, functionality aside... – TylerH Sep 14 at 18:47
  • 1
    @AdamLear Can we at least please get an answer that explains the cause of the bug? – Sonic the Masked Werehog Sep 14 at 18:59
  • 2
    @SonictheMaskedWerehog Well if we knew the cause of the bug, we'd fix the bug. :P – Adam Lear Sep 15 at 15:56
8

The underlying issue here has (hopefully) been fixed. Extra post history entries will be cleaned in the coming days.

The cause was a race condition on the hot network questions global cache:

  1. We cache Hot Network Questions (HNQ) across the entire network. The cache expires every 15 minutes. Every pageload (on every site) that shows HNQ hits this cache.
  2. As soon as the cache expires — at T1 —, the next request across the network will recalc the HNQ list and recache it in the global cache. This executes extremely quickly (normally in around 10-15 ms), and is completed at T4.
  3. If multiple requests come through between T1 and T4, then each of these requests would calculate a new HNQ list (with the last one being completed being the one to be saved in the global cache).
    1. This is not an issue for the performance of the HNQ. Worst case scenario is that a few extra individual pageloads somewhere on the network took an extra 10ms to load.
    2. In the case when a post is returned in the list that is on HNQ for the first time (and thus does not yet have a PostHistory entry for "became hot network question"), then each of the multiple requests will attempt to add this PostHistory entry.
    3. When adding the entry (on any of the requests), we first query for all new HNQ posts (T2) on the given site that dont have the PostHistory entry, and then add the entry (T3).
  4. If there are multiple requests (between T1 and T4) picking up a new HNQ post where at T2 for the request no other request had hit T3 (at which point a PostHistory entry would be recorded for the post and any subsequent requests initiated before T4 would pick them up at T2), then each one will record a PostHistory entry, leading to what was reported above (where the three PostHistory records where recorded from requests that occurred at 19:14:39.453, 19:14:39.457, 19:14:39.463).

The fix:

  • Change the logic of the PostHistory insert from EF to an If not exists...insert query. This eliminates the lag between T2 and min(T3) as the cause of the duplicate entry race condition here, as the existance check occurs during the insert request.
  • There is a chance that this will not completely eliminate the issue under high load, and we may need to add an UPDLOCK hint to the query as well. Decided to go incrementally with this, and will add the lock later if needed.
  • We'll be cleaning up the old duplicate history entries shortly, will update here when this is complete.

new HNQ post
concurrent requests hit cache
check hist, avoid race

| improve this answer | |
  • I appreciate the detailed clarification of the issue and the fix (and the haiku). I'll accept once I have seen the results :) – Glorfindel 22 hours ago
  • Just to be thorough, will this also fix this issue? – TylerH 17 hours ago
  • 1
    An "SQL Server Application lock" may be better then UPDLOCK hint, maybe protecting the update of the cache as well. – Ian Ringrose 16 hours ago
  • Or make the transaction serializable. – Ian Ringrose 16 hours ago

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .