Commit 0a52fd7b authored by Nathan Bronson's avatar Nathan Bronson Committed by Dave Watson

make FB_LOG_EVERY_MS thread safe

Summary:
Use compare_exchange_strong to update the previous time so that
there is no race.  This diff also adds microbenchmarks.

Test Plan: unit tests

Reviewed By: andrei.alexandrescu@fb.com

FB internal diff: D1191217
parent 3fb62b36
...@@ -17,6 +17,7 @@ ...@@ -17,6 +17,7 @@
#ifndef FOLLY_LOGGING_H_ #ifndef FOLLY_LOGGING_H_
#define FOLLY_LOGGING_H_ #define FOLLY_LOGGING_H_
#include <atomic>
#include <chrono> #include <chrono>
#include <glog/logging.h> #include <glog/logging.h>
...@@ -29,18 +30,24 @@ ...@@ -29,18 +30,24 @@
* " since you last saw this."; * " since you last saw this.";
* *
* The implementation uses for statements to introduce variables in * The implementation uses for statements to introduce variables in
* a nice way that doesn't mess surrounding statements. * a nice way that doesn't mess surrounding statements. It is thread
* safe.
*/ */
#define FB_LOG_EVERY_MS(severity, milli_interval) \ #define FB_LOG_EVERY_MS(severity, milli_interval) \
for (bool FB_LEM_once = true; FB_LEM_once; ) \ for (bool FB_LEM_once = true; FB_LEM_once; ) \
for (const auto FB_LEM_now = ::std::chrono::system_clock::now(); \ for (::std::chrono::milliseconds::rep FB_LEM_prev, FB_LEM_now = \
FB_LEM_once; ) \ ::std::chrono::duration_cast< ::std::chrono::milliseconds>( \
for (static ::std::chrono::system_clock::time_point FB_LEM_last; \ ::std::chrono::system_clock::now().time_since_epoch() \
FB_LEM_once; FB_LEM_once = false) \ ).count(); \
if (FB_LEM_now - FB_LEM_last < \ FB_LEM_once; ) \
::std::chrono::milliseconds(milli_interval)) { \ for (static ::std::atomic< ::std::chrono::milliseconds::rep> \
} else \ FB_LEM_hist; FB_LEM_once; FB_LEM_once = false) \
(FB_LEM_last = FB_LEM_now, LOG(severity)) if (FB_LEM_now - (FB_LEM_prev = \
FB_LEM_hist.load(std::memory_order_acquire)) < \
milli_interval || \
!FB_LEM_hist.compare_exchange_strong(FB_LEM_prev, FB_LEM_now)) { \
} else \
LOG(severity)
#endif #endif
......
...@@ -17,6 +17,7 @@ ...@@ -17,6 +17,7 @@
#include <folly/Logging.h> #include <folly/Logging.h>
#include <gflags/gflags.h> #include <gflags/gflags.h>
#include <gtest/gtest.h> #include <gtest/gtest.h>
#include <folly/Benchmark.h>
#include <vector> #include <vector>
TEST(LogEveryMs, basic) { TEST(LogEveryMs, basic) {
...@@ -39,8 +40,42 @@ TEST(LogEveryMs, basic) { ...@@ -39,8 +40,42 @@ TEST(LogEveryMs, basic) {
EXPECT_TRUE(atLeastOneIsGood); EXPECT_TRUE(atLeastOneIsGood);
} }
BENCHMARK(skip_overhead, iter) {
auto prev = FLAGS_minloglevel;
FLAGS_minloglevel = 2;
for (unsigned i = 0; i < iter; ++i) {
FB_LOG_EVERY_MS(INFO, 1000) << "every 1s";
}
FLAGS_minloglevel = prev;
}
BENCHMARK(dev_null_log_overhead, iter) {
auto prev = FLAGS_minloglevel;
FLAGS_minloglevel = 2;
for (unsigned i = 0; i < iter; ++i) {
FB_LOG_EVERY_MS(INFO, -1) << "every -1ms";
}
FLAGS_minloglevel = prev;
}
// ============================================================================
// folly/test/LoggingTest.cpp relative time/iter iters/s
// ============================================================================
// skip_overhead 36.37ns 27.49M
// dev_null_log_overhead 2.61us 382.57K
// ============================================================================
int main(int argc, char** argv) { int main(int argc, char** argv) {
testing::InitGoogleTest(&argc, argv); testing::InitGoogleTest(&argc, argv);
google::ParseCommandLineFlags(&argc, &argv, true); google::ParseCommandLineFlags(&argc, &argv, true);
return RUN_ALL_TESTS();
auto rv = RUN_ALL_TESTS();
if (!rv && FLAGS_benchmark) {
folly::runBenchmarks();
}
return rv;
} }
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment