benchmark selftest failures on WSL

[EricBackus]

I'm running under the Windows Subsystem for Linux (WSL), so this is close to a linux setup but not identical. I'm wondering if these failures are known/expected or if I should investigate them further.

I do the following:

git clone https://github.com/google/benchmark.git
cd benchmark
mkdir build
cd build
cmake -DBENCHMARK_ENABLE_GTEST_TESTS=OFF -DCMAKE_BUILD_TYPE=Release ..
cmake --build . --config Release
ctest -C Release

The cmake build is successful. Most of the tests pass, but four of them fail. The last part of the ctest output looks like this:

      Start 48: reporter_output_test
48/58 Test #48: reporter_output_test .......................***Exception: Child aborted  0.04 sec
      Start 49: templated_fixture_test
49/58 Test #49: templated_fixture_test .....................   Passed    0.02 sec
      Start 50: user_counters_test
50/58 Test #50: user_counters_test .........................***Exception: Child aborted  0.05 sec
      Start 51: internal_threading_test
51/58 Test #51: internal_threading_test ....................   Passed    1.82 sec
      Start 52: report_aggregates_only_test
52/58 Test #52: report_aggregates_only_test ................   Passed    0.02 sec
      Start 53: display_aggregates_only_test
53/58 Test #53: display_aggregates_only_test ...............   Passed    0.01 sec
      Start 54: user_counters_tabular_test
54/58 Test #54: user_counters_tabular_test .................***Exception: Child aborted  0.16 sec
      Start 55: user_counters_thousands_test
55/58 Test #55: user_counters_thousands_test ...............   Passed    0.02 sec
      Start 56: memory_manager_test
56/58 Test #56: memory_manager_test ........................   Passed    0.07 sec
      Start 57: cxx03
57/58 Test #57: cxx03 ......................................   Passed    0.30 sec
      Start 58: complexity_benchmark
58/58 Test #58: complexity_benchmark .......................***Exception: Child aborted  2.77 sec

93% tests passed, 4 tests failed out of 58

Total Test time (real) =  15.25 sec

The following tests FAILED:
	 48 - reporter_output_test (Child aborted)
	 50 - user_counters_test (Child aborted)
	 54 - user_counters_tabular_test (Child aborted)
	 58 - complexity_benchmark (Child aborted)
Errors while running CTest

The errors go away if I compile in debug mode, if that's any hint about what's going wrong.

Is this expected? If this needs more investigation, any hints for where I should start looking? Thanks!

[LebedevRI]

Test failure (be it either test that should pass not passing or the other way around) is likely not intended.
Maybe running ctest in more verbose mode so it actually tells what's wrong could be the first step.

[EricBackus]

Looks like all of these failures are trying to verify that the benchmark output matches an expected format, but the actual output contains "inf" or "nan" rather than an expected number. I'll attach output later. The "inf" or "nan" seems to be a result of tests that take zero time, leading to a divide-by-zero. I need to investigate these further - maybe the compiler is optimizing something away that it shouldn't? Maybe WSL doesn't support some call that is needed to avoid this issue?

I'm using gcc 7.4.0. Can somebody with a real Linux system and this version of gcc verify whether this failure is seen there?

[LebedevRI]

Do normal benchmarks work fine? I.e. do timers work in general in that, uhm, environment?

[EricBackus]

Benchmark test output looks reasonable for most things. I'm not sure what's different about these four failure cases to cause the times to be zero. I also have an external project that uses Benchmark for some performance characterization, and the results look reasonable to me.

[dmah42]

Curious! Our travis instance suggests that everything is working fine in "real" gcc/linux and clang/linux (and osx, and windows msvc) environments. I'm not sure what might be different about the compiler in WSL land. Is that where you run an Ubuntu app on Windows? If so, i've run stuff there and it's been fine. Can you confirm that you have no other installed instances of the benchmark library? (i think it's available as libbenchmark-dev).

…

On Mon, Jul 22, 2019 at 1:41 AM Eric Backus ***@***.***> wrote: Benchmark test output looks reasonable for most things. I'm not sure what's different about these four failure cases to cause the times to be zero. I also have an external project that uses Benchmark for some performance characterization, and the results look reasonable to me. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#839?email_source=notifications&email_token=AAD4QMUBKNUILABIYT3HBIDQAT64VA5CNFSM4IFQIT3KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD2OPIKY#issuecomment-513602603>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAD4QMXT2ERKGH6XMULISCDQAT64VANCNFSM4IFQIT3A> .

[EricBackus]

Yes, this is where I run an Ubuntu app on Windows. It is really close to running Linux. Executables on WSL are byte-for-byte identical to Linux. They've built in a Linux emulation layer somewhere, so there are limitations based on what that emulation layer implements, but at this point it is mostly corner cases that don't match a real Linux system.

Yes, I can confirm that there are no other installed instances of the benchmark library on my system.

After more investigation, here's what I've found:

