From 84b92c2ee37b967d9ad7ac21cfa435059fa38263 Mon Sep 17 00:00:00 2001 From: Ichthyostega Date: Wed, 20 Dec 2023 02:50:47 +0100 Subject: [PATCH] Scheduler-test: investigate and fix problem with the new Guard ...turns out to be a secondary problem (but must be fixed non the less). Since the planning-job no longer drops the token now, the workers have to wait; since they are waiting actively and contending on the token, a significant slowdown can happen. Sometimes the planning job gets behind its own scheduler and thus enters dispatch, in which case it drops the GoomingToken, causing an Assertion failure on return. The **actual problem** however is the slowdown due to active spinning --- src/vault/gear/scheduler-commutator.hpp | 3 +- wiki/thinkPad.ichthyo.mm | 882 +++++++++++++++++++++++- 2 files changed, 863 insertions(+), 22 deletions(-) diff --git a/src/vault/gear/scheduler-commutator.hpp b/src/vault/gear/scheduler-commutator.hpp index a882fc12d..7a64f0460 100644 --- a/src/vault/gear/scheduler-commutator.hpp +++ b/src/vault/gear/scheduler-commutator.hpp @@ -315,7 +315,8 @@ namespace gear { ~ScopedGroomingGuard() { - if (handledActively_) + if (handledActively_ and + commutator_.holdsGroomingToken(thisThread())) commutator_.dropGroomingToken(); } }; diff --git a/wiki/thinkPad.ichthyo.mm b/wiki/thinkPad.ichthyo.mm index 3d32455d6..48b3d78fa 100644 --- a/wiki/thinkPad.ichthyo.mm +++ b/wiki/thinkPad.ichthyo.mm @@ -105226,8 +105226,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
dieses Prinzip könnte man aufweichen — ich halte das aber für eine schlechte Idee, denn der Scheduler ist auch so schon schwer genug zu verstehen, auch die Activity-Language beginnt schon zu »bröseln« ... gefährliche Tendenz. Meine Einschätzung ist, wir planen ehr so 10 Jobs pro Metajob-Lauf, d.h. das wären dann Größenordnung 500-1000µs Zeit, in der jedwede andere Management-Tätigkeit geblockt ist (renderjobs laufen trotzdem weiter). Sofern diese Annahme nicht zutrifft, möchte ich dafür konkrete Beweise sehen

- - + @@ -105298,8 +105297,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
    of Grooming-Token handling and clarified the role of the API-functions.

- - + @@ -105313,8 +105311,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
aber sie dann auch zusätzlich in das post()  eingesetzt

- - + @@ -105330,8 +105327,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
...dann erlangt er es, und behält es

- - + @@ -105386,8 +105382,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
und: die Allokation findet hier statt

- - + @@ -105403,8 +105398,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
          .buildCalculationJob (job_, start_,death_));

- - + @@ -105419,8 +105413,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
...eben wenn jemand von außen kommt... das ist i.d.R. nur beim seedCalcStream() der Fall

- - + @@ -105444,8 +105437,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
zum einen ist das nicht genau das feste Raster, und außerdem braucht der OS-Scheduler sowiso immer etwas länger

- - + @@ -105463,8 +105455,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
sage bewußt »dokumentieren«, denn diese Logik hier ist derart einfach zu implementieren, daß eigentlich kein Test notwendig wäre

- - + @@ -105477,8 +105468,7 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
das ist nämlich unverhältnismäßig schwer im Test zu verifizieren, und steht in keinem Verhältnis zur Aufgabe

- - + @@ -105499,6 +105489,855 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
+ + + + + + + + + + + + + + + +

+ Assertion-Failure: der Aufrufer von dropGroomingToken() hält es nicht +

+ + + + + + + + + + + + + + +

+ vault::gear::SchedulerCommutator::dropGroomingToken()+0xeb +

+

+ +

+

+ vault::gear::SchedulerCommutator::ScopedGroomingGuard::~ScopedGroomingGuard()+0x27 +

+

+ +

+

+ vault::gear::ScheduleSpec::post()+0x1b8 +

+

+ +

+

+ vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::disposeStep(unsigned long, unsigned long)+0x22d +

