From a9ab5f190d05ba79efa2267d236fcff31ac5adf5 Mon Sep 17 00:00:00 2001 From: John Lee Date: Mon, 3 Feb 2025 16:33:57 -0800 Subject: [PATCH 1/3] Actually track total class test times, not the time a thread is alive --- test/lib/tpunit++.cpp | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/test/lib/tpunit++.cpp b/test/lib/tpunit++.cpp index e1ec8aeba..62a303b95 100644 --- a/test/lib/tpunit++.cpp +++ b/test/lib/tpunit++.cpp @@ -190,6 +190,7 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const // next thread in the loop. thread t = thread([&, threadID]{ auto start = chrono::steady_clock::now(); + auto end = start; threadInitFunction(); try { @@ -270,6 +271,9 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const } tpunit_run_test_class(f); + + // Do this to capture the longest test classes, not longest thread. + end = chrono::steady_clock::now(); } } catch (ShutdownException se) { // This will have broken us out of our main loop, so we'll just exit. We also set the exit flag to let @@ -278,7 +282,7 @@ 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)); From 458324cb3fe958fe613fbb9fe7dfeb428330efa2 Mon Sep 17 00:00:00 2001 From: John Lee Date: Mon, 3 Feb 2025 16:50:53 -0800 Subject: [PATCH 2/3] Improve bedrock tests --- test/lib/tpunit++.cpp | 64 +++++++++++++++++++++++++------------------ 1 file changed, 37 insertions(+), 27 deletions(-) diff --git a/test/lib/tpunit++.cpp b/test/lib/tpunit++.cpp index 62a303b95..313b96f06 100644 --- a/test/lib/tpunit++.cpp +++ b/test/lib/tpunit++.cpp @@ -189,8 +189,8 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const // 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(); - auto end = start; + chrono::steady_clock::time_point start = chrono::steady_clock::now(); + chrono::steady_clock::time_point end = start; threadInitFunction(); try { @@ -255,25 +255,32 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const continue; } - // At this point, we know this test should run. - if (!f->_multiThreaded) { - printf("--------------\n"); - } - { - lock_guard lock(currentTestNameMutex); - currentTestPtr = f; - if (f->_name) { - currentTestName = f->_name; - } else { - cout << "test has no name???" << endl; - currentTestName = "UNSPECIFIED"; - } - } - - tpunit_run_test_class(f); - - // Do this to capture the longest test classes, not longest thread. - end = chrono::steady_clock::now(); + // At this point, we know this test should run. + if (!f->_multiThreaded) { + printf("--------------\n"); + } + { + lock_guard lock(currentTestNameMutex); + currentTestPtr = f; + if (f->_name) { + currentTestName = f->_name; + } else { + cout << "test has no name???" << endl; + currentTestName = "UNSPECIFIED"; + } + } + + start = chrono::steady_clock::now(); + + tpunit_run_test_class(f); + + // Do this to capture the longest test classes, not longest thread. + end = chrono::steady_clock::now(); + + if (currentTestName.size() && currentTestName != "UNSPECIFIED") { + lock_guard lock(testTimeLock); + testTimes.emplace(make_pair(chrono::duration_cast(end - start), currentTestName)); + } } } catch (ShutdownException se) { // This will have broken us out of our main loop, so we'll just exit. We also set the exit flag to let @@ -282,11 +289,6 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const exitFlag = true; printf("Thread %d caught shutdown exception, exiting.\n", threadID); } - - if (currentTestName.size()) { - lock_guard lock(testTimeLock); - testTimes.emplace(make_pair(chrono::duration_cast(end - start), currentTestName)); - } }); threadList.push_back(move(t)); } @@ -325,15 +327,23 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const cout << endl; cout << "Slowest Test Classes: " << endl; + + long long totalTestTime = 0; + for (auto testTime : testTimes) { + totalTestTime += testTime.first.count(); + } + auto it = testTimes.rbegin(); for (size_t i = 0; i < 10; i++) { if (it == testTimes.rend()) { break; } - cout << it->first << ": " << it->second << endl; + cout << it->first << ": " << it->second << " " << (static_cast(it->first.count()) / totalTestTime) * 100.0 << "% of total test time" << endl; it++; } + cout << "Total test time across threads: " << totalTestTime << "ms" << endl; + return tpunit_detail_stats()._failures; } return 1; From b2d8506715865c2c4c365481903e3f9ec1ab75aa Mon Sep 17 00:00:00 2001 From: John Lee Date: Mon, 3 Feb 2025 16:51:00 -0800 Subject: [PATCH 3/3] Comments and better format --- test/lib/tpunit++.cpp | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/lib/tpunit++.cpp b/test/lib/tpunit++.cpp index 313b96f06..6b2a304b2 100644 --- a/test/lib/tpunit++.cpp +++ b/test/lib/tpunit++.cpp @@ -328,6 +328,7 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const cout << endl; cout << "Slowest Test Classes: " << endl; + // Combine total thread time so its not obscured by multi-threaded tests. long long totalTestTime = 0; for (auto testTime : testTimes) { totalTestTime += testTime.first.count(); @@ -338,7 +339,7 @@ int tpunit::_TestFixture::tpunit_detail_do_run(const set& include, const if (it == testTimes.rend()) { break; } - cout << it->first << ": " << it->second << " " << (static_cast(it->first.count()) / totalTestTime) * 100.0 << "% of total test time" << endl; + cout << it->first << ": " << it->second << " : " << (static_cast(it->first.count()) / totalTestTime) * 100.0 << "% of total test time" << endl; it++; }