folly/experimental/test/AutoTimerTest.cpp

   1 /*
   2  * Copyright 2017 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
  17 #include <folly/experimental/AutoTimer.h>
  18
  19 #include <folly/portability/GTest.h>
  20
  21 using namespace folly;
  22 using namespace std;
  23
  24 struct StubLogger {
  25   void operator()(StringPiece msg, std::chrono::duration<double> sec) {
  26     m = msg.str();
  27     t = sec.count();
  28   }
  29   static std::string m;
  30   static double t;
  31 };
  32
  33 std::string StubLogger::m = "";
  34 double StubLogger::t = 0;
  35
  36 struct StubClock {
  37   typedef std::chrono::seconds duration;
  38
  39   static std::chrono::time_point<StubClock> now() {
  40     return std::chrono::time_point<StubClock>(std::chrono::duration<int>(t));
  41   }
  42   static int t;
  43 };
  44
  45 int StubClock::t = 0;
  46
  47 TEST(TestAutoTimer, HandleBasicClosure) {
  48   auto logger = [](StringPiece mesg, auto sec) {
  49     return StubLogger()(mesg, sec);
  50   };
  51   StubClock::t = 1;
  52   // Here decltype is needed. But since most users are expected to use this
  53   // method with the default clock, template specification won't be needed even
  54   // when they use a closure. See test case HandleRealTimerClosure
  55   auto timer = makeAutoTimer<decltype(logger), StubClock>(
  56       "", std::chrono::duration<double>::zero(), std::move(logger));
  57   StubClock::t = 3;
  58   timer.log("foo");
  59   ASSERT_EQ("foo", StubLogger::m);
  60   ASSERT_EQ(2, StubLogger::t);
  61   timer.logFormat("bar {}", 5e-2);
  62   ASSERT_EQ("bar 0.05", StubLogger::m);
  63   ASSERT_EQ(0, StubLogger::t);
  64 }
  65
  66 TEST(TestAutoTimer, HandleBasic) {
  67   StubClock::t = 1;
  68   AutoTimer<StubLogger, StubClock> timer;
  69   StubClock::t = 3;
  70   timer.log("foo");
  71   ASSERT_EQ("foo", StubLogger::m);
  72   ASSERT_EQ(2, StubLogger::t);
  73   timer.logFormat("bar {}", 5e-2);
  74   ASSERT_EQ("bar 0.05", StubLogger::m);
  75   ASSERT_EQ(0, StubLogger::t);
  76 }
  77
  78 TEST(TestAutoTimer, HandleLogOnDestruct) {
  79   {
  80     StubClock::t = 0;
  81     AutoTimer<StubLogger, StubClock> timer("message");
  82     StubClock::t = 3;
  83     timer.log("foo");
  84     EXPECT_EQ("foo", StubLogger::m);
  85     EXPECT_EQ(3, StubLogger::t);
  86     StubClock::t = 5;
  87   }
  88   ASSERT_EQ("message", StubLogger::m);
  89   ASSERT_EQ(2, StubLogger::t);
  90 }
  91
  92 TEST(TestAutoTimer, HandleRealTimerClosure) {
  93   auto t = makeAutoTimer(
  94       "Third message on destruction",
  95       std::chrono::duration<double>::zero(),
  96       [](StringPiece mesg, auto sec) {
  97         GoogleLogger<GoogleLoggerStyle::PRETTY>()(mesg, sec);
  98       });
  99   t.log("First message");
 100   t.log("Second message");
 101 }
 102
 103 TEST(TestAutoTimer, HandleRealTimer) {
 104   AutoTimer<> t("Third message on destruction");
 105   t.log("First message");
 106   t.log("Second message");
 107 }
 108
 109 TEST(TestAutoTimer, HandleMinLogTime) {
 110   StubClock::t = 1;
 111   AutoTimer<StubLogger, StubClock> timer("", std::chrono::duration<double>(3));
 112   StubClock::t = 3;
 113   // only 2 "seconds" have passed, so this shouldn't log
 114   StubLogger::t = 0;
 115   ASSERT_EQ(std::chrono::duration<double>(2), timer.log("foo"));
 116   ASSERT_EQ(std::chrono::duration<double>::zero().count(), StubLogger::t);
 117 }
 118
 119 TEST(TestAutoTimer, MovedObjectDestructionDoesntLog) {
 120   const std::vector<std::string> expectedMsgs = {
 121       "BEFORE_MOVE", "AFTER_MOVE", "END"};
 122   int32_t current = 0;
 123   SCOPE_EXIT {
 124     EXPECT_EQ(3, current);
 125   };
 126
 127   auto timer = [&expectedMsgs, &current] {
 128     auto oldTimer = folly::makeAutoTimer(
 129         "END",
 130         std::chrono::duration<double>::zero(),
 131         [&expectedMsgs, &current](
 132             StringPiece msg, const std::chrono::duration<double>&) {
 133           EXPECT_EQ(expectedMsgs.at(current), msg);
 134           current++;
 135         });
 136     oldTimer.log("BEFORE_MOVE");
 137     auto newTimer = std::move(oldTimer); // force the move-ctor
 138     return newTimer;
 139   }();
 140   timer.log("AFTER_MOVE");
 141 }