Add TimedWriter and TimedReader decorators for benchmarking

- Making use of some rather general utilities that simply wrap calls to
member functions inbetween two calls to clock::now() to calculate the
duration of the call.

include/podio/BenchmarkRecorder.h

@@ -0,0 +1,102 @@
+#ifndef PODIO_BENCHMARK_RECORDER_H__
+#define PODIO_BENCHMARK_RECORDER_H__
+
+#include "podio/BenchmarkUtil.h"
+
+#include "TTree.h"
+#include "TFile.h"
+
+#include <vector>
+#include <chrono>
+#include <string>
+#include <algorithm>
+#include <utility>
+#include <deque>
+
+namespace podio::benchmark {
+
+
+class BenchmarkRecorderTree {
+public:
+  BenchmarkRecorderTree() = delete;
+  // Avoid some possible issues that could arise from copying by simply
+  // disallowing it
+  BenchmarkRecorderTree(const BenchmarkRecorderTree&) = delete;
+
+  BenchmarkRecorderTree(TFile* recFile, const std::string& name, const std::vector<std::string>& steps) :
+    m_stepNames(steps), m_stepTimes(steps.size()) {
+    recFile->cd();
+    m_recordTree = new TTree(name.c_str(), "time recording tree");
+    m_recordTree->SetDirectory(recFile);
+
+    for (size_t i = 0; i < m_stepNames.size(); ++i) {
+      m_recordTree->Branch(m_stepNames[i].c_str(), &m_stepTimes[i]);
+    }
+  }
+
+  template<typename TimingResolution=std::chrono::nanoseconds>
+  void recordTime(const std::string& stepName, const ClockT::duration time) {
+    const auto it = std::find(m_stepNames.cbegin(), m_stepNames.cend(), stepName);
+    const auto index = std::distance(m_stepNames.cbegin(), it);
+    m_stepTimes[index] = std::chrono::duration_cast<TimingResolution>(time).count();
+  }
+
+  void Fill() {
+    m_recordTree->Fill();
+  }
+
+  void Write() {
+    m_recordTree->Write();
+  }
+
+private:
+  TTree* m_recordTree{nullptr};
+  std::vector<std::string> m_stepNames;
+  std::vector<double> m_stepTimes;
+};
+
+
+class BenchmarkRecorder {
+public:
+  BenchmarkRecorder() = delete;
+  BenchmarkRecorder(const std::string& recFileName="podio_benchmark_file.root") {
+    m_recordFile = new TFile(recFileName.c_str(), "recreate");
+  }
+
+  ~BenchmarkRecorder() {
+    for (auto& [name, tree] : m_recordTrees) {
+      tree.Write();
+    }
+    m_recordFile->Write("", TObject::kWriteDelete);
+    m_recordFile->Close();
+  }
+
+  template<typename TimingResolution=std::chrono::nanoseconds>
+  void recordTime(const std::string& treeName, const std::string& stepName, const ClockT::duration time) {
+    auto it = std::find_if(m_recordTrees.begin(), m_recordTrees.end(),
+                           [&treeName] (const auto& recTree) { return recTree.first == treeName; });
+
+    it->second.template recordTime<TimingResolution>(stepName, time);
+  }
+
+  void Fill(const std::string& treeName) {
+    auto it = std::find_if(m_recordTrees.begin(), m_recordTrees.end(),
+                           [&treeName] (const auto& recTree) { return recTree.first == treeName; });
+    it->second.Fill();
+  }
+
+  BenchmarkRecorderTree& addTree(const std::string& name, const std::vector<std::string>& steps) {
+    return m_recordTrees.emplace_back(std::piecewise_construct,
+                                      std::forward_as_tuple(name),
+                                      std::forward_as_tuple(m_recordFile, name, steps)).second;
+  }
+
+private:
+  TFile* m_recordFile{nullptr};
+  // Stable references outside!!
+  std::deque<std::pair<std::string, BenchmarkRecorderTree>> m_recordTrees;
+};
+
+}
+
+#endif

include/podio/BenchmarkUtil.h

@@ -0,0 +1,44 @@
+#ifndef PODIO_BENCHMARK_UTIL_H__
+#define PODIO_BENCHMARK_UTIL_H__
+
+#include <chrono>
+#include <functional>
+#include <utility>
+
+namespace podio::benchmark {
+ using ClockT = std::chrono::high_resolution_clock;
+
+/**
+ * Run a member function and record the duration. Return the result and the
+ * duration in a pair.
+ */
+template<class Obj, typename MemberFunc, typename ...Args>
+inline std::pair<std::invoke_result_t<MemberFunc, Obj, Args...>,
+                 ClockT::duration>
+run_member_timed(Obj& obj, MemberFunc func, Args&&... args) {
+  const auto start = ClockT::now();
+  const auto retval = std::invoke(func, obj, std::forward<Args>(args)...);
+  const auto end = ClockT::now();
+
+  return std::make_pair(retval, end - start);
+}
+
+/**
+ * Run a member function without return value and record the duration. Return
+ * the duration and only use the side-effects of the member function. Can't get
+ * this to work in the above version with a void return value, so that is why we
+ * have a dedicated function for void functions here.
+ */
+template<class Obj, typename MemberFunc, typename ...Args>
+inline ClockT::duration
+run_void_member_timed(Obj& obj, MemberFunc func, Args&&... args) {
+  const auto start = ClockT::now();
+  std::invoke(func, obj, std::forward<Args>(args)...);
+  const auto end = ClockT::now();
+
+  return end - start;
+}
+
+} // namespace podio::benchmark
+
+#endif

