diff --git a/CMakeLists.txt b/CMakeLists.txt index 7b21d3d1..6e02e43f 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -218,6 +218,7 @@ set(DD_PROFILING_SOURCES src/perf_ringbuffer.cc src/perf_watcher.cc src/pevent_lib.cc + src/ratelimiter.cc src/ringbuffer_utils.cc src/signal_helper.cc src/sys_utils.cc diff --git a/bench/collatz/CMakeLists.txt b/bench/collatz/CMakeLists.txt index d74a5615..9838479b 100644 --- a/bench/collatz/CMakeLists.txt +++ b/bench/collatz/CMakeLists.txt @@ -1,10 +1,6 @@ # Reuse the same statsd implem as ddprof -set(STATSD_SRC_FILE ../../src/statsd.cc) -set(LOGGER_SRC_FILE ../../src/logger.cc) -set(DDRESLIST_SRC_FILE ../../src/ddres_list.cc) set(STATSD_INCLUDE_DIR ../../include) - -set(COLLATZ_SRC collatz.cc ${STATSD_SRC_FILE} ${LOGGER_SRC_FILE} ${DDRESLIST_SRC_FILE}) +set(COLLATZ_SRC collatz.cc ../../src/statsd.cc ../../src/logger.cc ../../src/ratelimiter.cc ../../src/ddres_list.cc) list(APPEND COLLATZ_DEFINITION_LIST "MYNAME=\"collatz\"" "VER_REV=\"${BUILD_REV}\"") add_exe( diff --git a/include/logger.hpp b/include/logger.hpp index 5cb74b15..4715dae8 100644 --- a/include/logger.hpp +++ b/include/logger.hpp @@ -5,6 +5,7 @@ #pragma once +#include #include #include "unlikely.hpp" @@ -90,11 +91,14 @@ void vlprintfln(int lvl, int fac, const char *name, const char *format, va_list args); // Setters for global logger context -bool LOG_setname(const char *name); +void LOG_setname(const char *name); void LOG_setlevel(int lvl); int LOG_getlevel(); void LOG_setfacility(int fac); +void LOG_setratelimit(uint64_t max_log_per_interval, + std::chrono::nanoseconds interval); + /******************************* Logging Macros *******************************/ #define ABS(__x) \ ({ \ diff --git a/include/logger_setup.hpp b/include/logger_setup.hpp index 7986b055..4c20cd35 100644 --- a/include/logger_setup.hpp +++ b/include/logger_setup.hpp @@ -5,6 +5,13 @@ #pragma once +#include + namespace ddprof { -void setup_logger(const char *log_mode, const char *log_level); -} +inline constexpr auto kMaxLogPerSecForNonDebug = 100; + +void setup_logger( + const char *log_mode, const char *log_level, + uint64_t max_log_per_sec_for_non_debug = kMaxLogPerSecForNonDebug); + +} // namespace ddprof diff --git a/src/logger.cc b/src/logger.cc index b269d407..27c4a9e3 100644 --- a/src/logger.cc +++ b/src/logger.cc @@ -3,6 +3,11 @@ // developed at Datadog (https://www.datadoghq.com/). Copyright 2021-Present // Datadog, Inc. +#include "logger.hpp" + +#include "ratelimiter.hpp" + +#include #include #include #include @@ -11,6 +16,7 @@ #include #include #include +#include #include #include #include @@ -33,41 +39,34 @@ namespace ddprof { namespace { struct LoggerContext { - int fd; - int mode; - int level; - int facility; - char *name; - int namelen; + int fd{-1}; + int mode{LOG_STDERR}; + int level{LL_ERROR}; + int facility{LF_USER}; + std::string name; + std::optional rate_limiter; }; -LoggerContext base_log_context = (LoggerContext){ - .fd = -1, .mode = LOG_STDERR, .level = LL_ERROR, .facility = LF_USER}; -LoggerContext *log_ctx = &base_log_context; +LoggerContext log_ctx{.fd = -1, .mode = LOG_STDERR, .level = LL_ERROR}; +} // namespace void LOG_setlevel(int lvl) { assert(lvl >= LL_EMERGENCY && lvl <= LL_DEBUG); if (lvl >= LL_EMERGENCY && lvl <= LL_DEBUG) { - log_ctx->level = lvl; + log_ctx.level = lvl; } } -int LOG_getlevel() { return log_ctx->level; } +int LOG_getlevel() { return log_ctx.level; } void LOG_setfacility(int fac) { assert(fac >= LF_KERNEL && fac <= LF_LOCAL7); if (fac >= LF_KERNEL && fac <= LF_LOCAL7) { - log_ctx->facility = fac; + log_ctx.facility = fac; } } -bool LOG_setname(const char *name) { - if (log_ctx->name) { - free(log_ctx->name); - } - log_ctx->name = strdup(name); - return log_ctx->name != nullptr; -} +void LOG_setname(const char *name) { log_ctx.name = name; } bool LOG_syslog_open() { const sockaddr_un sa = {AF_UNIX, "/dev/log"}; @@ -82,28 +81,28 @@ bool LOG_syslog_open() { return false; } - log_ctx->fd = fd; + log_ctx.fd = fd; return true; } void LOG_close() { - if (LOG_SYSLOG == log_ctx->mode || LOG_FILE == log_ctx->mode) { - close(log_ctx->fd); + if (LOG_SYSLOG == log_ctx.mode || LOG_FILE == log_ctx.mode) { + close(log_ctx.fd); } - log_ctx->fd = -1; + log_ctx.fd = -1; } bool LOG_open(int mode, const char *opts) { - if (log_ctx->fd >= 0) { + if (log_ctx.fd >= 0) { LOG_close(); } // Preemptively reset to initial state - log_ctx->mode = mode; + log_ctx.mode = mode; switch (mode) { case LOG_DISABLE: - log_ctx->fd = -1; + log_ctx.fd = -1; break; case LOG_SYSLOG: if (!LOG_syslog_open()) { @@ -112,10 +111,10 @@ bool LOG_open(int mode, const char *opts) { break; default: case LOG_STDOUT: - log_ctx->fd = STDOUT_FILENO; + log_ctx.fd = STDOUT_FILENO; break; case LOG_STDERR: - log_ctx->fd = STDERR_FILENO; + log_ctx.fd = STDERR_FILENO; break; case LOG_FILE: { int const fd = open(opts, O_RDWR | O_APPEND | O_CREAT | O_CLOEXEC, 0755); @@ -123,28 +122,20 @@ bool LOG_open(int mode, const char *opts) { if (-1 == fd) { return false; } - log_ctx->fd = fd; + log_ctx.fd = fd; break; } } // Finalize - log_ctx->mode = mode; + log_ctx.mode = mode; return true; } -// TODO this is a unix-ism and not portable to Windows. -#if defined(__APPLE__) || defined(__FreeBSD__) -char *name_default = getprogname(); -#elif defined(__linux__) -extern char *__progname; -# define name_default __progname -#else -char *name_default = "ddprof"; -#endif -#ifndef LOG_MSG_CAP -# define LOG_MSG_CAP 4096 -#endif +void LOG_setratelimit(uint64_t max_log_per_interval, + std::chrono::nanoseconds interval) { + log_ctx.rate_limiter.emplace(max_log_per_interval, interval); +} // The message buffer shall be a static, thread-local region defined by the // LOG_MSG_CAP compile-time parameter. The accessible storage amount shall be @@ -158,19 +149,23 @@ void vlprintfln(int lvl, int fac, const char *name, const char *format, ssize_t sz_h = -1; int rc = 0; + if (log_ctx.rate_limiter && !log_ctx.rate_limiter->check()) { + return; + } + // Special value handling if (lvl == -1) { - lvl = log_ctx->level; + lvl = log_ctx.level; } if (fac == -1) { - fac = log_ctx->mode; + fac = log_ctx.facility; } if (!name || !*name) { - name = (!log_ctx->name || !*log_ctx->name) ? log_ctx->name : name_default; + name = !log_ctx.name.empty() ? log_ctx.name.c_str() : name_default; } // Sanity checks - if (log_ctx->fd < 0) { + if (log_ctx.fd < 0) { return; } if (!format) { @@ -194,7 +189,7 @@ void vlprintfln(int lvl, int fac, const char *name, const char *format, // Get the PID; overriding if necessary (allow for testing overflow) pid_t const pid = getpid(); - if (log_ctx->mode == LOG_SYSLOG) { + if (log_ctx.mode == LOG_SYSLOG) { sz_h = snprintf(buf, LOG_MSG_CAP, "<%d>%s.%06ld %s[%d]: ", lvl + fac * LL_LENGTH, tm_str, d_us.count(), name, pid); @@ -224,7 +219,7 @@ void vlprintfln(int lvl, int fac, const char *name, const char *format, sz += sz_h; // Some consumers expect newline-delimited logs. - if (log_ctx->mode != LOG_SYSLOG) { + if (log_ctx.mode != LOG_SYSLOG) { buf[sz] = '\n'; buf[sz + 1] = '\0'; sz++; @@ -232,10 +227,10 @@ void vlprintfln(int lvl, int fac, const char *name, const char *format, // Flush to file descriptor do { - if (log_ctx->mode == LOG_SYSLOG) { - rc = sendto(log_ctx->fd, buf, sz, MSG_NOSIGNAL, nullptr, 0); + if (log_ctx.mode == LOG_SYSLOG) { + rc = sendto(log_ctx.fd, buf, sz, MSG_NOSIGNAL, nullptr, 0); } else { - rc = write(log_ctx->fd, buf, sz); + rc = write(log_ctx.fd, buf, sz); } } while (rc < 0 && errno == EINTR); } @@ -255,4 +250,5 @@ void lprintfln(int lvl, int fac, const char *name, const char *fmt, ...) { vlprintfln(lvl, fac, name, fmt, args); va_end(args); } + } // namespace ddprof diff --git a/src/logger_setup.cc b/src/logger_setup.cc index 38c19be3..e889e521 100644 --- a/src/logger_setup.cc +++ b/src/logger_setup.cc @@ -12,7 +12,8 @@ namespace ddprof { -void setup_logger(const char *log_mode, const char *log_level) { +void setup_logger(const char *log_mode, const char *log_level, + uint64_t max_log_per_sec_for_non_debug) { // Process logging mode char const *logpattern[] = {"stdout", "stderr", "syslog", "disabled"}; int const idx_log_mode = log_mode @@ -58,6 +59,10 @@ void setup_logger(const char *log_mode, const char *log_level) { LOG_setlevel(LL_WARNING); break; } + + if (LOG_getlevel() > LL_DEBUG) { + LOG_setratelimit(max_log_per_sec_for_non_debug, std::chrono::seconds(1)); + } } } // namespace ddprof diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index 1587963d..0c0677e5 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -45,7 +45,7 @@ function(add_unit_test name) message(STATUS "Creating unit test : " ${name}) # # Create exe with sources. Always add logger and error management in the unit tests - add_exe(${name} ../src/ddres_list.cc ../src/logger.cc ${ARGN}) + add_exe(${name} ../src/ddres_list.cc ../src/logger.cc ../src/ratelimiter.cc ${ARGN}) target_link_libraries(${name} PRIVATE gtest Threads::Threads gmock_main gmock) target_include_directories(${name} PRIVATE ${DDPROF_INCLUDE_LIST} ${GTEST_INCLUDE_DIRS} @@ -81,7 +81,7 @@ function(add_benchmark name) message(STATUS "Creating unit test : " ${name}) # # Create exe with sources. Always add logger and error management in the unit tests - add_exe(${name} ../src/ddres_list.cc ../src/logger.cc ${ARGN}) + add_exe(${name} ../src/ddres_list.cc ../src/logger.cc ../src/ratelimiter.cc ${ARGN}) target_link_libraries(${name} PRIVATE Threads::Threads benchmark::benchmark benchmark::benchmark_main)