From da0d0439177cf70e4af78ec71fd29ce002cd5430 Mon Sep 17 00:00:00 2001 From: Tyler Karaszewski Date: Mon, 11 Mar 2024 08:50:54 -0700 Subject: [PATCH] Revert "Revert test timing changes to unblock deploy" --- test/lib/tpunit++.cpp | 35 +++++++++++++++++++++++++++++++++-- 1 file changed, 33 insertions(+), 2 deletions(-) diff --git a/test/lib/tpunit++.cpp b/test/lib/tpunit++.cpp index 8443d91a6..ff2b49e07 100644 --- a/test/lib/tpunit++.cpp +++ b/test/lib/tpunit++.cpp @@ -2,6 +2,7 @@ #include #include #include +#include using namespace tpunit; bool tpunit::TestFixture::exitFlag = false; @@ -166,11 +167,15 @@ int tpunit::TestFixture::tpunit_detail_do_run(const set& include, const } list afterTests; + mutex testTimeLock; + multimap testTimes; for (int threadID = 0; threadID < threads; threadID++) { // Capture everything by reference except threadID, because we don't want it to be incremented for the // next thread in the loop. thread t = thread([&, threadID]{ + auto start = chrono::steady_clock::now(); + threadInitFunction(); try { // Do test. @@ -258,6 +263,11 @@ int tpunit::TestFixture::tpunit_detail_do_run(const set& include, const exitFlag = true; printf("Thread %d caught shutdown exception, exiting.\n", threadID); } + auto end = chrono::steady_clock::now(); + if (currentTestName.size()) { + lock_guard lock(testTimeLock); + testTimes.emplace(make_pair(chrono::duration_cast(end - start), currentTestName)); + } }); threadList.push_back(move(t)); } @@ -294,6 +304,17 @@ int tpunit::TestFixture::tpunit_detail_do_run(const set& include, const } } + cout << endl; + cout << "Slowest Test Classes: " << endl; + auto it = testTimes.rbegin(); + for (size_t i = 0; i < 10; i++) { + if (it == testTimes.rend()) { + break; + } + cout << it->first << ": " << it->second << endl; + it++; + } + return tpunit_detail_stats()._failures; } return 1; @@ -419,23 +440,33 @@ void tpunit::TestFixture::tpunit_detail_do_tests(TestFixture* f) { f->_stats._assertions = 0; f->_stats._exceptions = 0; f->testOutputBuffer = ""; + auto start = chrono::steady_clock::now(); tpunit_detail_do_methods(f->_befores); tpunit_detail_do_method(t); tpunit_detail_do_methods(f->_afters); + auto end = chrono::steady_clock::now(); + stringstream timeStream; + timeStream << "(" << chrono::duration_cast(end - start); + if (chrono::duration_cast(end - start) > 5000ms) { + timeStream << " \xF0\x9F\x90\x8C"; + } + timeStream << ")"; + string timeStr = timeStream.str(); + const char* time = timeStr.c_str(); // No new assertions or exceptions. This not currently synchronized correctly. They can cause tests that // passed to appear failed when another test failed while this test was running. They cannot cause failed // tests to appear to have passed. if(!f->_stats._assertions && !f->_stats._exceptions) { lock_guard lock(m); - printf("\xE2\x9C\x85 %s\n", t->_name); + printf("\xE2\x9C\x85 %s %s\n", t->_name, time); tpunit_detail_stats()._passes++; } else { lock_guard lock(m); // Dump the test buffer if the test included any log lines. f->printTestBuffer(); - printf("\xE2\x9D\x8C !FAILED! \xE2\x9D\x8C %s\n", t->_name); + printf("\xE2\x9D\x8C !FAILED! \xE2\x9D\x8C %s %s\n", t->_name, time); tpunit_detail_stats()._failures++; tpunit_detail_stats()._failureNames.emplace(t->_name); }