Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tests fail under alpha #711

Open
matoro opened this issue Oct 8, 2022 · 13 comments · May be fixed by #712
Open

Tests fail under alpha #711

matoro opened this issue Oct 8, 2022 · 13 comments · May be fixed by #712

Comments

@matoro
Copy link

matoro commented Oct 8, 2022

Description

I'm attempting to validate this package on alpha for Gentoo, but I'm getting (inconsistent) failures in the test suite related to the timeout decorator. Usually somewhere between 5 and 15 of the test cases will fail, the failures all look like this:

35/155 Testing: test_cases_and_suites.cpp_xml
35/155 Test: test_cases_and_suites.cpp_xml
Command: "/usr/bin/cmake" "-DCOMMAND=/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9_build/examples/all_features/all_features --no-skipped-summary --no-version -sf=*test_cases_and_suites.cpp --reporters=xml --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1" "-DTEST_OUTPUT_FILE=/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9/examples/all_features/test_output/test_cases_and_suites.cpp_xml.txt" "-DTEST_TEMP_FILE=/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9_build/examples/all_features/CMakeFiles/temp_test_output_test_cases_and_suites.cpp_xml.txt" "-DTEST_MODE=COMPARE" "-P" "/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9/scripts/cmake/exec_test.cmake"
Directory: /var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9_build/examples/all_features
"test_cases_and_suites.cpp_xml" start time: Oct 03 04:09 UTC
Output:
----------------------------------------------------------
-- Found Git: /usr/bin/git (found version "2.37.3") 
diff --git a/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9/examples/all_features/test_output/test_cases_and_suites.cpp_xml.txt b/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9_build/examples/all_features/CMakeFiles/temp_test_output_test_cases_and_suites.cpp_xml.txt
index 6fc245a..e9d1e79 100644
--- a/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9/examples/all_features/test_output/test_cases_and_suites.cpp_xml.txt
+++ b/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9_build/examples/all_features/CMakeFiles/temp_test_output_test_cases_and_suites.cpp_xml.txt
@@ -54,7 +54,7 @@
           failing because of the timeout decorator!
         </Text>
       </Message>
-      <OverallResultsAsserts successes="0" failures="0" test_case_success="false"/>
+      <OverallResultsAsserts successes="0" failures="0" test_case_success="true"/>
     </TestCase>
   </TestSuite>
   <TestSuite name="skipped test cases">
@@ -109,6 +109,6 @@
     </TestCase>
   </TestSuite>
   <OverallResultsAsserts successes="1" failures="11"/>
-  <OverallResultsTestCases successes="6" failures="9"/>
+  <OverallResultsTestCases successes="7" failures="8"/>
 </doctest>
 Program code.

CMake Error at /var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9/scripts/cmake/exec_test.cmake:69 (message):
  Running
  '/var/tmp/portage/dev-cpp/doctest-2.4.9/work/doctest-2.4.9_build/examples/all_features/all_features
  --no-skipped-summary --no-version -sf=*test_cases_and_suites.cpp
  --reporters=xml --dt-no-path-filenames=1 --dt-no-line-numbers=1
  --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1' ended
  with code 'Output is different from reference file!'

<end of output>
Test time =   0.22 sec
----------------------------------------------------------
Test Failed.
"test_cases_and_suites.cpp_xml" end time: Oct 03 04:09 UTC
"test_cases_and_suites.cpp_xml" time elapsed: 00:00:00

Steps to reproduce

mkdir build
cd build
cmake -G Ninja -DDOCTEST_WITH_TESTS=yes ..
ninja -v
ctest

Extra information

  • doctest version: v2.4.9 and git master (tried both)
  • Operating System: Gentoo Linux - kernel 6.0
  • Compiler+version: gcc 12.2.0

Downstream bug, along with a complete sample log, is here

I have real hardware available that can be used to debug if necessary! Let me know if this would be useful and I can provide access.

@Saalvage Saalvage linked a pull request Oct 8, 2022 that will close this issue
@Saalvage Saalvage linked a pull request Oct 8, 2022 that will close this issue
@Saalvage
Copy link
Member

Saalvage commented Oct 8, 2022

Wow, I think your runner is literally too fast for doctest!

Could you check if #712 fixes it?

@matoro
Copy link
Author

matoro commented Oct 8, 2022

Wow, I think your runner is literally too fast for doctest!