include/podio/TimedReader.h

@@ -0,0 +1,147 @@
+#ifndef PODIO_TIMEDREADER_H__
+#define PODIO_TIMEDREADER_H__
+
+#include "podio/BenchmarkUtil.h"
+#include "podio/BenchmarkRecorder.h"
+
+#include "podio/IReader.h"
+#include "podio/GenericParameters.h"
+
+#include <map>
+
+namespace podio {
+
+template<class WrappedReader>
+class TimedReader : public IReader {
+  using ClockT = benchmark::ClockT;
+
+public:
+  template<typename ...Args>
+  TimedReader(benchmark::BenchmarkRecorder& recorder, Args&&... args) :
+    m_start(ClockT::now()),
+    m_reader(WrappedReader(std::forward<Args>(args)...)),
+    m_end(ClockT::now()),
+    m_recorder(recorder),
+    m_perEventTree(m_recorder.addTree("event_times", {
+      "read_collections", "read_ev_md", "read_run_md", "read_coll_md",
+      "end_of_event"
+    }))
+  {
+    m_recorder.addTree("setup_times", {
+      "constructor", "open_file", "close_file", "read_collection_ids",
+      "get_entries"
+    });
+    m_recorder.recordTime("setup_times", "constructor", m_end - m_start);
+  }
+
+  virtual ~TimedReader() {
+    // Timing deconstructors is not straight forward when wrapping a value.
+    // Since nothing is usually happening in them in any case, we simply don't
+    // do it. We still have to fill the setup_times tree here though.
+    m_recorder.Fill("setup_times");
+  }
+
+  /// Read Collection of given name
+  /// Does not set references yet.
+  virtual CollectionBase* readCollection(const std::string& name) {
+    const auto [result, duration] = benchmark::run_member_timed(m_reader, &IReader::readCollection, name);
+    // since we cannot in general know how many collections there will be read
+    // we simply sum up all the requests in an event and record that
+    m_totalCollectionReadTime += duration;
+    return result;
+  }
+
+  /// Get CollectionIDTable of read-in data
+  virtual CollectionIDTable* getCollectionIDTable() {
+    return runTimed(false, "read_collection_ids", &IReader::getCollectionIDTable);
+  }
+
+  /// read event meta data from file
+  virtual GenericParameters* readEventMetaData() {
+    return runTimed(true, "read_ev_md", &IReader::readEventMetaData);
+  }
+
+  virtual std::map<int, GenericParameters>* readCollectionMetaData() {
+    return runTimed(true, "read_coll_md", &IReader::readCollectionMetaData);
+  }
+
+  virtual std::map<int, GenericParameters>* readRunMetaData() {
+    return runTimed(true, "read_run_md", &IReader::readRunMetaData);
+  }
+
+  /// get the number of events available from this reader
+  virtual unsigned getEntries() const {
+    return runTimed(false, "get_entries", &IReader::getEntries);
+  }
+
+  /// Prepare the reader to read the next event
+  virtual void endOfEvent() {
+    runVoidTimed(true, "end_of_event", &IReader::endOfEvent);
+
+    m_perEventTree.recordTime("read_collections", m_totalCollectionReadTime);
+    m_perEventTree.Fill();
+    m_totalCollectionReadTime = std::chrono::nanoseconds{0};
+  }
+
+  // not benchmarking this one
+  virtual bool isValid() const { return m_reader.isValid(); }
+
+  virtual void openFile(const std::string& filename) override {
+    runVoidTimed(false, "open_file", &IReader::openFile, filename);
+  }
+
+  virtual void closeFile() override {
+    runVoidTimed(false, "close_file", &IReader::closeFile);
+  }
+
+private:
+  void recordTime (bool perEvent, const std::string& step, ClockT::duration duration) const {
+    if (perEvent) {
+      m_perEventTree.recordTime(step, duration);
+    } else {
+      m_recorder.recordTime("setup_times", step, duration);
+    }
+  }
+
+  template<typename FuncT, typename ...Args>
+  inline std::invoke_result_t<FuncT, WrappedReader, Args...>
+  runTimed(bool perEvent, const std::string& step, FuncT func, Args&&... args) {
+    const auto [result, duration] = benchmark::run_member_timed(m_reader, func, std::forward<Args>(args)...);
+
+    recordTime(perEvent, step, duration);
+
+    return result;
+  }
+
+  template<typename FuncT, typename ...Args>
+  inline std::invoke_result_t<FuncT, WrappedReader, Args...>
+  runTimed(bool perEvent, const std::string& step, FuncT func, Args&&... args) const {
+    const auto [result, duration] = benchmark::run_member_timed(m_reader, func, std::forward<Args>(args)...);
+
+    recordTime(perEvent, step, duration);
+
+    return result;
+  }
+
+  template<typename FuncT, typename ...Args>
+  inline void runVoidTimed(bool perEvent, const std::string& step, FuncT func, Args&&... args) {
+    const auto duration = benchmark::run_void_member_timed(m_reader, func, std::forward<Args>(args)...);
+
+    recordTime(perEvent, step, duration);
+  }
+
+  // NOTE: c++ initializes its class members in the order they are defined not
+  // in the order in which they appear in the initializer list!
+  ClockT::time_point m_start; // to time the construction
+  WrappedReader m_reader; // the decorated reader that does the actual work
+  ClockT::time_point m_end; // to time the constructor call
+
+  benchmark::BenchmarkRecorder& m_recorder;
+  // Keep a reference to this one around, to save the look-up in each event
+  benchmark::BenchmarkRecorderTree& m_perEventTree;
+  ClockT::duration m_totalCollectionReadTime{std::chrono::nanoseconds{0}};
+};
+
+}
+
+#endif

