improve speed by allocating less; still slow

external/mesytec-mvlc

@@ -1 +1 @@
-Subproject commit 1ca81965546016a9a23ce3dd1af537dbaf3493cf
+Subproject commit c04c2114583d3f067e4f95036c3d2b805a423073

src/mvlc_nng_replay.cc

@@ -221,7 +221,7 @@ void listfile_reader_producer(
                 return;
             }
 
-            spdlog::info("listfile_reader_producer: sent message {} of size {}",
+            spdlog::debug("listfile_reader_producer: sent message {} of size {}",
                 bufferNumber, msgSize);
             totalBytesSent += msgSize;
         }
@@ -410,7 +410,11 @@ void listfile_parser_nng(
     auto configYaml = configSection->contentsToString();
     auto crateConfig = mvlc::crate_config_from_yaml(configYaml);
 
-    spdlog::info("listfile_parser_nng: CrateConfig:\n{}", to_yaml(crateConfig));
+    std::string stacksYaml;
+    for (const auto &stack: crateConfig.stacks)
+        stacksYaml += to_yaml(stack);
+
+    spdlog::info("listfile_parser_nng: readout stacks:\n{}", stacksYaml);
 
     auto crateIndex = 0;
     ParserNngContext parserContext;
@@ -431,6 +435,21 @@ void listfile_parser_nng(
     std::chrono::microseconds tTotal(0);
     auto tLastReport = std::chrono::steady_clock::now();
 
+    auto log_stats = [&]
+    {
+        spdlog::info("listfile_parser_nng: lastInputMessageNumber={}, inputBuffersLost={}, totalInput={:.2f} MiB",
+            lastInputMessageNumber, inputBuffersLost, 1.0 * totalInputBytes / util::Megabytes(1));
+        spdlog::info("listfile_parser_nng: time budget: "
+                    "  tReceive = {} ms, "
+                    "  tProcess = {} ms, "
+                    "  tSend = {} ms, "
+                    "  tTotal = {} ms",
+                    tReceive.count() / 1000.0,
+                    tProcess.count() / 1000.0,
+                    tSend.count() / 1000.0,
+                    tTotal.count() / 1000.0);
+    };
+
     while (true)
     {
         StopWatch stopWatch;
@@ -460,7 +479,7 @@ void listfile_parser_nng(
             auto bufferLoss = readout_parser::calc_buffer_loss(inputHeader.messageNumber, lastInputMessageNumber);
             inputBuffersLost += bufferLoss >= 0 ? bufferLoss : 0u;;
             lastInputMessageNumber = inputHeader.messageNumber;
-            spdlog::info("analysis_nng: received message {} of size {}", lastInputMessageNumber, nng_msg_len(inputMsg));
+            spdlog::debug("analysis_nng: received message {} of size {}", lastInputMessageNumber, nng_msg_len(inputMsg));
 
             nng_msg_trim(inputMsg, sizeof(ListfileBufferMessageHeader));
             auto inputData = reinterpret_cast<const u32 *>(nng_msg_body(inputMsg));
@@ -468,7 +487,7 @@ void listfile_parser_nng(
 
             if (!parserContext.outputMessage)
             {
-                if (auto res = nng_msg_alloc(&parserContext.outputMessage, util::Megabytes(1)))
+                if (auto res = nng_msg_alloc(&parserContext.outputMessage, nng_msg_len(inputMsg) * 1.5))
                 {
                     spdlog::error("listfile_parser_nng - nng_msg_alloc: {}", nng_strerror(res));
                     break;
@@ -508,7 +527,7 @@ void listfile_parser_nng(
 
                 parserContext.outputMessage = nullptr;
 
-                spdlog::info("listfile_parser_nng: sent message {} of size {}",
+                spdlog::debug("listfile_parser_nng: sent message {} of size {}",
                     outputMessageNumber, msgSize);
             }
 
@@ -529,15 +548,7 @@ void listfile_parser_nng(
 
             if (tElapsed >= ReportInterval)
             {
-                spdlog::info("listfile_parser_nng: time budget:\n"
+                log_stats();
-                            "  tReceive = {}\n"
-                            "  tProcess = {}\n"
-                            "  tSend = {}\n"
-                            "  tTotal = {}\n",
-                            tReceive.count(),
-                            tProcess.count(),
-                            tSend.count(),
-                            tTotal.count());
                 tLastReport = now;
             }
         }
@@ -551,18 +562,6 @@ void listfile_parser_nng(
 
     assert(!parserContext.outputMessage);
 
-    spdlog::info("listfile_parser_nng: lastInputMessageNumber={}, inputBuffersLost={}, totalInput={:.2f} MiB",
-        lastInputMessageNumber, inputBuffersLost, 1.0 * totalInputBytes / util::Megabytes(1));
-    spdlog::info("listfile_parser_nng: time budget:\n"
-                 "  tReceive = {} ms\n"
-                 "  tProcess = {} ms\n"
-                 "  tSend = {} ms\n"
-                 "  tTotal = {} ms\n",
-                 tReceive.count() / 1000.0,
-                 tProcess.count() / 1000.0,
-                 tSend.count() / 1000.0,
-                 tTotal.count() / 1000.0);
-
     // send empty message
     if (auto res = nng_msg_alloc(&parserContext.outputMessage, 0))
     {
@@ -577,6 +576,15 @@ void listfile_parser_nng(
         spdlog::error("listfile_parser_nng: send_message_retry: {}:", nng_strerror(res));
         return;
     }
+
+    log_stats();
+
+    {
+        std::ostringstream ss;
+        readout_parser::print_counters(ss, parserCounters);
+        spdlog::info("listfile_parser_nng: parser counters:\n{}", ss.str());
+    }
+
 }
 
 void analysis_nng(
@@ -615,7 +623,7 @@ void analysis_nng(
             auto bufferLoss = readout_parser::calc_buffer_loss(inputHeader.messageNumber, lastInputMessageNumber);
             inputBuffersLost += bufferLoss >= 0 ? bufferLoss : 0u;;
             lastInputMessageNumber = inputHeader.messageNumber;
-            spdlog::info("analysis_nng: received message {} of size {}", lastInputMessageNumber, nng_msg_len(inputMsg));
+            spdlog::debug("analysis_nng: received message {} of size {}", lastInputMessageNumber, nng_msg_len(inputMsg));
 
             nng_msg_trim(inputMsg, sizeof(ParsedEventsMessageHeader));