Process the event and put new data products into it.
113 {
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;
120 }
121
122
123 m_event_start_time_ = std::chrono::steady_clock::now();
124
125
126 uint32_t current_event_errors = 0;
127
128 while (m_reader_ && !m_reader_.
eof()) {
129
131 frame_header.
read(m_reader_);
132
133
134 const long long frame_end =
135 static_cast<long long>(m_reader_.
tell()) + frame_header.
size();
136
137
139
140 if (m_verbose_parse_)
141 ldmx_log(debug) << "skipping non-data frame (channel="
142 << frame_header.
channel() <<
")";
143 m_reader_.
seek(frame_end);
144 continue;
145 }
146
147
149 bool parsed_ok = false;
150
151
153 int pos_before_ror = m_reader_.
tell();
154
155
156 try {
157 ror_header.
read(m_reader_);
158
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();
164
165 if (m_verbose_parse_) {
166 ldmx_log(debug) << "parsed RoR header subsys="
170 }
171
172
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()),
178 payload_size);
179 }
180 fragment.payload_ = std::move(payload_data);
181 parsed_ok = true;
182 } catch (...) {
183
184 if (m_verbose_parse_)
185 ldmx_log(debug)
186 << "RoR header parse failed, trying packing subsystem format";
188 m_reader_.
seek(pos_before_ror);
189 }
190
191 if (!parsed_ok) {
192
194 try {
196 fragment.header_.subsystem_id_ = static_cast<uint64_t>(pkt.id());
197 fragment.header_.contributor_id_ =
198 0;
199 fragment.header_.timestamp_ =
static_cast<uint64_t
>(pkt.
header()[1]) *
200 1000000000ULL;
201
202
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()),
207 data.size() * 4);
208
209 if (m_verbose_parse_) {
210 ldmx_log(debug) << "parsed packing subsystem pkt subsys=" << pkt.id()
211 << " data_size=" << data.size();
212 }
213 parsed_ok = true;
214 } catch (...) {
215
216 if (m_verbose_parse_)
217 ldmx_log(debug) << "failed to parse as either format, skipping frame";
219 m_reader_.
seek(frame_end);
220 continue;
221 }
222 }
223
224 if (!parsed_ok) {
225 m_reader_.
seek(frame_end);
226 continue;
227 }
228
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();
234
235
236
237
238 long long fragment_ts = fragment.header_.timestamp_;
239 long long buffer_ref_time = m_event_buffer_.getReferenceTime();
240
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_)) {
244
245
246 std::vector<DataFragment> assembled_event_fragments;
247 if (m_event_buffer_.tryBuildEvent(m_coherence_window_ns_,
248 m_min_subsystems_,
249 assembled_event_fragments) &&
250 !assembled_event_fragments.empty()) {
251
252 ++m_event_id_;
253
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_;
264 }
265 }
266 event.getEventHeader().setIntParameter(
267 "RoR Timestamp", static_cast<long long>(event_timestamp));
268 event.getEventHeader().setRealData();
269
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();
277
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_);
285
286
287 unique_sources.insert(f.header_.subsystem_id_ << 8 |
288 f.header_.contributor_id_);
289 total_payload += f.payload_.size();
290 }
291
292 if (unique_sources.size() != assembled_event_fragments.size()) {
294 }
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);
301
302
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 -
313 m_start_time_);
314
315 double events_per_sec =
316 (total_elapsed_s.count() > 0)
317 ? static_cast<double>(m_total_events_built_) /
318 total_elapsed_s.count()
319 : 0.0;
320 double mb_per_sec = (total_elapsed_s.count() > 0)
321 ? static_cast<double>(m_total_bytes_read_) /
322 (1024.0 * 1024.0) /
323 total_elapsed_s.count()
324 : 0.0;
325
326
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_);
332
333
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;
343
344
345 m_window_start_time_ = now;
346 m_window_events_count_ = 0;
347 m_window_bytes_read_ = 0;
348 }
349
350
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_);
357
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)
364 << mb_per_sec;
365 }
366
367 current_event_errors = 0;
368
369
370
371
372
373 m_event_buffer_.addFragment(std::move(fragment));
374 return;
375 }
376 }
377
378
379 m_event_buffer_.addFragment(std::move(fragment));
380
381 if (m_verbose_parse_)
382 ldmx_log(debug) << "frame added to buffer, searching for more frames...";
383 }
384
385
386 if (m_verbose_parse_)
387 ldmx_log(debug) << "reached EOF, flushing remaining events";
388
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;
393
394
396
397 ++m_event_id_;
398
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_;
409 }
410 }
411 event.getEventHeader().setIntParameter(
412 "RoR Timestamp", static_cast<long long>(event_timestamp));
413 event.getEventHeader().setRealData();
414
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();
421
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_);
429
430
431 unique_sources.insert(f.header_.subsystem_id_ << 8 |
432 f.header_.contributor_id_);
433 total_payload += f.payload_.size();
434 }
435
436 if (unique_sources.size() != assembled_event_fragments.size()) {
438 }
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);
445
446
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_);
457
458 double events_per_sec = (total_elapsed_s.count() > 0)
459 ? static_cast<double>(m_total_events_built_) /
460 total_elapsed_s.count()
461 : 0.0;
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()
465 : 0.0;
466
467
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_);
473
474
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;
484 }
485
486
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_);
493
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)
500 << mb_per_sec;
501 }
502
503 current_event_errors = 0;
504
505 assembled_event_fragments.clear();
506 return;
507 }
508
509
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 -
514 m_start_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()
518 : 0.0;
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()
522 : 0.0;
523
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)
533 << final_mb_per_sec;
534 ldmx_log(info) << "=============================\n";
535 ldmx_log(info) << "Event building complete";
536
538}
void abortEvent()
Abort the event immediately.
Provides summary information about an assembled event, including error flags for data quality assessm...
void setSystemIds(const std::vector< uint64_t > &ids)
Set the system IDs.
void setNSystems(uint32_t ns)
Set the number of systems in this event.
void setPayloadSize(uint64_t size)
Set the total payload size.
void setTimestampNs(uint64_t ts)
Set the timestamp in nanoseconds.
void setEventNumber(uint64_t num)
Set the event number.
void setErrorFlags(uint32_t flags)
Set the error flags.
@ ERROR_PARSE_FAILURE
Frame parsing error.
@ ERROR_DUPLICATE_SUBSYSTEM
Duplicate subsystem in single event.
@ ERROR_TRUNCATED_EVENT
Event was truncated (EOF reached)
SubsystemPacket structure.
std::vector< uint32_t > & data()
Get data.
utility::Reader & read(utility::Reader &r)
read the subsystem packet from the input reader
std::vector< uint32_t > header() const
get the header words
std::streampos tell()
Tell us where the reader is.
bool eof()
check if file is done
void seek(std::streampos off, std::ios_base::seekdir dir=std::ios::beg)
Go ("seek") a specific position in the file.
Reader & read(WordType *w, std::size_t count)
Read the next 'count' words into the input handle.