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 | |
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, ¤t] { |
128 | auto oldTimer = folly::makeAutoTimer( |
129 | "END" , |
130 | std::chrono::duration<double>::zero(), |
131 | [&expectedMsgs, ¤t]( |
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 | } |
142 | |