Support 'min ms to log'

Summary:
Sometimes we only want to log if enough time has passed, e.g. when logging
inside of a loop doing work to detect if things are slow. Add an option for
that.

Test Plan:
build and unit tests of folly/experimental

Reviewed By: lesha@fb.com

Subscribers: trunkagent, folly-diffs@, yfeldblum

FB internal diff: D1909055

Signature: t1:1909055:1426627731:6d3ad94fd71967ec89ffebc90cd2907dd1631d36

diff --git a/folly/experimental/AutoTimer.h b/folly/experimental/AutoTimer.h
index fb2b033b56dcab53f865f28e8a23465b7aee5bf6..a3a057f1e9f2f9ddfa61273eedc20d787253449b 100644 (file)
--- a/folly/experimental/AutoTimer.h
+++ b/folly/experimental/AutoTimer.h
@@ -59,7 +59,8 @@ template<
 public:
   explicit AutoTimer(StringPiece msg = "")
     : destructionMessage_(msg.str()),
-      start_(Clock::now()) {
+      start_(Clock::now()),
+      minTimeToLog_(0.0) {
   }
 
   // Automatically generate a log message using to<std::string>. Makes it
@@ -68,7 +69,14 @@ public:
   template<typename... Args>
   explicit AutoTimer(Args&&... args)
     : destructionMessage_(to<std::string>(std::forward<Args>(args)...)),
-      start_(Clock::now()) {
+      start_(Clock::now()),
+      minTimeToLog_(0.0) {
+  }
+
+  // We don't expose this in the constructor because it creates ambiguity with
+  // the variadic template constructor.
+  void setMinTimeToLog(double t) {
+    minTimeToLog_ = t;
   }
 
   // It doesn't really make sense to copy/move an AutoTimer
@@ -104,17 +112,20 @@ private:
     double duration = std::chrono::duration_cast<std::chrono::duration<double>>(
       now - start_
     ).count();
-    Logger()(msg, duration);
+    if (duration >= minTimeToLog_) {
+      Logger()(msg, duration);
+    }
     start_ = Clock::now(); // Don't measure logging time
     return duration;
   }
 
   const std::string destructionMessage_;
   std::chrono::time_point<Clock> start_;
+  double minTimeToLog_;
 };
 
 template<GoogleLoggerStyle Style>
-struct GoogleLogger {
+struct GoogleLogger final {
   void operator()(StringPiece msg, double sec) const {
     if (msg.empty()) {
       return;

diff --git a/folly/experimental/test/AutoTimerTest.cpp b/folly/experimental/test/AutoTimerTest.cpp
index b5b0b2a3727b854defa154de79e0c951faba49b8..2c54a04aab9059d2712ec145675893f33a495690 100644 (file)
--- a/folly/experimental/test/AutoTimerTest.cpp
+++ b/folly/experimental/test/AutoTimerTest.cpp
@@ -74,3 +74,14 @@ TEST(TestAutoTimer, HandleRealTimer) {
   t.log("First message");
   t.log("Second message");
 }
+
+TEST(TestAutoTimer, HandleMinLogTime) {
+  StubClock::t = 1;
+  AutoTimer<StubLogger, StubClock> timer;
+  timer.setMinTimeToLog(3);
+  StubClock::t = 3;
+  // only 2 "seconds" have passed, so this shouldn't log
+  StubLogger::t = 0;
+  ASSERT_EQ(2.0, timer.log("foo"));
+  ASSERT_EQ(0, StubLogger::t);
+}