folly/experimental/test/AutoTimerTest.cpp

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