• The self-test failures are cases where the benchmark runs in zero time.
• By itself, running in zero time is not a problem. But the failures compute things like bytes/sec or other statistics, where they end up dividing by zero and getting either an infinity or a NaN result.
• Even these infinity or NaN values by themselves are not a problem. But the self-tests that fail then try to verify that the output format matches some expected regex pattern, and the pattern expects a number and not "inf" or "nan". So these self-tests report a failure.

So, why do these cases run in zero time?

• At first I suspected some issue with timers, where the time on WSL isn't being measured correctly. But this doesn't seem to be the problem. And everything works when the benchmark library is compiled in Debug mode, so that seems to indicate that the timers are working correctly.

• Then I thought maybe it's just that WSL timers don't have enough resolution. So maybe a debug build runs relatively slowly and everything works, but a release build is optimized enough that even at 1000000000 iterations (which is kMaxIterations), there is no timer tick before all the iterations are done. That seems unlikely though, because even a loop which takes just a single 2GHz system clock would last half a second at 1000000000 iterations. Nevertheless, to help verify this, I increased kMaxIterations by a factor of 100. This made no difference. Even at 10^11 iterations the benchmark gets zero time for these failing test cases.

Then I looked at the actual self-test code in the cases that take zero time. The code in test/reporter_output_test.cc for one of these looks like this:

void BM_basic(benchmark::State& state) {
  for (auto _ : state) {
  }
}
BENCHMARK(BM_basic);

Note that there is nothing in the inner loop. When compiled in debug mode, this would end up as just a tight loop, which is fine. But when compiled in release mode, the optimizer can see into the state iterator and can figure out that the entire loop can be eliminated. To verify this, I disassembled the test/reporter_output_test.cc, and found this:

00000000000000f0 <_Z8BM_basicRN9benchmark5StateE>:
  f0:   53                      push   %rbx
  f1:   48 89 fb                mov    %rdi,%rbx
  f4:   e8 00 00 00 00          callq  f9 <_Z8BM_basicRN9benchmark5StateE+0x9>
  f9:   48 89 df                mov    %rbx,%rdi
  fc:   5b                      pop    %rbx
  fd:   e9 00 00 00 00          jmpq   102 <_Z8BM_basicRN9benchmark5StateE+0x12>
 102:   0f 1f 40 00             nopl   0x0(%rax)
 106:   66 2e 0f 1f 84 00 00    nopw   %cs:0x0(%rax,%rax,1)
 10d:   00 00 00

Now, I'm no assembly expert, but it's pretty clear that there is no loop at all in this function. So the iteration count makes no difference. And benchmark will legitimately report zero time for this function.

But this means that the same result should be seen on a real Linux system. So, I conclude that the testing that is currently being done on a real Linux system doesn't compile the self-tests in release mode. Or possibly real Linux timers have so much more resolution that they report some non-zero value for these cases where there is no loop at all. Or possibly the testing uses an older compiler that doesn't optimize as thoroughly as gcc 7.4.0 does.

So, what do we do about all this?

• It seems to me that optimizing the inner loop away entirely is fine if the loop really is empty.
• It seems to me that the tests which are verifying the output format should either 1) put something in their inner loop to ensure that the time is non-zero, or 2) allow for infinity and NaN result values. I would vote for the first one, and I could provide a pull request for this if that's the desired path.
• It seems to me that whatever self tests you guys run should use release mode at least some of the time, if you're not already. Perhaps most of the time? Though I can imagine that there could be value in running some tests in debug mode.

[dmah42]

Amazing analysis. Thank you! I agree completely with your analysis and your conclusions. Looking at things from our side: A recent run of our travis CI is here: https://travis-ci.org/google/benchmark. Specifically, this job ( https://travis-ci.org/google/benchmark/jobs/562080468) ran on Linux with GCC, release build. Reporter output test passed ( https://travis-ci.org/google/benchmark/jobs/562080468#L1000). Similar results for Clang on Linux ( https://travis-ci.org/google/benchmark/jobs/562080473). This suggests that, as you say, either this release build didn't optimize out the loop (I doubt it) or we're seeing no mismatch between inf/nan in our output. Note, I have run these tests in WSL too and not encountered this issue (though there's a chance I only did it in Debug, I can't be sure... it was a while ago). For correctness, and a meaningful test, the reporter output tests should probably use BM_empty ( https://github.com/google/benchmark/blob/master/test/basic_test.cc#L6) as a template. I'd merge a PR with that change.

…

