Add AutoTimer to folly

Summary:
This 'moves' bistro::AutoTimer into folly. I actually changed it a bit, so I'm
not migrating any existing uses in this diff, but I can do that as a followup.
We're using it in various places now, so it doesn't make sense to have it in
bistro.

Basically this class lets you conveniently time a series of things while
printing log messages, e.g.:
{
AutoTimer t("Done");
processA();
t.log("processA() complete");
}

would print
"processA() complete in XXX seconds"
"Done in YYY seconds"

I changed some things from bistro::AutoTimer:
- Use std::chrono::time_point<Clock> to store the start time.
- I removed the gflags. It seems weird to rely on those to control the timer,
since they would affect all uses of this. If a specific user of the timer
wants to actually control timing at runtime, I think it's better to use a
custom logger.
- I removed the 'min log duration'. As implemented it actually made the
constructor conflict: AutoTimer("foo", 1.2) is ambiguous. Also, it should
probably be set on the logger, so this likewise feels like a place where you
could make a custom logger.

I'm not sure that the way I use the default logger as a template argument is
best, so please suggest improvements to that.

Test Plan: unit test

Reviewed By: lesha@fb.com

Subscribers: trunkagent, folly-diffs@, yfeldblum

FB internal diff: D1860794

Signature: t1:1860794:1424458219:a2dd0d428aedf063a888b2937b1443c7142554e8

folly/Makefile.am

@@ -68,6 +68,7 @@ nobase_follyinclude_HEADERS = \
 	ExceptionWrapper.h \
 	Executor.h \
 	EvictingCacheMap.h \
+	experimental/AutoTimer.h \
 	experimental/Bits.h \
 	experimental/EliasFanoCoding.h \
 	experimental/EventCount.h \

folly/experimental/AutoTimer.h

+/*
+ * Copyright 2015 Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#pragma once
+
+#include <chrono>
+#include <folly/Conv.h>
+#include <folly/Format.h>
+#include <folly/String.h>
+#include <glog/logging.h>
+#include <string>
+
+namespace folly {
+
+// Default logger
+enum class GoogleLoggerStyle { SECONDS, PRETTY };
+template<GoogleLoggerStyle> struct GoogleLogger;
+
+/**
+ * Automatically times a block of code, printing a specified log message on
+ * destruction or whenever the log() method is called. For example:
+ *
+ *   AutoTimer t("Foo() completed");
+ *   doWork();
+ *   t.log("Do work finished");
+ *   doMoreWork();
+ *
+ * This would print something like:
+ *   "Do work finished in 1.2 seconds"
+ *   "Foo() completed in 4.3 seconds"
+ *
+ * You can customize what you use as the logger and clock. The logger needs
+ * to have an operator()(StringPiece, double) that gets a message and a duration
+ * (in seconds). The clock needs to model Clock from std::chrono.
+ *
+ * The default logger logs usings glog. It only logs if the message is
+ * non-empty, so you can also just use this class for timing, e.g.:
+ *
+ *   AutoTimer t;
+ *   doWork()
+ *   const auto how_long = t.log();
+ */
+template<
+  class Logger = GoogleLogger<GoogleLoggerStyle::PRETTY>,
+  class Clock = std::chrono::high_resolution_clock
+> class AutoTimer final {
+public:
+  explicit AutoTimer(StringPiece msg = "")
+    : destructionMessage_(msg.str()),
+      start_(Clock::now()) {
+  }
+
+  // Automatically generate a log message using to<std::string>. Makes it
+  // easier to do the common case of things like:
+  // AutoTimer t("Processed ", n, " items");
+  template<typename... Args>
+  explicit AutoTimer(Args&&... args)
+    : destructionMessage_(to<std::string>(std::forward<Args>(args)...)),
+      start_(Clock::now()) {
+  }
+
+  // It doesn't really make sense to copy/move an AutoTimer
+  AutoTimer(const AutoTimer&) = delete;
+  AutoTimer(AutoTimer&&) = delete;
+  AutoTimer& operator=(const AutoTimer&) = delete;
+  AutoTimer& operator=(AutoTimer&&) = delete;
+
+  ~AutoTimer() {
+    log(destructionMessage_);
+  }
+
+  double log(StringPiece msg = "") {
+    return logImpl(Clock::now(), msg);
+  }
+
+  template<typename... Args>
+  double log(Args&&... args) {
+    auto now = Clock::now();
+    return logImpl(now, to<std::string>(std::forward<Args>(args)...));
+  }
+
+  template<typename... Args>
+  double logFormat(Args&&... args) {
+    auto now = Clock::now();
+    return logImpl(now, format(std::forward<Args>(args)...));
+  }
+
+private:
+  // We take in the current time so that we don't measure time to call
+  // to<std::string> or format() in the duration.
+  double logImpl(std::chrono::time_point<Clock> now, StringPiece msg) {
+    double duration = std::chrono::duration_cast<std::chrono::duration<double>>(
+      now - start_
+    ).count();
+    Logger()(msg, duration);
+    start_ = Clock::now(); // Don't measure logging time
+    return duration;
+  }
+
+  const std::string destructionMessage_;
+  std::chrono::time_point<Clock> start_;
+};
+
+template<GoogleLoggerStyle Style>
+struct GoogleLogger {
+  void operator()(StringPiece msg, double sec) const {
+    if (msg.empty()) {
+      return;
+    }
+    if (Style == GoogleLoggerStyle::PRETTY) {
+      LOG(INFO) << msg << " in " << prettyPrint(sec, PrettyType::PRETTY_TIME);
+    } else {
+      LOG(INFO) << msg << " in " << sec << " seconds";
+    }
+  }
+};
+
+
+}

folly/experimental/test/AutoTimerTest.cpp

+/*
+ * Copyright 2015 Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+#include <gtest/gtest.h>
+
+#include <folly/experimental/AutoTimer.h>
+
+using namespace folly;
+using namespace std;
+
+struct StubLogger {
+  void operator()(StringPiece msg, double sec) {
+    m = msg;
+    t = sec;
+  }
+  static StringPiece m;
+  static double t;
+};
+
+StringPiece StubLogger::m = "";
+double StubLogger::t = 0;
+
+struct StubClock {
+  typedef std::chrono::seconds duration;
+
+  static std::chrono::time_point<StubClock> now() {
+    return std::chrono::time_point<StubClock>(std::chrono::duration<int>(t));
+  }
+  static int t;
+};
+
+int StubClock::t = 0;
+
+TEST(TestAutoTimer, HandleBasic) {
+  StubClock::t = 1;
+  AutoTimer<StubLogger, StubClock> timer;
+  StubClock::t = 3;
+  timer.log("foo");
+  ASSERT_EQ("foo", StubLogger::m);
+  ASSERT_EQ(2, StubLogger::t);
+}
+
+TEST(TestAutoTimer, HandleLogOnDestruct) {
+  {
+    StubClock::t = 0;
+    AutoTimer<StubLogger, StubClock> timer("message");
+    StubClock::t = 3;
+    timer.log("foo");
+    EXPECT_EQ("foo", StubLogger::m);
+    EXPECT_EQ(3, StubLogger::t);
+    StubClock::t = 5;
+  }
+  ASSERT_EQ("message", StubLogger::m);
+  ASSERT_EQ(2, StubLogger::t);
+}
+
+TEST(TestAutoTimer, HandleRealTimer) {
+  AutoTimer<> t("Third message on destruction");
+  t.log("First message");
+  t.log("Second message");
+}