ichthyo/LUMIERA.clone
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Scheduler-test: resolve inconsistency in time accounting for instrumentation

Browse source 
Basically users are free to place the measurement calls to their liking.
This implies that bracketed measurement intervals can be defined overlapping
even within a single thread, thereby accounting the overlapping time interval
several times. However, for the time spent per thread, only actual thread
activity should be counted, disregarding overlaps. Thus introduce a
new aggregate, ''active time'', which is the sum of all thread times.

As an aside, do not need explicit randomness for the simple two-thread
test case — timings are random anyway...

+ bugfix for out-of-bounds access
This commit is contained in:
Fischlurch 2024-02-14 19:57:43 +01:00
parent 9f0878f885
commit d0c1017580
3 changed files with 74 additions and 31 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

29
src/lib/incidence-count.hpp
View file

@ -36,7 +36,7 @@
** launch a test, retrieve the observed statistics, destroy the object. Each
** separate Threads encountered gets the next consecutive ID. Thus it is *not possible*
** to have long-living instances or even multiple instances of IncidenceCount; doing so
** would require a much more elaborate ID management, which is beyond requirement's scope.
** would require a much more elaborate ID management, which is beyond requirement's scope.
**
** @see IncidenceCount_test
** @see vault::gear::TestChainLoad::ScheduleCtx
@ -155,7 +155,7 @@ namespace lib {
{
REQUIRE (cnt);
for (Sequence& s : rec_)
s.reserve (cnt);
s.reserve (2*cnt);
return *this;
}
@ -173,14 +173,15 @@ namespace lib {
{
size_t eventCnt{0};
size_t activationCnt{0};
double cumulatedTime{0};
double coveredTime{0};
double avgConcurrency{0};
double cumulatedTime{0}; ///< aggregated time over all cases
double activeTime{0}; ///< compounded time of thread activity
double coveredTime{0}; ///< overall timespan of observation
double avgConcurrency{0}; ///< amortised concurrency in timespan
vector<size_t> caseCntr{};
vector<size_t> thrdCntr{};
vector<double> caseTime{};
vector<double> thrdTime{};
vector<size_t> caseCntr{}; ///< counting activations per case
vector<size_t> thrdCntr{}; ///< counting activations per thread
vector<double> caseTime{}; ///< aggregated time per case
vector<double> thrdTime{}; ///< time of activity per thread
vector<double> concTime{};
template<typename VAL>
@ -235,12 +236,11 @@ namespace lib {
);
int active{0};
size_t numCases = std::numeric_limits<uint8_t>::max()+1;
vector<int> active_case(numCases);
vector<int> active_case;
vector<int> active_thrd(numThreads);
stat.thrdCntr.resize (numThreads);
stat.thrdTime.resize (numThreads);
stat.concTime.resize (numThreads);
stat.concTime.resize (numThreads+1); // also accounting for idle times in range
// Integrate over the timeline...
// - book the preceding interval length into each affected partial sum
@ -250,6 +250,7 @@ namespace lib {
{
if (event.caseID >= stat.caseCntr.size())
{
active_case .resize (event.caseID+1);
stat.caseCntr.resize (event.caseID+1);
stat.caseTime.resize (event.caseID+1);
}
@ -258,7 +259,8 @@ namespace lib {
for (uint i=0; i < stat.caseCntr.size(); ++i)
stat.caseTime[i] += active_case[i] * timeSlice.count();
for (uint i=0; i < numThreads; ++i)
stat.thrdTime[i] += active_thrd[i] * timeSlice.count();
if (active_thrd[i]) // note: counting activity per thread, without overlapping cases
stat.thrdTime[i] += timeSlice.count();
size_t concurr = explore(active_thrd).filter([](int a){ return 0 < a; }).count();
ENSURE (concurr <= numThreads);
stat.avgConcurrency += concurr * timeSlice.count(); // contribution for weighted average
@ -289,6 +291,7 @@ namespace lib {
ENSURE (0 < stat.activationCnt);
ENSURE (stat.eventCnt % 2 == 0);
stat.avgConcurrency /= stat.coveredTime; // time used as weight sum
stat.activeTime = explore(stat.thrdTime).resultSum();
return stat;
}

64
tests/library/incidence-count-test.cpp
View file

@ -40,12 +40,20 @@
using util::isLimited;
using std::this_thread::sleep_for;
using std::chrono_literals::operator ""ms;
using std::chrono_literals::operator ""us;
using std::chrono::microseconds;
namespace lib {
namespace test{
namespace {
inline bool
isNumEq (double d1, double d2)
{
return 0.001 > abs(d1-d2);
};
}
@ -120,6 +128,7 @@ namespace test{
auto stat = watch.evaluate();
SHOW_EXPR(stat.cumulatedTime);
SHOW_EXPR(stat.coveredTime);
SHOW_EXPR(stat.activeTime);
SHOW_EXPR(stat.eventCnt);
SHOW_EXPR(stat.activationCnt);
SHOW_EXPR(stat.cntCase(0));
@ -136,7 +145,7 @@ SHOW_EXPR(stat.cntThread(0));
SHOW_EXPR(stat.cntThread(1));
SHOW_EXPR(stat.timeThread(0));
SHOW_EXPR(stat.timeThread(1));
CHECK (isLimited (15500, stat.cumulatedTime, 17500)); // ≈ 16ms
CHECK (isLimited (15500, stat.cumulatedTime, 17800)); // ≈ 16ms
CHECK (isLimited ( 8500, stat.coveredTime, 10000)); // ≈ 9ms
CHECK (10== stat.eventCnt);
CHECK (5 == stat.activationCnt);
@ -152,9 +161,10 @@ SHOW_EXPR(stat.timeThread(1));
CHECK (0 == stat.timeCase(4));
CHECK (5 == stat.cntThread(0));
CHECK (0 == stat.cntThread(1));
CHECK (stat.cumulatedTime == stat.timeThread(0));
CHECK (0 == stat.timeThread(1));
CHECK (1 > abs(stat.cumulatedTime - (stat.timeCase(1) + stat.timeCase(2) + stat.timeCase(3))));
CHECK (stat.activeTime == stat.timeThread(0));
CHECK (0 == stat.timeThread(1));
CHECK (isNumEq (stat.activeTime, stat.coveredTime));
CHECK (isNumEq (stat.cumulatedTime , stat.timeCase(1) + stat.timeCase(2) + stat.timeCase(3)));
}
@ -165,18 +175,16 @@ SHOW_EXPR(stat.timeThread(1));
verify_concurrencyStatistic()
{
MARK_TEST_FUN
const size_t CONCURR = std::thread::hardware_concurrency();
IncidenceCount watch;
watch.expectThreads(CONCURR)
.expectIncidents(5000);
watch.expectThreads(2)
.expectIncidents(2);
auto act = [&]{ // two nested activities with random delay
uint delay = 100 + rand() % 800;
auto act = [&]{ // two nested activities
watch.markEnter();
sleep_for (microseconds(delay));
sleep_for (600us);
watch.markEnter(2);
sleep_for (microseconds(delay));
sleep_for (200us);
watch.markLeave(2);
watch.markLeave();
};
@ -196,6 +204,7 @@ SHOW_EXPR(stat.timeThread(1));
auto stat = watch.evaluate();
SHOW_EXPR(runTime)
SHOW_EXPR(stat.cumulatedTime);
SHOW_EXPR(stat.activeTime);
SHOW_EXPR(stat.coveredTime);
SHOW_EXPR(stat.eventCnt);
SHOW_EXPR(stat.activationCnt);
@ -217,8 +226,10 @@ SHOW_EXPR(stat.avgConcurrency);
SHOW_EXPR(stat.timeAtConc(0));
SHOW_EXPR(stat.timeAtConc(1));
SHOW_EXPR(stat.timeAtConc(2));
SHOW_EXPR(stat.timeAtConc(3));
CHECK (runTime > stat.coveredTime);
CHECK (stat.coveredTime < stat.cumulatedTime);
CHECK (stat.activeTime <= stat.cumulatedTime);
CHECK (8 == stat.eventCnt);
CHECK (4 == stat.activationCnt);
CHECK (2 == stat.cntCase(0));
@ -228,18 +239,19 @@ SHOW_EXPR(stat.timeAtConc(2));
CHECK (2 == stat.cntThread(0));
CHECK (2 == stat.cntThread(1));
CHECK (0 == stat.cntThread(3));
CHECK (isLimited(0, stat.avgConcurrency, 2));
CHECK (stat.timeAtConc(0) == 0.0);
CHECK (isLimited(1, stat.avgConcurrency, 2));
CHECK (0 == stat.timeAtConc(0));
CHECK (0 < stat.timeAtConc(1));
CHECK (0 < stat.timeAtConc(2));
CHECK (0 == stat.timeAtConc(3));
CHECK (stat.timeAtConc(1) < stat.coveredTime);
CHECK (stat.timeAtConc(2) < stat.coveredTime);
auto isNumEq = [](double d1, double d2){ return 0,001 > abs(d1-d2); };
CHECK (isNumEq (stat.avgConcurrency, (1*stat.timeAtConc(1) + 2*stat.timeAtConc(2)) // average concurrency is a weighted mean
/ stat.coveredTime)); // of the times spent at each concurrency level
CHECK (isNumEq (stat.cumulatedTime , stat.timeThread(0) + stat.timeThread(1))); // cumulated time is spent in both threads
CHECK (isNumEq (stat.cumulatedTime , stat.timeCase(0) + stat.timeCase(2))); // and likewise in all cases together
CHECK (isNumEq (stat.cumulatedTime , stat.timeCase(0) + stat.timeCase(2))); // cumulated time compounds all cases, including overlap
CHECK (isNumEq (stat.activeTime , stat.timeThread(0) + stat.timeThread(1))); // while active time disregards overlapping activities per thread
CHECK (isNumEq (stat.coveredTime , stat.timeAtConc(1) + stat.timeAtConc(2))); // the covered time happens at any non-zero concurrency level
CHECK (stat.timeCase(2) < stat.timeCase(0)); // Note: case-2 is nested into case-0
@ -253,7 +265,23 @@ SHOW_EXPR(stat.timeAtConc(2));
void
perform_multithreadStressTest()
{
UNIMPLEMENTED("verify thread-safe operation under pressure");
MARK_TEST_FUN
const size_t CONCURR = std::thread::hardware_concurrency();
IncidenceCount watch;
watch.expectThreads(CONCURR)
.expectIncidents(5000);
auto act = [&]{ // two nested activities with random delay
uint delay = 100 + rand() % 800;
watch.markEnter();
sleep_for (microseconds(delay));
watch.markEnter(2);
sleep_for (microseconds(delay));
watch.markLeave(2);
watch.markLeave();
};
}
};

12
wiki/thinkPad.ichthyo.mm
View file

@ -111085,6 +111085,18 @@ Date:&#160;&#160;&#160;Thu Apr 20 18:53:17 2023 +0200<br/>
<icon BUILTIN="button_ok"/>
</node>
</node>
<node BACKGROUND_COLOR="#e0ceaa" COLOR="#690f14" CREATED="1707936281530" ID="ID_710775644" MODIFIED="1707936315141" TEXT="Inkonsistenz in der Auswertung : beobachtete Cases k&#xf6;nnen sich &#xfc;berlappen">
<icon BUILTIN="messagebox_warning"/>
<node CREATED="1707936316947" ID="ID_1876995714" MODIFIED="1707936417871" TEXT="h&#xe4;ngt eben davon ab, wie die Start/Stop-Aufrufe erfolgen">
<icon BUILTIN="idea"/>
</node>
<node BACKGROUND_COLOR="#c8c0b6" COLOR="#690f14" CREATED="1707936336633" ID="ID_1544753205" MODIFIED="1707936412846" TEXT="man kann ein-und-dieselbe Thread-Aktivit&#xe4;t so durchaus mehrfach z&#xe4;hlen">
<icon BUILTIN="clanbomber"/>
</node>
<node COLOR="#338800" CREATED="1707936355570" ID="ID_280065222" MODIFIED="1707936399484" TEXT="aber die &#xbb;active time&#xab; sollte nur tats&#xe4;chliche Thread-Aktivit&#xe4;t messen">
<icon BUILTIN="button_ok"/>
</node>
</node>
</node>
</node>
<node BACKGROUND_COLOR="#eef0c5" COLOR="#990000" CREATED="1707754958979" ID="ID_284055307" MODIFIED="1707880406370" TEXT="IncidenceCount_test">