include/podio/TimedWriter.h

@@ -0,0 +1,65 @@
+#ifndef PODIO_TIMEDWRITER_H__
+#define PODIO_TIMEDWRITER_H__
+
+#include "podio/BenchmarkUtil.h"
+#include "podio/BenchmarkRecorder.h"
+
+#include <string>
+#include <chrono>
+
+namespace podio {
+
+template<class WrappedWriter>
+class TimedWriter {
+  using ClockT = benchmark::ClockT;
+
+public:
+  template<typename ...Args>
+  TimedWriter(benchmark::BenchmarkRecorder& recorder, Args&&... args) :
+    m_start(ClockT::now()),
+    m_writer(WrappedWriter(std::forward<Args>(args)...)),
+    m_end(ClockT::now()),
+    m_recorder(recorder),
+    m_perEventTree(m_recorder.addTree("event_times", {"write_event"}))
+  {
+    m_recorder.addTree("setup_times", {"constructor", "finish", "register_for_write"});
+    m_recorder.recordTime("setup_times", "constructor", m_end - m_start);
+  }
+
+  ~TimedWriter()
+  {
+    m_recorder.recordTime("setup_times", "register_for_write", m_registerTime);
+    m_recorder.Fill("setup_times");
+  }
+
+  void registerForWrite(const std::string& name) {
+    // summing up the times it takes for all the collections to be registered
+    // here, since we do not know in advance how many collections there will be
+    // in the end
+    const auto duration = benchmark::run_void_member_timed(m_writer, &WrappedWriter::registerForWrite, name);
+    m_registerTime += duration;
+  }
+
+  void writeEvent() {
+    m_perEventTree.recordTime("write_event",
+                              benchmark::run_void_member_timed(m_writer, &WrappedWriter::writeEvent));
+    m_perEventTree.Fill();
+  }
+
+  void finish() {
+    m_recorder.recordTime("setup_times", "finish",
+                          benchmark::run_void_member_timed(m_writer, &WrappedWriter::finish));
+  }
+
+private:
+  ClockT::time_point m_start;
+  WrappedWriter m_writer;
+  ClockT::time_point m_end;
+  benchmark::BenchmarkRecorder& m_recorder;
+  benchmark::BenchmarkRecorderTree& m_perEventTree;
+  ClockT::duration m_registerTime{std::chrono::nanoseconds{0}};
+};
+
+}
+
+#endif

tests/CMakeLists.txt

@@ -25,7 +25,7 @@ function(CREATE_PODIO_TEST sourcefile additional_libs)
     )
 endfunction()
 
-set(root_dependent_tests write.cpp read.cpp read-multiple.cpp relation_range.cpp)
+set(root_dependent_tests write.cpp read.cpp read-multiple.cpp relation_range.cpp write_timed.cpp read_timed.cpp)
 set(root_libs TestDataModelDict podio::podioRootIO)
 foreach( sourcefile ${root_dependent_tests} )
   CREATE_PODIO_TEST(${sourcefile} "${root_libs}")
@@ -49,6 +49,7 @@ endif()
 #--- set some dependencies between the different tests to ensure input generating ones are run first
 set_property(TEST read PROPERTY DEPENDS write)
 set_property(TEST read-multiple PROPERTY DEPENDS write)
+set_property(TEST read_timed PROPERTY DEPENDS write_timed)
 if (TARGET read_sio)
   set_property(TEST read_sio PROPERTY DEPENDS write_sio)
 endif()

tests/read_timed.cpp

@@ -0,0 +1,16 @@
+#include "read_test.h"
+#include "podio/ROOTReader.h"
+#include "podio/TimedReader.h"
+#include "podio/BenchmarkRecorder.h"
+
+int main() {
+  podio::benchmark::BenchmarkRecorder recorder("benchmark_file.root");
+
+  podio::TimedReader<podio::ROOTReader> reader(recorder);
+  reader.openFile("example_timed.root");
+
+  run_read_test(reader);
+
+  reader.closeFile();
+  return 0;
+}