folly/experimental/AutoTimer.h

   1 /*
   2  * Copyright 2015 Facebook, Inc.
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *   http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16 #pragma once
  17
  18 #include <chrono>
  19 #include <folly/Conv.h>
  20 #include <folly/Format.h>
  21 #include <folly/String.h>
  22 #include <glog/logging.h>
  23 #include <string>
  24
  25 namespace folly {
  26
  27 // Default logger
  28 enum class GoogleLoggerStyle { SECONDS, PRETTY };
  29 template<GoogleLoggerStyle> struct GoogleLogger;
  30
  31 /**
  32  * Automatically times a block of code, printing a specified log message on
  33  * destruction or whenever the log() method is called. For example:
  34  *
  35  *   AutoTimer t("Foo() completed");
  36  *   doWork();
  37  *   t.log("Do work finished");
  38  *   doMoreWork();
  39  *
  40  * This would print something like:
  41  *   "Do work finished in 1.2 seconds"
  42  *   "Foo() completed in 4.3 seconds"
  43  *
  44  * You can customize what you use as the logger and clock. The logger needs
  45  * to have an operator()(StringPiece, double) that gets a message and a duration
  46  * (in seconds). The clock needs to model Clock from std::chrono.
  47  *
  48  * The default logger logs usings glog. It only logs if the message is
  49  * non-empty, so you can also just use this class for timing, e.g.:
  50  *
  51  *   AutoTimer t;
  52  *   doWork()
  53  *   const auto how_long = t.log();
  54  */
  55 template<
  56   class Logger = GoogleLogger<GoogleLoggerStyle::PRETTY>,
  57   class Clock = std::chrono::high_resolution_clock
  58 > class AutoTimer final {
  59 public:
  60   explicit AutoTimer(StringPiece msg = "")
  61     : destructionMessage_(msg.str()),
  62       start_(Clock::now()),
  63       minTimeToLog_(0.0) {
  64   }
  65
  66   // Automatically generate a log message using to<std::string>. Makes it
  67   // easier to do the common case of things like:
  68   // AutoTimer t("Processed ", n, " items");
  69   template<typename... Args>
  70   explicit AutoTimer(Args&&... args)
  71     : destructionMessage_(to<std::string>(std::forward<Args>(args)...)),
  72       start_(Clock::now()),
  73       minTimeToLog_(0.0) {
  74   }
  75
  76   // We don't expose this in the constructor because it creates ambiguity with
  77   // the variadic template constructor.
  78   void setMinTimeToLog(double t) {
  79     minTimeToLog_ = t;
  80   }
  81
  82   // It doesn't really make sense to copy/move an AutoTimer
  83   AutoTimer(const AutoTimer&) = delete;
  84   AutoTimer(AutoTimer&&) = delete;
  85   AutoTimer& operator=(const AutoTimer&) = delete;
  86   AutoTimer& operator=(AutoTimer&&) = delete;
  87
  88   ~AutoTimer() {
  89     log(destructionMessage_);
  90   }
  91
  92   double log(StringPiece msg = "") {
  93     return logImpl(Clock::now(), msg);
  94   }
  95
  96   template<typename... Args>
  97   double log(Args&&... args) {
  98     auto now = Clock::now();
  99     return logImpl(now, to<std::string>(std::forward<Args>(args)...));
 100   }
 101
 102   template<typename... Args>
 103   double logFormat(Args&&... args) {
 104     auto now = Clock::now();
 105     return logImpl(now, format(std::forward<Args>(args)...).str());
 106   }
 107
 108 private:
 109   // We take in the current time so that we don't measure time to call
 110   // to<std::string> or format() in the duration.
 111   double logImpl(std::chrono::time_point<Clock> now, StringPiece msg) {
 112     double duration = std::chrono::duration_cast<std::chrono::duration<double>>(
 113       now - start_
 114     ).count();
 115     if (duration >= minTimeToLog_) {
 116       Logger()(msg, duration);
 117     }
 118     start_ = Clock::now(); // Don't measure logging time
 119     return duration;
 120   }
 121
 122   const std::string destructionMessage_;
 123   std::chrono::time_point<Clock> start_;
 124   double minTimeToLog_;
 125 };
 126
 127 template<GoogleLoggerStyle Style>
 128 struct GoogleLogger final {
 129   void operator()(StringPiece msg, double sec) const {
 130     if (msg.empty()) {
 131       return;
 132     }
 133     if (Style == GoogleLoggerStyle::PRETTY) {
 134       LOG(INFO) << msg << " in " << prettyPrint(sec, PrettyType::PRETTY_TIME);
 135     } else {
 136       LOG(INFO) << msg << " in " << sec << " seconds";
 137     }
 138   }
 139 };
 140
 141
 142 }