HttpNetworkTransactionTest.*MeasuresTimeTo* tests are flaky |
||||||
Issue descriptionSample failure: https://ci.chromium.org/p/chromium/builders/luci.chromium.ci/fuchsia-fyi-x64-rel/7144 Error message: Expected: (load_timing_info.receive_headers_start - load_timing_info.connect_timing.connect_end) < (kSleepDuration), actual: 0.013547 s vs 0.01 s It appears something is going wrong when setting the timings info. I could not reproduce locally,
,
Jan 9
Sure, I can take this.
,
Jan 9
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/6b09c8b853a1fcf6d253fab24a1b3dcc869869c2 commit 6b09c8b853a1fcf6d253fab24a1b3dcc869869c2 Author: Fabrice de Gans-Riberi <fdegans@chromium.org> Date: Wed Jan 09 23:12:18 2019 [Fuchsia] Disable HttpNetworkTransactionTest.MeasuresTimeToFirst100ResponseForSpdy Flakes regularly. e.g. https://ci.chromium.org/p/chromium/builders/luci.chromium.ci/fuchsia-fyi-x64-rel/7144 Bug: 918726 Change-Id: I6feaef4dd19f66e4dbd2f01e093f245d7196a12d Reviewed-on: https://chromium-review.googlesource.com/c/1393625 Reviewed-by: Matt Menke <mmenke@chromium.org> Commit-Queue: Fabrice de Gans-Riberi <fdegans@chromium.org> Cr-Commit-Position: refs/heads/master@{#621361} [modify] https://crrev.com/6b09c8b853a1fcf6d253fab24a1b3dcc869869c2/testing/buildbot/filters/fuchsia.net_unittests.filter
,
Jan 10
HttpNetworkTransactionTest.LoadTimingMeasuresTimeToFirstByteForHttp flaked under Fuchsia in run https://ci.chromium.org/p/chromium/builders/luci.chromium.ci/Fuchsia%20x64/27172 Looking at these three new tests, it's not clear to me that the EXPECT_LT(..., kSleepDuration) expectations are _ever_ valid, but the assumption that Sleep(kSleepDuration) sleeps for at-most kSleepDuration is definitely invalid. Rather than Sleep(), these tests should be using a MOCK_TIME ScopedTaskEnvironment, with mocked NowSource, so that the test can FastForwardBy(kSleepDuration) and get deterministic behaviour.
,
Jan 10
THe assumption, as I recall, was that Sleep(kSleepDuration) sleeps for *at-least* kSleepDuration, which certainly seems valid?
,
Jan 10
The problem with MockTime is these tests go through a bunch of layers, including the socket pools, and pushing times through there really isn't a good idea - both in terms of complexity, and in terms of per-socket parameters needing to uniquely ID a socket group - adding more stuff there really just isn't a good idea.
,
Jan 10
Re #5: The failing expectation in the MeasuresTimeToFirst100Response* tests is at https://cs.chromium.org/chromium/src/net/http/http_network_transaction_unittest.cc?l=1576 and is: EXPECT_LT(load_timing_info.receive_headers_start - load_timing_info.connect_timing.connect_end, kSleepDuration); i.e. the expectation is that the time between Connect() completing, and us starting to receive headers, is less-than kSleepDuration. I'm not familiar enough with the internals of the rest of this test to know how the Connect() and header receipt is expected to line-up with the Sleep() call, but as previously noted, there's no reason to assume that Sleep(kSleepDuration) will sleep for _only_ kSleepDuration, and even if it did, it's perfectly possible for a thread to be preempted immediately after that - timeslices are typically of the order of tens of ms, so kSleepDuration of 10ms could easily be exceeded by a preemption.
,
Jan 10
Yea, that's the time *before* we start sleeping - I should have caught that would be problematic. The issue is presumably just Fuchsia is slow (We're most likely to see the same issue on ASAN builders).
,
Jan 10
Re #6: ScopedTaskEnvironment supports both MOCK_TIME for the main-thread, and also allows the Now() source to be based on the main-thread's mock time, without having to explicitly plumb a MockTickClock through to the various network components. Would that make MOCK_TIME viable for these tests? Do we need wall-clock time because of the interaction with the HTTP test server, for example? +gab in case he's aware of reasons that the ScopedTaskEnvironment mocking wouldn't work for this case.
,
Jan 10
Re #8: Perhaps we just need the test to manually sample TimeTicks::Now() at relevant points, and it can then make EXPECT_LT/EXPECT_GT expectations between the test and code-under-test timing values?
,
Jan 10
It mocks out base::TimeTicks::Now() for the main thread's time? That would certainly be sufficient. We don't need wall clock time, we just need consistent times, and there are too many layers here that have too many issues with extra parameters to pass in a mock clock to all layers in the test.
,
Jan 10
Re #11: Yes, I think that ScopedTaskEnvironment's mock NowSource mode should do what you want, then - adding gab@ to confirm, but I believe that's exactly what it's for. :D
,
Jan 10
I've used it for making PostDelayedTasks run, but hadn't realized it also mocked out values returned by Now().
,
Jan 10
Re #13: It is a separate property of the ScopedTaskEnvironment, recently added, I believe, and not yet widely used. :)
,
Jan 10
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/75f7dec9d49739c4e987f3809ee68a7de89c9dae commit 75f7dec9d49739c4e987f3809ee68a7de89c9dae Author: Wez <wez@chromium.org> Date: Thu Jan 10 19:26:50 2019 Disable HttpNetworkTransactionTest.*MeasuresTimeTo* tests. These tests have expectations on the behaviour of Sleep() that are not always valid, causing the tests to flake depending on how the test threads happen to get scheduled. We also move the test that was filtered-out by https://chromium-review.googlesource.com/c/chromium/src/+/1393625 to be disabled in the unittest.cc along with the others. Bug: 918726 Change-Id: I04d1f3c2eb4cf89dd01fd2ca28927320ed9d1d89 Reviewed-on: https://chromium-review.googlesource.com/c/1405442 Reviewed-by: Matt Menke <mmenke@chromium.org> Commit-Queue: Wez <wez@chromium.org> Cr-Commit-Position: refs/heads/master@{#621701} [modify] https://crrev.com/75f7dec9d49739c4e987f3809ee68a7de89c9dae/net/http/http_network_transaction_unittest.cc [modify] https://crrev.com/75f7dec9d49739c4e987f3809ee68a7de89c9dae/testing/buildbot/filters/fuchsia.net_unittests.filter
,
Jan 10
> Re #6: ScopedTaskEnvironment supports both MOCK_TIME for the main-thread, and also allows the Now() source to be based on the main-thread's mock time, without having to explicitly plumb a MockTickClock through to the various network components. This is great! I'll post a CL to use this ASAP. > Looking at these three new tests, it's not clear to me that the EXPECT_LT(..., kSleepDuration) expectations are _ever_ valid, but the assumption that Sleep(kSleepDuration) sleeps for at-most kSleepDuration is definitely invalid. The idea behind the 100-status tests is to ensure that if the server returns two responses, a 100 then a 200, the timing of the 100 response is used to back responseStart (rather than the 200 response). This was tested by adding a sleep between the serving of the responses, and ensuring that we didn't include that delay in responseStart.
,
Jan 10
,
Jan 10
That's indeed precisely what NowSource::MAIN_THREAD_MOCK_TIME is for. It comes with its set of warnings because Wait()'s are still real-time, but if all you're doing is using PostDelayedTask() and comparing Now(), you're fine. (ultimately we aim to have proper mock-time across all threads and make base's Wait()'s mock-time-aware but for now we opted to expose NowSource::MAIN_THREAD_MOCK_TIME for use cases like this one where it's much cleaner to have this despite the subtle pitfalls)
,
Jan 14
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/517a92cfaaf01ca273e64216fcf6888931cb6d2d commit 517a92cfaaf01ca273e64216fcf6888931cb6d2d Author: Andrew Comminos <acomminos@fb.com> Date: Mon Jan 14 17:49:56 2019 Use overridden mock clock for `receive_headers_start` load timing tests Avoid flakiness by overriding the clock backing TimeTicks::Now with a mock clock. Re-enables the flaky tests. Bug: 918726 Change-Id: Ie18689d4c4ad99d7561a68046e2d1606d29a18f5 Reviewed-on: https://chromium-review.googlesource.com/c/1406172 Reviewed-by: Matt Menke <mmenke@chromium.org> Commit-Queue: Andrew Comminos <acomminos@fb.com> Cr-Commit-Position: refs/heads/master@{#622503} [modify] https://crrev.com/517a92cfaaf01ca273e64216fcf6888931cb6d2d/net/http/http_network_transaction_unittest.cc [modify] https://crrev.com/517a92cfaaf01ca273e64216fcf6888931cb6d2d/net/test/test_with_scoped_task_environment.h
,
Jan 14
|
||||||
►
Sign in to add a comment |
||||||
Comment 1 by mmenke@chromium.org
, Jan 9Owner: mmenke@chromium.org
Status: Assigned (was: Untriaged)