From 4f8da45a67efbd895fb6eeb07aa8e25b067e4c37 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Florian=20L=C3=BCke?= Date: Tue, 4 Jul 2023 00:47:19 +0200 Subject: [PATCH] improve speed by allocating less; still slow --- external/mesytec-mvlc | 2 +- src/mvlc_nng_replay.cc | 62 ++++++++++++++++++++++++------------------ 2 files changed, 36 insertions(+), 28 deletions(-) diff --git a/external/mesytec-mvlc b/external/mesytec-mvlc index 1ca8196..c04c211 160000 --- a/external/mesytec-mvlc +++ b/external/mesytec-mvlc @@ -1 +1 @@ -Subproject commit 1ca81965546016a9a23ce3dd1af537dbaf3493cf +Subproject commit c04c2114583d3f067e4f95036c3d2b805a423073 diff --git a/src/mvlc_nng_replay.cc b/src/mvlc_nng_replay.cc index 2fd3c68..3bd679b 100644 --- a/src/mvlc_nng_replay.cc +++ b/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(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" - " tReceive = {}\n" - " tProcess = {}\n" - " tSend = {}\n" - " tTotal = {}\n", - tReceive.count(), - tProcess.count(), - tSend.count(), - tTotal.count()); + log_stats(); 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));