test_stopwatch: fix on mingw

[neheb]

There are some timing shenanigans with GCC's chrono that make this
unreliable. Add a start/stop and test for that to work around.

Signed-off-by: Rosen Penev rosenp@gmail.com

[tt4g]

@neheb Could you also fix the test case "stopwatch2"? It should have the same problem.

[neheb]

Having trouble figuring that out. stopwatch2 deals with doubles whereas std::chrono::milliseconds deals with long_int. Some weird conversion is needed.

[tt4g]

In GCC std::chrono::duration_cast<duration>(milliseconds(250)) works.
Does it not work in MinGW?

Wandbox

#include <iostream>
#include <cstdlib>

#include <chrono>
#include <thread>

int main()
{
    using std::chrono::milliseconds;
    using std::chrono::duration_cast;
    using clock = std::chrono::steady_clock;
    using duration = clock::duration;

    duration wait_duration(milliseconds(250));
    duration tolerance_duration(milliseconds(250));

    auto start_duration = clock::now();
    std::this_thread::sleep_for(wait_duration);
    auto stop_duration = clock::now();

    auto diff_duration = stop_duration - start_duration;

    std::cout << duration_cast<duration>(milliseconds(250)).count() << "\n";
    std::cout << duration_cast<milliseconds>(diff_duration).count() << "\n";
    std::cout << diff_duration.count() << "\n";
    std::cout << (diff_duration + tolerance_duration).count() << "\n";
}

[tt4g]

I noticed that spdlog::stopwatch::elapsed() returns std::chrono::duration<double> (I had overlooked this).
@neheb Would the following code allow MinGW to pass the test as well?

TEST_CASE("stopwatch2", "[stopwatch]")
{
    using spdlog::sinks::test_sink_st;
    using std::chrono::duration_cast;
    using std::chrono::milliseconds;
    using clock = std::chrono::steady_clock;

    clock::duration wait_duration(milliseconds(250));
    clock::duration tolerance_duration(milliseconds(250));

    auto test_sink = std::make_shared<test_sink_st>();

    auto start = clock::now();
    spdlog::stopwatch sw;
    spdlog::logger logger("test-stopwatch", test_sink);
    logger.set_pattern("%v");
    std::this_thread::sleep_for(wait_duration);
    auto stop = clock::now();
    logger.info("{}", sw);
    std::cout << test_sink->lines()[0] << "\n";
    auto val = std::stod(test_sink->lines()[0]);
    auto diff_duration = duration_cast<std::chrono::duration<double>>(stop - start);

    REQUIRE(val >= diff_duration.count());
    REQUIRE(val <= (diff_duration + tolerance_duration).count());
}

Diff

 TEST_CASE("stopwatch2", "[stopwatch]")
 {
     using spdlog::sinks::test_sink_st;
+    using std::chrono::duration_cast;
+    using std::chrono::milliseconds;
+    using clock = std::chrono::steady_clock;

-    std::chrono::duration<double> wait_duration(0.250);
-    std::chrono::duration<double> tolerance_duration(0.250);
+    clock::duration wait_duration(milliseconds(250));
+    clock::duration tolerance_duration(milliseconds(250));

     auto test_sink = std::make_shared<test_sink_st>();

+    auto start = clock::now();
     spdlog::stopwatch sw;
     spdlog::logger logger("test-stopwatch", test_sink);
     logger.set_pattern("%v");
     std::this_thread::sleep_for(wait_duration);
+    auto stop = clock::now();
     logger.info("{}", sw);
+    std::cout << test_sink->lines()[0] << "\n";
     auto val = std::stod(test_sink->lines()[0]);
+    auto diff_duration = duration_cast<std::chrono::duration<double>>(stop - start);

-    REQUIRE(val >= wait_duration.count());
-    REQUIRE(val <= (wait_duration + tolerance_duration).count());
+    REQUIRE(val >= diff_duration.count());
+    REQUIRE(val <= (diff_duration + tolerance_duration).count());
 }

[neheb]

It already passes. Just test one had issues.

edit: nvm just failed:

0.2499963 >= 0.25

[neheb]

Updated.

[tt4g]

Oh wait, the source code I pasted still has the statement for debugging.
Sorry. Please remove std::cout << test_sink->lines()[0] << "\n";.

[neheb]

I don’t think that’s the error here.

[neheb]

Ah I have a stoll call.

[gabime]

Lets please use same diff method in both functions.

[neheb]

This is needed because test2 uses a double.

[gabime]

Thanks @neheb and @tt4g

[neheb]

@tt4g found out why this was an issue.

LLVM's libc++ calls the proper windows APIs directly instead of going through clock_gettime. libstdc++ uses clock_gettime. The difference is that clock_gettime as implemented in winpthreads calls GetSystemTimeAsFileTime. libc++ uses GetSystemTimePreciseAsFileTime and falls back to GetSystemTimeAsFileTime for Windows versions older than 8.

[tt4g]

@neheb Great!