Scheduler-test: complements and fixes for the instrumentation

- supplement the pre-dimensioning for data capture; without that,
  sporadic memory corruption indeed happens (as expected, since
  concurrent re-allocation of the vector with an entry for each
  thread is not threadsafe, and this test shows much contention)

- add a top-level logging for better diagnostics of errors
  emanating from the test run

src/lib/error.hpp

@@ -284,6 +284,23 @@ namespace lumiera {
                    , _OP_DESCR_, errID?errID:"??");         \
     }
 
+#define ERROR_LOG_AND_RETHROW(_FLAG_,_OP_DESCR_) \
+  catch (std::exception& problem)                 \
+    {                                              \
+      const char* errID = lumiera_error();          \
+      WARN (_FLAG_, "%s failed: %s", _OP_DESCR_, problem.what()); \
+      TRACE (debugging, "Error flag was: %s", errID); \
+      throw;                                           \
+    }                                                   \
+  catch (...)                                            \
+    {                                                     \
+      const char* errID = lumiera_error();                 \
+      ERROR (_FLAG_, "%s failed with unknown exception; "   \
+                     "error flag is: %s"                     \
+                   , _OP_DESCR_, errID?errID:"??");           \
+      throw;                                                   \
+    }
+
 /******************************************************//**
  * convenience shortcut to catch and absorb any exception,
  * then returning a default value instead. This scheme is
@@ -294,7 +311,7 @@ namespace lumiera {
   catch (std::exception& problem)                \
     {                                             \
       const char* errID = lumiera_error();         \
-      WARN (stage, "%s (Signal Handler) failed: %s",\
+      WARN (stage, "%s (Handler) failed: %s",       \
                    _OP_DESCR_, problem.what());      \
       TRACE (debugging, "Error flag was: %s", errID); \
       return (_VAL_);                                  \
@@ -302,7 +319,7 @@ namespace lumiera {
   catch (...)                                            \
     {                                                     \
       const char* errID = lumiera_error();                 \
-      ERROR (stage, "(Signal Handler) %s failed with "      \
+      ERROR (stage, "(Handler) %s failed with "             \
                     "unknown exception; error flag is: %s"   \
                    , _OP_DESCR_, errID?errID:"??");           \
       return (_VAL_);                                          \

src/lib/incidence-count.hpp

@@ -228,9 +228,9 @@ namespace lib {
       for (Sequence& seq : rec_)
         for (Inc& event : seq)
           timeline.emplace_back(event);
-      std::sort (timeline.begin(), timeline.end()
-                ,[](Inc const& l, Inc const& r) { return l.when < r.when; }
-                );
+      std::stable_sort (timeline.begin(), timeline.end()
+                       ,[](Inc const& l, Inc const& r) { return l.when < r.when; }
+                       );
       
       int active{0};
       vector<int> active_case;

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

@@ -1789,14 +1789,15 @@ namespace test {
        */
       double
       launch_and_wait()
-        {
-          return benchmarkTime ([this]
-                                {
-                                  awaitBlocking(
-                                    performRun());
-                                })
-               -_uSec(preRoll_);
-        }     // timing starts with nominal zero without pre-roll
+        try {
+            return benchmarkTime ([this]
+                                  {
+                                    awaitBlocking(
+                                      performRun());
+                                  })
+                 -_uSec(preRoll_); // timing accounted without pre-roll
+          }
+          ERROR_LOG_AND_RETHROW(test,"Scheduler testing")
       
       auto
       getScheduleSeq()