+

+ +

+

+ vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::ScheduleCtx(vault::gear::test::TestChainLoad<16ul>&, vault::gear::Scheduler&)::{lambda(unsigned long, unsigned long)#1}::operator()(unsigned long, unsigned long) const+0x2e +

+

+ +

+

+ std::_Function_handler<void (unsigned long, unsigned long), vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::ScheduleCtx(vault::gear::test::TestChainLoad<16ul>&, vault::gear::Scheduler&)::{lambda(unsigned long, unsigned long)#1}>::_M_invoke(std::_Any_data const&, unsigned long&&, std::_Any_data const&)+0x52 +

+

+ +

+

+ std::function<void (unsigned long, unsigned long)>::operator()(unsigned long, unsigned long) const+0x61 +

+

+ +

+

+ vault::gear::test::RandomChainPlanFunctor<16ul>::invokeJobOperation(lumiera_jobParameter_struct const&)+0x29d +

+

+ +

+

+ vault::gear::Activity::invokeFunktor(lib::time::Time)+0x740 +

+

+ +

+

+ vault::gear::activity::Proc vault::gear::Activity::activate<vault::gear::Scheduler::ExecutionCtx>(lib::time::Time, vault::gear::Scheduler::ExecutionCtx&)+0x70 +

+

+ +

+

+ vault::gear::activity::Proc vault::gear::ActivityLang::activateChain<vault::gear::Scheduler::ExecutionCtx>(vault::gear::Activity*, vault::gear::Scheduler::ExecutionCtx&)+0x4e +

+

+ +

+

+ vault::gear::activity::Proc vault::gear::ActivityLang::dispatchChain<vault::gear::Scheduler::ExecutionCtx>(vault::gear::Activity*, vault::gear::Scheduler::ExecutionCtx&)+0x68 +

+

+ +

+

+ vault::gear::activity::Proc vault::gear::SchedulerCommutator::postDispatch<vault::gear::Scheduler::ExecutionCtx>(vault::gear::ActivationEvent, vault::gear::Scheduler::ExecutionCtx&, vault::gear::SchedulerInvocation&)+0xc1 +

+

+ +

+

+ vault::gear::Scheduler::postChain(vault::gear::ActivationEvent)+0x2a9 +

+

+ +

+

+ vault::gear::Scheduler::continueMetaJob(lib::time::Time, vault::gear::Job, vault::gear::ManifestationID)+0x164 +

+

+ +

+

+ vault::gear::Scheduler::seedCalcStream(vault::gear::Job, vault::gear::ManifestationID, lib::time::FrameRate)+0x8b +

+

+ +

+

+ vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::performRun()+0x17e +

+

+ +

+

+ vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::launch_and_wait()::{lambda()#1}::operator()() const+0x2a +

+

+ +

+

+ double lib::test::benchmarkTime<vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::launch_and_wait()::{lambda()#1}>(vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::launch_and_wait()::{lambda()#1} const&, unsigned long)+0x25 +

+

+ +

+

+ vault::gear::test::TestChainLoad<16ul>::ScheduleCtx::launch_and_wait()+0x25 +

+

+ +

+

+ vault::gear::test::SchedulerStress_test::smokeTest()+0x4af +

+

+ +

+ + + + + + + + + + + + + + + + + +

+    ·‖ 20: @22281 HT:0  -> ∘ +

+

+    ·‖ 20: @22304 HT:0  -> ∘ +

+

+    ·‖ 0F: @22307 HT:0  -> ∘ +

+

+ +

+

+ ... dispose(i=46,lev:23) -> @23000 +

+

+ +

+

+    ·‖ 5A: @22184 HT:0  -> ∘ +

+

+    ·‖ 18: @22217 HT:0  -> ∘ +

+

+    ·‖ 24: @22249 HT:0  -> ∘ +

+

+    ·‖ 5A: @22358 HT:0  -> ∘ +

+

+    ·‖ 7C: @22389 HT:0  -> ∘ +

+

+    ·‖ 24: @22402 HT:0  -> ∘ +

+

+    ·‖ 7C: @22414 HT:0  -> ∘ +

+

+    ·‖ 0F: @22361 HT:0  -> ∘ +

+

+    ·‖ 18: @22438 HT:0  -> ∘ +

+

+    ·‖ CD: @22456 HT:0  -> ∘ +

+

+    ·‖ F6: @22247 HT:0  -> ∘ +

+

+    ·‖ CD: @22486 HT:0  -> ∘ +

+

+    ·‖ 20: @22337 HT:0  -> ∘ +

+

+    ·‖ CD: @22507 HT:0  -> ∘ +

+

+    ·‖ 18: @22466 HT:0  -> ∘ +

+

+    ·‖ 24: @22528 HT:0  -> ∘ +

+

+    ·‖ F6: @22498 HT:0  -> ∘ +

+

+    ·‖ CD: @22548 HT:0  -> ∘ +

+

+    ·‖ CD: @22573 HT:0  -> ∘ +

+

+    ·‖ 0F: @22605 HT:0  -> ∘ +

+

+    ·‖ 7C: @22436 HT:0  -> ∘ +

+

+    ·‖ 0F: @22632 HT:0  -> ∘ +

+

+    ·‖ 7C: @22646 HT:0  -> ∘ +

+

+    ·‖ 5A: @22381 HT:0  -> ∘ +

+

+    ·‖ 0F: @22659 HT:0  -> ∘ +

+

+    ·‖ 7C: @22668 HT:0  -> ∘ +

+

+    ·‖ 24: @22552 HT:0  -> ∘ +

+

+    ·‖ 7C: @22691 HT:0  -> ∘ +

+

+    ·‖ CD: @22721 HT:0  -> ∘ +

+

+    ·‖ 0F: @22735 HT:0  -> ∘ +

+

+    ·‖ 5A: @22751 HT:0  -> ∘ +

+

+    ·‖ 0F: @22762 HT:0  -> ∘ +

+

+    ·‖ 5A: @22774 HT:0  -> ∘ +

+

+    ·‖ 7C: @22714 HT:0  -> ∘ +

+

+    ·‖ 5A: @22796 HT:0  -> ∘ +

+

+    ·‖ 7C: @22807 HT:0  -> ∘ +

+

+    ·‖ 5A: @22821 HT:0  -> ∘ +

+

+    ·‖ 7C: @22830 HT:0  -> ∘ +

+

+    ·‖ 18: @22836 HT:0  -> ∘ +

+

+    ·‖ 5A: @22844 HT:0  -> ∘ +

+

+    ·‖ CD: @22745 HT:0  -> ∘ +

+

+    ·‖ 5A: @22866 HT:0  -> ∘ +

+

+    ·‖ 20: @22575 HT:0  -> ∘ +

+

+    ·‖ 0F: @22897 HT:0  -> ∘ +

+

+    ·‖ 0F: @22927 HT:0  -> ∘ +

+

+    ·‖ 0F: @22952 HT:0  -> ∘ +

+

+    ·‖ 20: @22965 HT:0  -> ∘ +

+

+    ·‖ 7C: @22900 HT:0  -> ∘ +

+

+    ·‖ 0F: @22975 HT:0  -> ∘ +

+

+    ·‖ 20: @22986 HT:0  -> ∘ +

+

+    ·‖ CD: @22892 HT:0  -> ∘ +

+

+    ·‖ 5A: @23015 HT:0  -> ∘ +

+

+    ·‖ 24: @23020 HT:0  -> ∘ +

+

+    ·‖ 20: @23012 HT:0  -> ∘ +

+

+    ·‖ 20: @23088 HT:0  -> ∘ +

+

+    ·‖ 7C: @23106 HT:0  -> ∘ +

+

+    ·‖ F6: @22810 HT:0  -> ∘ +

+

+    ·‖ 20: @23118 HT:0  -> ∘ +

+

+    +

+

+ ‖•△•‖     wof:8 HT:0 +

+

+ ‖SCH‖ 0C: @23067 ○ start=23000 dead:30000 +

+

+ +

+

+    ·‖ 20: @23149 HT:0  -> ∘ +

+

+    ·‖ 5A: @23099 HT:0  -> ∘ +

+

+    ·‖ 18: @22917 HT:0  -> ∘ +

+

+    ·‖ 20: @23174 HT:0  -> ∘ +

+

+    ·‖ 24: @23049 HT:0  -> ∘ +

+

+    ·‖ CD: @23157 HT:0  -> ∘ +

+

+    ·‖ 0F: @23231 HT:0  -> ∘ +

+

+    ·‖ 7C: @23127 HT:0  -> ∘ +

+

+    ·‖ F6: @23241 HT:0  -> ∘ +

+

+    ·‖ 0F: @23252 HT:0  -> ∘ +

+

+    ·‖ F6: @23265 HT:0  -> ∘ +

+

+    ·‖ 0F: @23276 HT:0  -> ∘ +

+

+    ·‖ 5A: @23296 HT:0  -> ∘ +

+

+    ·‖ 5A: @23318 HT:0  -> ∘ +

+

+    ·‖ 5A: @23339 HT:0  -> ∘ +

+

+    ·‖ 20: @23210 HT:0  -> ∘ +

+

+    ·‖ 0F: @23371 HT:0  -> ∘ +

+

+    ·‖ 24: @23383 HT:0  -> ∘ +

+

+    ·‖ 0F: @23395 HT:0  -> ∘ +

+

+    ·‖ 0F: @23412 HT:0  -> ∘ +

+

+    ·‖ F6: @23286 HT:0  -> ∘ +

+

+    ·‖ 18: @23309 HT:0  -> ∘ +

+

+    ·‖ CD: @23360 HT:0  -> ∘ +

+

+    ·‖ F6: @23455 HT:0  -> ∘ +

+

+    ·‖ 24: @23404 HT:0  -> ∘ +

+

+    ·‖ 0F: @23436 HT:81  -> ▶ 0 +

+

+    ·‖ 18: @23470 HT:81  -> ∘ +

+

+    +

+

+ !◆!   0C: @23447  ⚙  calc(i=46, lev:23) +

+

+ +

+

+    ·‖ 24: @23525 HT:81  -> ∘ +

+

+    ·‖ 5A: @23554 HT:81  -> ∘ +

+

+ +

+

+ !◆!   0C: @23510  ⤴       (i=46) +

+

+ ..!   0F: @23537  ⚙  calc(i=0, lev:0) +

+

+ +

+

+    ·‖ 24: @23553 HT:1000  -> ▶ 81 +

+

+    ·‖ F6: @23616 HT:1000  -> ∘ +

+

+    ·‖ 20: @23627 HT:1000  -> ∘ +

+

+    ·‖ CD: @23644 HT:1000  -> ∘ +

+

+ +

+

+ ‖▷▷▷‖ 24: @ 23658 HT:1000 +

+

+ +

+

+    ·‖ 20: @23679 HT:1000  -> ∘ +

+

+    ·‖ F6: @23648 HT:1000  -> ∘ +

+

+    ·‖ 20: @23706 HT:1000  -> ∘ +

+

+    ·‖ 18: @23588 HT:1000  -> ∘ +

+

+    ·‖ F6: @23720 HT:1000  -> ∘ +

+

+    ·‖ 20: @23731 HT:1000  -> ∘ +

+

+    ·‖ 5A: @23617 HT:1000  -> ∘ +

+

+    ·‖ 24: @23739 HT:2000  -> ▶ 1000 +

+

+    ·‖ 7C: @23638 HT:1000  -> ∘ +

+

+ +

+

+ ... +

+

+ +

+

+ +

+

+    ·‖ 7C: @24156 HT:6000  -> ∘ +

+

+ !◆!   24: @24126  ⚙  calc(i=1, lev:1) +

+

+    ·‖ F6: @24098 HT:5000  -> ∘ +

+

+    ·‖ 5A: @24185 HT:7000  -> ∘ +

+

+    ·‖ 5A: @24212 HT:7000  -> ∘ +

+

+    ·‖ 0F: @24168 HT:7000  -> ∘ +

+

+                 |n.(47,lev:23) +

+

+    ·‖ F6: @24258 HT:7000  -> ∘ +

+

+    ·‖ CD: @23881 HT:4000  -> ∘ +

+

+    ·‖ 7C: @24270 HT:7000  -> ∘ +

+

+    ·‖ 0F: @24314 HT:7000  -> ∘ +

+

+    ·‖ 7C: @24329 HT:7000  -> ∘ +

+

+    ·‖ 20: @24339 HT:7000  -> ∘ +

+

+    ·‖ 5A: @24241 HT:7000  -> ∘ +

+

+    ·‖ CD: @24316 HT:7000  -> ∘ +

+

+    ·‖ 5A: @24380 HT:7000  -> ∘ +

+

+    ·‖ 0F: @24341 HT:7000  -> ∘ +

+

+    ·‖ 5A: @24401 HT:7000  -> ∘ +

+

+ ... dispose(i=47,lev:23) -> @23000 +

+

+    ·‖ 5A: @24431 HT:7000  -> ∘ +

+

+    ·‖ 7C: @24411 HT:7000  -> ∘ +

+

+    ·‖ 0F: @24470 HT:7000  -> ∘ +

+

+ ..!   24: @24456  ⤴       (i=1) +

+

+    ·‖ 7C: @24498 HT:7000  -> ∘ +

+

+ +

+

+    ·‖ 7C: @24522 HT:7000  -> ∘ +

+

+ +

+

+    ·‖ 7C: @24543 HT:7000  -> ∘ +

+

+    ·‖ F6: @24284 HT:7000  -> ∘ +

+

+    ·‖ 7C: @24563 HT:7000  -> ∘ +

+

+    ·‖ 18: @24162 HT:7000  -> ▶ 6000 +

+

+    ·‖ F6: @24577 HT:7000  -> ∘ +

+

+    ·‖ 7C: @24585 HT:7000  -> ∘ +

+

+    ·‖ 5A: @24618 HT:7000  -> ∘ +

+

+    ·‖ 5A: @24642 HT:7000  -> ∘ +

+

+ +

+

+ ... +

+

+ +

+

+    ·‖ F6: @30810 HT:23000  -> ∘ +

+

+    ·‖ 18: @30789 HT:23000  -> ∘ +

+

+    ·‖ 20: @30830 HT:23000  -> ∘ +

+

+ +

+

+ !◆!   0F: @30867  ⚙  calc(i=5, lev:5) +

+

+ +

+

+    ·‖ 7C: @30858 HT:23000  -> ∘ +

+

+    ·‖ 24: @30882 HT:73658  -> ▶ 23000 +

+

+ ..!   0F: @30974  ⤴       (i=5) +

+

+ ‖PST‖ 0F: @31024 ◒ start=5000▹▹6000 dead:30000 +

+

+    ·‖ 0F: @31055 HT:73658  -> ▶ 6000 +

+

+ +

+

+ !◆!   0F: @31079  ⚙  calc(i=6, lev:6) +

+

+ ‖•△•‖     wof:8 HT:73658 +

+

+ ‖SCH‖ 0C: @31199 ○ start=23000 dead:30000 +

+

+ +

+

+ !◆!   0C: @31217  ⚙  calc(i=47, lev:23) +

+

+ ..!   0F: @31876  ⤴       (i=6) +

+

+ ‖PST‖ 0F: @31920 ◒ start=6000▹▹7000 dead:30000 +

+

+    ·‖ 0F: @31946 HT:73658  -> ▶ 7000 +

+

+ +

+

+ !◆!   0F: @31971  ⚙  calc(i=7, lev:7) +

+

+ ..!   0C: @33137  ⤴       (i=47) +

+

+ 0000000609: PRECONDITION: scheduler-commutator.hpp:155: thread_1: dropGroomingToken: (groomingToken_.load(memory_order_relaxed) == thisThread()) +

+

+ +

+ + + + + + + + + + + + +

+ da nun t > 23000, kann er selber in den Dispatch gehen +

+ + + + + + + + + + + + + + + + +

+ um @31217  führt er selber aus ⚙  calc(i=47, lev:23) +

+ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + +

+ ⟹ Forderung: ein echer Planer muß das erkennen und abbrechen +

+ + + + + + + + + + + + + + + + + + + + + + + + + + + + @@ -105531,7 +106370,8 @@ Date:   Thu Apr 20 18:53:17 2023 +0200
- + +