[TEST] Time only the quit in ElegantQuitQuick, and bound it where the two outcomes are - #4488
[TEST] Time only the quit in ElegantQuitQuick, and bound it where the two outcomes are#4488thc1006 wants to merge 1 commit into
Conversation
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #4488 +/- ##
==========================================
- Coverage 83.25% 83.24% -0.00%
==========================================
Files 521 521
Lines 20384 20384
==========================================
- Hits 16969 16967 -2
- Misses 3415 3417 +2 🚀 New features to boost your workflow:
|
|
A sighting from today, since #4342 is closed and this is still happening.
#4337 changes five files and all of them are under The same job is green on So the cost today was one unrelated pull request going red in a run that had nothing else wrong with it, and the next person to see it spending the time I just spent working out whose it is. That is the argument for this change rather than the measurement in the description, which only says the bound is safe to move. Correction, same day. The paragraph above reads as though raising the bound would have kept that run green. It would not have, and I should have read the number before writing it. The assertion prints the cost it measured, and on #4337 it was A second sighting the same day says the same thing from a different job. That leaves the case for this change where the description put it, and it strengthens the half I was least able to evidence. The widened bound gives up no detection on real CI hardware either: 247 and 249 both still trip 100 ms. What today adds is that the underlying missed wakeup is more frequent than #4265 suggests, twice in a day on two pull requests that touch neither this case nor the client it exercises. That is the part this change explicitly does not fix, and it belongs with the transport work in #4448. |
… two outcomes are The case exists to catch a destruction that lets the polling background thread sleep out scheduled_delay_milliseconds_ instead of waking it. Measured on an idle host, that quit costs 0.1 to 0.5 ms; measured with the wakeup removed, it costs 256.5 to 256.9 ms, and there is nothing in between. The bound sat at 20 ms, which is close enough to the fast outcome that a host adding scheduling delay to a sub millisecond operation trips it. The 21 ms failure reported on open-telemetry#4265 is that, and the 247 ms one is a quit that really did wait the poll out. 100 ms partitions the same two sets: over 24 runs of each arm, no measurement landed between 20 and 100 ms, so the wider bound gives up no detection. The window now covers the quit alone. The request is finished first through the file's own waitForRequests(), which also removes the fixed 10 ms sleep that was standing in for it. Signed-off-by: thc1006 <84045975+thc1006@users.noreply.github.com>
3168ce7 to
eafad11
Compare
1 participant
Fixes #4265.
The two failures reported on that issue are not the same failure, and only one of them is the test's fault.
What the case is measuring
ElegantQuitQuickdestroys the client while its background thread is polling, and checks that the destructor woke the thread rather than letting it sleep outscheduled_delay_milliseconds_, which is 256 ms. A missed wakeup makes the quit slow rather than wrong, so a duration is the only thing there is to assert.I measured both outcomes on this branch before changing anything. 24 runs of each, same binary, idle host:
curl_multi_wakeupremovedThe working quit costs 0.1 to 0.5 ms. A quit that waited the poll out costs 256.5 to 256.9 ms. Nothing lands between them.
Why 20 ms is the wrong bound and 100 ms is not just a larger one
The bound sat 20 ms above an operation that takes half a millisecond. A host that adds scheduling delay to that operation trips it while the wakeup is working perfectly. That is the
cost ms: 21in the issue.cost ms: 247is the other one. It matches the measured missed wakeup exactly, so the case was right that time, and disabling it would drop a signal it has already produced once.100 ms was chosen from the gap rather than by doubling. Both bounds partition those 48 measurements identically, so the wider one gives up no detection while removing the class of false alarm that 20 ms invites. I would rather not raise it further: 256 ms is what it has to stay under.
It is still costing runs.
Bazel asan configon #4337 failed at this line on 31 August, and #4337 changes five files that are all underexporters/elasticsearch/.bazel query "somepath(//ext/test/http:curl_http_test, //exporters/elasticsearch/...)"returns an empty result, so nothing in it reaches that binary, and the same job is green on themaincommit it is rebased onto. That is one unrelated pull request going red in a run with nothing else wrong with it.What else changed
The timed window used to open before
FinishAllSessions()with the request still going, after a fixedsleep_for(10ms)that was standing in for the request completing. The window now covers the quit alone, and the request is finished first throughwaitForRequests(), which this file already uses for the same purpose inSendGetRequest. That removes the sleep as well.The two response assertions moved above the window, where they now guard it rather than trail it.
Checks
curl_http_testpasses 26 of 26.Measured again under
--config=asan, since that is the configuration that goes red and the one where a wall clock bound is most fragile. Options copied fromci/do_ci.sh bazel.asan, thirty runs per arm,--local_test_jobs=1so the runs do not race each other for port 19000:main's 20 ms bound, 32 busy loops on 32 coresThe third row is a negative result and I would rather report it than leave it out. This host does not reproduce the failure that CI produced this morning, so the fail before evidence here is CI's own red rather than anything I can show locally. A 32 core host recovers from a scheduling delay faster than a shared two core runner does, which is the same reason the bound is a bad fit for CI in the first place.
An earlier attempt at this measurement used
--runs_per_test=30without serialising and reported 18 of 30 failing. Those failed atwaitForRequests, each after the full 30 seconds, because thirty copies of the test were competing for port 19000 and only one of them had a server. It measured the harness.Removing
curl_multi_wakeupstill turns the case red, atcost ms: 256. It is worth saying that this catches it 19 times in 24 rather than every time: with the wakeup gone, the poll is sometimes broken by the cancelled transfer instead. That was true of the old bound too, and it is why the failure on CI is intermittent rather than constant.One thing this does not fix
It does not explain why the wakeup was missed on the run that produced 247 ms.
wakeupBackgroundThread()is called more than once on the destruction path, and libcurl documents that "multiple calls to this function wake up the same waiting operation", so two wakeups collapsing into one while two poll iterations remain would produce exactly this. That is a hypothesis, not a measurement, and it belongs to the transport work in #4448 rather than to a test fix.Landing next to the other curl changes
ext/test/http/curl_http_test.ccis also touched by #4395, #4405, #4406, #4431 and #4457, so this conflicts with each of them in that file. This is the smallest of the six and changes one case, so it is the cheapest to take first and rebase the others onto. Whichever order suits you, I rebase the rest.For significant contributions please make sure you have completed the following items:
CHANGELOG.mdupdated for non-trivial changes - N/A, test only, no behaviour change