From 22ae5bc24afaf19b417c3c7f590b3e46968e25e2 Mon Sep 17 00:00:00 2001 From: Jarmo Jaakkola Date: Wed, 9 Dec 2015 13:22:53 +0200 Subject: [PATCH 1/2] Add traces to suite and test case starts. Print tracing information when a test suite or test case is started in CxxTests. Use '-v' parameter to enable traces. This provides better context information for hard to track unit test problems like timeouts or segfaults. --- cxxtest/ErrorFormatter.h | 109 +++++++++++++++++++++++++++++++++++++-- 1 file changed, 106 insertions(+), 3 deletions(-) diff --git a/cxxtest/ErrorFormatter.h b/cxxtest/ErrorFormatter.h index 3319dec..5deb1b0 100644 --- a/cxxtest/ErrorFormatter.h +++ b/cxxtest/ErrorFormatter.h @@ -25,9 +25,67 @@ #include #include #include +#include + +#ifdef _WIN32 +#include +#endif namespace CxxTest { +namespace { +#ifdef _WIN32 + struct timespec + { + time_t tv_sec; + long tv_nsec; + }; + + static const int NANOS = 1000000000; // nanoseconds in a second (10^9) + typedef int clockid_t; + static const clockid_t CLOCK_MONOTONIC = 0; + int clock_gettime(const clockid_t, timespec* tp) + { + LARGE_INTEGER freq; // ticks / second + LARGE_INTEGER count; // current tick count + bool success(QueryPerformanceFrequency(&freq)); + success = success && QueryPerformanceCounter(&count); + if (success) + { + tp->tv_sec = count.QuadPart / freq.QuadPart; + tp->tv_nsec = static_cast( + (count.QuadPart % freq.QuadPart) + * (static_cast(NANOS) / freq.QuadPart) + ); + } + + return (success ? 0 : -1); + } +#endif + + static const timespec invalidTime = { -1, -1 }; + + bool operator!=(const timespec& left, const timespec& right) + { + return !(left.tv_sec == right.tv_sec && left.tv_nsec == right.tv_nsec); + } + + timespec operator-(const timespec& left, const timespec& right) + { + timespec retval = { + static_cast(std::difftime(left.tv_sec, right.tv_sec)), + left.tv_nsec - right.tv_nsec + }; + if (retval.tv_nsec < 0) + { + retval.tv_sec -= 1; + retval.tv_nsec += 1000000000; + } + + return retval; + } +} + class OutputStream { public: @@ -54,7 +112,8 @@ class ErrorFormatter : public TestListener _preLine(preLine), _postLine(postLine), _errorString(errorString), - _warningString(warningString) + _warningString(warningString), + _testEnterTime() { } @@ -79,18 +138,60 @@ class ErrorFormatter : public TestListener o << wd.strTotalTests(s) << (wd.numTotalTests() == 1 ? " test" : " tests"); } - void enterSuite(const SuiteDescription &) + void enterSuite(const SuiteDescription& suite) { + if (tracker().print_tracing) + { + // enterTest() starts with a newline, so don't put one here + // to avoid an unnecessary empty line. + (*_o) << "\nStarting " << suite.suiteName(); + _o->flush(); + fflush(stdout); + } _reported = false; } - void enterTest(const TestDescription &) + void enterTest(const TestDescription& test) { + if (tracker().print_tracing) + { + // Print the name on its own line with indent so that the suite + // names stand out a bit better in a wall of text. Append + // a space and do not use a newline so that leaveTest() + // will print the '.' or 's' in way that makes some sense. + (*_o) << "\n Starting " << test.testName() << " "; + _o->flush(); + fflush(stdout); + } + if (clock_gettime(CLOCK_MONOTONIC, &_testEnterTime) != 0) + { + _testEnterTime = invalidTime; + } _reported = false; } void leaveTest(const TestDescription &) { + if (!tracker().testSkipped() + && tracker().print_tracing + && _testEnterTime != invalidTime) + { + timespec testLeaveTime; + if (clock_gettime(CLOCK_MONOTONIC, &testLeaveTime) == 0) + { + timespec duration(testLeaveTime - _testEnterTime); + // OutputStream does not have setw(), can't use snprintf + // because of Microsoft's non-conformant compiler. + static const std::size_t SIZE(10); + char nsecBuf[SIZE]; + std::sprintf(nsecBuf, "%0*ld", SIZE - 1, duration.tv_nsec); + (*_o) << (tracker().testFailed() ? "\n" : "") + << "test took " + << duration.tv_sec << "." << nsecBuf + << " seconds "; + } + } + if (tracker().testSkipped()) { (*_o) << "s"; @@ -339,6 +440,8 @@ class ErrorFormatter : public TestListener const char *_postLine; const char *_errorString; const char *_warningString; + + timespec _testEnterTime; }; } From 6dca23af46fac71ecfd93ab4e55d64f8167c2e2c Mon Sep 17 00:00:00 2001 From: Jarmo Jaakkola Date: Wed, 16 Dec 2015 18:13:59 +0200 Subject: [PATCH 2/2] Add verbose tracing option for CxxTest unittests. Suite and test case tracing is extra verbose, hide it from from "-v" tracing. Add support for "-v -v" to enable verbose tracing, which prints suite and test case tracing in addition to regular tracing. This allows a developer to better see regular traces when test failures are expected, e.g. when developing a new test suite or debugging a single test case. Use of "-vv" is a change from the previous non-configurable verbosity behaviour, but this has the same effect as "-v" had before this change. "-v" used to enable all tracing, including verbose tracing. --- cxxtest/ErrorFormatter.h | 6 +++--- cxxtest/TestMain.h | 15 +++++++++++++++ cxxtest/TestTracker.cpp | 1 + cxxtest/TestTracker.h | 1 + 4 files changed, 20 insertions(+), 3 deletions(-) diff --git a/cxxtest/ErrorFormatter.h b/cxxtest/ErrorFormatter.h index 5deb1b0..3a6667c 100644 --- a/cxxtest/ErrorFormatter.h +++ b/cxxtest/ErrorFormatter.h @@ -140,7 +140,7 @@ class ErrorFormatter : public TestListener void enterSuite(const SuiteDescription& suite) { - if (tracker().print_tracing) + if (tracker().print_verbose_tracing) { // enterTest() starts with a newline, so don't put one here // to avoid an unnecessary empty line. @@ -153,7 +153,7 @@ class ErrorFormatter : public TestListener void enterTest(const TestDescription& test) { - if (tracker().print_tracing) + if (tracker().print_verbose_tracing) { // Print the name on its own line with indent so that the suite // names stand out a bit better in a wall of text. Append @@ -173,7 +173,7 @@ class ErrorFormatter : public TestListener void leaveTest(const TestDescription &) { if (!tracker().testSkipped() - && tracker().print_tracing + && tracker().print_verbose_tracing && _testEnterTime != invalidTime) { timespec testLeaveTime; diff --git a/cxxtest/TestMain.h b/cxxtest/TestMain.h index c4d14bb..747cc49 100644 --- a/cxxtest/TestMain.h +++ b/cxxtest/TestMain.h @@ -35,12 +35,15 @@ namespace CxxTest inline void print_help(const char* name) { + CXXTEST_STD(cerr) << CXXTEST_STD(endl); + CXXTEST_STD(cerr) << "CxxTest test runner usage: " << CXXTEST_STD(endl); CXXTEST_STD(cerr) << name << " " << CXXTEST_STD(endl); CXXTEST_STD(cerr) << name << " " << CXXTEST_STD(endl); CXXTEST_STD(cerr) << name << " -h" << CXXTEST_STD(endl); CXXTEST_STD(cerr) << name << " --help" << CXXTEST_STD(endl); CXXTEST_STD(cerr) << name << " --help-tests" << CXXTEST_STD(endl); CXXTEST_STD(cerr) << name << " -v Enable tracing output." << CXXTEST_STD(endl); + CXXTEST_STD(cerr) << name << " -v -v Enable verbose tracing output." << CXXTEST_STD(endl); } #endif @@ -85,8 +88,20 @@ int Main(TesterT& tmp, int argc, char* argv[]) while ((argc > 1) && (argv[1][0] == '-')) { if (CXXTEST_STD(strcmp)(argv[1], "-v") == 0) + { + if (tracker().print_tracing) + { + tracker().print_verbose_tracing = true; + } + else + { + tracker().print_tracing = true; + } + } + else if (CXXTEST_STD(strcmp)(argv[1], "-vv") == 0) { tracker().print_tracing = true; + tracker().print_verbose_tracing = true; } else { diff --git a/cxxtest/TestTracker.cpp b/cxxtest/TestTracker.cpp index fbb6dcd..2f1298c 100644 --- a/cxxtest/TestTracker.cpp +++ b/cxxtest/TestTracker.cpp @@ -18,6 +18,7 @@ namespace CxxTest { bool TestTracker::_created = false; bool TestTracker::print_tracing = false; +bool TestTracker::print_verbose_tracing = false; TestTracker::TestTracker() { diff --git a/cxxtest/TestTracker.h b/cxxtest/TestTracker.h index 50e59bc..823bfd5 100644 --- a/cxxtest/TestTracker.h +++ b/cxxtest/TestTracker.h @@ -32,6 +32,7 @@ class TestTracker : public TestListener static TestTracker &tracker(); static bool print_tracing; + static bool print_verbose_tracing; const TestDescription *fixTest(const TestDescription *d) const; const SuiteDescription *fixSuite(const SuiteDescription *d) const;