Could you check if #712 fixes it?

No, that does not do the trick unfortunately. However I highly doubt that being "too fast" is the cause - this is a CPU from 1999 running at 1GHz! And I ran it on machines I know to be much, much faster and did not see the issue there.

I think a much more likely explanation has to do with clock resolution, it might be that the RTC cannot measure time that precisely. What units is the timeout decorator in? This machine runs with CONFIG_HZ=1024. I tested in a loop and from my measurements the clock can only measure down to around ~360ns precision.

Again, if it's easier for you to just try it out on the machine yourself, let me know!

@Saalvage
Copy link
Member

Saalvage commented Oct 8, 2022

Interesting, thank you for this very detailed report. The resolution is microseconds and the argument to the timeout decorator is in seconds, so in theory this shouldn't be a problem.
This is the code responsible for calculating the ticks, which is what's being compared:

ticks_t getCurrentTicks() {
    timeval t;
    gettimeofday(&t, nullptr);
    return static_cast<ticks_t>(t.tv_sec) * 1000000 + static_cast<ticks_t>(t.tv_usec);
}

The simplest solution is probably just using std::this_thread::sleep_for in the test, but I think in conjunction with that I'm just going to rewrite this to use C++ 11's chrono library.

@Saalvage
Copy link
Member

Saalvage commented Oct 8, 2022

Does the current version do the trick for you? I've moved to std::chrono but am not currently using sleep_for as that is causing issues with older versions of clang for x86..

@matoro
Copy link
Author

matoro commented Oct 8, 2022

Does the current version do the trick for you? I've moved to std::chrono but am not currently using sleep_for as that is causing issues with older versions of clang for x86..

Unfortunately still nope.

34/155 Testing: test_cases_and_suites.cpp
34/155 Test: test_cases_and_suites.cpp
Command: "/usr/bin/cmake" "-DCOMMAND=/tmp/doctest/build/examples/all_features/all_features --no-skipped-summary --no-version -sf=*test_cases_and_suites.cpp --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1" "-DTEST_OUTPUT_FILE=/tmp/doctest/examples/all_features/test_output/test_cases_and_suites.cpp.txt" "-DTEST_TEMP_FILE=/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_test_cases_and_suites.cpp.txt" "-DTEST_MODE=COMPARE" "-P" "/tmp/doctest/scripts/cmake/exec_test.cmake"
Directory: /tmp/doctest/build/examples/all_features
"test_cases_and_suites.cpp" start time: Oct 08 19:55 EDT
Output:
----------------------------------------------------------
-- Found Git: /usr/bin/git (found version "2.38.0") 
diff --git a/tmp/doctest/examples/all_features/test_output/test_cases_and_suites.cpp.txt b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_test_cases_and_suites.cpp.txt
index 299559d..7af8c19 100644
--- a/tmp/doctest/examples/all_features/test_output/test_cases_and_suites.cpp.txt
+++ b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_test_cases_and_suites.cpp.txt
@@ -40,7 +40,6 @@ TEST CASE:  normal test in a test suite from a decorator
 
 test_cases_and_suites.cpp(0): MESSAGE: failing because of the timeout decorator!
 
-Test case exceeded time limit of 0.000001!
 ===============================================================================
 test_cases_and_suites.cpp(0):
 DESCRIPTION: this test has overridden its skip decorator
@@ -95,7 +94,7 @@ test_cases_and_suites.cpp(0): ERROR:
 
 Didn't fail exactly 1 times so marking it as failed!
 ===============================================================================
-[doctest] test cases: 16 | 7 passed |  9 failed |
+[doctest] test cases: 16 | 8 passed |  8 failed |
 [doctest] assertions: 13 | 2 passed | 11 failed |
 [doctest] Status: FAILURE!
 Program code.
 
CMake Error at /tmp/doctest/scripts/cmake/exec_test.cmake:69 (message):
  Running '/tmp/doctest/build/examples/all_features/all_features
  --no-skipped-summary --no-version -sf=*test_cases_and_suites.cpp
  --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1
  --dt-gnu-file-line=0 --dt-no-time-in-output=1' ended with code 'Output is
  different from reference file!'
 
<end of output>
Test time =   0.12 sec
----------------------------------------------------------
Test Failed.
"test_cases_and_suites.cpp" end time: Oct 08 19:55 EDT
"test_cases_and_suites.cpp" time elapsed: 00:00:00
----------------------------------------------------------

