114 static int produce_call_count = 0;
115 produce_call_count++;
116 ldmx_log(debug) <<
"produce() called, count=" << produce_call_count;
117 ldmx_log(debug) <<
"verbose_parse=" << (m_verbose_parse_ ?
"true" :
"false");
118 if (m_verbose_parse_ || produce_call_count <= 3) {
119 ldmx_log(info) <<
"produce() call #" << produce_call_count;
123 m_event_start_time_ = std::chrono::steady_clock::now();
126 uint32_t current_event_errors = 0;
128 while (m_reader_ && !m_reader_.
eof()) {
131 frame_header.
read(m_reader_);
134 const long long frame_end =
135 static_cast<long long>(m_reader_.
tell()) + frame_header.
size();
140 if (m_verbose_parse_)
141 ldmx_log(debug) <<
"skipping non-data frame (channel="
142 << frame_header.
channel() <<
")";
143 m_reader_.
seek(frame_end);
149 bool parsed_ok =
false;
153 int pos_before_ror = m_reader_.
tell();
157 ror_header.
read(m_reader_);
159 fragment.header_.subsystem_id_ =
160 static_cast<uint64_t
>(ror_header.
subsystem());
161 fragment.header_.contributor_id_ =
163 fragment.header_.timestamp_ = ror_header.
timestamp();
165 if (m_verbose_parse_) {
166 ldmx_log(debug) <<
"parsed RoR header subsys="
173 std::vector<uint8_t> payload_data;
174 long long payload_size = frame_end - m_reader_.
tell();
175 if (payload_size > 0) {
176 payload_data.resize(payload_size);
177 m_reader_.
read(
reinterpret_cast<char*
>(payload_data.data()),
180 fragment.payload_ = std::move(payload_data);
184 if (m_verbose_parse_)
186 <<
"RoR header parse failed, trying packing subsystem format";
188 m_reader_.
seek(pos_before_ror);
196 fragment.header_.subsystem_id_ =
static_cast<uint64_t
>(pkt.id());
197 fragment.header_.contributor_id_ =
199 fragment.header_.timestamp_ =
static_cast<uint64_t
>(pkt.
header()[1]) *
203 const auto& data = pkt.
data();
204 fragment.payload_.resize(data.size() * 4);
205 std::memcpy(fragment.payload_.data(),
206 reinterpret_cast<const char*
>(data.data()),
209 if (m_verbose_parse_) {
210 ldmx_log(debug) <<
"parsed packing subsystem pkt subsys=" << pkt.id()
211 <<
" data_size=" << data.size();
216 if (m_verbose_parse_)
217 ldmx_log(debug) <<
"failed to parse as either format, skipping frame";
219 m_reader_.
seek(frame_end);
225 m_reader_.
seek(frame_end);
229 if (m_verbose_parse_)
230 ldmx_log(debug) <<
"adding fragment subsys="
231 << fragment.header_.subsystem_id_
232 <<
" ts=" << fragment.header_.timestamp_
233 <<
" bytes=" << fragment.payload_.size();
238 long long fragment_ts = fragment.header_.timestamp_;
239 long long buffer_ref_time = m_event_buffer_.getReferenceTime();
241 if (buffer_ref_time > 0 &&
242 (fragment_ts < buffer_ref_time - m_coherence_window_ns_ ||
243 fragment_ts > buffer_ref_time + m_coherence_window_ns_)) {
246 std::vector<DataFragment> assembled_event_fragments;
247 if (m_event_buffer_.tryBuildEvent(m_coherence_window_ns_,
249 assembled_event_fragments) &&
250 !assembled_event_fragments.empty()) {
254 uint64_t event_timestamp = 0;
255 for (
const auto& frag : assembled_event_fragments) {
257 static_cast<uint8_t
>(frag.header_.subsystem_id_),
258 static_cast<uint8_t
>(frag.header_.contributor_id_));
259 std::vector<uint8_t> payload_bytes(frag.payload_.begin(),
260 frag.payload_.end());
261 event.add(subsys_name, payload_bytes);
262 if (event_timestamp == 0) {
263 event_timestamp = frag.header_.timestamp_;
266 event.getEventHeader().setIntParameter(
267 "RoR Timestamp",
static_cast<long long>(event_timestamp));
268 event.getEventHeader().setRealData();
271 assemblePayload(assembled_event_fragments);
273 ldmx_log(info) <<
"assembled event id=" << m_event_id_
274 <<
" timestamp=" << final_event.timestamp_
275 <<
" fragments=" << assembled_event_fragments.size()
276 <<
" systems=" << final_event.systems_readout_.size();
280 summary.
setTimestampNs(
static_cast<uint64_t
>(final_event.timestamp_));
281 std::set<uint64_t> unique_sys, unique_sources;
282 uint64_t total_payload = 0;
283 for (
const auto& f : assembled_event_fragments) {
284 unique_sys.insert(f.header_.subsystem_id_);
287 unique_sources.insert(f.header_.subsystem_id_ << 8 |
288 f.header_.contributor_id_);
289 total_payload += f.payload_.size();
292 if (unique_sources.size() != assembled_event_fragments.size()) {
295 summary.
setNSystems(
static_cast<uint32_t
>(unique_sys.size()));
297 std::vector<uint64_t>(unique_sys.begin(), unique_sys.end()));
300 event.add(
"EventSummary", summary);
303 m_total_bytes_read_ += total_payload;
304 m_total_events_built_++;
305 m_events_since_last_report_++;
306 std::chrono::steady_clock::time_point now =
307 std::chrono::steady_clock::now();
308 std::chrono::milliseconds event_build_time_ms =
309 std::chrono::duration_cast<std::chrono::milliseconds>(
310 now - m_event_start_time_);
311 std::chrono::seconds total_elapsed_s =
312 std::chrono::duration_cast<std::chrono::seconds>(now -
315 double events_per_sec =
316 (total_elapsed_s.count() > 0)
317 ?
static_cast<double>(m_total_events_built_) /
318 total_elapsed_s.count()
320 double mb_per_sec = (total_elapsed_s.count() > 0)
321 ?
static_cast<double>(m_total_bytes_read_) /
323 total_elapsed_s.count()
327 m_window_events_count_++;
328 m_window_bytes_read_ += total_payload;
329 std::chrono::seconds window_elapsed_s =
330 std::chrono::duration_cast<std::chrono::seconds>(
331 now - m_window_start_time_);
334 double window_events_per_sec = 0.0;
335 double window_mb_per_sec = 0.0;
336 if (m_window_events_count_ >= WINDOW_SIZE) {
337 double window_time_sec =
338 std::max(1.0,
static_cast<double>(window_elapsed_s.count()));
339 window_events_per_sec =
340 static_cast<double>(m_window_events_count_) / window_time_sec;
341 window_mb_per_sec =
static_cast<double>(m_window_bytes_read_) /
342 (1024.0 * 1024.0) / window_time_sec;
345 m_window_start_time_ = now;
346 m_window_events_count_ = 0;
347 m_window_bytes_read_ = 0;
351 long long event_build_time_ms_val = event_build_time_ms.count();
353 static_cast<double>(event_build_time_ms_val),
354 events_per_sec, mb_per_sec,
355 window_events_per_sec, window_mb_per_sec,
356 m_total_events_built_, m_total_bytes_read_);
358 if (m_verbose_parse_ || m_events_since_last_report_ % 100 == 0) {
359 ldmx_log(info) <<
"Performance: "
360 <<
"total_events=" << m_total_events_built_ <<
", "
361 <<
"events_per_sec=" << std::fixed
362 << std::setprecision(2) << events_per_sec <<
", "
363 <<
"mb_per_sec=" << std::fixed << std::setprecision(3)
367 current_event_errors = 0;
373 m_event_buffer_.addFragment(std::move(fragment));
379 m_event_buffer_.addFragment(std::move(fragment));
381 if (m_verbose_parse_)
382 ldmx_log(debug) <<
"frame added to buffer, searching for more frames...";
386 if (m_verbose_parse_)
387 ldmx_log(debug) <<
"reached EOF, flushing remaining events";
389 std::vector<DataFragment> assembled_event_fragments;
390 while (m_event_buffer_.tryBuildEvent(
391 m_coherence_window_ns_, m_min_subsystems_, assembled_event_fragments)) {
392 if (assembled_event_fragments.empty())
break;
399 uint64_t event_timestamp = 0;
400 for (
const auto& frag : assembled_event_fragments) {
402 static_cast<uint8_t
>(frag.header_.subsystem_id_),
403 static_cast<uint8_t
>(frag.header_.contributor_id_));
404 std::vector<uint8_t> payload_bytes(frag.payload_.begin(),
405 frag.payload_.end());
406 event.add(subsys_name, payload_bytes);
407 if (event_timestamp == 0) {
408 event_timestamp = frag.header_.timestamp_;
411 event.getEventHeader().setIntParameter(
412 "RoR Timestamp",
static_cast<long long>(event_timestamp));
413 event.getEventHeader().setRealData();
417 ldmx_log(info) <<
"assembled event id=" << m_event_id_
418 <<
" timestamp=" << final_event.timestamp_
419 <<
" fragments=" << assembled_event_fragments.size()
420 <<
" systems=" << final_event.systems_readout_.size();
424 summary.
setTimestampNs(
static_cast<uint64_t
>(final_event.timestamp_));
425 std::set<uint64_t> unique_sys, unique_sources;
426 uint64_t total_payload = 0;
427 for (
const auto& f : assembled_event_fragments) {
428 unique_sys.insert(f.header_.subsystem_id_);
431 unique_sources.insert(f.header_.subsystem_id_ << 8 |
432 f.header_.contributor_id_);
433 total_payload += f.payload_.size();
436 if (unique_sources.size() != assembled_event_fragments.size()) {
439 summary.
setNSystems(
static_cast<uint32_t
>(unique_sys.size()));
441 std::vector<uint64_t>(unique_sys.begin(), unique_sys.end()));
444 event.add(
"EventSummary", summary);
447 m_total_bytes_read_ += total_payload;
448 m_total_events_built_++;
449 m_events_since_last_report_++;
450 std::chrono::steady_clock::time_point now =
451 std::chrono::steady_clock::now();
452 std::chrono::milliseconds event_build_time_ms =
453 std::chrono::duration_cast<std::chrono::milliseconds>(
454 now - m_event_start_time_);
455 std::chrono::seconds total_elapsed_s =
456 std::chrono::duration_cast<std::chrono::seconds>(now - m_start_time_);
458 double events_per_sec = (total_elapsed_s.count() > 0)
459 ?
static_cast<double>(m_total_events_built_) /
460 total_elapsed_s.count()
462 double mb_per_sec = (total_elapsed_s.count() > 0)
463 ?
static_cast<double>(m_total_bytes_read_) /
464 (1024.0 * 1024.0) / total_elapsed_s.count()
468 m_window_events_count_++;
469 m_window_bytes_read_ += total_payload;
470 std::chrono::seconds window_elapsed_s =
471 std::chrono::duration_cast<std::chrono::seconds>(now -
472 m_window_start_time_);
475 double window_events_per_sec = 0.0;
476 double window_mb_per_sec = 0.0;
477 if (m_window_events_count_ >= WINDOW_SIZE || window_elapsed_s.count() > 0) {
478 double window_time_sec =
479 std::max(1.0,
static_cast<double>(window_elapsed_s.count()));
480 window_events_per_sec =
481 static_cast<double>(m_window_events_count_) / window_time_sec;
482 window_mb_per_sec =
static_cast<double>(m_window_bytes_read_) /
483 (1024.0 * 1024.0) / window_time_sec;
487 long long event_build_time_ms_val = event_build_time_ms.count();
489 static_cast<double>(event_build_time_ms_val),
490 events_per_sec, mb_per_sec, window_events_per_sec,
491 window_mb_per_sec, m_total_events_built_,
492 m_total_bytes_read_);
494 if (m_verbose_parse_ || m_events_since_last_report_ % 100 == 0) {
495 ldmx_log(info) <<
"Performance: "
496 <<
"total_events=" << m_total_events_built_ <<
", "
497 <<
"events_per_sec=" << std::fixed << std::setprecision(2)
498 << events_per_sec <<
", "
499 <<
"mb_per_sec=" << std::fixed << std::setprecision(3)
503 current_event_errors = 0;
505 assembled_event_fragments.clear();
510 std::chrono::steady_clock::time_point final_time =
511 std::chrono::steady_clock::now();
512 std::chrono::seconds total_time_s =
513 std::chrono::duration_cast<std::chrono::seconds>(final_time -
515 double final_events_per_sec =
516 (total_time_s.count() > 0)
517 ?
static_cast<double>(m_total_events_built_) / total_time_s.count()
519 double final_mb_per_sec = (total_time_s.count() > 0)
520 ?
static_cast<double>(m_total_bytes_read_) /
521 (1024.0 * 1024.0) / total_time_s.count()
524 ldmx_log(info) <<
"\n===== FINAL STATISTICS =====";
525 ldmx_log(info) <<
"Total events built: " << m_total_events_built_;
526 ldmx_log(info) <<
"Total bytes read: "
527 << m_total_bytes_read_ / (1024.0 * 1024.0) <<
" MB";
528 ldmx_log(info) <<
"Total time: " << total_time_s.count() <<
" seconds";
529 ldmx_log(info) <<
"Average throughput: "
530 <<
"events_per_sec=" << std::fixed << std::setprecision(2)
531 << final_events_per_sec <<
", "
532 <<
"mb_per_sec=" << std::fixed << std::setprecision(3)
534 ldmx_log(info) <<
"=============================\n";
535 ldmx_log(info) <<
"Event building complete";