test: simulated time block on sleep #10551

jmarantz · 2020-03-26T23:42:09Z

Description: SimulatedTimeSystem::sleep() would advance time to trigger firing of timers, but does block on the threads executing those timers completing. That is the behavior does not match real-time sleep(), making it hard to retarget existing integration tests from real to simulated time.

However, there were some unit tests that are not multi-threaded, and used simulated time sleep in fashion where the timer callbacks would run on the same thread, and these need to retain the existing behavior. For these, a new API advanceTime() is now added, which enables callbacks but does not block waiting for them to complete.

Note that this PR does not yet solve all issues with sim-time in integration tests (#10568), as the infrastructure still relies on real-time sleeps in ways that are not fully understood. But it is a step in that direction.
Risk Level: low -- this is is a test/...-only PR.
Testing: /test/... in normal mode, and with tsan.
Docs Changes: n/a
Release Notes: n/a
Fixes: #10567

Signed-off-by: Joshua Marantz <jmarantz@google.com>

…s in FakeUpstream Signed-off-by: Joshua Marantz <jmarantz@google.com>

Signed-off-by: Joshua Marantz <jmarantz@google.com>

…which seems to work for the cache test. Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz · 2020-03-30T16:58:53Z

failure in asan on IpVersions/ProxyFilterIntegrationTest.UpstreamTls/IPv4 in //test/extensions/filters/http/dynamic_forward_proxy:proxy_filter_integration_test

2020-03-30T15:59:20.7841856Z [ RUN      ] IpVersions/ProxyFilterIntegrationTest.UpstreamTls/IPv4
2020-03-30T15:59:20.7843072Z [2020-03-30 15:58:37.264][17][critical][assert] [test/integration/http_integration.cc:376] assert failure: result. Details: Expected new stream event, but got a different event.
2020-03-30T15:59:20.7843919Z AddressSanitizer:DEADLYSIGNAL
2020-03-30T15:59:20.7844544Z =================================================================
2020-03-30T15:59:20.7845498Z ==17==ERROR: AddressSanitizer: ABRT on unknown address 0xfffe00000011 (pc 0x7f33af45e428 bp 0x7ffcbc765f90 sp 0x7ffcbc765668 T0)
2020-03-30T15:59:20.7846545Z     #0 0x7f33af45e427 in raise (/lib/x86_64-linux-gnu/libc.so.6+0x35427)
2020-03-30T15:59:20.7847694Z     #1 0x7f33af460029 in abort (/lib/x86_64-linux-gnu/libc.so.6+0x37029)
2020-03-30T15:59:20.7849259Z     #2 0x105158fc in Envoy::HttpIntegrationTest::waitForNextUpstreamRequest(std::__1::vector<unsigned long, std::__1::allocator<unsigned long> > const&, std::__1::chrono::duration<long long, std::__1::ratio<1l, 1000l> >) /proc/self/cwd/test/integration/http_integration.cc:376:3

Signed-off-by: Joshua Marantz <jmarantz@google.com>

…p on 0ms real time for now Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz · 2020-04-05T23:30:14Z

/azp run

azure-pipelines · 2020-04-05T23:30:24Z

Azure Pipelines successfully started running 1 pipeline(s), but failed to run 2 pipeline(s).

Signed-off-by: Joshua Marantz <jmarantz@google.com>

mattklein123

Thanks this is awesome. A few small comments and I will definitely like @alyssawilk to do a review also if possible. Also, can you try to do a big --runs_per_test run over all the tests that use simulated time to make sure we don't have any flakes? It should be all the tests you modified I guess.

/wait

mattklein123 · 2020-04-07T23:25:25Z

test/test_common/test_time_system.h

+   * Advances time forward by the specified duration. Timers may be triggered on
+   * their threads, but unlike advanceTimeWait(), this method does not block
+   * waiting for them to complete.


Can you add some text to each function as to why a test writer would want to use each one? It may not be immediately clear.

done: added:

* This function should be used in multi-threaded tests, where other * threads are running dispatcher loops. Integration tests should usually * use this variant.

and

* This function should be used in single-threaded tests, in scenarios where * after time is advanced, the main test thread will run a dispatcher * loop. Unit tests will often use this variant.

mattklein123 · 2020-04-07T23:27:28Z

test/test_common/simulated_time_system.cc

+  // This real-time polling delay should not be necessary. But without it,
+  // /test/extensions/filters/http/cache:cache_filter_integration_test fails
+  // about 40% of the time.


Should this be a TODO?

Yes -- referencing #10568 . Changed.

Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz · 2020-04-08T00:33:49Z

Running all tests that referenced SimulatedTime with tsan and runs_per_test=100. Will check back tomorrow.

Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz · 2020-04-08T11:38:21Z

All the tests that mention SimulatedTime (which covers more than what was modified in this PR) passed with tsan and --runs_per_test=100.

There are still races (where there is still real-time there are races) I believe but they didn't come out in that run.

Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz · 2020-04-08T14:53:03Z

@alyssawilk can you take another look? thanks.

mattklein123

Thanks this LGTM.

alyssawilk

I'm mostly trusting Matt on what's called where, so only two remaining nits. The comments are a huge help, thanks.

As said on slack I'd love to see more than 100 runs since flakes generally show up 1:1000 or less.
As a random aside, the only_one_thread naming makes me sad because the function which is supposed to be called by multi-threaded tests checks "only one thread" and I had to spelunk in order to figure out why that was Ok.

alyssawilk · 2020-04-08T20:10:33Z

test/test_common/simulated_time_system.cc

  const Duration real_time_poll_delay(
      std::min(std::chrono::duration_cast<Duration>(std::chrono::milliseconds(50)), duration));
  const MonotonicTime end_time = monotonicTime() + duration;

-  while (true) {
+  bool cont = true;


better naming please?

Renamed to timeout_not_reached

did you forget to upload? I'm not seeing it?

Nope; I thought I'd try intentionally not uploading until you were fine with my proposed changes, to avoid wasted CI churn :)

alyssawilk · 2020-04-08T20:12:01Z

test/test_common/simulated_time_system.cc

-      if (alarms_.empty()) {
-        // If no alarms are pending, sleep till the end time.
-        setMonotonicTimeAndUnlock(end_time);
+    mutex.unlock();


can you comment on the unusual lock pattern?

Added comment:

// This function runs with the caller-provided mutex held. We need to // hold this->mutex_ while accessing the timer-queue and blocking on // callbacks completing. To avoid potential deadlock we must drop // the caller's mutex before taking ours. We also must care to avoid // break/continue/return/throw during this non-RAII lock operation.

mattklein123 · 2020-04-08T20:22:35Z

As a random aside, the only_one_thread naming makes me sad because the function which is supposed to be called by multi-threaded tests checks "only one thread" and I had to spelunk in order to figure out why that was Ok.

+1 to change this and make it more clear. I had to look it up also.

jmarantz · 2020-04-09T15:26:52Z

I made some renaming comment changes per suggestion. PTAL just at the comments; won't push till we finish iterating on the wording.

I also successfully ran 1000 iters of tsan on 67 tests that mentioned SimulatedTime. That took 19 hours.

I have not done anything about the only_one_thread confusion. I'll take responsibility for that but it's not really part of this PR; can we iterate on better naming for that in a follow-up? Do you have a specific suggestion as to what would be clearer to you?

alyssawilk

Yay on tests, thanks for the overnight run!
Also thanks for picking up the rename - I'd totally prefer a follow-up so you're good there.

alyssawilk · 2020-04-09T15:51:02Z

test/test_common/simulated_time_system.cc

  const Duration real_time_poll_delay(
      std::min(std::chrono::duration_cast<Duration>(std::chrono::milliseconds(50)), duration));
  const MonotonicTime end_time = monotonicTime() + duration;

-  while (true) {
+  bool cont = true;


did you forget to upload? I'm not seeing it?

alyssawilk · 2020-04-09T16:44:17Z

oh bleh, you even said, but I only saw the last email. yeah SGTM.

alyssawilk · 2020-04-09T16:46:27Z

Also fwiw this is all I had to say - headed afk to see if I can rest my headache away but I'm fine with Matt merging if he signs off else I'll TAL when I'm feeling better

Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz · 2020-04-09T21:54:35Z

@mattklein123 you want to take a final look (maybe just at the local-var name-change and comment?)

Make unit tests to use advanceTimeWait in favor of sleep (see envoyproxy/envoy#10551) Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

jmarantz added 11 commits January 21, 2020 09:21

first cut.

7d3b23e

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

6e6a025

Signed-off-by: Joshua Marantz <jmarantz@google.com>

get all tests working.

9d9e104

Signed-off-by: Joshua Marantz <jmarantz@google.com>

clean up comments.

4ee85a7

Signed-off-by: Joshua Marantz <jmarantz@google.com>

remove unused member vars.

4767293

Signed-off-by: Joshua Marantz <jmarantz@google.com>

fix a few tests that were sleeping and the blocking in the same thread.

8f7ccb0

Signed-off-by: Joshua Marantz <jmarantz@google.com>

add explicit dependency to hopefully unbreak clang-tidy.

a661b60

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

b587221

Signed-off-by: Joshua Marantz <jmarantz@google.com>

cleanups and convert another flaky integration test to simtime.

c3c58c0

Signed-off-by: Joshua Marantz <jmarantz@google.com>

shadow the signaled state in a local enum in CondVar.

9a7261d

Signed-off-by: Joshua Marantz <jmarantz@google.com>

use atomic bool for condvar signaled state, use finer-grained condvar…

7d4ee46

…s in FakeUpstream Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz mentioned this pull request Mar 29, 2020

test: some integration tests fail when using simulated time #10568

Closed

jmarantz added 3 commits March 29, 2020 19:31

format and comments.

bcfb1a3

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

b148b62

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Decrease real-time polling delay in simulated time to 1ms from 50ms, …

435b660

…which seems to work for the cache test. Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz added 6 commits March 30, 2020 15:36

move public definition out of anon namespace

5649e70

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

4ac4a30

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

76ac2f5

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

57ad7c5

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

2d6aa6e

Signed-off-by: Joshua Marantz <jmarantz@google.com>

cleanup and some of the trickier tests now seem to be working; gave u…

5576b7c

…p on 0ms real time for now Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz marked this pull request as ready for review April 5, 2020 23:28

jmarantz requested review from alyssawilk and mattklein123 as code owners April 5, 2020 23:28

jmarantz assigned alyssawilk and mattklein123 Apr 5, 2020

jmarantz changed the title ~~WiP test: simulated time block on sleep~~ test: simulated time block on sleep Apr 6, 2020

clang-tidy tweak.

27a68ca

Signed-off-by: Joshua Marantz <jmarantz@google.com>

mattklein123 requested changes Apr 7, 2020

View reviewed changes

repokitteh-read-only bot added the waiting label Apr 7, 2020

comment-suggestions from review.

8382a0b

Signed-off-by: Joshua Marantz <jmarantz@google.com>

Merge branch 'master' into simtime-block-on-sleep

9b0be70

Signed-off-by: Joshua Marantz <jmarantz@google.com>

repokitteh-read-only bot removed the waiting label Apr 8, 2020

rename sleep to advanceTimeAsync

a0b385e

Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz mentioned this pull request Apr 8, 2020

WiP/RFC time: remove return-value from TestTimeSystem::waitFor(). #10656

Closed

mattklein123 previously approved these changes Apr 8, 2020

View reviewed changes

alyssawilk reviewed Apr 8, 2020

View reviewed changes

mattklein123 added the waiting label Apr 8, 2020

alyssawilk reviewed Apr 9, 2020

View reviewed changes

variable renames per review.

5267e6d

Signed-off-by: Joshua Marantz <jmarantz@google.com>

jmarantz dismissed mattklein123’s stale review via 5267e6d April 9, 2020 17:13

repokitteh-read-only bot removed the waiting label Apr 9, 2020

Merge branch 'master' into simtime-block-on-sleep

c8ec0ff

Signed-off-by: Joshua Marantz <jmarantz@google.com>

mattklein123 approved these changes Apr 9, 2020

View reviewed changes

mattklein123 merged commit f11be0b into envoyproxy:master Apr 9, 2020

jmarantz deleted the simtime-block-on-sleep branch April 9, 2020 23:04

oschaaf mentioned this pull request Apr 10, 2020

Update Envoy to 8e8209fa75f87ab53d4c78a466c8f927df930e50 envoyproxy/nighthawk#322

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: simulated time block on sleep #10551

test: simulated time block on sleep #10551

jmarantz commented Mar 26, 2020 •

edited

Loading

jmarantz commented Mar 30, 2020

jmarantz commented Apr 5, 2020

azure-pipelines bot commented Apr 5, 2020

mattklein123 left a comment

mattklein123 Apr 7, 2020

jmarantz Apr 8, 2020

mattklein123 Apr 7, 2020

jmarantz Apr 8, 2020

jmarantz commented Apr 8, 2020

jmarantz commented Apr 8, 2020 •

edited

Loading

jmarantz commented Apr 8, 2020

mattklein123 left a comment

alyssawilk left a comment

alyssawilk Apr 8, 2020

jmarantz Apr 9, 2020

alyssawilk Apr 9, 2020

jmarantz Apr 9, 2020

alyssawilk Apr 8, 2020

jmarantz Apr 9, 2020

mattklein123 commented Apr 8, 2020

jmarantz commented Apr 9, 2020

alyssawilk left a comment

alyssawilk Apr 9, 2020

alyssawilk commented Apr 9, 2020

alyssawilk commented Apr 9, 2020

jmarantz commented Apr 9, 2020

test: simulated time block on sleep #10551

test: simulated time block on sleep #10551

Conversation

jmarantz commented Mar 26, 2020 • edited Loading

jmarantz commented Mar 30, 2020

jmarantz commented Apr 5, 2020

azure-pipelines bot commented Apr 5, 2020

mattklein123 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmarantz commented Apr 8, 2020

jmarantz commented Apr 8, 2020 • edited Loading

jmarantz commented Apr 8, 2020

mattklein123 left a comment

Choose a reason for hiding this comment

alyssawilk left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mattklein123 commented Apr 8, 2020

jmarantz commented Apr 9, 2020

alyssawilk left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alyssawilk commented Apr 9, 2020

alyssawilk commented Apr 9, 2020

jmarantz commented Apr 9, 2020

jmarantz commented Mar 26, 2020 •

edited

Loading

jmarantz commented Apr 8, 2020 •

edited

Loading