From b5e9d67a79af4ef82dfde4c51154f7ca7a98656e Mon Sep 17 00:00:00 2001 From: Ichthyostega Date: Fri, 27 Oct 2023 03:37:24 +0200 Subject: [PATCH] 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 --- src/lib/test/event-log.cpp | 1 - src/vault/gear/activity.hpp | 17 +-- src/vault/gear/scheduler-commutator.hpp | 25 +---- src/vault/gear/scheduler.hpp | 18 +-- tests/vault/gear/activity-detector.hpp | 1 - tests/vault/gear/scheduler-service-test.cpp | 92 +++++++--------- wiki/thinkPad.ichthyo.mm | 115 ++++++++++++-------- 7 files changed, 113 insertions(+), 156 deletions(-) diff --git a/src/lib/test/event-log.cpp b/src/lib/test/event-log.cpp index c00a63e4e..c4f5c15ae 100644 --- a/src/lib/test/event-log.cpp +++ b/src/lib/test/event-log.cpp @@ -613,7 +613,6 @@ namespace test{ EventLog::EventLog (string logID) : log_(new Log) { - log_->reserve(2000); log({"type=EventLogHeader", "this="+logID}); } diff --git a/src/vault/gear/activity.hpp b/src/vault/gear/activity.hpp index faab2ad3e..07aa6bd06 100644 --- a/src/vault/gear/activity.hpp +++ b/src/vault/gear/activity.hpp @@ -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"< #include @@ -108,7 +106,7 @@ namespace gear { using ThreadID = std::thread::id; atomic 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")<<")"< #include @@ -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)<<")"<"<<_raw(targetedDelay)<<"\n"; std::this_thread::sleep_for (std::chrono::microseconds (_raw(targetedDelay))); return activity::SKIP; // indicates to abort this processing-chain for good } diff --git a/tests/vault/gear/activity-detector.hpp b/tests/vault/gear/activity-detector.hpp index 5e2cdc412..259e40f2f 100644 --- a/tests/vault/gear/activity-detector.hpp +++ b/tests/vault/gear/activity-detector.hpp @@ -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 diff --git a/tests/vault/gear/scheduler-service-test.cpp b/tests/vault/gear/scheduler-service-test.cpp index 03ac47171..d59683184 100644 --- a/tests/vault/gear/scheduler-service-test.cpp +++ b/tests/vault/gear/scheduler-service-test.cpp @@ -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..."< up-front delay"< 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"< 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()); diff --git a/wiki/thinkPad.ichthyo.mm b/wiki/thinkPad.ichthyo.mm index 3970624d5..51d4edf3b 100644 --- a/wiki/thinkPad.ichthyo.mm +++ b/wiki/thinkPad.ichthyo.mm @@ -88271,16 +88271,17 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
- - + + - + + - + @@ -88292,38 +88293,41 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
 - + + + + + + - - - +

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

- - + - + + + + - - + + - - - +

...wir sind noch nicht so weit (nach Plan) @@ -88337,8 +88341,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
- - + @@ -88363,36 +88366,28 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
 - - - +

...zumal ich jetzt alles im Debug-Mode untersuche, und auch noch COUT-Statements und Clock-Aufrufe eingebaut habe

- - + - - - +

steckt in Activity::activate

- - + - - - +

steckt in Activity::callHook @@ -88400,13 +88395,15 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
+ + - + @@ -88415,21 +88412,17 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
 - + + - - - - - - +

|capacity=0 @@ -88453,10 +88446,14 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
res:2 delay=29µs

- - + + + + + + @@ -88470,9 +88467,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
- - - +

einziger Unterschied: Zeiten im Call-stack addieren sich weniger auf... @@ -88493,8 +88488,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
+++++Dispatch: 54µs (0|+|54)

- - + @@ -88506,14 +88500,39 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
...sondern nur die wenigen Translation-Units, die ich für relevant halte. Das könnte dann insgesamt nochmal einen Unterschied machen

- - + + + + + + + + + + + + + + + + + + +

+ Optimierung hat darauf keinerlei Einfluß +

+ + + + + +