Chain-Load: Scheduler instrumentation for observation

- prime diagnostics with the first time invocation
- print timings relative to this first invocation
- DUMP output to watch the crucial scheduling operations

src/vault/gear/scheduler.hpp

@@ -115,6 +115,7 @@
 //#include "lib/symbol.hpp"
 #include  "lib/nocopy.hpp"
 //#include "lib/util.hpp"
+#include "lib/format-cout.hpp"///////////////////////TODO
 
 //#include <string>
 #include <optional>
@@ -583,6 +584,26 @@ namespace gear {
     return move(*this);
   }
   
+namespace{
+  inline string
+  relT (int64_t pling)
+  {
+    static int64_t nulli{0};
+    if (nulli == 0) nulli = pling;
+    return util::toString(pling - nulli);
+  }
+  inline string
+  relT (Time plong)
+  {
+    return relT(_raw(plong));
+  }
+  
+  inline string
+  markThread()
+  {
+    return util::showHashLSB (std::hash<std::thread::id>{}(thisThread()));
+  }
+}
   
   /**
    * Enqueue for time-bound execution, possibly dispatch immediately.
@@ -593,7 +614,8 @@ namespace gear {
   inline void
   Scheduler::postChain (ActivationEvent actEvent)
   {
-    maybeScaleWorkForce();
+    maybeScaleWorkForce ();
+cout<<"‖SCH‖ "+markThread()+": @"+relT(RealClock::now())+" ○ start="+relT(actEvent.starting)+" dead:"+util::toString(actEvent.deadline - actEvent.starting)<<endl;
     ExecutionCtx ctx{*this, actEvent};
     layer2_.postDispatch (actEvent, ctx, layer1_);
   }
@@ -632,6 +654,7 @@ namespace gear {
                       .performStep([&]{
                                         Time now = getSchedTime();
                                         auto toDispatch = layer2_.findWork (layer1_,now);
+cout<<"   ·‖ "+markThread()+": @ "+relT(now)+" HT:"+relT(layer1_.headTime())+"  -> "+(toDispatch? "▶ "+relT(toDispatch.starting): string("∘"))<<endl;
                                         ExecutionCtx ctx{*this, toDispatch};
                                         return layer2_.postDispatch (toDispatch, ctx, layer1_);
                                       })
@@ -724,6 +747,7 @@ namespace gear {
   inline void
   Scheduler::handleDutyCycle (Time now)
   {
+cout<<"‖▷▷▷‖ "+markThread()+": @ "+relT(now)+(empty()? string(" EMPTY"): " HT:"+relT(layer1_.headTime()))<<endl;
     // consolidate queue content
     layer1_.feedPrioritisation();
     // clean-up of outdated tasks here
@@ -761,6 +785,8 @@ namespace gear {
       triggerEmergency();
     else
       loadControl_.markWorkerExit();
+Time now = getSchedTime();
+cout<<"‖▽▼▽‖ "+markThread()+": @ "+relT(now)<<endl;
   }
   
   /**
@@ -775,9 +801,15 @@ namespace gear {
   Scheduler::maybeScaleWorkForce()
   {
     if (empty())
+{
       ignite();
+cout<<"‖IGN‖     wof:"+util::toString(workForce_.size())<<endl;
+}
     else
+{
       workForce_.incScale();
+cout<<"‖•△•‖     wof:"+util::toString(workForce_.size())+" HT:"+relT(layer1_.headTime())<<endl;
+}
   }
   
   /**

tests/vault/gear/test-chain-load.hpp

@@ -1135,6 +1135,7 @@ namespace test {
           Node& target = startNode_[nodeIdx];
           ASSERT (target.level == level);
           // invoke the »media calculation«
+cout<<_Fmt{"\n!◆! %s: calc(i=%d, lev:%d)"} % markThread() % nodeIdx % level <<endl;          
           target.calculate();
         }
       
@@ -1187,9 +1188,11 @@ namespace test {
       invokeJobOperation (JobParameter param)  override
         {
           size_t targetLevel = decodeLevel (TimeValue{param.nominalTime});
+cout<<_Fmt{"\n!◆!plan...to:%d%19t|curr=%d (max:%d)"} % targetLevel % currIdx_ % maxCnt_<<endl;          
           for ( ; currIdx_<maxCnt_; ++currIdx_)
             {
               Node* n = &nodes_[currIdx_];
+cout<<_Fmt{"%16t|n.(%d,lev:%d)"} % currIdx_ % n->level <<endl;
               if (n->level > targetLevel)
                 break;
               scheduleCalcJob_(currIdx_, n->level);
@@ -1250,6 +1253,7 @@ namespace test {
       void
       disposeStep (size_t idx, size_t level)
         {
+cout <<_Fmt{"... dispose(i=%d,lev:%d) -> @%s"} % idx % level % relT(calcStartTime(level))<<endl;
           schedule_[idx] = scheduler_.defineSchedule(calcJob (idx,level))
                                      .manifestation(manID_)
                                      .startTime (calcStartTime(level))
@@ -1270,9 +1274,11 @@ namespace test {
       void
       continuation (size_t levelDone, bool work_left)
         {
+cout <<_Fmt{"+++ %s: Continuation(levelDone=%d, work_left:%s)"} % markThread() % levelDone % work_left <<endl;
           if (work_left)
             {
               size_t nextChunkLevel = calcNextLevel (levelDone);
+cout <<"--> reschedule to "<<nextChunkLevel<<endl;
               scheduler_.continueMetaJob (calcPlanScheduleTime (nextChunkLevel)
                                          ,planningJob (nextChunkLevel)
                                          ,manID_);
@@ -1285,6 +1291,7 @@ namespace test {
       performRun()
         {
           size_t numNodes = chainLoad_.size();
+cout <<"+++ "<<markThread()<<": seed(num:"<<numNodes<<")"<<endl;
           schedule_.allocate (numNodes);
           startTime_ = anchorStartTime();
           scheduler_.seedCalcStream (planningJob(0)
@@ -1353,7 +1360,10 @@ namespace test {
       Time
       anchorStartTime()
         {
-          return RealClock::now() + preRoll_;
+Time ank = RealClock::now() + preRoll_;
+cout<<"ANCHOR="+relT(ank)+" preRoll="+util::toString(_raw(preRoll_))<<endl;
+//          return RealClock::now() + preRoll_;
+          return ank;
         }
       
       FrameRate