Fix task reaper batching

[dperny]

Signed-off-by: Drew Erny drew.erny@docker.com

- What I did

The batching logic of the task reaper was previously race-y because of its use of timer.Reset. This fixes the logic to guarantee it's not race-y.

- How I did it

Before resetting the timer, always make sure it's stopped first. Only reset the timer when it is stopped.

- How to test it

Added some maybe kludge-y code which allows checking that the task reaper fires at the appropriate times, and added a test to verify that the task reaper behaves as expected.

/cc @anshulpundir and @dani-docker

[codecov]

Codecov Report

Merging #2669 into master will decrease coverage by 0.38%.
The diff coverage is 80%.

@@            Coverage Diff             @@
##           master    #2669      +/-   ##
==========================================
- Coverage   62.57%   62.18%   -0.39%     
==========================================
  Files          56      134      +78     
  Lines        7939    21760   +13821     
==========================================
+ Hits         4968    13532    +8564     
- Misses       2436     6789    +4353     
- Partials      535     1439     +904

[anshulpundir]

Can we instead use the side-effects caused by tick() to test ?

[dperny]

not cleanly, as far as i could tell, unless you have a better idea?

additionally, it would make the test fragile to changes in the implementation of tick. right now, the test is only relevant to the implementation of the code under test.

[anshulpundir]

Maybe. Can we just check to see if the tasks were actually cleaned up to verify that tick() was called ?

Alternatively, we could just add a counter to count the number of times tick() was executed. The benefit of this is that we could additionally use that counter to expose stats.

[dperny]

bringing in a conversation @anshulpundir and i had in meatspace:

i've chosen to add this code for the purpose of determining affirmatively or negatively that tick has or has not been called. Relying on side effects can tell that tick has been called, but cannot prove definitively that it has not been called.

[dani-docker]

FYI, running few tests with this fix and the tick() is not running after the timer is reset.
Need to build with some debug statements to check the value of isTimerStopped

[anshulpundir]

The batching logic of the task reaper was previously race-y because of its use of timer.Reset. This fixes the logic to guarantee it's not race-y.

Can you please describe how it is race-y ? What are the side-effects ? @dperny

[dperny]

So, there are a few things wrong with this code that have been fixed:

Calling Reset on a timer that has not been stopped is inherently race-y unless you can guarantee that the timer has been stopped. In this case, we cannot. I'm not clear on the details, but I know not changing it will cause trouble

More importantly, it seems that the intended behavior of the code is is to do batching every 250ms but only when there are items to clean, or whenever 1000 items pile up. As implemented before this change, the behavior is wrong. The timer would be reset every time something new is added to the set. This means the tick would not fire until 250ms had elapsed between events. If, for example, events were coming in every ~100ms, then the tick function would not get called until 1000 items had accrued.

[anshulpundir]

because we just did it.

Are you referring to the cleanup that happens above during startup ?

[dperny]

yes.

[anshulpundir]

Whats the purpose of this select ? Please add a comment.

[anshulpundir]

This is used in a few places. Can we move this to a function called drainTimer() ?

[dperny]

I don't think it's worthwhile to move this to a function. it's essentially just an if statement for a channel read. sort of like

if HasValue(channel) {
    <-channel
}

but you can't do such an if statement, so you do this select with an empty default.

[dperny]

alternatively you can do

if !timer.Stop() {
    <-timer.C
}

which is how the docs drain a channel, but for some reason doing it that way was deadlocking, so i did it the easy way instead of trying to figure out what was weird.

[anshulpundir]

I see your point. The second option is more readable than the first one.

My point was that its 4 lines of code thats repeated at least 3x, which can be replaced by a single function call. But I'll let you decide.

[anshulpundir]

does it matter here if you always call Reset() without checking if the timer was stopped ?

[dperny]

you've got the added and removed lines confused.

[anshulpundir]

No :). I'm asking why not always call Reset() without checking isTimerStopped. At the same time, I'm also questioning if we need the bool isTimerStopped and whether we can do without it. @dperny

[cyli]

Non-blocking - this code's logic seems fine, but looking at some of our vendored code like GRPC (see clientconn.go) it seems like the pattern is to create a timer at the beginning of the loop. If the timer fires, set the timer to nil. If the timer is not nil at the end of the loop, stop it and set it to nil, and there's no need to drain timer.C. This does increase GC load, though, but it is easier to read and would be slightly less repeated code to drain the timer.

I am fine with this as is, though.

[cyli]

@anshulpundir If I'm understanding the intent correctly, we want to clean up whenever maxDirty is reached or the timer ticks, whichever is sooner. I think if we always called Reset without checking isTimerStopped, the the timer may never tick and we will just wait for maxDirty all the time (since calling Reset would mean that the the timer would be reset to start waiting another reaperBatchingInterval seconds every time an event comes in without hitting maxDirty.

[anshulpundir]

How do we know that the timer is already stopped here ? Also, if its already stopped, why are we setting isTimerStopped=true ?

[anshulpundir]

tagging it in case you missed ^ comment @dperny

[anshulpundir]

move to a function.

[dani-docker]

Ran more stress test and logic looks solid , ignore my last comment, my debug logs were getting dropped.

[cyli]

LGTM - a couple of non-blocking nits that could be addressed, or not.

[cyli]

nit: eligiable - > eligible

[cyli]

nitpick: "because the timer has now expired", as opposed to "because we already know that the ti mer is stopped" because it might not have been manually stopped.

[cyli]

Non-blocking - this code's logic seems fine, but looking at some of our vendored code like GRPC (see clientconn.go) it seems like the pattern is to create a timer at the beginning of the loop. If the timer fires, set the timer to nil. If the timer is not nil at the end of the loop, stop it and set it to nil, and there's no need to drain timer.C. This does increase GC load, though, but it is easier to read and would be slightly less repeated code to drain the timer.

I am fine with this as is, though.

[cyli]

As a note, we seem to have racy timer usage in other parts of our codebase, like the dispatcher batch timer.

[dperny]

I moved the test I wrote to in between the two original tests, because rebasing on master with the test anshul wrote was causing absolutely intractable merge conflicts.