@Saalvage
Copy link
Member

Saalvage commented Oct 9, 2022

Okay, implemented platform specific sleeping now since the standardized one wouldn't work.

Could you test one last time if the branch works for you now? If not, then there's seriously something wrong somewhere!

@matoro
Copy link
Author

matoro commented Oct 9, 2022

That seems to have gotten rid of the timeout issue, but introduced three new failures (at least I think they are new). Luckily these failures are deterministic at least.

98% tests passed, 3 tests failed out of 155

Total Test time (real) =  27.02 sec

The following tests FAILED:
         76 - coverage_maxout.cpp (Failed)
         77 - coverage_maxout.cpp_xml (Failed)
         78 - coverage_maxout.cpp_junit (Failed)

The output from the three failures is:

76/155 Testing: coverage_maxout.cpp
76/155 Test: coverage_maxout.cpp
Command: "/usr/bin/cmake" "-DCOMMAND=/tmp/doctest/build/examples/all_features/all_features --no-skipped-summary --no-version -sf=*coverage_maxout.cpp --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1" "-DTEST_OUTPUT_FILE=/tmp/doctest/examples/all_features/test_output/coverage_maxout.cpp.txt" "-DTEST_TEMP_FILE=/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp.txt" "-DTEST_MODE=COMPARE" "-P" "/tmp/doctest/scripts/cmake/exec_test.cmake"
Directory: /tmp/doctest/build/examples/all_features
"coverage_maxout.cpp" start time: Oct 08 23:15 EDT
Output:
----------------------------------------------------------
-- Found Git: /usr/bin/git (found version "2.38.0") 
diff --git a/tmp/doctest/examples/all_features/test_output/coverage_maxout.cpp.txt b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp.txt
index e0c193d..e69de29 100644
--- a/tmp/doctest/examples/all_features/test_output/coverage_maxout.cpp.txt
+++ b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp.txt
@@ -1,43 +0,0 @@
-[doctest] run with "--help" for options
-===============================================================================
-coverage_maxout.cpp(0):
-TEST CASE:  exercising tricky code paths of doctest
-
-coverage_maxout.cpp(0): ERROR: CHECK( str.compare(const_str, true) != 0 ) is NOT correct!
-  values: CHECK( 0 != 0 )
-  logged: should fail
-
-coverage_maxout.cpp(0): ERROR: CHECK( str.compare("omgomgomg", false) != 0 ) is NOT correct!
-  values: CHECK( 0 != 0 )
-  logged: should fail
-
-coverage_maxout.cpp(0): ERROR: CHECK_FALSE( isThereAnything ) is NOT correct!
-  values: CHECK_FALSE( true )
-  logged: should fail
-
-===============================================================================
-coverage_maxout.cpp(0):
-TEST SUITE: exception related
-TEST CASE:  will end from a std::string exception
-
-coverage_maxout.cpp(0): ERROR: test case THREW exception: std::string!
-
-===============================================================================
-coverage_maxout.cpp(0):
-TEST SUITE: exception related
-TEST CASE:  will end from a const char* exception
-
-coverage_maxout.cpp(0): ERROR: test case THREW exception: const char*!
-
-===============================================================================
-coverage_maxout.cpp(0):
-TEST SUITE: exception related
-TEST CASE:  will end from an unknown exception
-
-coverage_maxout.cpp(0): ERROR: test case THREW exception: unknown exception
-
-===============================================================================
-[doctest] test cases:  4 |  0 passed | 4 failed |
-[doctest] assertions: 31 | 28 passed | 3 failed |
-[doctest] Status: FAILURE!
-Program code.
 
CMake Error at /tmp/doctest/scripts/cmake/exec_test.cmake:69 (message):
  Running '/tmp/doctest/build/examples/all_features/all_features
  --no-skipped-summary --no-version -sf=*coverage_maxout.cpp
  --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1
  --dt-gnu-file-line=0 --dt-no-time-in-output=1' ended with code 'Output is
  different from reference file!'
 
<end of output>
Test time =   0.08 sec
----------------------------------------------------------
Test Failed.
"coverage_maxout.cpp" end time: Oct 08 23:15 EDT
"coverage_maxout.cpp" time elapsed: 00:00:00
----------------------------------------------------------