@@ -1831,7 +1832,14 @@ namespace test {
       ScheduleCtx&&
       withInstrumentation (bool doWatch =true)
         {
-          watchInvocations_.reset (doWatch? new lib::IncidenceCount : nullptr);
+          if (doWatch)
+            {
+              watchInvocations_.reset (new lib::IncidenceCount);
+              watchInvocations_->expectThreads (work::Config::COMPUTATION_CAPACITY)
+                                .expectIncidents(chainLoad_.size());
+            }
+          else
+            watchInvocations_.reset();
           return move(*this);
         }
       

wiki/thinkPad.ichthyo.mm

@@ -111174,6 +111174,82 @@ Date:&#160;&#160;&#160;Thu Apr 20 18:53:17 2023 +0200<br/>
 <node COLOR="#338800" CREATED="1707960970597" ID="ID_1158951100" MODIFIED="1707960975655" TEXT="pragmatisch: l&#xe4;uft">
 <icon BUILTIN="button_ok"/>
 </node>
+<node BACKGROUND_COLOR="#d3bdad" COLOR="#435e98" CREATED="1708020916581" FOLDED="true" ID="ID_640197991" MODIFIED="1708025384909" TEXT="sporadische Memory-corruption">
+<icon BUILTIN="broken-line"/>
+<node CREATED="1708020937804" ID="ID_1671644739" MODIFIED="1708020941949" TEXT="schwer zu fassen"/>
+<node CREATED="1708020942683" ID="ID_1311204177" MODIFIED="1708021017716" TEXT="passiert irgendwo in den Workern"/>
+<node CREATED="1708021019319" ID="ID_933251621" MODIFIED="1708021051197" TEXT="Callstacks lassen auf heftige Contention schlie&#xdf;en">
+<richcontent TYPE="NOTE"><html>
+  <head>
+    
+  </head>
+  <body>
+    <p>
+      fast alle Threads sind im Contention-wait
+    </p>
+  </body>
+</html>
+</richcontent>
+</node>
+<node BACKGROUND_COLOR="#cdc17d" COLOR="#a50125" CREATED="1708021069617" ID="ID_146646167" MODIFIED="1708021356534" TEXT="Wichtiger Umstand: habe Vor-Dimensionierung des IncidenceCount noch nicht implementiert">
+<richcontent TYPE="NOTE"><html>
+  <head>
+    
+  </head>
+  <body>
+    <p>
+      das ist zwar ganz klar geplant, aber ich jetzt lasse ich die Tests erst mal so laufen...
+    </p>
+  </body>
+</html>
+</richcontent>
+<icon BUILTIN="messagebox_warning"/>
+</node>
+<node CREATED="1708021150829" ID="ID_841513991" MODIFIED="1708021415380" TEXT="Theorie: der Basis-Vector f&#xfc;r die Threads wird concurrent erweitert">
+<richcontent TYPE="NOTE"><html>
+  <head>
+    
+  </head>
+  <body>
+    <p>
+      Zwar beobachte ich die Memory-Corruption dann ehr beim Einf&#252;gen der Events, aber das kann sehr wohl ein Folge-Fehler sein. Ich sehe auch anderes Verhalten, das &#8222;eigentlich gar nicht m&#246;glich ist&#8220;
+    </p>
+  </body>
+</html>
+</richcontent>
+<icon BUILTIN="idea"/>
+<node CREATED="1708021200631" ID="ID_1507367200" MODIFIED="1708021325426" TEXT="das ist nicht threadsafe">
+<richcontent TYPE="NOTE"><html>
+  <head>
+    
+  </head>
+  <body>
+    <p>
+      Hier passiert ein Vector-realloc. Wenn w&#228;hrenddessen der n&#228;chste Thread kommt, macht der ebenfalls ein re-Alloc und die Memory-corruption w&#228;re garantiert.
+    </p>
+  </body>
+</html>
+</richcontent>
+</node>
+<node CREATED="1708021206366" ID="ID_34842564" MODIFIED="1708021215512" TEXT="eigentlich m&#xfc;&#xdf;te hier ein Mutex verwendet werden"/>
+<node CREATED="1708021217380" ID="ID_1094048458" MODIFIED="1708021275576" TEXT="KISS &#x27f9; stattdessen richtig vor-Dimensionieren">
+<richcontent TYPE="NOTE"><html>
+  <head>
+    
+  </head>
+  <body>
+    <p>
+      Das ist ein Instrumentierungs-Hilfsmittel, und generell nur darauf ausgelegt, &#187;richtig verwendet zu werden&#171;
+    </p>
+  </body>
+</html>
+</richcontent>
+</node>
+</node>
+<node COLOR="#338800" CREATED="1708025327359" ID="ID_461738408" MODIFIED="1708025344662" TEXT="mit Vor-Dimensionierung nicht mehr beobachtet">
+<icon BUILTIN="button_ok"/>
+</node>
+</node>
 <node CREATED="1707960978559" ID="ID_688220827" MODIFIED="1707960986968" TEXT="Statistik zuschalten">
 <icon BUILTIN="forward"/>
 <node CREATED="1707960988842" ID="ID_1122286519" MODIFIED="1707960994318" TEXT="erste Ergebnisse sehen gut aus"/>