AutoTimerTest.cpp 4.0 KB

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