77/155 Testing: coverage_maxout.cpp_xml
77/155 Test: coverage_maxout.cpp_xml
Command: "/usr/bin/cmake" "-DCOMMAND=/tmp/doctest/build/examples/all_features/all_features --no-skipped-summary --no-version -sf=*coverage_maxout.cpp --reporters
=xml --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1" "-DTEST_OUTPUT_FILE=/tmp/doctest/examples/
all_features/test_output/coverage_maxout.cpp_xml.txt" "-DTEST_TEMP_FILE=/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp_
xml.txt" "-DTEST_MODE=COMPARE" "-P" "/tmp/doctest/scripts/cmake/exec_test.cmake"
Directory: /tmp/doctest/build/examples/all_features
"coverage_maxout.cpp_xml" start time: Oct 08 23:15 EDT
Output:
----------------------------------------------------------
-- Found Git: /usr/bin/git (found version "2.38.0") 
diff --git a/tmp/doctest/examples/all_features/test_output/coverage_maxout.cpp_xml.txt b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_cove
rage_maxout.cpp_xml.txt
index 9a9bf10..a50eb9d 100644
--- a/tmp/doctest/examples/all_features/test_output/coverage_maxout.cpp_xml.txt
+++ b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp_xml.txt
@@ -25,41 +25,3 @@
           should fail
         </Info>
       </Expression>
-      <Expression success="false" type="CHECK_FALSE" filename="coverage_maxout.cpp" line="0">
-        <Original>
-          isThereAnything
-        </Original>
-        <Expanded>
-          true
-        </Expanded>
-        <Info>
-          should fail
-        </Info>
-      </Expression>
-      <OverallResultsAsserts successes="28" failures="3" test_case_success="false"/>
-    </TestCase>
-  </TestSuite>
-  <TestSuite name="exception related">
-    <TestCase name="will end from a std::string exception" filename="coverage_maxout.cpp" line="0">
-      <Exception crash="false">
-        std::string!
-      </Exception>
-      <OverallResultsAsserts successes="0" failures="0" test_case_success="false"/>
-    </TestCase>
-    <TestCase name="will end from a const char* exception" filename="coverage_maxout.cpp" line="0">
-      <Exception crash="false">
-        const char*!
-      </Exception>
-      <OverallResultsAsserts successes="0" failures="0" test_case_success="false"/>
-    </TestCase>
-    <TestCase name="will end from an unknown exception" filename="coverage_maxout.cpp" line="0">
-      <Exception crash="false">
-        unknown exception
-      </Exception>
-      <OverallResultsAsserts successes="0" failures="0" test_case_success="false"/>
-    </TestCase>
-  </TestSuite>
-  <OverallResultsAsserts successes="28" failures="3"/>
-  <OverallResultsTestCases successes="0" failures="4"/>
-</doctest>
-Program code.

CMake Error at /tmp/doctest/scripts/cmake/exec_test.cmake:69 (message):
  Running '/tmp/doctest/build/examples/all_features/all_features
  --no-skipped-summary --no-version -sf=*coverage_maxout.cpp --reporters=xml
  --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1
  --dt-gnu-file-line=0 --dt-no-time-in-output=1' ended with code 'Output is
  different from reference file!'

<end of output>
Test time =   0.08 sec
----------------------------------------------------------
Test Failed.
"coverage_maxout.cpp_xml" end time: Oct 08 23:15 EDT
"coverage_maxout.cpp_xml" time elapsed: 00:00:00
----------------------------------------------------------

78/155 Testing: coverage_maxout.cpp_junit
78/155 Test: coverage_maxout.cpp_junit
Command: "/usr/bin/cmake" "-DCOMMAND=/tmp/doctest/build/examples/all_features/all_features --no-skipped-summary --no-version -sf=*coverage_maxout.cpp --reporters
=junit --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1" "-DTEST_OUTPUT_FILE=/tmp/doctest/example
s/all_features/test_output/coverage_maxout.cpp_junit.txt" "-DTEST_TEMP_FILE=/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp_junit.txt" "-DTEST_MODE=COMPARE" "-P" "/tmp/doctest/scripts/cmake/exec_test.cmake"
Directory: /tmp/doctest/build/examples/all_features
"coverage_maxout.cpp_junit" start time: Oct 08 23:15 EDT
Output:
----------------------------------------------------------
-- Found Git: /usr/bin/git (found version "2.38.0") 
diff --git a/tmp/doctest/examples/all_features/test_output/coverage_maxout.cpp_junit.txt b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp_junit.txt
index 8f1e992..e69de29 100644
--- a/tmp/doctest/examples/all_features/test_output/coverage_maxout.cpp_junit.txt
+++ b/tmp/doctest/build/examples/all_features/CMakeFiles/temp_test_output_coverage_maxout.cpp_junit.txt
@@ -1,44 +0,0 @@
-<?xml version="1.0" encoding="UTF-8"?>
-<testsuites>
-  <testsuite name="all_features" errors="3" failures="3" tests="31">
-    <testcase classname="coverage_maxout.cpp" name="exercising tricky code paths of doctest" status="run">
-      <failure message="0 != 0" type="CHECK">
-coverage_maxout.cpp(0):
-CHECK( str.compare(const_str, true) != 0 ) is NOT correct!
-  values: CHECK( 0 != 0 )
-  logged: should fail
-
-      </failure>
-      <failure message="0 != 0" type="CHECK">
-coverage_maxout.cpp(0):
-CHECK( str.compare("omgomgomg", false) != 0 ) is NOT correct!
-  values: CHECK( 0 != 0 )
-  logged: should fail
-
-      </failure>
-      <failure message="true" type="CHECK_FALSE">
-coverage_maxout.cpp(0):
-CHECK_FALSE( isThereAnything ) is NOT correct!
-  values: CHECK_FALSE( true )
-  logged: should fail
-
-      </failure>
-    </testcase>
-    <testcase classname="coverage_maxout.cpp" name="will end from a std::string exception" status="run">
-      <error message="exception">
-        std::string!
-      </error>
-    </testcase>
-    <testcase classname="coverage_maxout.cpp" name="will end from a const char* exception" status="run">
-      <error message="exception">
-        const char*!
-      </error>
-    </testcase>
-    <testcase classname="coverage_maxout.cpp" name="will end from an unknown exception" status="run">
-      <error message="exception">
-        unknown exception
-      </error>
-    </testcase>
-  </testsuite>
-</testsuites>
-Program code.
 
CMake Error at /tmp/doctest/scripts/cmake/exec_test.cmake:69 (message):
  Running '/tmp/doctest/build/examples/all_features/all_features
  --no-skipped-summary --no-version -sf=*coverage_maxout.cpp
  --reporters=junit --dt-no-path-filenames=1 --dt-no-line-numbers=1
  --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1' ended
  with code 'Output is different from reference file!'
 
<end of output>
Test time =   0.08 sec
----------------------------------------------------------
Test Failed.
"coverage_maxout.cpp_junit" end time: Oct 08 23:15 EDT
"coverage_maxout.cpp_junit" time elapsed: 00:00:00
----------------------------------------------------------

@Saalvage
Copy link
Member

Saalvage commented Oct 9, 2022

Seems like it just exits unexpectedly at some point, assuming it just throws an exception, are you able to attach a debugger to figure out what's going on here?

@matoro
Copy link
Author

matoro commented Oct 9, 2022

Seems like it just exits unexpectedly at some point, assuming it just throws an exception, are you able to attach a debugger to figure out what's going on here?

I'm not really sure tbh. But what I have done is gone ahead and provisioned you an account so that you can try it out yourself - you should be able to log in with your ssh key to saalvage [at] alphadev [dot] matoro [dot] tk. tmux, git, gdb, etc are all available. Let me know if you are able to log in and check it out.

@matoro
Copy link
Author

matoro commented Nov 19, 2022

Hi @Saalvage , were you able to try logging into the account I provisioned above? This machine is still available so that you can check out the issue firsthand.

@matoro
Copy link
Author

matoro commented Nov 30, 2022

Turns out this also affects HPPA (PA-RISC), at least the machine I just got. I am wondering if this is simply something that shows up on very slow hardware in general...

@matoro
Copy link
Author

matoro commented Dec 24, 2022

After digging into this for quite a while I finally understand what is going on. My very first suspicion was correct - clock resolution is the problem. I used this snippet in order to get information about the clock resolution: https://gist.github.com/traversaro/e031b324dd278acbd033059e3604ed3f

On x86, ARM, POWERPC it returns the following:

