diff --git a/AUTHORS b/AUTHORS index 1780c12ba..5d8cc0db9 100644 --- a/AUTHORS +++ b/AUTHORS @@ -13,6 +13,7 @@ Abhishek Parmar Andrew Schwartzmeyer Andy Ying Brian Silverman +Dmitriy Arbitman Google Inc. Guillaume Dumont Marco Wang diff --git a/CMakeLists.txt b/CMakeLists.txt index 77a7cee03..0f3d48506 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -242,6 +242,17 @@ std::atomic i; int main() { } " HAVE_CXX11_ATOMIC) +check_cxx_source_compiles (" +constexpr int x = 0; +int main() { } +" HAVE_CXX11_CONSTEXPR) + +check_cxx_source_compiles (" +#include +std::chrono::seconds s; +int main() { } +" HAVE_CXX11_CHRONO) + check_cxx_source_compiles (" #include void foo(std::nullptr_t) {} @@ -389,6 +400,18 @@ else (HAVE_USING_OPERATOR) set (ac_cv_cxx_using_operator 0) endif (HAVE_USING_OPERATOR) +if (HAVE_CXX11_CONSTEXPR) + set (ac_cv_cxx11_constexpr 1) +else (HAVE_CXX11_CONSTEXPR) + set (ac_cv_cxx11_constexpr 0) +endif (HAVE_CXX11_CONSTEXPR) + +if (HAVE_CXX11_CHRONO) + set (ac_cv_cxx11_chrono 1) +else (HAVE_CXX11_CHRONO) + set (ac_cv_cxx11_chrono 0) +endif (HAVE_CXX11_CHRONO) + if (HAVE_CXX11_NULLPTR_T) set (ac_cv_cxx11_nullptr_t 1) else (HAVE_CXX11_NULLPTR_T) diff --git a/CONTRIBUTORS b/CONTRIBUTORS index c1c44fe51..571fd9618 100644 --- a/CONTRIBUTORS +++ b/CONTRIBUTORS @@ -28,6 +28,7 @@ Andrew Schwartzmeyer Andy Ying Bret McKee Brian Silverman +Dmitriy Arbitman Fumitoshi Ukai Guillaume Dumont Håkan L. S. Younes diff --git a/README.rst b/README.rst index 4858f6f93..6d9b24f0d 100644 --- a/README.rst +++ b/README.rst @@ -346,6 +346,19 @@ output to the first n occurrences: Outputs log messages for the first 20 times it is executed. Again, the ``google::COUNTER`` identifier indicates which repetition is happening. +Other times, it is desired to only log a message periodically based on a time. +So for example, to log a message every 10ms: + +.. code:: cpp + + LOG_EVERY_T(INFO, 0.01) << "Got a cookie"; + +Or every 2.35s: + +.. code:: cpp + + LOG_EVERY_T(INFO, 2.35) << "Got a cookie"; + Debug Mode Support ~~~~~~~~~~~~~~~~~~ diff --git a/bazel/glog.bzl b/bazel/glog.bzl index 7b47db7f3..15dc8227c 100644 --- a/bazel/glog.bzl +++ b/bazel/glog.bzl @@ -189,6 +189,8 @@ def glog_library(namespace = "google", with_gflags = 1, **kwargs): common_config = { "@ac_cv_cxx11_atomic@": "1", + "@ac_cv_cxx11_constexpr@": "1", + "@ac_cv_cxx11_chrono@": "1", "@ac_cv_cxx11_nullptr_t@": "1", "@ac_cv_cxx_using_operator@": "1", "@ac_cv_have_inttypes_h@": "0", diff --git a/src/config.h.cmake.in b/src/config.h.cmake.in index 8a989e4f7..4187e5d7b 100644 --- a/src/config.h.cmake.in +++ b/src/config.h.cmake.in @@ -195,6 +195,9 @@ /* Check whether C++11 atomic is available */ #cmakedefine HAVE_CXX11_ATOMIC ${HAVE_CXX11_ATOMIC} +/* Check whether C++11 chrono is available */ +#cmakedefine HAVE_CXX11_CHRONO ${HAVE_CXX11_CHRONO} + /* Check whether C++11 nullptr_t is available */ #cmakedefine HAVE_CXX11_NULLPTR_T ${HAVE_CXX11_NULLPTR_T} diff --git a/src/glog/logging.h.in b/src/glog/logging.h.in index c8e912881..61937329b 100644 --- a/src/glog/logging.h.in +++ b/src/glog/logging.h.in @@ -36,6 +36,10 @@ #ifndef _LOGGING_H_ #define _LOGGING_H_ +#if @ac_cv_cxx11_chrono@ +#include +#endif + #include #include #include @@ -984,6 +988,17 @@ PLOG_IF(FATAL, GOOGLE_PREDICT_BRANCH_NOT_TAKEN((invocation) == -1)) \ #define LOG_OCCURRENCES LOG_EVERY_N_VARNAME(occurrences_, __LINE__) #define LOG_OCCURRENCES_MOD_N LOG_EVERY_N_VARNAME(occurrences_mod_n_, __LINE__) +#if @ac_cv_cxx11_constexpr@ +#define GLOG_CONSTEXPR constexpr +#else +#define GLOG_CONSTEXPR const +#endif + +#define LOG_TIME_PERIOD LOG_EVERY_N_VARNAME(timePeriod_, __LINE__) +#define LOG_PREVIOUS_TIME_RAW LOG_EVERY_N_VARNAME(previousTimeRaw_, __LINE__) +#define LOG_TIME_DELTA LOG_EVERY_N_VARNAME(deltaTime_, __LINE__) +#define LOG_CURRENT_TIME LOG_EVERY_N_VARNAME(currentTime_, __LINE__) +#define LOG_PREVIOUS_TIME LOG_EVERY_N_VARNAME(previousTime_, __LINE__) #if defined(__has_feature) #define _GLOG_HAS_FEATURE(...) __has_feature(__VA_ARGS__) @@ -1016,6 +1031,51 @@ extern "C" void AnnotateBenignRaceSized( namespace google { #endif +#if @ac_cv_cxx11_chrono@ && @ac_cv_cxx11_atomic@ // Have and +#define SOME_KIND_OF_LOG_EVERY_T(severity, seconds) \ + GLOG_CONSTEXPR std::chrono::duration> LOG_TIME_PERIOD(seconds); \ + static std::atomic LOG_PREVIOUS_TIME_RAW; \ + _GLOG_IFDEF_THREAD_SANITIZER( \ + AnnotateBenignRaceSized(__FILE__, __LINE__, &LOG_TIME_PERIOD, sizeof(int64), "")); \ + _GLOG_IFDEF_THREAD_SANITIZER( \ + AnnotateBenignRaceSized(__FILE__, __LINE__, &LOG_PREVIOUS_TIME_RAW, sizeof(int64), "")); \ + const auto LOG_CURRENT_TIME = std::chrono::steady_clock::now().time_since_epoch(); \ + const decltype(LOG_CURRENT_TIME) LOG_PREVIOUS_TIME(LOG_PREVIOUS_TIME_RAW.load(std::memory_order_relaxed)); \ + const auto LOG_TIME_DELTA = LOG_CURRENT_TIME - LOG_PREVIOUS_TIME; \ + if (LOG_TIME_DELTA > LOG_TIME_PERIOD) \ + LOG_PREVIOUS_TIME_RAW.store(LOG_CURRENT_TIME.count(), std::memory_order_relaxed); \ + if (LOG_TIME_DELTA > LOG_TIME_PERIOD) @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::GLOG_ ## severity).stream() +#elif defined(OS_WINDOWS) +#define SOME_KIND_OF_LOG_EVERY_T(severity, seconds) \ + GLOG_CONSTEXPR int64 LOG_TIME_PERIOD(seconds * 1000000000.0); \ + static int64 LOG_PREVIOUS_TIME = 0; \ + int64 LOG_TIME_DELTA = 0; \ + { \ + LARGE_INTEGER currTime; \ + LARGE_INTEGER freq; \ + QueryPerformanceCounter(&currTime); \ + QueryPerformanceFrequency(&freq); \ + LOG_TIME_DELTA = (currTime.QuadPart * 1000000000.0 / freq.QuadPart) - LOG_PREVIOUS_TIME; \ + } \ + if (LOG_TIME_DELTA > LOG_TIME_PERIOD) InterlockedExchangeAdd64(&LOG_PREVIOUS_TIME, LOG_TIME_DELTA); \ + if (LOG_TIME_DELTA > LOG_TIME_PERIOD) google::LogMessage( \ + __FILE__, __LINE__, google::GLOG_ ## severity).stream() +#else +#define SOME_KIND_OF_LOG_EVERY_T(severity, seconds) \ + GLOG_CONSTEXPR int64 LOG_TIME_PERIOD(seconds * 1000000000.0); \ + static int64 LOG_PREVIOUS_TIME; \ + int64 LOG_TIME_DELTA = 0; \ + { \ + timespec currentTime{}; \ + clock_gettime(CLOCK_MONOTONIC, ¤tTime); \ + LOG_TIME_DELTA = (currentTime.tv_sec * 1000000000 + currentTime.tv_nsec) - LOG_PREVIOUS_TIME; \ + } \ + if (LOG_TIME_DELTA > LOG_TIME_PERIOD) __sync_add_and_fetch(&LOG_PREVIOUS_TIME, LOG_TIME_DELTA); \ + if (LOG_TIME_DELTA > LOG_TIME_PERIOD) @ac_google_namespace@::LogMessage( \ + __FILE__, __LINE__, @ac_google_namespace@::GLOG_ ## severity).stream() +#endif + #ifdef HAVE_CXX11_ATOMIC #define SOME_KIND_OF_LOG_EVERY_N(severity, n, what_to_do) \ static std::atomic LOG_OCCURRENCES(0), LOG_OCCURRENCES_MOD_N(0); \ @@ -1159,6 +1219,8 @@ GOOGLE_GLOG_DLL_DECL bool IsFailureSignalHandlerInstalled(); #define LOG_EVERY_N(severity, n) \ SOME_KIND_OF_LOG_EVERY_N(severity, (n), @ac_google_namespace@::LogMessage::SendToLog) +#define LOG_EVERY_T(severity, T) SOME_KIND_OF_LOG_EVERY_T(severity, (T)) + #define SYSLOG_EVERY_N(severity, n) \ SOME_KIND_OF_LOG_EVERY_N(severity, (n), @ac_google_namespace@::LogMessage::SendToSyslogAndLog) diff --git a/src/googletest.h b/src/googletest.h index 72306063c..6d023c6c7 100644 --- a/src/googletest.h +++ b/src/googletest.h @@ -118,6 +118,15 @@ void InitGoogleTest(int*, char**) {} // The following is some bare-bones testing infrastructure +#define EXPECT_NEAR(val1, val2, abs_error) \ + do { \ + if (abs(val1 - val2) > abs_error) { \ + fprintf(stderr, "Check failed: %s within %s of %s\n", #val1, #abs_error, \ + #val2); \ + exit(1); \ + } \ + } while (0) + #define EXPECT_TRUE(cond) \ do { \ if (!(cond)) { \ diff --git a/src/logging_unittest.cc b/src/logging_unittest.cc index 2b50a257d..f8eb4fbb6 100644 --- a/src/logging_unittest.cc +++ b/src/logging_unittest.cc @@ -115,6 +115,7 @@ static void TestWrapper(); static void TestErrno(); static void TestTruncate(); static void TestCustomLoggerDeletionOnShutdown(); +static void TestLogPeriodically(); static int x = -1; static void BM_Check1(int n) { @@ -248,6 +249,7 @@ int main(int argc, char **argv) { TestErrno(); TestTruncate(); TestCustomLoggerDeletionOnShutdown(); + TestLogPeriodically(); fprintf(stdout, "PASS\n"); return 0; @@ -995,6 +997,96 @@ static void TestCustomLoggerDeletionOnShutdown() { EXPECT_FALSE(IsGoogleLoggingInitialized()); } +namespace LogTimes { +// Log a "message" every 10ms, 10 times. These numbers are nice compromise +// between total running time of 100ms and the period of 10ms. The period is +// large enough such that any CPU and OS scheduling variation shouldn't affect +// the results from the ideal case by more than 5% (500us or 0.5ms) +GLOG_CONSTEXPR int64_t LOG_PERIOD_NS = 10000000; // 10ms +GLOG_CONSTEXPR int64_t LOG_PERIOD_TOL_NS = 500000; // 500us + +// Set an upper limit for the number of times the stream operator can be +// called. Make sure not to exceed this number of times the stream operator is +// called, since it is also the array size and will be indexed by the stream +// operator. +GLOG_CONSTEXPR size_t MAX_CALLS = 10; +} // namespace LogStreamTimes + +#ifdef HAVE_CXX11_CHRONO +struct LogTimeRecorder { + size_t m_streamTimes = 0; + std::chrono::steady_clock::time_point m_callTimes[LogTimes::MAX_CALLS]; +}; +// The stream operator is called by LOG_EVERY_T every time a logging event +// occurs. Make sure to save the times for each call as they will be used later +// to verify the time delta between each call. +std::ostream& operator<<(std::ostream& stream, LogTimeRecorder& t) { + t.m_callTimes[t.m_streamTimes++] = std::chrono::steady_clock::now(); + return stream; +} +// get elapsed time in nanoseconds +int64 elapsedTime_ns(const std::chrono::steady_clock::time_point& begin, + const std::chrono::steady_clock::time_point& end) { + return std::chrono::duration_cast((end - begin)) + .count(); +} +#elif defined(OS_WINDOWS) +struct LogTimeRecorder { + size_t m_streamTimes = 0; + LARGE_INTEGER m_callTimes[LogTimes::MAX_CALLS]; +}; +std::ostream& operator<<(std::ostream& stream, LogTimeRecorder& t) { + QueryPerformanceCounter(&t.m_callTimes[t.m_streamTimes++]); + return stream; +} +// get elapsed time in nanoseconds +int64 elapsedTime_ns(const LARGE_INTEGER& begin, const LARGE_INTEGER& end) { + LARGE_INTEGER freq; + QueryPerformanceFrequency(&freq); + return (end.QuadPart - begin.QuadPart) * 1000000000 / freq.QuadPart; +} +#else +struct LogTimeRecorder { + size_t m_streamTimes = 0; + timespec m_callTimes[LogTimes::MAX_CALLS]; +}; +std::ostream& operator<<(std::ostream& stream, LogTimeRecorder& t) { + clock_gettime(CLOCK_MONOTONIC, &t.m_callTimes[t.m_streamTimes++]); + return stream; +} +// get elapsed time in nanoseconds +int64 elapsedTime_ns(const timespec& begin, const timespec& end) { + return (end.tv_sec - begin.tv_sec) * 1000000000 + + (end.tv_nsec - begin.tv_nsec); +} +#endif + +static void TestLogPeriodically() { + fprintf(stderr, "==== Test log periodically\n"); + + LogTimeRecorder timeLogger; + + GLOG_CONSTEXPR double LOG_PERIOD_SEC = LogTimes::LOG_PERIOD_NS / 1000000000.0; + + while (timeLogger.m_streamTimes < LogTimes::MAX_CALLS) { + LOG_EVERY_T(INFO, LOG_PERIOD_SEC) + << timeLogger << "Timed Message #" << timeLogger.m_streamTimes; + } + + // Calculate time between each call in nanoseconds for higher resolution to + // minimize error. + int64 nsBetweenCalls[LogTimes::MAX_CALLS - 1]; + for (size_t i = 1; i < LogTimes::MAX_CALLS; ++i) { + nsBetweenCalls[i - 1] = elapsedTime_ns( + timeLogger.m_callTimes[i - 1], timeLogger.m_callTimes[i]); + } + + for (size_t idx = 0; idx < LogTimes::MAX_CALLS - 1; ++idx) { + int64 time_ns = nsBetweenCalls[idx]; + EXPECT_NEAR(time_ns, LogTimes::LOG_PERIOD_NS, LogTimes::LOG_PERIOD_TOL_NS); + } +} + _START_GOOGLE_NAMESPACE_ namespace glog_internal_namespace_ { extern // in logging.cc