Scheduler: wrap-up and comment test cases thus far
...up to now, Behaviour is as expected - with some minor discrepancies still to be fixed - and an effect due to the test-scaffolding
This commit is contained in:
parent
097001d16f
commit
b5e9d67a79
7 changed files with 113 additions and 156 deletions
|
|
@ -613,7 +613,6 @@ namespace test{
|
|||
EventLog::EventLog (string logID)
|
||||
: log_(new Log)
|
||||
{
|
||||
log_->reserve(2000);
|
||||
log({"type=EventLogHeader", "this="+logID});
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -70,8 +70,6 @@
|
|||
#include "lib/time/timevalue.hpp"
|
||||
#include "lib/meta/function.hpp"
|
||||
#include "lib/util.hpp"
|
||||
#include "lib/format-cout.hpp" /////////////////////////TODO
|
||||
#include "vault/real-clock.hpp"
|
||||
|
||||
|
||||
namespace vault{
|
||||
|
|
@ -616,14 +614,7 @@ namespace gear {
|
|||
case FEED:
|
||||
return activity::PASS;
|
||||
case HOOK:
|
||||
// return callHook (now, executionCtx);
|
||||
{
|
||||
Time t0 = executionCtx.getSchedTime();
|
||||
activity::Proc res = callHook (now, executionCtx);
|
||||
Time t2 = executionCtx.getSchedTime();
|
||||
cout << "+++++++++++HO: "<<_raw(t2) - _raw(t0)<<"µs"<<endl;
|
||||
return res;
|
||||
}
|
||||
return callHook (now, executionCtx);
|
||||
case TICK:
|
||||
return doTick (now, executionCtx);
|
||||
default:
|
||||
|
|
@ -666,11 +657,7 @@ cout << "+++++++++++HO: "<<_raw(t2) - _raw(t0)<<"µs"<<endl;
|
|||
case FEED: // signal just to proceed with next...
|
||||
return activity::PASS;
|
||||
default:
|
||||
Time t0 = executionCtx.getSchedTime();
|
||||
activity::Proc res = activate (now, executionCtx);
|
||||
Time t2 = executionCtx.getSchedTime();
|
||||
cout << "++++++++++ACT: "<<_raw(t2) - _raw(t0)<<"µs"<<endl;
|
||||
return res;
|
||||
return activate (now, executionCtx);
|
||||
}
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -76,8 +76,6 @@
|
|||
#include "vault/gear/activity-lang.hpp"
|
||||
#include "lib/time/timevalue.hpp"
|
||||
#include "lib/nocopy.hpp"
|
||||
#include "lib/format-cout.hpp" /////////////////////////TODO
|
||||
#include "vault/real-clock.hpp"
|
||||
|
||||
#include <thread>
|
||||
#include <atomic>
|
||||
|
|
@ -108,7 +106,7 @@ namespace gear {
|
|||
using ThreadID = std::thread::id;
|
||||
atomic<ThreadID> groomingToken_{};
|
||||
|
||||
auto thisThread() { return ThreadID();}/////////////////TODO std::this_thread::get_id(); }
|
||||
auto thisThread() { return std::this_thread::get_id(); }
|
||||
|
||||
|
||||
public:
|
||||
|
|
@ -125,7 +123,6 @@ namespace gear {
|
|||
bool
|
||||
acquireGoomingToken() noexcept
|
||||
{
|
||||
return true;
|
||||
ThreadID expect_noThread; // expect no one else to be in...
|
||||
return groomingToken_.compare_exchange_strong (expect_noThread, thisThread()
|
||||
,memory_order_acquire // success also constitutes an acquire barrier
|
||||
|
|
@ -142,7 +139,6 @@ return true;
|
|||
void
|
||||
dropGroomingToken() noexcept
|
||||
{ // expect that this thread actually holds the Grooming-Token
|
||||
return;
|
||||
REQUIRE (groomingToken_.load(memory_order_relaxed) == thisThread());
|
||||
const ThreadID noThreadHoldsIt;
|
||||
groomingToken_.store (noThreadHoldsIt, memory_order_release);
|
||||
|
|
@ -155,7 +151,6 @@ return;
|
|||
bool
|
||||
holdsGroomingToken (ThreadID id) noexcept
|
||||
{
|
||||
return true;
|
||||
return id == groomingToken_.load (memory_order_relaxed);
|
||||
}
|
||||
|
||||
|
|
@ -220,26 +215,14 @@ return true;
|
|||
if (!chain) return activity::WAIT;
|
||||
|
||||
Time now = executionCtx.getSchedTime();
|
||||
bool shallDispatch =decideDispatchNow (when, now);
|
||||
Time t1 = executionCtx.getSchedTime();
|
||||
activity::Proc res;
|
||||
if (shallDispatch)
|
||||
{
|
||||
res = ActivityLang::dispatchChain (chain, executionCtx);
|
||||
}
|
||||
// return ActivityLang::dispatchChain (chain, executionCtx);
|
||||
if (decideDispatchNow (when, now))
|
||||
return ActivityLang::dispatchChain (chain, executionCtx);
|
||||
else
|
||||
{
|
||||
if (holdsGroomingToken (thisThread()))
|
||||
layer1.feedPrioritisation (*chain, when);
|
||||
else
|
||||
layer1.instruct (*chain, when);
|
||||
// return activity::PASS;
|
||||
res = activity::PASS;
|
||||
}
|
||||
Time t2 = executionCtx.getSchedTime();
|
||||
cout << "+++++++++Post: "<<_raw(t2) - _raw(now)<<"µs ("<<_raw(t1)-_raw(now)<<"|+|"<<_raw(t2)-_raw(t1)<<(shallDispatch?":dispatch":":enqueue")<<")"<<endl;
|
||||
return res;
|
||||
return activity::PASS;
|
||||
}
|
||||
};
|
||||
|
||||
|
|
|
|||
|
|
@ -52,9 +52,8 @@
|
|||
#include "vault/gear/engine-observer.hpp"
|
||||
#include "vault/real-clock.hpp"
|
||||
//#include "lib/symbol.hpp"
|
||||
#include "lib/nocopy.hpp"
|
||||
#include "lib/nocopy.hpp"
|
||||
//#include "lib/util.hpp"
|
||||
#include "lib/format-cout.hpp" /////////////////////////TODO
|
||||
|
||||
//#include <string>
|
||||
#include <utility>
|
||||
|
|
@ -336,11 +335,7 @@ namespace gear {
|
|||
.performStep([&]{
|
||||
Time now = ctx.getSchedTime();
|
||||
Activity* act = layer2_.findWork (layer1_,now);
|
||||
Time moo = ctx.getSchedTime();
|
||||
auto res = ctx.post (now, act, ctx);
|
||||
Time boo = ctx.getSchedTime();
|
||||
cout << "+++++Dispatch: "<<_raw(boo) - _raw(now)<<"µs ("<<_raw(moo)-_raw(now)<<"|+|"<<_raw(boo)-_raw(moo)<<")"<<endl;
|
||||
return res;
|
||||
return ctx.post (now, act, ctx);
|
||||
})
|
||||
.performStep([&]{
|
||||
Time now = ctx.getSchedTime();
|
||||
|
|
@ -368,12 +363,10 @@ cout << "+++++Dispatch: "<<_raw(boo) - _raw(now)<<"µs ("<<_raw(moo)-_raw(now)<<
|
|||
inline activity::Proc
|
||||
Scheduler::scatteredDelay (Time now, LoadController::Capacity capacity)
|
||||
{
|
||||
cout<<"|capacity="<<capacity<<"\n";
|
||||
switch (capacity) {
|
||||
case LoadController::DISPATCH:
|
||||
return activity::PASS;
|
||||
case LoadController::SPINTIME:
|
||||
cout<<"|yield\n";
|
||||
std::this_thread::yield();
|
||||
return activity::SKIP;
|
||||
case LoadController::IDLEWAIT:
|
||||
|
|
@ -385,18 +378,11 @@ cout<<"|yield\n";
|
|||
if (not loadControl_.tendedNext(head)
|
||||
and (layer2_.holdsGroomingToken(self)
|
||||
or layer2_.acquireGoomingToken()))
|
||||
{
|
||||
cout << "|tendNext...";
|
||||
loadControl_.tendNext(head);
|
||||
}else
|
||||
{
|
||||
cout << "|not tendNext...";
|
||||
}
|
||||
}// Fall-through to perform targeted wait
|
||||
// @suppress("No break at end of case")
|
||||
default:
|
||||
Offset targetedDelay = loadControl_.scatteredDelayTime (now, capacity);
|
||||
cout << "|sleep->"<<_raw(targetedDelay)<<"\n";
|
||||
std::this_thread::sleep_for (std::chrono::microseconds (_raw(targetedDelay)));
|
||||
return activity::SKIP; // indicates to abort this processing-chain for good
|
||||
}
|
||||
|
|
|
|||
|
|
@ -360,7 +360,6 @@ namespace test {
|
|||
if (data_.callback.arg == 0)
|
||||
{// no adapted target; just record this activation
|
||||
log_(util::toString(now) + " ⧐ ");
|
||||
// log_(" ⧐ ");
|
||||
return activity::PASS;
|
||||
}
|
||||
else
|
||||
|
|
|
|||
|
|
@ -143,76 +143,60 @@ namespace test {
|
|||
and wasClose (invoked, start);
|
||||
};
|
||||
|
||||
start = Time::ZERO;
|
||||
// auto& ctx = detector.executionCtx;
|
||||
auto& ctx = Scheduler::ExecutionCtx::from(scheduler);
|
||||
probe.activate(start, ctx);
|
||||
auto [muck,_] = lib::test::microBenchmark([&](size_t){ probe.activate(start, ctx);
|
||||
return size_t(1);
|
||||
}
|
||||
, 200);
|
||||
SHOW_EXPR(muck)
|
||||
|
||||
cout << "Scheduled right away..."<<endl;
|
||||
start = RealClock::now();
|
||||
post(start);
|
||||
|
||||
SHOW_EXPR(_raw(detector.invokeTime(probe)) - _raw(start))
|
||||
|
||||
CHECK (wasInvoked(start));
|
||||
post(start); // Post the testProbe to be scheduled "now"
|
||||
CHECK (wasInvoked(start)); // Result: invoked directly, not enqueued at all
|
||||
CHECK (scheduler.empty());
|
||||
|
||||
cout << "pullWork() on empty queue..."<<endl;
|
||||
// start = RealClock::now();
|
||||
pullWork();
|
||||
|
||||
SHOW_EXPR(wasInvoked(start))
|
||||
CHECK (activity::WAIT == res);
|
||||
CHECK (slip_us < 100);
|
||||
|
||||
cout << "pullWork() on empty queue..."<<endl;
|
||||
pullWork(); // Call the work-Function on empty Scheduler queue
|
||||
CHECK (activity::WAIT == res); // get immediately signalled to go to sleep
|
||||
|
||||
|
||||
cout << "Due at pullWork()..."<<endl;
|
||||
TimeVar now = RealClock::now();
|
||||
start = now + t100us;
|
||||
start = now + t100us; // Set a schedule 100ms ahead of "now"
|
||||
post (start);
|
||||
CHECK (not scheduler.empty());
|
||||
CHECK (not scheduler.empty()); // was enqueued
|
||||
CHECK (not wasInvoked(start)); // ...but not activated yet
|
||||
|
||||
TimeVar cow = RealClock::now();
|
||||
sleep_for (100us);
|
||||
TimeVar wow = RealClock::now();
|
||||
sleep_for (100us); // wait beyond the planned start point (typically waits ~150µs or more)
|
||||
pullWork();
|
||||
SHOW_EXPR(_raw(cow) - _raw(now))
|
||||
SHOW_EXPR(_raw(wow) - _raw(cow))
|
||||
SHOW_EXPR(_raw(detector.invokeTime(probe)) - _raw(wow))
|
||||
CHECK (activity::WAIT == res);
|
||||
CHECK (wasInvoked(start));
|
||||
CHECK (scheduler.empty());
|
||||
CHECK (delay_us < 500);
|
||||
CHECK (slip_us < 500);
|
||||
|
||||
CHECK (delay_us < 500); // Note: the call itself can take 50..150µs, due to the EventLog in the testProbe
|
||||
CHECK (slip_us < 500); // Note: also there is a slip of typically 100..200µs, because sleep waits longer
|
||||
|
||||
|
||||
cout << "next some time ahead => up-front delay"<<endl;
|
||||
now = RealClock::now();
|
||||
start = now + t500us;
|
||||
start = now + t500us; // Set a schedule significantly into the future...
|
||||
post (start);
|
||||
CHECK (not scheduler.empty());
|
||||
|
||||
pullWork();
|
||||
CHECK (activity::PASS == res);
|
||||
CHECK (not wasInvoked(start));
|
||||
CHECK (delay_us > 500);
|
||||
pullWork(); // ...and invoke the work-Function immediately "now"
|
||||
CHECK (activity::PASS == res); // Result: this thread was kept in sleep in the work-Function
|
||||
CHECK (not wasInvoked(start)); // but the next dispatch did not happen yet; we are instructed to re-invoke immediately
|
||||
CHECK (delay_us > 500); // this proves that there was a delay to wait for the next schedule
|
||||
CHECK (delay_us < 1000);
|
||||
pullWork();
|
||||
CHECK (wasInvoked(start));
|
||||
CHECK (delay_us < 200); ///////////////OOO dangerously tight
|
||||
pullWork(); // if we now re-invoke the work-Function as instructed...
|
||||
CHECK (wasInvoked(start)); // then the next schedule is already slightly overdue and immediately invoked
|
||||
CHECK (delay_us < 300); // Warning: this limit is dangerously tight
|
||||
CHECK (slip_us < 500);
|
||||
CHECK (activity::WAIT == res);
|
||||
CHECK (activity::WAIT == res); // since there is nothing left in the Queue, we are instructed to sleep
|
||||
CHECK (scheduler.empty());
|
||||
|
||||
|
||||
cout << "follow-up with some distance => follow-up delay"<<endl;
|
||||
now = RealClock::now();
|
||||
start = now + t100us;
|
||||
post (start);
|
||||
post (start+t1ms);
|
||||
sleep_for (100us);
|
||||
post (start); // This time the schedule is set to be "soon"
|
||||
post (start+t1ms); // But another schedule is placed 1ms behind
|
||||
sleep_for (100us); // wait for "soon" to pass...
|
||||
pullWork();
|
||||
SHOW_EXPR(_raw(now))
|
||||
SHOW_EXPR(_raw(start))
|
||||
|
|
@ -222,18 +206,18 @@ SHOW_EXPR(delay_us)
|
|||
SHOW_EXPR(slip_us)
|
||||
SHOW_EXPR(wasInvoked(start))
|
||||
SHOW_EXPR(scheduler.empty())
|
||||
CHECK (wasInvoked(start));
|
||||
CHECK (delay_us > 900);
|
||||
CHECK (wasInvoked(start)); // Result: the first invocation happened immediately
|
||||
CHECK (slip_us < 100);
|
||||
CHECK (activity::PASS == res);
|
||||
CHECK (not scheduler.empty());
|
||||
CHECK (delay_us > 900); // yet this thread was afterwards kept in sleep to await the next one
|
||||
CHECK (activity::PASS == res); // instruction to re-invoke immediately
|
||||
CHECK (not scheduler.empty()); // since there is still work in the queue
|
||||
|
||||
start += t1ms;
|
||||
pullWork();
|
||||
CHECK (wasInvoked(start));
|
||||
CHECK (delay_us < 500);
|
||||
CHECK (slip_us < 500);
|
||||
CHECK (activity::WAIT == res);
|
||||
start += t1ms; // (just re-adjust the reference point to calculate slip_us)
|
||||
pullWork(); // re-invoke immediately as instructed
|
||||
CHECK (wasInvoked(start)); // Result: also the next Activity has been dispatched
|
||||
CHECK (delay_us < 300); // not much slip and delay
|
||||
CHECK (slip_us < 300); // Remark: here we often see cache-effects, since last EventLog call is way back, due to the long sleep
|
||||
CHECK (activity::WAIT == res); // since queue is empty, we are instructed to sleep
|
||||
CHECK (scheduler.empty());
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -88271,16 +88271,17 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
<icon BUILTIN="full-2"/>
|
||||
</node>
|
||||
</node>
|
||||
<node BACKGROUND_COLOR="#eef0c5" COLOR="#990000" CREATED="1698287556673" ID="ID_1372932043" MODIFIED="1698287566144" TEXT="Untersuchung: instrumentieren">
|
||||
<icon BUILTIN="pencil"/>
|
||||
<node COLOR="#338800" CREATED="1698287556673" ID="ID_1372932043" MODIFIED="1698368308498" TEXT="Untersuchung: instrumentieren">
|
||||
<icon BUILTIN="button_ok"/>
|
||||
<node CREATED="1698287646293" ID="ID_1871424665" MODIFIED="1698287655991" TEXT="das scatteredDelay-Verhalten ist wie erwartet"/>
|
||||
<node CREATED="1698287656675" ID="ID_320386665" MODIFIED="1698287664918" TEXT="die Zeit wird im Dispatch verbraucht">
|
||||
<node CREATED="1698287748455" ID="ID_1506124813" MODIFIED="1698287762817" TEXT="sehe zwei Muster: ~50µs und > 100µs"/>
|
||||
<node CREATED="1698287764965" ID="ID_940081146" MODIFIED="1698287775063" TEXT="kein nennenswerter Unterschied mit -O3"/>
|
||||
</node>
|
||||
<node BACKGROUND_COLOR="#f0d5c5" COLOR="#990033" CREATED="1698290015010" ID="ID_721827843" MODIFIED="1698290021903" TEXT="was kann das sein?">
|
||||
<node BACKGROUND_COLOR="#e0ceaa" COLOR="#690f14" CREATED="1698290015010" ID="ID_721827843" MODIFIED="1698368154184" TEXT="was kann das sein?">
|
||||
<arrowlink COLOR="#ff5e74" DESTINATION="ID_1387737580" ENDARROW="Default" ENDINCLINATION="-124;5;" ID="Arrow_ID_1118831155" STARTARROW="None" STARTINCLINATION="-4;22;"/>
|
||||
<icon BUILTIN="help"/>
|
||||
<node COLOR="#5b280f" CREATED="1698290023095" ID="ID_244045665" MODIFIED="1698364804781" TEXT="die Activity-Probe? Invocation kostet 25µs">
|
||||
<node COLOR="#5b280f" CREATED="1698290023095" ID="ID_244045665" MODIFIED="1698368206320" TEXT="die Activity-Probe? Invocation kostet 25µs">
|
||||
<richcontent TYPE="NOTE"><html>
|
||||
<head>
|
||||
|
||||
|
|
@ -88292,38 +88293,41 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
<linktarget COLOR="#e0359d" DESTINATION="ID_244045665" ENDARROW="Default" ENDINCLINATION="640;0;" ID="Arrow_ID_555943254" SOURCE="ID_1132126993" STARTARROW="None" STARTINCLINATION="-19;-136;"/>
|
||||
<linktarget COLOR="#e0359d" DESTINATION="ID_244045665" ENDARROW="Default" ENDINCLINATION="634;35;" ID="Arrow_ID_555943254" SOURCE="ID_1132126993" STARTARROW="None" STARTINCLINATION="-19;-136;"/>
|
||||
<icon BUILTIN="broken-line"/>
|
||||
<node CREATED="1698368173278" HGAP="29" ID="ID_365964235" MODIFIED="1698368213973" TEXT="Meßfehler..." VSHIFT="-8">
|
||||
<icon BUILTIN="info"/>
|
||||
<node CREATED="1698368183760" ID="ID_1846329958" MODIFIED="1698368190984" TEXT="beim ersten Mal sind es 250µs"/>
|
||||
<node CREATED="1698368191812" ID="ID_1685045655" MODIFIED="1698368200935" TEXT="die nächsten Aufrufe kosten 42µs"/>
|
||||
</node>
|
||||
</node>
|
||||
<node CREATED="1698334890581" ID="ID_1143827394" MODIFIED="1698334929969" TEXT="rein reiner scatteredDelay-Aufruf ohne Dispatch: 18µs"/>
|
||||
<node CREATED="1698334982878" ID="ID_446507952" MODIFIED="1698335179829" TEXT="in einem ~50µs-Fall dauert es ~20µs bis Probe-activation">
|
||||
<richcontent TYPE="NOTE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<head/>
|
||||
<body>
|
||||
<p>
|
||||
das bedeutet: in diesem Fall liegt der überwiegende Teil des extra-Aufwands vermutlich vor der Activity-Activation (weil die bekanntermaßen aufwendigen Log-Operationen erst nach dem Eintritt in die activation-Funktion der ActivityProbe erfolgen). ~50µs bedeutet ⟹ gut die Hälfte wird außerhalb aber im Dispatch verbrannt
|
||||
</p>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</html></richcontent>
|
||||
</node>
|
||||
<node CREATED="1698336313556" ID="ID_1829519407" MODIFIED="1698336353089" TEXT="auch andere Testfälle erscheinen insgesamt plausibel: scatteredDelay kostet jeweils 20µs"/>
|
||||
<node CREATED="1698336608768" ID="ID_108542402" MODIFIED="1698336641428" TEXT="die ~50µs-Fälle sind weitgehen stabil, die 100er-Fälle flukturieren, sind aber stets höher">
|
||||
<node CREATED="1698336759920" ID="ID_78621664" MODIFIED="1698336854839" TEXT="Theorie: vor den kurzen stabilen Aufrufen erfolgte unmittelbar vorher ein sleep"/>
|
||||
</node>
|
||||
<node BACKGROUND_COLOR="#eee5c3" COLOR="#990000" CREATED="1698336354388" ID="ID_1387737580" MODIFIED="1698336382404" TEXT="bleibt also definitiv aufzuklären, wo die Zeit im Dispatch verbraucht wird">
|
||||
<node BACKGROUND_COLOR="#e0ceaa" COLOR="#690f14" CREATED="1698336354388" ID="ID_1387737580" MODIFIED="1698368224270" TEXT="bleibt also definitiv aufzuklären, wo die Zeit im Dispatch verbraucht wird">
|
||||
<arrowlink COLOR="#fe2672" DESTINATION="ID_1378612293" ENDARROW="Default" ENDINCLINATION="63;-82;" ID="Arrow_ID_787245495" STARTARROW="None" STARTINCLINATION="238;10;"/>
|
||||
<linktarget COLOR="#ff5e74" DESTINATION="ID_1387737580" ENDARROW="Default" ENDINCLINATION="-124;5;" ID="Arrow_ID_1118831155" SOURCE="ID_721827843" STARTARROW="None" STARTINCLINATION="-4;22;"/>
|
||||
<font NAME="SansSerif" SIZE="12"/>
|
||||
<icon BUILTIN="yes"/>
|
||||
</node>
|
||||
</node>
|
||||
<node BACKGROUND_COLOR="#eef0c5" COLOR="#990000" CREATED="1698337369511" ID="ID_267596520" MODIFIED="1698337394105" TEXT="Untersuchung post/dispatch">
|
||||
<icon BUILTIN="pencil"/>
|
||||
<node COLOR="#338800" CREATED="1698337369511" ID="ID_267596520" MODIFIED="1698368087753" TEXT="Untersuchung post/dispatch">
|
||||
<icon BUILTIN="button_ok"/>
|
||||
<node CREATED="1698337396337" ID="ID_850954916" MODIFIED="1698337536065" TEXT="GroomingToken wird bisher sofort erlangt und nicht gedropped">
|
||||
<richcontent TYPE="NOTE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<head/>
|
||||
<body>
|
||||
<p>
|
||||
...wir sind noch nicht so weit (nach Plan)
|
||||
|
|
@ -88337,8 +88341,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
</li>
|
||||
</ul>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</html></richcontent>
|
||||
</node>
|
||||
<node CREATED="1698337748324" ID="ID_24250671" MODIFIED="1698337772891" TEXT="Grooming-Token-Behandlung auskommentiert ⟶ kein sichtbarer Effekt">
|
||||
<icon BUILTIN="idea"/>
|
||||
|
|
@ -88363,36 +88366,28 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
</node>
|
||||
<node CREATED="1698363756532" ID="ID_1505607665" MODIFIED="1698363887123" TEXT="in jedem Scope kommen ca. 10µs dazu — das erscheint plausibel">
|
||||
<richcontent TYPE="NOTE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<head/>
|
||||
<body>
|
||||
<p>
|
||||
...zumal ich jetzt alles im Debug-Mode untersuche, und auch noch COUT-Statements und Clock-Aufrufe eingebaut habe
|
||||
</p>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</html></richcontent>
|
||||
</node>
|
||||
<node CREATED="1698363734030" ID="ID_834239605" MODIFIED="1698363894327">
|
||||
<richcontent TYPE="NODE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<head/>
|
||||
<body>
|
||||
<p>
|
||||
steckt in Activity::<b>activate</b>
|
||||
</p>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</html></richcontent>
|
||||
<icon BUILTIN="forward"/>
|
||||
</node>
|
||||
<node CREATED="1698363734030" ID="ID_1378612293" MODIFIED="1698364693054">
|
||||
<richcontent TYPE="NODE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<head/>
|
||||
<body>
|
||||
<p>
|
||||
steckt in Activity::<b>callHook</b>
|
||||
|
|
@ -88400,13 +88395,15 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
<arrowlink COLOR="#ff1c0d" DESTINATION="ID_189228492" ENDARROW="Default" ENDINCLINATION="147;-184;" ID="Arrow_ID_431919133" STARTARROW="None" STARTINCLINATION="-30;57;"/>
|
||||
<linktarget COLOR="#fe2672" DESTINATION="ID_1378612293" ENDARROW="Default" ENDINCLINATION="63;-82;" ID="Arrow_ID_787245495" SOURCE="ID_1387737580" STARTARROW="None" STARTINCLINATION="238;10;"/>
|
||||
<icon BUILTIN="forward"/>
|
||||
<node BACKGROUND_COLOR="#f0d5c5" COLOR="#990033" CREATED="1698364711100" ID="ID_108118943" MODIFIED="1698364721336" TEXT="???">
|
||||
<icon BUILTIN="help"/>
|
||||
<icon BUILTIN="help"/>
|
||||
</node>
|
||||
<node CREATED="1698364726554" ID="ID_1132126993" MODIFIED="1698364804780" TEXT="ich hatte das doch auf ca 25µs gemessen...">
|
||||
<arrowlink COLOR="#e0359d" DESTINATION="ID_244045665" ENDARROW="Default" ENDINCLINATION="640;0;" ID="Arrow_ID_555943254" STARTARROW="None" STARTINCLINATION="-19;-136;"/>
|
||||
<arrowlink COLOR="#e0359d" DESTINATION="ID_244045665" ENDARROW="Default" ENDINCLINATION="634;35;" ID="Arrow_ID_555943254" STARTARROW="None" STARTINCLINATION="-19;-136;"/>
|
||||
</node>
|
||||
<node BACKGROUND_COLOR="#e0ceaa" COLOR="#690f14" CREATED="1698364809287" ID="ID_1459395793" MODIFIED="1698364832751" TEXT="Fehler in der Anwendung des Microbenchmark: es sind 250µs">
|
||||
<icon BUILTIN="broken-line"/>
|
||||
|
|
@ -88415,21 +88412,17 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
</node>
|
||||
</node>
|
||||
</node>
|
||||
<node CREATED="1698365664716" ID="ID_787946068" MODIFIED="1698365680310" TEXT="ActivityProbe untersuchen">
|
||||
<node COLOR="#338800" CREATED="1698365664716" ID="ID_787946068" MODIFIED="1698368085571" TEXT="ActivityProbe untersuchen">
|
||||
<icon BUILTIN="button_ok"/>
|
||||
<node CREATED="1698365702450" ID="ID_390220364" MODIFIED="1698365715993" TEXT="der erste Aufruf kostet ~250µs"/>
|
||||
<node CREATED="1698365716733" ID="ID_62593769" MODIFIED="1698365889494" TEXT="danach ein Microbenchmark: pendelt zwischen 44µs und 37µs ⟶ ∅=42µs"/>
|
||||
<node CREATED="1698365907268" ID="ID_861542439" MODIFIED="1698365933463" TEXT="aber die nachfolgenden Aufrufe zeigen stets das Muster stabil / größer schwankend"/>
|
||||
<node CREATED="1698365935877" ID="ID_553351296" MODIFIED="1698365950489" TEXT="⟹ es muß sich um einen Cache-Effekt handeln">
|
||||
<node CREATED="1698365953435" ID="ID_179845408" MODIFIED="1698365963728" TEXT="insofern war die Theorie mit dem "sleep" vorher korrekt"/>
|
||||
<node CREATED="1698365966654" ID="ID_792601273" MODIFIED="1698365980693" TEXT="wenn kurz vorher ein gleicher Aufruf war, ist die Funktion stabil"/>
|
||||
<node CREATED="1698366000951" ID="ID_1501602744" MODIFIED="1698366013225" TEXT="eine pre-Allokation im EventLog ändert daran auch nichts"/>
|
||||
</node>
|
||||
<node CREATED="1698366197981" ID="ID_189228492" MODIFIED="1698366221342" TEXT="Event-Log auskommentiert ⟶ RATZ-FATZ">
|
||||
<node CREATED="1698366253166" ID="ID_1905813765" MODIFIED="1698367464173">
|
||||
<richcontent TYPE="NODE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<head/>
|
||||
<body>
|
||||
<p>
|
||||
<font face="Monospaced">|capacity=0 </font>
|
||||
|
|
@ -88453,10 +88446,14 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
<font face="Monospaced">res:2 delay=29µs </font>
|
||||
</p>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</html></richcontent>
|
||||
<icon BUILTIN="list"/>
|
||||
</node>
|
||||
<node CREATED="1698366000951" ID="ID_1501602744" MODIFIED="1698366013225" TEXT="eine pre-Allokation im EventLog ändert daran auch nichts"/>
|
||||
</node>
|
||||
<node BACKGROUND_COLOR="#c8c0b6" COLOR="#a50125" CREATED="1698366197981" ID="ID_189228492" MODIFIED="1698368292199" TEXT="Event-Log auskommentiert ⟶ RATZ-FATZ">
|
||||
<linktarget COLOR="#ff1c0d" DESTINATION="ID_189228492" ENDARROW="Default" ENDINCLINATION="147;-184;" ID="Arrow_ID_431919133" SOURCE="ID_1378612293" STARTARROW="None" STARTINCLINATION="-30;57;"/>
|
||||
<icon BUILTIN="broken-line"/>
|
||||
<node CREATED="1698366339269" ID="ID_680875013" MODIFIED="1698366362449" TEXT="im Micro-Benchmark(200 repetitions) ⟶ 3µs"/>
|
||||
</node>
|
||||
<node CREATED="1698366474504" ID="ID_292495776" MODIFIED="1698366493361" TEXT="Event-Log, aber nur festen String ⟶ 23µs">
|
||||
|
|
@ -88470,9 +88467,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
<node CREATED="1698367363098" ID="ID_1293990863" MODIFIED="1698367375332" TEXT="mit allem : 43µs"/>
|
||||
<node CREATED="1698367382589" ID="ID_785763328" MODIFIED="1698367453717">
|
||||
<richcontent TYPE="NODE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<head/>
|
||||
<body>
|
||||
<p>
|
||||
einziger Unterschied: Zeiten im Call-stack addieren sich weniger auf...
|
||||
|
|
@ -88493,8 +88488,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
<font face="Monospaced">+++++Dispatch: 54µs (0|+|54) </font>
|
||||
</p>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</html></richcontent>
|
||||
</node>
|
||||
<node CREATED="1698367558424" ID="ID_46488042" MODIFIED="1698367603285" TEXT="Anmerkung: ich baue aber nicht die ganze Applikation from-scratch mit -O3">
|
||||
<richcontent TYPE="NOTE"><html>
|
||||
|
|
@ -88506,14 +88500,39 @@ Date:   Thu Apr 20 18:53:17 2023 +0200<br/>
|
|||
...sondern nur die wenigen Translation-Units, die ich für relevant halte. Das könnte dann insgesamt nochmal einen Unterschied machen
|
||||
</p>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</html></richcontent>
|
||||
<icon BUILTIN="messagebox_warning"/>
|
||||
</node>
|
||||
</node>
|
||||
</node>
|
||||
</node>
|
||||
</node>
|
||||
<node BACKGROUND_COLOR="#fefc4e" COLOR="#351d75" CREATED="1698368312924" ID="ID_1043330780" MODIFIED="1698368334114" TEXT="dies ist die Test-Instrumentierung + Cache-Effekte">
|
||||
<font BOLD="true" NAME="SansSerif" SIZE="12"/>
|
||||
<icon BUILTIN="idea"/>
|
||||
<node COLOR="#338800" CREATED="1698368341481" ID="ID_1301549939" MODIFIED="1698368476694" TEXT="der Callgraph wurde im Detail untersucht und verhält sich plausibel">
|
||||
<icon BUILTIN="button_ok"/>
|
||||
</node>
|
||||
<node COLOR="#338800" CREATED="1698368360150" ID="ID_1118033823" MODIFIED="1698368483185" TEXT="die gesamte exzessive Zeit steckt im ActicityProbe">
|
||||
<icon BUILTIN="idea"/>
|
||||
<node CREATED="1698368425422" ID="ID_935344383" MODIFIED="1698368432896" TEXT="im Schnitt kostet ein Aufruf 43µs"/>
|
||||
<node CREATED="1698368403104" ID="ID_1488693576" MODIFIED="1698368423793" TEXT="wenn man dort das Event-Log entfernt, reduziert sich der Rest auf 3µs"/>
|
||||
<node CREATED="1698368434649" ID="ID_136517479" MODIFIED="1698368458717" TEXT="nur ein fester String ohne Zeit-Formatieren kostet 22µs"/>
|
||||
<node CREATED="1698368460513" ID="ID_1076705660" MODIFIED="1698368471860">
|
||||
<richcontent TYPE="NODE"><html>
|
||||
<head>
|
||||
|
||||
</head>
|
||||
<body>
|
||||
<p>
|
||||
Optimierung hat darauf <b>keinerlei Einfluß</b>
|
||||
</p>
|
||||
</body>
|
||||
</html>
|
||||
</richcontent>
|
||||
</node>
|
||||
</node>
|
||||
</node>
|
||||
</node>
|
||||
</node>
|
||||
</node>
|
||||
|
|
|
|||
Loading…
Reference in a new issue