Added FnTimer class for measuring function eval performance

CombineHarvester/CombineTools/interface/Logging.h

@@ -2,13 +2,16 @@
 #define CombineTools_Logging_h
 #include <string>
 #include <iostream>
+#include <chrono>
 
 namespace ch {
 
 #define FNERROR(x) FnError(x, __FILE__, __LINE__, __PRETTY_FUNCTION__)
 
 #define LOGLINE(x, y) LogLine(x, __func__, y)
 
+#define FNLOG(x) x << "[" << __func__ << "]"
+#define FNLOGC(x, y) if (y) x << "[" << __func__ << "] "
 /**
  * \brief Writes a logging message to a given ostream
  * \details Should be used with the macro LOGLINE which will call this function
@@ -33,7 +36,6 @@ void LogLine(std::ostream& stream, std::string const& func,
  */
 std::string FnError(std::string const& message, std::string const& file,
                     unsigned line, std::string const& fn);
-}
 
 /**
  * \brief Extracts the fully-qualified function name from a complete function
@@ -49,4 +51,60 @@ std::string FnError(std::string const& message, std::string const& file,
  */
 std::string GetQualififedName(std::string const& str);
 
+/**
+ * Conveniently initialise a ch::FnTimer instance
+ *
+ * This macro should be placed at the start of a function, e.g.:
+ *
+ *     void MyFunction() {
+ *      LAUNCH_FUNCTION_TIMER(__timer__, __token__)
+ *     }
+ *
+ * The arguments are the names of two objects (a ch::FnTimer and a
+ * ch::FnTimer::Token) that will be created by this macro. Note that the
+ * ch::FnTimer will be assigned the current function name automatically.
+ */
+#define LAUNCH_FUNCTION_TIMER(x, y)                             \
+  static FnTimer x(ch::GetQualififedName(__PRETTY_FUNCTION__)); \
+  auto y = x.Inc();
+
+/**
+ * Determine the total amount of time spent in a function
+ *
+ * An FnTimer instance should typically be declared as a static variable at
+ * the beginning of a function, follwed by a call to the Inc() method, which
+ * will increment the counter. The Inc() method also returns an FnTimer::Token
+ * object that records the time at which it is constructed and then destroyed,
+ * the latter occurring automatically at the end of the function. At the end
+ * of the program the FnTimer destructor will write a message to the screen
+ * summarising the number of calls and the time information.
+ *
+ *  \note A simple way of using this class is via the LAUNCH_FUNCTION_TIMER(x,y)
+ *  macro
+ */
+class FnTimer {
+ public:
+  class Token {
+    public:
+      explicit Token(FnTimer *src);
+      ~Token();
+    private:
+      FnTimer *src_;
+  };
+
+  explicit FnTimer(std::string name);
+  ~FnTimer();
+  Token Inc();
+  void StartTimer();
+  void StopTimer();
+
+ private:
+  std::string name_;
+  unsigned calls_;
+  std::chrono::time_point<std::chrono::system_clock> start_;
+  std::chrono::time_point<std::chrono::system_clock> end_;
+  double elapsed_;
+};
+}
+
 #endif

CombineHarvester/CombineTools/src/Logging.cc

@@ -44,4 +44,23 @@ std::string FnError(std::string const& message, std::string const& file,
   res += "\n" + banner;
   return res;
 }
+
+// Implementation of FnTimer ("Function Timer") class
+FnTimer::FnTimer(std::string name) : name_(name), calls_(0), elapsed_(0.) {}
+FnTimer::~FnTimer() {
+  printf(
+      "[Timer] %-40s Calls: %-20u Total [s]: %-20.5g Per-call [s]: %-20.5g\n",
+      name_.c_str(), calls_, elapsed_, elapsed_ / double(calls_));
+}
+FnTimer::Token FnTimer::Inc() {
+  ++calls_;
+  return Token(this);
+}
+void FnTimer::StartTimer() { start_ = std::chrono::system_clock::now(); }
+void FnTimer::StopTimer() {
+  end_ = std::chrono::system_clock::now();
+  elapsed_ += std::chrono::duration<double>(end_ - start_).count();
+}
+FnTimer::Token::Token(FnTimer* src) : src_(src) { src_->StartTimer(); }
+FnTimer::Token::~Token() { src_->StopTimer(); }
 }