On Tue, Jul 23, 2019 at 4:27 AM Eric Backus ***@***.***> wrote: Yes, this is where I run an Ubuntu app on Windows. It is really close to running Linux. Executables on WSL are byte-for-byte identical to Linux. They've built in a Linux emulation layer somewhere, so there are limitations based on what that emulation layer implements, but at this point it is mostly corner cases that don't match a real Linux system. Yes, I can confirm that there are no other installed instances of the benchmark library on my system. After more investigation, here's what I've found: - The self-test failures are cases where the benchmark runs in zero time. - By itself, running in zero time is not a problem. But the failures compute things like bytes/sec or other statistics, where they end up dividing by zero and getting either an infinity or a NaN result. - Even these infinity or NaN values by themselves are not a problem. But the self-tests that fail then try to verify that the output format matches some expected regex pattern, and the pattern expects a number an not "inf" or "nan". So these self-tests report a failure. So, why do these cases run in zero time? - At first I suspected some issue with timers, where the time on WSL isn't being measured correctly. But this doesn't seem to be the problem. And everything works when the benchmark library is compiled in Debug mode, so that seems to indicate that the timers are working correctly. Then I thought maybe it's just that WSL timers don't have enough resolution. So maybe a debug build runs relatively slowly and everything works, but a release build is optimized enough that even at 1000000000 iterations (which is kMaxIterations), there is no timer tick before all the iterations are done. That seems unlikely though, because even a loop which takes just a single 2GHz system clock would last half a second at 1000000000 iterations. Nevertheless, to help verify this, I increased kMaxIterations by a factor of 100. This made no difference. Even at 10^11 iterations the benchmark gets zero time for these failing test cases. - Then I looked at the actual self-test code in the cases that take zero time. The code in test/reporter_output_test.cc for one of these looks like this: void BM_basic(benchmark::State& state) { for (auto _ : state) { } } BENCHMARK(BM_basic); Note that there is *nothing* in the inner loop. When compiled in debug mode, this would end up as just a tight loop, which is fine. But when compiled in release mode, the optimizer can see into the state iterator and can figure out that the entire loop can be eliminated. To verify this, I disassembled the test/reporter_output_test.cc, and found this: 00000000000000f0 <_Z8BM_basicRN9benchmark5StateE>: f0: 53 push %rbx f1: 48 89 fb mov %rdi,%rbx f4: e8 00 00 00 00 callq f9 <_Z8BM_basicRN9benchmark5StateE+0x9> f9: 48 89 df mov %rbx,%rdi fc: 5b pop %rbx fd: e9 00 00 00 00 jmpq 102 <_Z8BM_basicRN9benchmark5StateE+0x12> 102: 0f 1f 40 00 nopl 0x0(%rax) 106: 66 2e 0f 1f 84 00 00 nopw %cs:0x0(%rax,%rax,1) 10d: 00 00 00 Now, I'm no assembly expert, but it's pretty clear that there is no loop at all in this function. So the iteration count makes no difference. And benchmark will report zero time for this function. But this means that the same result should be seen on a real Linux system. So, I conclude that the testing that is currently being done on a real Linux system doesn't compile the self-tests in release mode. Or possibly the testing uses an older compiler that doesn't optimize as thoroughly as gcc 7.4.0 does. So, what do we do about all this? - It seems to me that optimizing the inner loop away entirely is fine if the loop really is empty. - It seems to me that the tests which are verifying the output format should either 1) put something in their inner loop to ensure that the time is non-zero, or 2) allow for infinity and NaN result values. I would vote for the first one, and I could provide a pull request for this if that's the desired path. - It seems to me that whatever self tests you guys run should use release mode at least some of the time. Perhaps most of the time. I can imagine that there could be value is running some tests in debug mode though. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#839?email_source=notifications&email_token=AAD4QMVIHZTG4JLATNXIK6LQAZ3CRA5CNFSM4IFQIT3KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD2RZ3JY#issuecomment-514039207>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAD4QMU63YXQ4KTIWJYWGIDQAZ3CRANCNFSM4IFQIT3A> .

[EricBackus]

I agree, BM_empty from basic_test looks like a good template to follow. However, I'd really like to see the output of reporter_output_test on a Linux release build. Maybe I'll fire up VirtualBox and see what it shows. Then I'll do a PR with the change.

I notice that the Travis tests seem to use gcc 4.8.4. It seems possible that it doesn't optimize the loop as well as the gcc 7.4.0 that I'm using.
Edit: No, that's not it. I installed gcc 4.8.5, and it optimizes the loop away just like 7.4.0.

[EricBackus]

I did some investigation on Linux in a VirtualBox. The issue here is that Linux provides relatively high resolution for measuring real-time (using the TSC register on x86 hardware, I believe) and also relatively high resolution for measuring process-specific CPU time (using clock_gettime() I believe).

By comparison, WSL has the same high resolution for real-time (using the TSC register on x86 hardware) but coarse resolution for process-specific CPU time. I think the CPU time resolution is something like 64 Hz.

So, even if the inner loop is optimized away, on Linux there is still a non-zero CPU time, and divide-by-zero is avoided. But on WSL, the optimized-away loop measures as zero CPU time, and a divide-by-zero happens.

I wanted to understand the difference. But really it doesn't change the conclusion, which is that tests which require non-zero time should put something into the timing loop. I'll submit a PR that fixes the failing cases on WSL.

[dmah42]

I think wholesale replacing the reporter output tests with something meaningful is a good idea.

Actually i think removing BM_empty in general is likely a good idea as it doesn't really test anything.