Fix logFormat
[folly.git] / 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   }
64
65   // Automatically generate a log message using to<std::string>. Makes it
66   // easier to do the common case of things like:
67   // AutoTimer t("Processed ", n, " items");
68   template<typename... Args>
69   explicit AutoTimer(Args&&... args)
70     : destructionMessage_(to<std::string>(std::forward<Args>(args)...)),
71       start_(Clock::now()) {
72   }
73
74   // It doesn't really make sense to copy/move an AutoTimer
75   AutoTimer(const AutoTimer&) = delete;
76   AutoTimer(AutoTimer&&) = delete;
77   AutoTimer& operator=(const AutoTimer&) = delete;
78   AutoTimer& operator=(AutoTimer&&) = delete;
79
80   ~AutoTimer() {
81     log(destructionMessage_);
82   }
83
84   double log(StringPiece msg = "") {
85     return logImpl(Clock::now(), msg);
86   }
87
88   template<typename... Args>
89   double log(Args&&... args) {
90     auto now = Clock::now();
91     return logImpl(now, to<std::string>(std::forward<Args>(args)...));
92   }
93
94   template<typename... Args>
95   double logFormat(Args&&... args) {
96     auto now = Clock::now();
97     return logImpl(now, format(std::forward<Args>(args)...).str());
98   }
99
100 private:
101   // We take in the current time so that we don't measure time to call
102   // to<std::string> or format() in the duration.
103   double logImpl(std::chrono::time_point<Clock> now, StringPiece msg) {
104     double duration = std::chrono::duration_cast<std::chrono::duration<double>>(
105       now - start_
106     ).count();
107     Logger()(msg, duration);
108     start_ = Clock::now(); // Don't measure logging time
109     return duration;
110   }
111
112   const std::string destructionMessage_;
113   std::chrono::time_point<Clock> start_;
114 };
115
116 template<GoogleLoggerStyle Style>
117 struct GoogleLogger {
118   void operator()(StringPiece msg, double sec) const {
119     if (msg.empty()) {
120       return;
121     }
122     if (Style == GoogleLoggerStyle::PRETTY) {
123       LOG(INFO) << msg << " in " << prettyPrint(sec, PrettyType::PRETTY_TIME);
124     } else {
125       LOG(INFO) << msg << " in " << sec << " seconds";
126     }
127   }
128 };
129
130
131 }