From 215e906491aa017e3a46610aa8efc204bbc92dd3 Mon Sep 17 00:00:00 2001 From: Andrey Goder Date: Fri, 20 Feb 2015 13:48:36 -0800 Subject: [PATCH] Add AutoTimer to folly Summary: This 'moves' bistro::AutoTimer into folly. I actually changed it a bit, so I'm not migrating any existing uses in this diff, but I can do that as a followup. We're using it in various places now, so it doesn't make sense to have it in bistro. Basically this class lets you conveniently time a series of things while printing log messages, e.g.: { AutoTimer t("Done"); processA(); t.log("processA() complete"); } would print "processA() complete in XXX seconds" "Done in YYY seconds" I changed some things from bistro::AutoTimer: - Use std::chrono::time_point to store the start time. - I removed the gflags. It seems weird to rely on those to control the timer, since they would affect all uses of this. If a specific user of the timer wants to actually control timing at runtime, I think it's better to use a custom logger. - I removed the 'min log duration'. As implemented it actually made the constructor conflict: AutoTimer("foo", 1.2) is ambiguous. Also, it should probably be set on the logger, so this likewise feels like a place where you could make a custom logger. I'm not sure that the way I use the default logger as a template argument is best, so please suggest improvements to that. Test Plan: unit test Reviewed By: lesha@fb.com Subscribers: trunkagent, folly-diffs@, yfeldblum FB internal diff: D1860794 Signature: t1:1860794:1424458219:a2dd0d428aedf063a888b2937b1443c7142554e8 --- folly/Makefile.am | 1 + folly/experimental/AutoTimer.h | 131 ++++++++++++++++++++++ folly/experimental/test/AutoTimerTest.cpp | 73 ++++++++++++ 3 files changed, 205 insertions(+) create mode 100644 folly/experimental/AutoTimer.h create mode 100644 folly/experimental/test/AutoTimerTest.cpp diff --git a/folly/Makefile.am b/folly/Makefile.am index b273f71d..ffbf0dc9 100644 --- a/folly/Makefile.am +++ b/folly/Makefile.am @@ -68,6 +68,7 @@ nobase_follyinclude_HEADERS = \ ExceptionWrapper.h \ Executor.h \ EvictingCacheMap.h \ + experimental/AutoTimer.h \ experimental/Bits.h \ experimental/EliasFanoCoding.h \ experimental/EventCount.h \ diff --git a/folly/experimental/AutoTimer.h b/folly/experimental/AutoTimer.h new file mode 100644 index 00000000..dfe2bcfe --- /dev/null +++ b/folly/experimental/AutoTimer.h @@ -0,0 +1,131 @@ +/* + * Copyright 2015 Facebook, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +#include +#include +#include +#include +#include +#include + +namespace folly { + +// Default logger +enum class GoogleLoggerStyle { SECONDS, PRETTY }; +template struct GoogleLogger; + +/** + * Automatically times a block of code, printing a specified log message on + * destruction or whenever the log() method is called. For example: + * + * AutoTimer t("Foo() completed"); + * doWork(); + * t.log("Do work finished"); + * doMoreWork(); + * + * This would print something like: + * "Do work finished in 1.2 seconds" + * "Foo() completed in 4.3 seconds" + * + * You can customize what you use as the logger and clock. The logger needs + * to have an operator()(StringPiece, double) that gets a message and a duration + * (in seconds). The clock needs to model Clock from std::chrono. + * + * The default logger logs usings glog. It only logs if the message is + * non-empty, so you can also just use this class for timing, e.g.: + * + * AutoTimer t; + * doWork() + * const auto how_long = t.log(); + */ +template< + class Logger = GoogleLogger, + class Clock = std::chrono::high_resolution_clock +> class AutoTimer final { +public: + explicit AutoTimer(StringPiece msg = "") + : destructionMessage_(msg.str()), + start_(Clock::now()) { + } + + // Automatically generate a log message using to. Makes it + // easier to do the common case of things like: + // AutoTimer t("Processed ", n, " items"); + template + explicit AutoTimer(Args&&... args) + : destructionMessage_(to(std::forward(args)...)), + start_(Clock::now()) { + } + + // It doesn't really make sense to copy/move an AutoTimer + AutoTimer(const AutoTimer&) = delete; + AutoTimer(AutoTimer&&) = delete; + AutoTimer& operator=(const AutoTimer&) = delete; + AutoTimer& operator=(AutoTimer&&) = delete; + + ~AutoTimer() { + log(destructionMessage_); + } + + double log(StringPiece msg = "") { + return logImpl(Clock::now(), msg); + } + + template + double log(Args&&... args) { + auto now = Clock::now(); + return logImpl(now, to(std::forward(args)...)); + } + + template + double logFormat(Args&&... args) { + auto now = Clock::now(); + return logImpl(now, format(std::forward(args)...)); + } + +private: + // We take in the current time so that we don't measure time to call + // to or format() in the duration. + double logImpl(std::chrono::time_point now, StringPiece msg) { + double duration = std::chrono::duration_cast>( + now - start_ + ).count(); + Logger()(msg, duration); + start_ = Clock::now(); // Don't measure logging time + return duration; + } + + const std::string destructionMessage_; + std::chrono::time_point start_; +}; + +template +struct GoogleLogger { + void operator()(StringPiece msg, double sec) const { + if (msg.empty()) { + return; + } + if (Style == GoogleLoggerStyle::PRETTY) { + LOG(INFO) << msg << " in " << prettyPrint(sec, PrettyType::PRETTY_TIME); + } else { + LOG(INFO) << msg << " in " << sec << " seconds"; + } + } +}; + + +} diff --git a/folly/experimental/test/AutoTimerTest.cpp b/folly/experimental/test/AutoTimerTest.cpp new file mode 100644 index 00000000..bb232395 --- /dev/null +++ b/folly/experimental/test/AutoTimerTest.cpp @@ -0,0 +1,73 @@ +/* + * Copyright 2015 Facebook, Inc. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#include + +#include + +using namespace folly; +using namespace std; + +struct StubLogger { + void operator()(StringPiece msg, double sec) { + m = msg; + t = sec; + } + static StringPiece m; + static double t; +}; + +StringPiece StubLogger::m = ""; +double StubLogger::t = 0; + +struct StubClock { + typedef std::chrono::seconds duration; + + static std::chrono::time_point now() { + return std::chrono::time_point(std::chrono::duration(t)); + } + static int t; +}; + +int StubClock::t = 0; + +TEST(TestAutoTimer, HandleBasic) { + StubClock::t = 1; + AutoTimer timer; + StubClock::t = 3; + timer.log("foo"); + ASSERT_EQ("foo", StubLogger::m); + ASSERT_EQ(2, StubLogger::t); +} + +TEST(TestAutoTimer, HandleLogOnDestruct) { + { + StubClock::t = 0; + AutoTimer timer("message"); + StubClock::t = 3; + timer.log("foo"); + EXPECT_EQ("foo", StubLogger::m); + EXPECT_EQ(3, StubLogger::t); + StubClock::t = 5; + } + ASSERT_EQ("message", StubLogger::m); + ASSERT_EQ(2, StubLogger::t); +} + +TEST(TestAutoTimer, HandleRealTimer) { + AutoTimer<> t("Third message on destruction"); + t.log("First message"); + t.log("Second message"); +} -- 2.34.1