luo980/glog
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Implement LOG_EVERY_T.

Browse Source 
Use <chrono> and <atomic> for C++11 or greater.
For non-Windows pre-C++11 systems, use <time.h> and built-in atomic operations.
For Windows pre-C++11, use the Windows implementations for time and atomic operations.
This commit is contained in:
Dmitriy A 2021-06-10 18:58:55 -07:00
parent 6e46c125e3
commit a1374c4200
9 changed files with 206 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
AUTHORS
View File

@ -13,6 +13,7 @@ Abhishek Parmar <abhishek@orng.net>
Andrew Schwartzmeyer <andrew@schwartzmeyer.com>
Andy Ying <andy@trailofbits.com>
Brian Silverman <bsilver16384@gmail.com>
Dmitriy Arbitman <d.arbitman@gmail.com>
Google Inc.
Guillaume Dumont <dumont.guillaume@gmail.com>
Marco Wang <m.aesophor@gmail.com>

23
CMakeLists.txt
View File

@ -242,6 +242,17 @@ std::atomic<int> i;
int main() { }
" HAVE_CXX11_ATOMIC)
check_cxx_source_compiles ("
constexpr int x = 0;
int main() { }
" HAVE_CXX11_CONSTEXPR)
check_cxx_source_compiles ("
#include <chrono>
std::chrono::seconds s;
int main() { }
" HAVE_CXX11_CHRONO)
check_cxx_source_compiles ("
#include <cstddef>
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)

1
CONTRIBUTORS
View File

@ -28,6 +28,7 @@ Andrew Schwartzmeyer <andrew@schwartzmeyer.com>
Andy Ying <andy@trailofbits.com>
Bret McKee <bretmckee@google.com>
Brian Silverman <bsilver16384@gmail.com>
Dmitriy Arbitman <d.arbitman@gmail.com>
Fumitoshi Ukai <ukai@google.com>
Guillaume Dumont <dumont.guillaume@gmail.com>
Håkan L. S. Younes <hyounes@google.com>

13
README.rst
View File

@ -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
~~~~~~~~~~~~~~~~~~

2
bazel/glog.bzl
View File

@ -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",

3
src/config.h.cmake.in
View File

@ -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}

62
src/glog/logging.h.in
View File

@ -36,6 +36,10 @@
#ifndef _LOGGING_H_
#define _LOGGING_H_
#if @ac_cv_cxx11_chrono@
#include <chrono>
#endif
#include <cerrno>
#include <cstddef>
#include <cstring>
@ -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 <chrono> and <atomic>
#define SOME_KIND_OF_LOG_EVERY_T(severity, seconds) \
GLOG_CONSTEXPR std::chrono::duration<double, std::ratio<1, 1>> LOG_TIME_PERIOD(seconds); \
static std::atomic<int64> 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, &currentTime); \
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<int> 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)

9
src/googletest.h
View File

@ -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)) { \

92
src/logging_unittest.cc
View File

@ -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<std::chrono::nanoseconds>((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