New issue
Advanced search Search tips

Issue 918726 link

Starred by 3 users

Issue metadata

Status: Fixed
Owner:
Closed: Jan 14
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Fuchsia
Pri: 3
Type: Bug



Sign in to add a comment

HttpNetworkTransactionTest.*MeasuresTimeTo* tests are flaky

Project Member Reported by fdegans@chromium.org, Jan 2

Issue description

Sample 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,
 
Cc: acomminos@fb.com
Owner: mmenke@chromium.org
Status: Assigned (was: Untriaged)
[acomminos]:  Be great if you could find time to look into this, as you added the test.  If not, I'll put it in my queue.
Owner: acomminos@fb.com
Sure, I can take this.
Project Member

Comment 3 by bugdroid1@chromium.org, 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

Summary: HttpNetworkTransactionTest.*MeasuresTimeTo* tests are flaky (was: HttpNetworkTransactionTest.MeasuresTimeToFirst100ResponseForSpdy flaked in net_unittests on Fuchsia)
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.
THe assumption, as I recall, was that Sleep(kSleepDuration) sleeps for *at-least* kSleepDuration, which certainly seems valid?
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.
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.
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).
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.
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?
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.
Cc: gab@chromium.org
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
I've used it for making PostDelayedTasks run, but hadn't realized it also mocked out values returned by Now().
Re #13: It is a separate property of the ScopedTaskEnvironment, recently added, I believe, and not yet widely used. :)
Project Member

Comment 15 by bugdroid1@chromium.org, 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

> 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.
Labels: Test-Disabled
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)
Project Member

Comment 19 by bugdroid1@chromium.org, 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

Status: Fixed (was: Assigned)

Sign in to add a comment