--> Testing POSIX APIs
    Error macros values: 
    EINTR : 4
    EINVAL: 22
    ENOTSUP: 95
    Testing CLOCK_MONOTONIC 
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
    Testing CLOCK_REALTIME 
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
    Testing CLOCK_PROCESS_CPUTIME_ID 
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
    Testing CLOCK_THREAD_CPUTIME_ID  
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
--> Testing C++ APIs
    Testing std::chrono::high_resolution_clock 
    resolution: 1 nanoseconds.
    Testing std::chrono::system_clock 
    resolution: 1 nanoseconds.
    Testing std::chrono::steady_clock 
    resolution: 1 nanoseconds.

But on alpha, it outputs:

--> Testing POSIX APIs
    Error macros values: 
    EINTR : 4
    EINVAL: 22
    ENOTSUP: 45
    Testing CLOCK_MONOTONIC 
    clock_getres return value: 0 with errno 0, 
    resolution: 976563 nanoseconds.
    Testing CLOCK_REALTIME 
    clock_getres return value: 0 with errno 0, 
    resolution: 976563 nanoseconds.
    Testing CLOCK_PROCESS_CPUTIME_ID 
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
    Testing CLOCK_THREAD_CPUTIME_ID  
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
--> Testing C++ APIs
    Testing std::chrono::high_resolution_clock 
    resolution: 1 nanoseconds.
    Testing std::chrono::system_clock 
    resolution: 1 nanoseconds.
    Testing std::chrono::steady_clock 
    resolution: 1 nanoseconds.

And HPPA is even less precise:

--> Testing POSIX APIs
    Error macros values: 
    EINTR : 4
    EINVAL: 22
    ENOTSUP: 223
    Testing CLOCK_MONOTONIC 
    clock_getres return value: 0 with errno 0, 
    resolution: 4000000 nanoseconds.
    Testing CLOCK_REALTIME 
    clock_getres return value: 0 with errno 0, 
    resolution: 4000000 nanoseconds.
    Testing CLOCK_PROCESS_CPUTIME_ID 
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
    Testing CLOCK_THREAD_CPUTIME_ID  
    clock_getres return value: 0 with errno 0, 
    resolution: 1 nanoseconds.
--> Testing C++ APIs
    Testing std::chrono::high_resolution_clock 
    resolution: 1 nanoseconds.
    Testing std::chrono::system_clock 
    resolution: 1 nanoseconds.
    Testing std::chrono::steady_clock 
    resolution: 1 nanoseconds.

Small patch I added for debugging:

diff --git a/doctest/parts/doctest.cpp b/doctest/parts/doctest.cpp
index 5ee79f7..82cb16d 100644
--- a/doctest/parts/doctest.cpp
+++ b/doctest/parts/doctest.cpp
@@ -445,7 +456,9 @@ using ticks_t = timer_large_integer::type;
         }
 
         void finalizeTestCaseData() {
-            seconds = timer.getElapsedSeconds();
+            const auto mseconds = timer.getElapsedMicroseconds();
+            // seconds = timer.getElapsedSeconds();
+            seconds = static_cast<double>(mseconds) / 1000.0;
 
             // update the non-atomic counters
             numAsserts += numAssertsCurrentTest_atomic;
@@ -456,9 +469,11 @@ using ticks_t = timer_large_integer::type;
             if(numAssertsFailedCurrentTest)
                 failure_flags |= TestCaseFailureReason::AssertFailure;
 
+            std::cout << "[DEBUG] microseconds: " << std::fixed << mseconds << std::endl;
             if(Approx(currentTest->m_timeout).epsilon(DBL_EPSILON) != 0 &&
-               Approx(seconds).epsilon(DBL_EPSILON) > currentTest->m_timeout)
+               Approx(seconds).epsilon(DBL_EPSILON) > currentTest->m_timeout) {
                 failure_flags |= TestCaseFailureReason::Timeout;
+            }
 
             if(currentTest->m_should_fail) {
                 if(failure_flags) {

Then, I took a random sampling of test runtimes. On x86:

$ grep "microseconds" Testing/Temporary/LastTest.log | shuf | head -n 25
+[DEBUG] microseconds: 120
+[DEBUG] microseconds: 3
[DEBUG] microseconds: 7
+[DEBUG] microseconds: 10
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 51
+[DEBUG] microseconds: 10
+[DEBUG] microseconds: 19
+[DEBUG] microseconds: 146
+[DEBUG] microseconds: 2
+[DEBUG] microseconds: 12
+[DEBUG] microseconds: 9
+[DEBUG] microseconds: 63
+[DEBUG] microseconds: 2
+[DEBUG] microseconds: 7
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 17
+[DEBUG] microseconds: 1
+[DEBUG] microseconds: 18
+[DEBUG] microseconds: 37
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 1
+[DEBUG] microseconds: 34
+[DEBUG] microseconds: 12
+[DEBUG] microseconds: 14

But on alpha:

$ grep "microseconds" Testing/Temporary/LastTest.log | shuf | head -n 25
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 977
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 1953
[DEBUG] microseconds: 0
[DEBUG] microseconds: 976
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 977
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 976
+[DEBUG] microseconds: 0
[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 976
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0
+[DEBUG] microseconds: 0

Because of our clock precision, test runtimes are going to be rounded to the nearest millisecond (977 microseconds technically, but easier to just say 1 millisecond). Anything with a short enough runtime is just going to be rounded down to 0.

It seems that tests which are expected to fail MUST sleep() for at least one clock-precision length in order not to have their measured runtime rounded down to 0. Strangely, I am not sure why only clock_getres() reports this precision correctly, while the std::chrono APIs do not. I wrote a small sample program that used std::chrono and it indeed cannot measure anything shorter than 1 millisecond on alpha:

$ cat test2.cpp
#include <chrono>
#include <iostream>
#include <thread>

int main(void)
{
        const auto a = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now().time_since_epoch()).count();
        std::this_thread::sleep_for(std::chrono::microseconds(1));
        const auto b = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::high_resolution_clock::now().time_since_epoch()).count();
        std::cout << b - a << std::endl;
        return 0;
}
$ ./test2
977
$ ./test2
976
$ ./test2
977
$ ./test2
976
$ ./test2
977

@matoro
Copy link
Author

matoro commented Dec 24, 2022

Simply adding a sleep to the test that is expected to time out is sufficient to solve the timeout issues, no need for the test of #712. This is sufficient to get all tests passing on HPPA.

As for the three remaining issues on alpha, it is indeed a segfault, but gdb is not really functional it seems...so it could be difficult to track down where the problem is.

$ gdb -q --args examples/all_features/all_features --no-skipped-summary --no-version -sf=*coverage_maxout.cpp --reporters=
xml --dt-no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1

Reading symbols from examples/all_features/all_features...
(gdb) r
Starting program: examples/all_features/all_features --no-skipped-summary --no-version -sf=\*coverage_maxout.cpp --reporters=xml --dt-
no-path-filenames=1 --dt-no-line-numbers=1 --dt-no-exitcode=1 --dt-gnu-file-line=0 --dt-no-time-in-output=1
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/libthread_db.so.1".
<?xml version="1.0" encoding="UTF-8"?>
<doctest binary="all_features">
  <Options order_by="file" rand_seed="324" first="0" last="4294967295" abort_after="0" subcase_filter_levels="2147483647" case_sensitive="false" no_throw="false"
 no_skip="false"/>
  <TestSuite>
    <TestCase name="exercising tricky code paths of doctest" filename="coverage_maxout.cpp" line="0">
      <Expression success="false" type="CHECK" filename="coverage_maxout.cpp" line="0">
        <Original>
          str.compare(const_str, true) != 0
        </Original>
        <Expanded>
          0 != 0
        </Expanded>
        <Info>
          should fail
        </Info>
      </Expression>
      <Expression success="false" type="CHECK" filename="coverage_maxout.cpp" line="0">
        <Original>
          str.compare("omgomgomg", false) != 0
        </Original>
        <Expanded>
          0 != 0
        </Expanded>
        <Info>
          should fail
        </Info>
      </Expression>

Program received signal SIGSEGV, Segmentation fault.
(gdb) bt
Python Exception <class 'gdb.MemoryError'>: Cannot access memory at address 0x0
Cannot access memory at address 0x0

Seems to have jumped to the zero address somehow (pc register):

(gdb) info all-registers
v0             0x50                80
t0             0x50                80
t1             0x11f9c7630         4825314864
t2             0x11f9c7100         4825313536
t3             0x20000400240       2199027450432
t4             0x0                 0
t5             0x11f9c7658         4825314904
t6             0x200003d0e50       2199027256912
t7             0x3f                63
s0             0x2000114d870       2199041398896
s1             0x0                 0
s2             0x0                 0
s3             0x2000112f298       2199041274520
s4             0x11f9c8fe0         4825321440
s5             0x2000003fd10       2199023516944
fp             0x11f9c7680         4825314944
a0             0x11f9c76a0         4825314976
a1             0x0                 0
a2             0x20000131ef0       2199024508656
a3             0xf                 15
a4             0x11f9c7100         4825313536
a5             0x200002e8ee0       2199026306784
t8             0x200003d14c8       2199027258568
t9             0x11f9c6c40         4825312320
t10            0x200003d05ec       2199027254764
t11            0x11f9c63c0         4825310144
ra             0x20001016a6c       2199040125548
t12            0x2                 2
at             0x50                80
gp             0x20000408010       0x20000408010
sp             0x11f9c7680         0x11f9c7680
zero           0x0                 0
f0             1.1920928955078125e-07 (raw 0x3e80000000000000)
f1             0                   (raw 0x0000000000000000)
f2             0                   (raw 0x0000000000000000)
f3             0                   (raw 0x0000000000000000)
f4             0                   (raw 0x0000000000000000)
f5             0                   (raw 0x0000000000000000)
f6             0                   (raw 0x0000000000000000)
f7             0                   (raw 0x0000000000000000)
f8             0                   (raw 0x0000000000000000)
f9             0                   (raw 0x0000000000000000)
f10            2                   (raw 0x4000000000000000)
f11            1.1920928955078125e-05 (raw 0x3ee9000000000000)
f12            0                   (raw 0x0000000000000000)
f13            1.125               (raw 0x3ff2000000000000)
f14            0                   (raw 0x0000000000000000)
f15            0                   (raw 0x0000000000000000)
f16            0                   (raw 0x0000000000000000)
f17            0                   (raw 0x0000000000000000)
f18            0                   (raw 0x0000000000000000)
f19            0                   (raw 0x0000000000000000)
f20            0                   (raw 0x0000000000000000)
f21            0                   (raw 0x0000000000000000)
f22            0                   (raw 0x0000000000000000)
f23            0                   (raw 0x0000000000000000)
f24            0                   (raw 0x0000000000000000)
f25            0                   (raw 0x0000000000000000)
f26            0                   (raw 0x0000000000000000)
f27            0                   (raw 0x0000000000000000)
f28            0                   (raw 0x0000000000000000)
f29            0                   (raw 0x0000000000000000)
f30            0                   (raw 0x0000000000000000)
fpcr           0x680e000000000000  7497930429618454528
pc             0x0                 0x0
unique         0x20000036fc0       2199023480768

This seems to be as close as I can get to a backtrace by stepping through it until it errors like so:

(gdb) s
Warning:
Cannot insert breakpoint 0.
Cannot access memory at address 0x0

(gdb) bt
#0  0x0000020001016a68 in doctest::assertString (at=3)
    at /home/matoro/doctest/doctest/parts/doctest.cpp:778
#1  0x00000200010ce788 in DOCTEST_ANON_FUNC_16 ()
    at /home/matoro/doctest/examples/all_features/coverage_maxout.cpp:72
#2  0x0000020001033d70 in doctest::Context::run (this=0x11fc5ce28)
    at /home/matoro/doctest/doctest/parts/doctest.cpp:3897
#3  0x00000200010353c4 in main (argc=10, argv=0x11fc5cf88)
    at /home/matoro/doctest/examples/all_features/main.cpp:24

matoro added a commit to matoro/doctest that referenced this issue Apr 15, 2023
matoro added a commit to matoro/doctest that referenced this issue Apr 15, 2023
matoro added a commit to matoro/doctest that referenced this issue Apr 15, 2023
matoro added a commit to matoro/doctest that referenced this issue Apr 15, 2023
matoro added a commit to matoro/gentoo that referenced this issue Apr 15, 2023
gentoo-bot pushed a commit to gentoo/gentoo that referenced this issue Apr 26, 2023
See: doctest/doctest#770
See: doctest/doctest#711
Bug: https://bugs.gentoo.org/874345
Signed-off-by: Matoro Mahri <matoro@users.noreply.github.com>
Closes: #30607
Signed-off-by: Sam James <sam@gentoo.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants