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

Scheduler: investigate timings of dispatch()

Browse source 
...there seemed to be an anomaly of 50...100µs

==> conclusion: this is due to the instrumentation code
    - it largely caused by the EventLog, which was never meant
      to be used in performance-critical code, and does hefty
      heap allocations and string processing.
    - moreover, there clearly is a cache-effect, adding a Factor 2
      whenever some time passed since the last EventLog call

==> can be considered just an artifact of the test setup and
    will have no impact on the scheduler


remark: this commit adds a lot of instrumentation code
This commit is contained in:
Fischlurch 2023-10-27 02:53:34 +02:00
parent a90a5d9636
commit 097001d16f
7 changed files with 321 additions and 49 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
src/lib/test/event-log.cpp
View file

@ -613,6 +613,7 @@ namespace test{
EventLog::EventLog (string logID)
: log_(new Log)
{
log_->reserve(2000);
log({"type=EventLogHeader", "this="+logID});
}

17
src/vault/gear/activity.hpp
View file

@ -70,6 +70,8 @@
#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{
@ -614,7 +616,14 @@ namespace gear {
case FEED:
return activity::PASS;
case HOOK:
return callHook (now, executionCtx);
// 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;
}
case TICK:
return doTick (now, executionCtx);
default:
@ -657,7 +666,11 @@ namespace gear {
case FEED: // signal just to proceed with next...
return activity::PASS;
default:
return activate (now, executionCtx);
Time t0 = executionCtx.getSchedTime();
activity::Proc res = activate (now, executionCtx);
Time t2 = executionCtx.getSchedTime();
cout << "++++++++++ACT: "<<_raw(t2) - _raw(t0)<<"µs"<<endl;
return res;
}
}

25
src/vault/gear/scheduler-commutator.hpp
View file

@ -76,6 +76,8 @@
#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>
@ -106,7 +108,7 @@ namespace gear {
using ThreadID = std::thread::id;
atomic<ThreadID> groomingToken_{};
auto thisThread() { return std::this_thread::get_id(); }
auto thisThread() { return ThreadID();}/////////////////TODO std::this_thread::get_id(); }
public:
@ -123,6 +125,7 @@ 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
@ -139,6 +142,7 @@ namespace gear {
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);
@ -151,6 +155,7 @@ namespace gear {
bool
holdsGroomingToken (ThreadID id) noexcept
{
return true;
return id == groomingToken_.load (memory_order_relaxed);
}
@ -215,14 +220,26 @@ namespace gear {
if (!chain) return activity::WAIT;
Time now = executionCtx.getSchedTime();
if (decideDispatchNow (when, now))
return ActivityLang::dispatchChain (chain, executionCtx);
bool shallDispatch =decideDispatchNow (when, now);
Time t1 = executionCtx.getSchedTime();
activity::Proc res;
if (shallDispatch)
{
res = ActivityLang::dispatchChain (chain, executionCtx);
}
// return ActivityLang::dispatchChain (chain, executionCtx);
else
{
if (holdsGroomingToken (thisThread()))
layer1.feedPrioritisation (*chain, when);
else
layer1.instruct (*chain, when);
return activity::PASS;
// 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;
}
};

18
src/vault/gear/scheduler.hpp
View file

@ -52,8 +52,9 @@
#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>
@ -335,7 +336,11 @@ namespace gear {
.performStep([&]{
Time now = ctx.getSchedTime();
Activity* act = layer2_.findWork (layer1_,now);
return ctx.post (now, act, ctx);
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;
})
.performStep([&]{
Time now = ctx.getSchedTime();
@ -363,10 +368,12 @@ namespace gear {
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:
@ -378,11 +385,18 @@ namespace gear {
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
}

1
tests/vault/gear/activity-detector.hpp
View file

@ -360,6 +360,7 @@ namespace test {
if (data_.callback.arg == 0)
{// no adapted target; just record this activation
log_(util::toString(now) + " ⧐ ");
// log_(" ⧐ ");
return activity::PASS;
}
else

56
tests/vault/gear/scheduler-service-test.cpp
View file

@ -143,12 +143,21 @@ 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(start))
SHOW_EXPR(_raw(detector.invokeTime(probe)))
SHOW_EXPR(_raw(detector.invokeTime(probe)) - _raw(start))
CHECK (wasInvoked(start));
CHECK (scheduler.empty());
@ -157,11 +166,6 @@ SHOW_EXPR(_raw(detector.invokeTime(probe)))
// start = RealClock::now();
pullWork();
SHOW_EXPR(_raw(start))
SHOW_EXPR(_raw(detector.invokeTime(probe)))
SHOW_EXPR(res);
SHOW_EXPR(delay_us)
SHOW_EXPR(slip_us)
SHOW_EXPR(wasInvoked(start))
CHECK (activity::WAIT == res);
CHECK (slip_us < 100);
@ -176,15 +180,9 @@ SHOW_EXPR(wasInvoked(start))
sleep_for (100us);
TimeVar wow = RealClock::now();
pullWork();
SHOW_EXPR(_raw(now))
SHOW_EXPR(_raw(cow))
SHOW_EXPR(_raw(wow))
SHOW_EXPR(_raw(start))
SHOW_EXPR(_raw(detector.invokeTime(probe)))
SHOW_EXPR(res);
SHOW_EXPR(delay_us)
SHOW_EXPR(slip_us)
SHOW_EXPR(wasInvoked(start))
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());
@ -198,29 +196,13 @@ SHOW_EXPR(wasInvoked(start))
CHECK (not scheduler.empty());
pullWork();
SHOW_EXPR(_raw(now))
SHOW_EXPR(_raw(cow))
SHOW_EXPR(_raw(wow))
SHOW_EXPR(_raw(start))
SHOW_EXPR(_raw(detector.invokeTime(probe)))
SHOW_EXPR(res);
SHOW_EXPR(delay_us)
SHOW_EXPR(slip_us)
SHOW_EXPR(wasInvoked(start))
CHECK (activity::PASS == res);
CHECK (not wasInvoked(start));
CHECK (delay_us > 500);
CHECK (delay_us < 1000);
pullWork();
SHOW_EXPR(_raw(now))
SHOW_EXPR(_raw(start))
SHOW_EXPR(_raw(detector.invokeTime(probe)))
SHOW_EXPR(res);
SHOW_EXPR(delay_us)
SHOW_EXPR(slip_us)
SHOW_EXPR(wasInvoked(start))
CHECK (wasInvoked(start));
CHECK (delay_us < 200);
CHECK (delay_us < 200); ///////////////OOO dangerously tight
CHECK (slip_us < 500);
CHECK (activity::WAIT == res);
CHECK (scheduler.empty());
@ -248,14 +230,6 @@ SHOW_EXPR(scheduler.empty())
start += t1ms;
pullWork();
SHOW_EXPR(_raw(now))
SHOW_EXPR(_raw(start))
SHOW_EXPR(_raw(detector.invokeTime(probe)))
SHOW_EXPR(res);
SHOW_EXPR(delay_us)
SHOW_EXPR(slip_us)
SHOW_EXPR(wasInvoked(start))
SHOW_EXPR(scheduler.empty())
CHECK (wasInvoked(start));
CHECK (delay_us < 500);
CHECK (slip_us < 500);

252
wiki/thinkPad.ichthyo.mm
View file

@ -82222,6 +82222,15 @@ Date:&#160;&#160;&#160;Thu Apr 20 18:53:17 2023 +0200<br/>
</node>
</node>
</node>
<node BACKGROUND_COLOR="#fdfdcf" COLOR="#ff0000" CREATED="1698286167843" ID="ID_3145780" MODIFIED="1698286178482" TEXT="GroomingToken richtig behandeln">
<icon BUILTIN="flag-pink"/>
<node BACKGROUND_COLOR="#eee5c3" COLOR="#990000" CREATED="1698286228019" ID="ID_1492651640" MODIFIED="1698286242507" TEXT="acquire sollte schon korrekt sein (pr&#xfc;fen!)">
<icon BUILTIN="flag-yellow"/>
</node>
<node BACKGROUND_COLOR="#eee5c3" COLOR="#990000" CREATED="1698286180725" ID="ID_1291141353" MODIFIED="1698286214373" TEXT="sicherstellen da&#xdf; es am Ende gedropped wurde">
<icon BUILTIN="flag-yellow"/>
</node>
</node>
<node BACKGROUND_COLOR="#eee5c3" COLOR="#990000" CREATED="1698004014170" ID="ID_359097355" MODIFIED="1698203266998" TEXT="Test">
<icon BUILTIN="flag-yellow"/>
<node COLOR="#435e98" CREATED="1698203252783" ID="ID_161810851" MODIFIED="1698240150155" TEXT="was kann man hier sinnvoll testen?">
@ -88262,6 +88271,249 @@ Date:&#160;&#160;&#160;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 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&#xb5;s und &gt; 100&#xb5;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?">
<icon BUILTIN="help"/>
<node COLOR="#5b280f" CREATED="1698290023095" ID="ID_244045665" MODIFIED="1698364804781" TEXT="die Activity-Probe? Invocation kostet 25&#xb5;s">
<richcontent TYPE="NOTE"><html>
<head>
</head>
<body>
<p>
...und das ist so auch plausibel (interessanterweise gibt es hier keinen Unterschied debug/O3 )...&#160;&#160;hier wird ein Vector bef&#252;llt und jede Menge String-Konvertierungen gemacht, und auch ein virtual call
</p>
</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;"/>
<icon BUILTIN="broken-line"/>
</node>
<node CREATED="1698334890581" ID="ID_1143827394" MODIFIED="1698334929969" TEXT="rein reiner scatteredDelay-Aufruf ohne Dispatch: 18&#xb5;s"/>
<node CREATED="1698334982878" ID="ID_446507952" MODIFIED="1698335179829" TEXT="in einem ~50&#xb5;s-Fall dauert es ~20&#xb5;s bis Probe-activation">
<richcontent TYPE="NOTE"><html>
<head>
</head>
<body>
<p>
das bedeutet: in diesem Fall liegt der &#252;berwiegende Teil des extra-Aufwands vermutlich vor der Activity-Activation (weil die bekannterma&#223;en aufwendigen Log-Operationen erst nach dem Eintritt in die activation-Funktion der ActivityProbe erfolgen). ~50&#181;s bedeutet &#10233; gut die H&#228;lfte wird au&#223;erhalb aber im Dispatch verbrannt
</p>
</body>
</html>
</richcontent>
</node>
<node CREATED="1698336313556" ID="ID_1829519407" MODIFIED="1698336353089" TEXT="auch andere Testf&#xe4;lle erscheinen insgesamt plausibel: scatteredDelay kostet jeweils 20&#xb5;s"/>
<node CREATED="1698336608768" ID="ID_108542402" MODIFIED="1698336641428" TEXT="die ~50&#xb5;s-F&#xe4;lle sind weitgehen stabil, die 100er-F&#xe4;lle flukturieren, sind aber stets h&#xf6;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&#xe4;ren, wo die Zeit im Dispatch verbraucht wird">
<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 CREATED="1698337396337" ID="ID_850954916" MODIFIED="1698337536065" TEXT="GroomingToken wird bisher sofort erlangt und nicht gedropped">
<richcontent TYPE="NOTE"><html>
<head>
</head>
<body>
<p>
...wir sind noch nicht so weit (nach Plan)
</p>
<ul>
<li>
Grooming-Token soll nur per explizitem &#220;bergang geDropped werden; beide F&#228;lle sind noch nicht implementiert (work-Function und &#955;-work)
</li>
<li>
dieser Test l&#228;uft im Haupt-Thread, d.h. der erste Aufruf (in dem das post() auch direkt den Dispatch macht) erlangt das Grooming-Token
</li>
</ul>
</body>
</html>
</richcontent>
</node>
<node CREATED="1698337748324" ID="ID_24250671" MODIFIED="1698337772891" TEXT="Grooming-Token-Behandlung auskommentiert &#x27f6; kein sichtbarer Effekt">
<icon BUILTIN="idea"/>
</node>
<node CREATED="1698338028250" ID="ID_232195006" MODIFIED="1698338045574" TEXT="layer1_.getWork() ist nicht das Problem">
<icon BUILTIN="idea"/>
<node CREATED="1698338046962" ID="ID_1234104100" MODIFIED="1698338055206" TEXT="stets &lt; 10&#xb5;s"/>
<node CREATED="1698338055747" ID="ID_1169473748" MODIFIED="1698338061342" TEXT="verh&#xe4;lt sich sehr konsistent">
<node CREATED="1698338062292" ID="ID_604721995" MODIFIED="1698338080916" TEXT="der erste Aufruf kostet ~10&#xb5;s (Allokation!)"/>
<node CREATED="1698338082423" ID="ID_324188378" MODIFIED="1698338104888" TEXT="die weiteren &lt; 5&#xb5;s, oft nur 2"/>
<node CREATED="1698338106212" ID="ID_486609208" MODIFIED="1698338123606" TEXT="das erkl&#xe4;rt auch, warum der erste &quot;stabile&quot; Dispatch stets etwas l&#xe4;nger braucht"/>
</node>
</node>
<node CREATED="1698338198486" ID="ID_574393940" MODIFIED="1698338228688" TEXT="die stabilen F&#xe4;lle brauchen 46&#xb5;s im Dispatch, die anderen flukturieren 46&#xb5;s ... &gt;100&#xb5;s"/>
<node CREATED="1698363202461" ID="ID_919677379" MODIFIED="1698363240098" TEXT="&#x27f9; Hauptzweig im Detail untersuchen">
<node CREATED="1698363241543" ID="ID_1104038412" MODIFIED="1698363265551" TEXT="decideDispatchNow .... marginal ~5&#xb5;s oder weniger"/>
<node CREATED="1698363275186" ID="ID_693865088" MODIFIED="1698363286372" TEXT="enqueue: beim ersten Mal 30&#xb5;s, dann ~10&#xb5;s"/>
<node CREATED="1698363297295" ID="ID_245887528" MODIFIED="1698363305707" TEXT="ActivityLang::dispatchChain">
<node CREATED="1698363334802" ID="ID_1899875446" MODIFIED="1698363369164" TEXT="im stabilen Fall: ~45&#xb5;s / sonst mehr"/>
<node CREATED="1698363369702" ID="ID_625338504" MODIFIED="1698363755143" TEXT="der fragw&#xfc;rdige Aufwand steckt nur hier...">
<icon BUILTIN="idea"/>
</node>
<node CREATED="1698363756532" ID="ID_1505607665" MODIFIED="1698363887123" TEXT="in jedem Scope kommen ca. 10&#xb5;s dazu &#x2014; das erscheint plausibel">
<richcontent TYPE="NOTE"><html>
<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>
</node>
<node CREATED="1698363734030" ID="ID_834239605" MODIFIED="1698363894327">
<richcontent TYPE="NODE"><html>
<head>
</head>
<body>
<p>
steckt in Activity::<b>activate</b>
</p>
</body>
</html>
</richcontent>
<icon BUILTIN="forward"/>
</node>
<node CREATED="1698363734030" ID="ID_1378612293" MODIFIED="1698364693054">
<richcontent TYPE="NODE"><html>
<head>
</head>
<body>
<p>
steckt in Activity::<b>callHook</b>
</p>
</body>
</html>
</richcontent>
<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&#xb5;s gemessen...">
<arrowlink COLOR="#e0359d" DESTINATION="ID_244045665" ENDARROW="Default" ENDINCLINATION="640;0;" 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&#xb5;s">
<icon BUILTIN="broken-line"/>
</node>
<node CREATED="1698364840371" ID="ID_1624877749" MODIFIED="1698364852005" TEXT="aber nur beim ersten Mal ... mit d&#xe4;mmert was da los ist"/>
</node>
</node>
</node>
<node CREATED="1698365664716" ID="ID_787946068" MODIFIED="1698365680310" TEXT="ActivityProbe untersuchen">
<node CREATED="1698365702450" ID="ID_390220364" MODIFIED="1698365715993" TEXT="der erste Aufruf kostet ~250&#xb5;s"/>
<node CREATED="1698365716733" ID="ID_62593769" MODIFIED="1698365889494" TEXT="danach ein Microbenchmark: pendelt zwischen 44&#xb5;s und 37&#xb5;s &#x27f6; &#x2205;=42&#xb5;s"/>
<node CREATED="1698365907268" ID="ID_861542439" MODIFIED="1698365933463" TEXT="aber die nachfolgenden Aufrufe zeigen stets das Muster stabil / gr&#xf6;&#xdf;er schwankend"/>
<node CREATED="1698365935877" ID="ID_553351296" MODIFIED="1698365950489" TEXT="&#x27f9; es mu&#xdf; sich um einen Cache-Effekt handeln">
<node CREATED="1698365953435" ID="ID_179845408" MODIFIED="1698365963728" TEXT="insofern war die Theorie mit dem &quot;sleep&quot; 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 &#xe4;ndert daran auch nichts"/>
</node>
<node CREATED="1698366197981" ID="ID_189228492" MODIFIED="1698366221342" TEXT="Event-Log auskommentiert &#x27f6; RATZ-FATZ">
<node CREATED="1698366253166" ID="ID_1905813765" MODIFIED="1698367464173">
<richcontent TYPE="NODE"><html>
<head>
</head>
<body>
<p>
<font face="Monospaced">|capacity=0 </font>
</p>
<p>
<font face="Monospaced">+++++++++++</font><font color="#bd0000" face="Monospaced">HO: 0&#181;s</font>
</p>
<p>
<font face="Monospaced">++++++++++ACT: 4&#181;s </font>
</p>
<p>
<font face="Monospaced">+++++++++Post: 10&#181;s (0|+|10:dispatch) </font>
</p>
<p>
<font face="Monospaced">+++++Dispatch: 17&#181;s (2|+|15) </font>
</p>
<p>
<font face="Monospaced">|capacity=5 </font>
</p>
<p>
<font face="Monospaced">res:2 delay=29&#181;s </font>
</p>
</body>
</html>
</richcontent>
<icon BUILTIN="list"/>
</node>
<node CREATED="1698366339269" ID="ID_680875013" MODIFIED="1698366362449" TEXT="im Micro-Benchmark(200 repetitions) &#x27f6; 3&#xb5;s"/>
</node>
<node CREATED="1698366474504" ID="ID_292495776" MODIFIED="1698366493361" TEXT="Event-Log, aber nur festen String &#x27f6; 23&#xb5;s">
<node CREATED="1698366494637" ID="ID_1958920972" MODIFIED="1698366505360" TEXT="aber die Cache-Effekte sind wieder da"/>
</node>
<node CREATED="1698366708517" ID="ID_25940092" MODIFIED="1698366714384" TEXT="zum Vergleich mit -O3">
<node CREATED="1698367325817" ID="ID_678154494" MODIFIED="1698367331712" TEXT="kein Logging: 3&#xb5;s"/>
<node CREATED="1698366725646" ID="ID_1159461342" MODIFIED="1698366731449" TEXT="fester String: 22&#xb5;s">
<node CREATED="1698366776372" ID="ID_1569743039" MODIFIED="1698366781234" TEXT="+ gleiche Cache-Effekte"/>
</node>
<node CREATED="1698367363098" ID="ID_1293990863" MODIFIED="1698367375332" TEXT="mit allem : 43&#xb5;s"/>
<node CREATED="1698367382589" ID="ID_785763328" MODIFIED="1698367453717">
<richcontent TYPE="NODE"><html>
<head>
</head>
<body>
<p>
einziger Unterschied: Zeiten im Call-stack addieren sich weniger auf...
</p>
<p>
</p>
<p>
<font face="Monospaced">+++++++++++HO: 45&#181;s </font>
</p>
<p>
<font face="Monospaced">++++++++++ACT: 50&#181;s </font>
</p>
<p>
<font face="Monospaced">+++++++++Post: 52&#181;s (0|+|52:dispatch) </font>
</p>
<p>
<font face="Monospaced">+++++Dispatch: 54&#181;s (0|+|54) </font>
</p>
</body>
</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>
<head>
</head>
<body>
<p>
...sondern nur die wenigen Translation-Units, die ich f&#252;r relevant halte. Das k&#246;nnte dann insgesamt nochmal einen Unterschied machen
</p>
</body>
</html>
</richcontent>
<icon BUILTIN="messagebox_warning"/>
</node>
</node>
</node>
</node>
</node>
</node>
</node>
</node>