From 7b6c17e378224844d8663a410da2da5353b205b9 Mon Sep 17 00:00:00 2001 From: Derek Mauro Date: Tue, 5 Dec 2023 07:07:07 -0800 Subject: Add VLOG and friends These are methods for configurable verbose logging PiperOrigin-RevId: 588059727 Change-Id: Ib3703edd2493050a5da8b30e88b21adc643b1f7f --- CMake/AbseilDll.cmake | 3 + absl/log/BUILD.bazel | 83 ++++++++++ absl/log/CMakeLists.txt | 89 ++++++++-- absl/log/absl_log.h | 12 ++ absl/log/flags.cc | 23 +++ absl/log/internal/BUILD.bazel | 1 + absl/log/internal/flags.h | 6 + absl/log/internal/log_impl.h | 66 ++++++++ absl/log/log.h | 39 +++++ absl/log/log_entry.h | 3 +- absl/log/vlog_config.cc | 334 ++++++++++++++++++++++++++++++++++++++ absl/log/vlog_config.h | 162 ++++++++++++++++++ absl/log/vlog_config_benchmark.cc | 187 +++++++++++++++++++++ absl/log/vlog_is_on.h | 115 +++++++++++++ absl/log/vlog_is_on_test.cc | 175 ++++++++++++++++++++ 15 files changed, 1284 insertions(+), 14 deletions(-) create mode 100644 absl/log/vlog_config.cc create mode 100644 absl/log/vlog_config.h create mode 100644 absl/log/vlog_config_benchmark.cc create mode 100644 absl/log/vlog_is_on.h create mode 100644 absl/log/vlog_is_on_test.cc diff --git a/CMake/AbseilDll.cmake b/CMake/AbseilDll.cmake index 19272795..f21ba284 100644 --- a/CMake/AbseilDll.cmake +++ b/CMake/AbseilDll.cmake @@ -191,6 +191,9 @@ set(ABSL_INTERNAL_DLL_FILES "log/log_sink_registry.h" "log/log_streamer.h" "log/structured.h" + "log/vlog_config.cc" + "log/vlog_config.h" + "log/vlog_is_on.h" "memory/memory.h" "meta/type_traits.h" "numeric/bits.h" diff --git a/absl/log/BUILD.bazel b/absl/log/BUILD.bazel index 40c1bfbc..cb069381 100644 --- a/absl/log/BUILD.bazel +++ b/absl/log/BUILD.bazel @@ -50,6 +50,7 @@ cc_library( copts = ABSL_DEFAULT_COPTS, linkopts = ABSL_DEFAULT_LINKOPTS, deps = [ + ":vlog_is_on", "//absl/log/internal:log_impl", ], ) @@ -91,6 +92,7 @@ cc_library( visibility = ["//visibility:public"], deps = [ ":globals", + ":vlog_config", "//absl/base:config", "//absl/base:core_headers", "//absl/base:log_severity", @@ -143,6 +145,7 @@ cc_library( copts = ABSL_DEFAULT_COPTS, linkopts = ABSL_DEFAULT_LINKOPTS, deps = [ + ":vlog_is_on", "//absl/log/internal:log_impl", ], ) @@ -235,6 +238,86 @@ cc_library( ], ) +cc_library( + name = "vlog_config", + srcs = ["vlog_config.cc"], + hdrs = ["vlog_config.h"], + copts = ABSL_DEFAULT_COPTS, + linkopts = ABSL_DEFAULT_LINKOPTS, + visibility = ["//visibility:private"], + deps = [ + "//absl/base", + "//absl/base:config", + "//absl/base:core_headers", + "//absl/log/internal:fnmatch", + "//absl/memory", + "//absl/strings", + "//absl/synchronization", + "//absl/types:optional", + ], +) + +cc_library( + name = "vlog_is_on", + hdrs = ["vlog_is_on.h"], + copts = ABSL_DEFAULT_COPTS, + linkopts = ABSL_DEFAULT_LINKOPTS, + visibility = [ + "//absl/log:__subpackages__", + ], + deps = [ + ":vlog_config", + "//absl/base:config", + "//absl/base:core_headers", + "//absl/strings", + ], +) + +# TODO(b/200695798): run this in TAP projects with -DABSL_MAX_VLOG_VERBOSITY={-100,100} +cc_test( + name = "vlog_is_on_test", + size = "small", + srcs = [ + "vlog_is_on_test.cc", + ], + copts = ABSL_TEST_COPTS, + linkopts = ABSL_DEFAULT_LINKOPTS, + deps = [ + ":flags", + ":log", + ":scoped_mock_log", + ":vlog_is_on", + "//absl/base:log_severity", + "//absl/flags:flag", + "//absl/types:optional", + "@com_google_googletest//:gtest", + "@com_google_googletest//:gtest_main", + ], +) + +cc_test( + name = "vlog_config_benchmark", + size = "medium", + srcs = ["vlog_config_benchmark.cc"], + copts = ABSL_TEST_COPTS, + linkopts = ABSL_DEFAULT_LINKOPTS, + tags = [ + "benchmark", + "no_test_loonix", + "notsan", + ], + deps = [ + ":vlog_config", + "//absl/base:config", + "//absl/base:core_headers", + "//absl/container:layout", + "//absl/memory", + "//absl/random:distributions", + "//absl/strings", + "@com_github_google_benchmark//:benchmark_main", + ], +) + # Test targets cc_test( diff --git a/absl/log/CMakeLists.txt b/absl/log/CMakeLists.txt index aa008865..916b5bea 100644 --- a/absl/log/CMakeLists.txt +++ b/absl/log/CMakeLists.txt @@ -157,6 +157,7 @@ absl_cc_library( absl::log_internal_conditions absl::log_internal_message absl::log_internal_strip + absl::vlog_is_on ) absl_cc_library( @@ -418,6 +419,7 @@ absl_cc_library( ${ABSL_DEFAULT_LINKOPTS} DEPS absl::log_internal_log_impl + absl::vlog_is_on PUBLIC ) @@ -481,6 +483,7 @@ absl_cc_library( absl::flags absl::flags_marshalling absl::strings + absl::vlog_config_internal PUBLIC ) @@ -536,6 +539,7 @@ absl_cc_library( ${ABSL_DEFAULT_LINKOPTS} DEPS absl::log_internal_log_impl + absl::vlog_is_on PUBLIC ) @@ -673,19 +677,78 @@ absl_cc_library( ) absl_cc_library( - NAME - log_internal_fnmatch - SRCS - "internal/fnmatch.cc" - HDRS - "internal/fnmatch.h" - COPTS - ${ABSL_DEFAULT_COPTS} - LINKOPTS - ${ABSL_DEFAULT_LINKOPTS} - DEPS - absl::config - absl::strings + NAME + vlog_config_internal + SRCS + "vlog_config.cc" + HDRS + "vlog_config.h" + COPTS + ${ABSL_DEFAULT_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + DEPS + absl::base + absl::config + absl::core_headers + absl::log_internal_fnmatch + absl::memory + absl::strings + absl::synchronization + absl::optional +) + + +absl_cc_library( + NAME + vlog_is_on + COPTS + ${ABSL_DEFAULT_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + HDRS + "vlog_is_on.h" + DEPS + absl::vlog_config_internal + absl::config + absl::core_headers + absl::strings +) + +absl_cc_test( + NAME + vlog_is_on_test + SRCS + "vlog_is_on_test.cc" + COPTS + ${ABSL_TEST_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + DEPS + absl::log_flags + absl::log + absl::scoped_mock_log + absl::vlog_is_on + absl::log_severity + absl::flags + absl::optional + GTest::gmock_main +) + +absl_cc_library( + NAME + log_internal_fnmatch + SRCS + "internal/fnmatch.cc" + HDRS + "internal/fnmatch.h" + COPTS + ${ABSL_DEFAULT_COPTS} + LINKOPTS + ${ABSL_DEFAULT_LINKOPTS} + DEPS + absl::config + absl::strings ) # Test targets diff --git a/absl/log/absl_log.h b/absl/log/absl_log.h index 0517760b..0fd9ae3f 100644 --- a/absl/log/absl_log.h +++ b/absl/log/absl_log.h @@ -39,6 +39,9 @@ #define ABSL_PLOG(severity) ABSL_LOG_INTERNAL_PLOG_IMPL(_##severity) #define ABSL_DLOG(severity) ABSL_LOG_INTERNAL_DLOG_IMPL(_##severity) +#define ABSL_VLOG(verbose_level) ABSL_LOG_INTERNAL_VLOG_IMPL(verbose_level) +#define ABSL_DVLOG(verbose_level) ABSL_LOG_INTERNAL_DVLOG_IMPL(verbose_level) + #define ABSL_LOG_IF(severity, condition) \ ABSL_LOG_INTERNAL_LOG_IF_IMPL(_##severity, condition) #define ABSL_PLOG_IF(severity, condition) \ @@ -73,6 +76,15 @@ #define ABSL_DLOG_EVERY_N_SEC(severity, n_seconds) \ ABSL_LOG_INTERNAL_DLOG_EVERY_N_SEC_IMPL(_##severity, n_seconds) +#define ABSL_VLOG_EVERY_N(verbose_level, n) \ + ABSL_LOG_INTERNAL_VLOG_EVERY_N_IMPL(verbose_level, n) +#define ABSL_VLOG_FIRST_N(verbose_level, n) \ + ABSL_LOG_INTERNAL_VLOG_FIRST_N_IMPL(verbose_level, n) +#define ABSL_VLOG_EVERY_POW_2(verbose_level, n) \ + ABSL_LOG_INTERNAL_VLOG_EVERY_POW_2_IMPL(verbose_level, n) +#define ABSL_VLOG_EVERY_N_SEC(verbose_level, n) \ + ABSL_LOG_INTERNAL_VLOG_EVERY_N_SEC_IMPL(verbose_level, n) + #define ABSL_LOG_IF_EVERY_N(severity, condition, n) \ ABSL_LOG_INTERNAL_LOG_IF_EVERY_N_IMPL(_##severity, condition, n) #define ABSL_LOG_IF_FIRST_N(severity, condition, n) \ diff --git a/absl/log/flags.cc b/absl/log/flags.cc index 215b7bd5..dfb0d8e6 100644 --- a/absl/log/flags.cc +++ b/absl/log/flags.cc @@ -28,6 +28,7 @@ #include "absl/flags/marshalling.h" #include "absl/log/globals.h" #include "absl/log/internal/config.h" +#include "absl/log/vlog_config.h" #include "absl/strings/numbers.h" #include "absl/strings/string_view.h" @@ -118,3 +119,25 @@ ABSL_FLAG(bool, log_prefix, true, .OnUpdate([] { absl::log_internal::RawEnableLogPrefix(absl::GetFlag(FLAGS_log_prefix)); }); + +ABSL_FLAG(int, v, 0, + "Show all VLOG(m) messages for m <= this. Overridable by --vmodule.") + .OnUpdate([] { + absl::log_internal::UpdateGlobalVLogLevel(absl::GetFlag(FLAGS_v)); + }); + +ABSL_FLAG( + std::string, vmodule, "", + "per-module log verbosity level." + " Argument is a comma-separated list of =." + " is a glob pattern, matched against the filename base" + " (that is, name ignoring .cc/.h./-inl.h)." + " A pattern without slashes matches just the file name portion, otherwise" + " the whole file path below the workspace root" + " (still without .cc/.h./-inl.h) is matched." + " ? and * in the glob pattern match any single or sequence of characters" + " respectively including slashes." + " overrides any value given by --v.") + .OnUpdate([] { + absl::log_internal::UpdateVModule(absl::GetFlag(FLAGS_vmodule)); + }); diff --git a/absl/log/internal/BUILD.bazel b/absl/log/internal/BUILD.bazel index 2030a3d7..90643a5e 100644 --- a/absl/log/internal/BUILD.bazel +++ b/absl/log/internal/BUILD.bazel @@ -153,6 +153,7 @@ cc_library( ":conditions", ":log_message", ":strip", + "//absl/log:vlog_is_on", ], ) diff --git a/absl/log/internal/flags.h b/absl/log/internal/flags.h index b91b8644..c4539785 100644 --- a/absl/log/internal/flags.h +++ b/absl/log/internal/flags.h @@ -50,4 +50,10 @@ ABSL_DECLARE_FLAG(std::string, log_backtrace_at); // each message logged. Defaults to true. ABSL_DECLARE_FLAG(bool, log_prefix); +// Global log verbosity level. Default is 0. +ABSL_DECLARE_FLAG(int, v); + +// Per-module log verbosity level. By default is empty and is unused. +ABSL_DECLARE_FLAG(std::string, vmodule); + #endif // ABSL_LOG_INTERNAL_FLAGS_H_ diff --git a/absl/log/internal/log_impl.h b/absl/log/internal/log_impl.h index 9326780d..ba90eda8 100644 --- a/absl/log/internal/log_impl.h +++ b/absl/log/internal/log_impl.h @@ -18,6 +18,7 @@ #include "absl/log/internal/conditions.h" #include "absl/log/internal/log_message.h" #include "absl/log/internal/strip.h" +#include "absl/log/vlog_is_on.h" // ABSL_LOG() #define ABSL_LOG_INTERNAL_LOG_IMPL(severity) \ @@ -41,6 +42,35 @@ ABSL_LOGGING_INTERNAL_LOG##severity.InternalStream() #endif +// The `switch` ensures that this expansion is the begnning of a statement (as +// opposed to an expression). The use of both `case 0` and `default` is to +// suppress a compiler warning. +#define ABSL_LOG_INTERNAL_VLOG_IMPL(verbose_level) \ + switch (const int absl_logging_internal_verbose_level = (verbose_level)) \ + case 0: \ + default: \ + ABSL_LOG_INTERNAL_LOG_IF_IMPL( \ + _INFO, VLOG_IS_ON(absl_logging_internal_verbose_level)) \ + .WithVerbosity(absl_logging_internal_verbose_level) + +#ifndef NDEBUG +#define ABSL_LOG_INTERNAL_DVLOG_IMPL(verbose_level) \ + switch (const int absl_logging_internal_verbose_level = (verbose_level)) \ + case 0: \ + default: \ + ABSL_LOG_INTERNAL_LOG_IF_IMPL( \ + _INFO, VLOG_IS_ON(absl_logging_internal_verbose_level)) \ + .WithVerbosity(absl_logging_internal_verbose_level) +#else +#define ABSL_LOG_INTERNAL_DVLOG_IMPL(verbose_level) \ + switch (const int absl_logging_internal_verbose_level = (verbose_level)) \ + case 0: \ + default: \ + ABSL_LOG_INTERNAL_LOG_IF_IMPL( \ + _INFO, false && VLOG_IS_ON(absl_logging_internal_verbose_level)) \ + .WithVerbosity(absl_logging_internal_verbose_level) +#endif + #define ABSL_LOG_INTERNAL_LOG_IF_IMPL(severity, condition) \ ABSL_LOG_INTERNAL_CONDITION##severity(STATELESS, condition) \ ABSL_LOGGING_INTERNAL_LOG##severity.InternalStream() @@ -134,6 +164,42 @@ (EveryNSec, n_seconds) ABSL_LOGGING_INTERNAL_LOG##severity.InternalStream() #endif // def NDEBUG +#define ABSL_LOG_INTERNAL_VLOG_EVERY_N_IMPL(verbose_level, n) \ + switch (const int absl_logging_internal_verbose_level = (verbose_level)) \ + case 0: \ + default: \ + ABSL_LOG_INTERNAL_CONDITION_INFO( \ + STATEFUL, VLOG_IS_ON(absl_logging_internal_verbose_level)) \ + (EveryN, n) ABSL_LOGGING_INTERNAL_LOG_INFO.InternalStream().WithVerbosity( \ + absl_logging_internal_verbose_level) + +#define ABSL_LOG_INTERNAL_VLOG_FIRST_N_IMPL(verbose_level, n) \ + switch (const int absl_logging_internal_verbose_level = (verbose_level)) \ + case 0: \ + default: \ + ABSL_LOG_INTERNAL_CONDITION_INFO( \ + STATEFUL, VLOG_IS_ON(absl_logging_internal_verbose_level)) \ + (FirstN, n) ABSL_LOGGING_INTERNAL_LOG_INFO.InternalStream().WithVerbosity( \ + absl_logging_internal_verbose_level) + +#define ABSL_LOG_INTERNAL_VLOG_EVERY_POW_2_IMPL(verbose_level) \ + switch (const int absl_logging_internal_verbose_level = (verbose_level)) \ + case 0: \ + default: \ + ABSL_LOG_INTERNAL_CONDITION_INFO( \ + STATEFUL, VLOG_IS_ON(absl_logging_internal_verbose_level)) \ + (EveryPow2) ABSL_LOGGING_INTERNAL_LOG_INFO.InternalStream().WithVerbosity( \ + absl_logging_internal_verbose_level) + +#define ABSL_LOG_INTERNAL_VLOG_EVERY_N_SEC_IMPL(verbose_level, n_seconds) \ + switch (const int absl_logging_internal_verbose_level = (verbose_level)) \ + case 0: \ + default: \ + ABSL_LOG_INTERNAL_CONDITION_INFO( \ + STATEFUL, VLOG_IS_ON(absl_logging_internal_verbose_level)) \ + (EveryNSec, n_seconds) ABSL_LOGGING_INTERNAL_LOG_INFO.InternalStream() \ + .WithVerbosity(absl_logging_internal_verbose_level) + #define ABSL_LOG_INTERNAL_LOG_IF_EVERY_N_IMPL(severity, condition, n) \ ABSL_LOG_INTERNAL_CONDITION##severity(STATEFUL, condition)(EveryN, n) \ ABSL_LOGGING_INTERNAL_LOG##severity.InternalStream() diff --git a/absl/log/log.h b/absl/log/log.h index 99e78ea8..b721b087 100644 --- a/absl/log/log.h +++ b/absl/log/log.h @@ -53,6 +53,14 @@ // * .NoPrefix() // Omits the prefix from this line. The prefix includes metadata about the // logged data such as source code location and timestamp. +// * .WithVerbosity(int verbose_level) +// Sets the verbosity field of the logged message as if it was logged by +// `VLOG(verbose_level)`. Unlike `VLOG`, this method does not affect +// evaluation of the statement when the specified `verbose_level` has been +// disabled. The only effect is on `LogSink` implementations which make use +// of the `absl::LogSink::verbosity()` value. The value +// `absl::LogEntry::kNoVerbosityLevel` can be specified to mark the message +// not verbose. // * .WithTimestamp(absl::Time timestamp) // Uses the specified timestamp instead of one collected at the time of // execution. @@ -190,6 +198,7 @@ #define ABSL_LOG_LOG_H_ #include "absl/log/internal/log_impl.h" +#include "absl/log/vlog_is_on.h" // IWYU pragma: export // LOG() // @@ -213,11 +222,32 @@ // terminate the program if `NDEBUG` is defined. #define DLOG(severity) ABSL_LOG_INTERNAL_DLOG_IMPL(_##severity) +// `VLOG` uses numeric levels to provide verbose logging that can configured at +// runtime, including at a per-module level. `VLOG` statements are logged at +// `INFO` severity if they are logged at all; the numeric levels are on a +// different scale than the proper severity levels. Positive levels are +// disabled by default. Negative levels should not be used. +// Example: +// +// VLOG(1) << "I print when you run the program with --v=1 or higher"; +// VLOG(2) << "I print when you run the program with --v=2 or higher"; +// +// See vlog_is_on.h for further documentation, including the usage of the +// --vmodule flag to log at different levels in different source files. +#define VLOG(severity) ABSL_LOG_INTERNAL_VLOG_IMPL(severity) + +// `DVLOG` behaves like `VLOG` in debug mode (i.e. `#ifndef NDEBUG`). +// Otherwise, it compiles away and does nothing. +#define DVLOG(severity) ABSL_LOG_INTERNAL_DVLOG_IMPL(severity) + // `LOG_IF` and friends add a second argument which specifies a condition. If // the condition is false, nothing is logged. // Example: // // LOG_IF(INFO, num_cookies > 10) << "Got lots of cookies"; +// +// There is no `VLOG_IF` because the order of evaluation of the arguments is +// ambiguous and the alternate spelling with an `if`-statement is trivial. #define LOG_IF(severity, condition) \ ABSL_LOG_INTERNAL_LOG_IF_IMPL(_##severity, condition) #define PLOG_IF(severity, condition) \ @@ -285,6 +315,15 @@ #define DLOG_EVERY_N_SEC(severity, n_seconds) \ ABSL_LOG_INTERNAL_DLOG_EVERY_N_SEC_IMPL(_##severity, n_seconds) +#define VLOG_EVERY_N(severity, n) \ + ABSL_LOG_INTERNAL_VLOG_EVERY_N_IMPL(severity, n) +#define VLOG_FIRST_N(severity, n) \ + ABSL_LOG_INTERNAL_VLOG_FIRST_N_IMPL(severity, n) +#define VLOG_EVERY_POW_2(severity) \ + ABSL_LOG_INTERNAL_VLOG_EVERY_POW_2_IMPL(severity) +#define VLOG_EVERY_N_SEC(severity, n_seconds) \ + ABSL_LOG_INTERNAL_VLOG_EVERY_N_SEC_IMPL(severity, n_seconds) + // `LOG_IF_EVERY_N` and friends behave as the corresponding `LOG_EVERY_N` // but neither increment a counter nor log a message if condition is false (as // `LOG_IF`). diff --git a/absl/log/log_entry.h b/absl/log/log_entry.h index 9e4ae8eb..7a55dfe2 100644 --- a/absl/log/log_entry.h +++ b/absl/log/log_entry.h @@ -96,7 +96,8 @@ class LogEntry final { // LogEntry::verbosity() // // Returns this entry's verbosity, or `kNoVerbosityLevel` for a non-verbose - // entry. Verbosity control is not available outside of Google yet. + // entry. Taken from the argument to `VLOG` or from + // `LOG(...).WithVerbosity(...)`. int verbosity() const { return verbose_level_; } // LogEntry::timestamp() diff --git a/absl/log/vlog_config.cc b/absl/log/vlog_config.cc new file mode 100644 index 00000000..7375b279 --- /dev/null +++ b/absl/log/vlog_config.cc @@ -0,0 +1,334 @@ +// Copyright 2022 The Abseil Authors +// +// 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 +// +// https://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 "absl/log/vlog_config.h" + +#include + +#include +#include +#include +#include +#include +#include +#include + +#include "absl/base/attributes.h" +#include "absl/base/config.h" +#include "absl/base/const_init.h" +#include "absl/base/internal/spinlock.h" +#include "absl/base/optimization.h" +#include "absl/base/thread_annotations.h" +#include "absl/log/internal/fnmatch.h" +#include "absl/memory/memory.h" +#include "absl/strings/numbers.h" +#include "absl/strings/str_split.h" +#include "absl/strings/string_view.h" +#include "absl/strings/strip.h" +#include "absl/synchronization/mutex.h" +#include "absl/types/optional.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN +namespace log_internal { +namespace { +bool ModuleIsPath(absl::string_view module_pattern) { +#ifdef _WIN32 + return module_pattern.find_first_of("/\\") != module_pattern.npos; +#else + return module_pattern.find('/') != module_pattern.npos; +#endif +} +} // namespace +} // namespace log_internal + +bool VLogSite::SlowIsEnabled(int stale_v, int level) { + if (ABSL_PREDICT_TRUE(stale_v != kUninitialized)) { + // Because of the prerequisites to this function, we know that stale_v is + // either uninitialized or >= level. If it's not uninitialized, that means + // it must be >= level, thus we should log. + return true; + } + stale_v = log_internal::RegisterAndInitialize(this); + return ABSL_PREDICT_FALSE(stale_v >= level); +} + +bool VLogSite::SlowIsEnabled0(int stale_v) { return SlowIsEnabled(stale_v, 0); } +bool VLogSite::SlowIsEnabled1(int stale_v) { return SlowIsEnabled(stale_v, 1); } +bool VLogSite::SlowIsEnabled2(int stale_v) { return SlowIsEnabled(stale_v, 2); } +bool VLogSite::SlowIsEnabled3(int stale_v) { return SlowIsEnabled(stale_v, 3); } +bool VLogSite::SlowIsEnabled4(int stale_v) { return SlowIsEnabled(stale_v, 4); } +bool VLogSite::SlowIsEnabled5(int stale_v) { return SlowIsEnabled(stale_v, 5); } + +namespace log_internal { +namespace { +struct VModuleInfo final { + std::string module_pattern; + bool module_is_path; // i.e. it contains a path separator. + int vlog_level; + + // Allocates memory. + VModuleInfo(absl::string_view module_pattern_arg, bool module_is_path_arg, + int vlog_level_arg) + : module_pattern(std::string(module_pattern_arg)), + module_is_path(module_is_path_arg), + vlog_level(vlog_level_arg) {} +}; + +// `mutex` guards all of the data structures that aren't lock-free. +// To avoid problems with the heap checker which calls into `VLOG`, `mutex` must +// be a `SpinLock` that prevents fiber scheduling instead of a `Mutex`. +ABSL_CONST_INIT absl::base_internal::SpinLock mutex( + absl::kConstInit, absl::base_internal::SCHEDULE_KERNEL_ONLY); +// `update_sites_mutex` serializes updates to all of the sites (i.e. those in +// `site_list_head`) themselves. +ABSL_CONST_INIT absl::Mutex update_sites_mutex + ABSL_ACQUIRED_AFTER(mutex)(absl::kConstInit); + +ABSL_CONST_INIT int global_v ABSL_GUARDED_BY(mutex) = 0; +// `site_list_head` is the head of a singly-linked list. Traversal, insertion, +// and reads are atomic, so no locks are required, but updates to existing +// elements are guarded by `update_sites_mutex`. +ABSL_CONST_INIT std::atomic site_list_head{nullptr}; +ABSL_CONST_INIT std::vector* vmodule_info ABSL_GUARDED_BY(mutex) + ABSL_PT_GUARDED_BY(mutex){nullptr}; + +// Only used for lisp. +ABSL_CONST_INIT std::vector>* update_callbacks + ABSL_GUARDED_BY(update_sites_mutex) + ABSL_PT_GUARDED_BY(update_sites_mutex){nullptr}; + +// Allocates memory. +std::vector& get_vmodule_info() + ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex) { + if (!vmodule_info) vmodule_info = new std::vector; + return *vmodule_info; +} + +// Does not allocate or take locks. +int VLogLevel(absl::string_view file, const std::vector* infos, + int current_global_v) { + // `infos` is null during a call to `VLOG` prior to setting `vmodule` (e.g. by + // parsing flags). We can't allocate in `VLOG`, so we treat null as empty + // here and press on. + if (!infos || infos->empty()) return current_global_v; + // Get basename for file + absl::string_view basename = file; + { + const size_t sep = basename.rfind('/'); + if (sep != basename.npos) { + basename.remove_prefix(sep + 1); +#ifdef _WIN32 + } else { + const size_t sep = basename.rfind('\\'); + if (sep != basename.npos) basename.remove_prefix(sep + 1); +#endif + } + } + + absl::string_view stem = file, stem_basename = basename; + { + const size_t sep = stem_basename.find('.'); + if (sep != stem_basename.npos) { + stem.remove_suffix(stem_basename.size() - sep); + stem_basename.remove_suffix(stem_basename.size() - sep); + } + if (absl::ConsumeSuffix(&stem_basename, "-inl")) { + stem.remove_suffix(absl::string_view("-inl").size()); + } + } + for (const auto& info : *infos) { + if (info.module_is_path) { + // If there are any slashes in the pattern, try to match the full + // name. + if (FNMatch(info.module_pattern, stem)) { + return info.vlog_level == kUseFlag ? current_global_v : info.vlog_level; + } + } else if (FNMatch(info.module_pattern, stem_basename)) { + return info.vlog_level == kUseFlag ? current_global_v : info.vlog_level; + } + } + + return current_global_v; +} + +// Allocates memory. +int AppendVModuleLocked(absl::string_view module_pattern, int log_level) + ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex) { + for (const auto& info : get_vmodule_info()) { + if (FNMatch(info.module_pattern, module_pattern)) { + // This is a memory optimization to avoid storing patterns that will never + // match due to exit early semantics. Primarily optimized for our own unit + // tests. + return info.vlog_level; + } + } + bool module_is_path = ModuleIsPath(module_pattern); + get_vmodule_info().emplace_back(std::string(module_pattern), module_is_path, + log_level); + return global_v; +} + +// Allocates memory. +int PrependVModuleLocked(absl::string_view module_pattern, int log_level) + ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex) { + absl::optional old_log_level; + for (const auto& info : get_vmodule_info()) { + if (FNMatch(info.module_pattern, module_pattern)) { + old_log_level = info.vlog_level; + break; + } + } + bool module_is_path = ModuleIsPath(module_pattern); + auto iter = get_vmodule_info().emplace(get_vmodule_info().cbegin(), + std::string(module_pattern), + module_is_path, log_level); + + // This is a memory optimization to avoid storing patterns that will never + // match due to exit early semantics. Primarily optimized for our own unit + // tests. + get_vmodule_info().erase( + std::remove_if(++iter, get_vmodule_info().end(), + [module_pattern](const VModuleInfo& info) { + return FNMatch(info.module_pattern, module_pattern); + }), + get_vmodule_info().cend()); + return old_log_level.value_or(global_v); +} +} // namespace + +int VLogLevel(absl::string_view file) ABSL_LOCKS_EXCLUDED(mutex) { + absl::base_internal::SpinLockHolder l(&mutex); + return VLogLevel(file, vmodule_info, global_v); +} + +int RegisterAndInitialize(VLogSite* v) ABSL_LOCKS_EXCLUDED(mutex) { + // std::memory_order_seq_cst is overkill in this function, but given that this + // path is intended to be slow, it's not worth the brain power to relax that. + VLogSite* h = site_list_head.load(std::memory_order_seq_cst); + + VLogSite* old = nullptr; + if (v->next_.compare_exchange_strong(old, h, std::memory_order_seq_cst, + std::memory_order_seq_cst)) { + // Multiple threads may attempt to register this site concurrently. + // By successfully setting `v->next` this thread commits to being *the* + // thread that installs `v` in the list. + while (!site_list_head.compare_exchange_weak( + h, v, std::memory_order_seq_cst, std::memory_order_seq_cst)) { + v->next_.store(h, std::memory_order_seq_cst); + } + } + + int old_v = VLogSite::kUninitialized; + int new_v = VLogLevel(v->file_); + // No loop, if someone else set this, we should respect their evaluation of + // `VLogLevel`. This may mean we return a stale `v`, but `v` itself will + // always arrive at the freshest value. Otherwise, we could be writing a + // stale value and clobbering the fresher one. + if (v->v_.compare_exchange_strong(old_v, new_v, std::memory_order_seq_cst, + std::memory_order_seq_cst)) { + return new_v; + } + return old_v; +} + +void UpdateVLogSites() ABSL_UNLOCK_FUNCTION(mutex) + ABSL_LOCKS_EXCLUDED(update_sites_mutex) { + std::vector infos = get_vmodule_info(); + int current_global_v = global_v; + // We need to grab `update_sites_mutex` before we release `mutex` to ensure + // that updates are not interleaved (resulting in an inconsistent final state) + // and to ensure that the final state in the sites matches the final state of + // `vmodule_info`. We unlock `mutex` to ensure that uninitialized sites don't + // have to wait on all updates in order to acquire `mutex` and initialize + // themselves. + absl::MutexLock ul(&update_sites_mutex); + mutex.Unlock(); + VLogSite* n = site_list_head.load(std::memory_order_seq_cst); + // Because sites are added to the list in the order they are executed, there + // tend to be clusters of entries with the same file. + const char* last_file = nullptr; + int last_file_level = 0; + while (n != nullptr) { + if (n->file_ != last_file) { + last_file = n->file_; + last_file_level = VLogLevel(n->file_, &infos, current_global_v); + } + n->v_.store(last_file_level, std::memory_order_seq_cst); + n = n->next_.load(std::memory_order_seq_cst); + } + if (update_callbacks) { + for (auto& cb : *update_callbacks) { + cb(); + } + } +} + +void UpdateVModule(absl::string_view vmodule) + ABSL_LOCKS_EXCLUDED(mutex, update_sites_mutex) { + std::vector> glob_levels; + for (absl::string_view glob_level : absl::StrSplit(vmodule, ',')) { + const size_t eq = glob_level.rfind('='); + if (eq == glob_level.npos) continue; + const absl::string_view glob = glob_level.substr(0, eq); + int level; + if (!absl::SimpleAtoi(glob_level.substr(eq + 1), &level)) continue; + glob_levels.emplace_back(glob, level); + } + mutex.Lock(); // Unlocked by UpdateVLogSites(). + get_vmodule_info().clear(); + for (const auto& it : glob_levels) { + const absl::string_view glob = it.first; + const int level = it.second; + AppendVModuleLocked(glob, level); + } + UpdateVLogSites(); +} + +int UpdateGlobalVLogLevel(int v) + ABSL_LOCKS_EXCLUDED(mutex, update_sites_mutex) { + mutex.Lock(); // Unlocked by UpdateVLogSites(). + const int old_global_v = global_v; + if (v == global_v) { + mutex.Unlock(); + return old_global_v; + } + global_v = v; + UpdateVLogSites(); + return old_global_v; +} + +int PrependVModule(absl::string_view module_pattern, int log_level) + ABSL_LOCKS_EXCLUDED(mutex, update_sites_mutex) { + mutex.Lock(); // Unlocked by UpdateVLogSites(). + int old_v = PrependVModuleLocked(module_pattern, log_level); + UpdateVLogSites(); + return old_v; +} + +void OnVLogVerbosityUpdate(std::function cb) + ABSL_LOCKS_EXCLUDED(update_sites_mutex) { + absl::MutexLock ul(&update_sites_mutex); + if (!update_callbacks) + update_callbacks = new std::vector>; + update_callbacks->push_back(std::move(cb)); +} + +VLogSite* SetVModuleListHeadForTestOnly(VLogSite* v) { + return site_list_head.exchange(v, std::memory_order_seq_cst); +} + +} // namespace log_internal +ABSL_NAMESPACE_END +} // namespace absl diff --git a/absl/log/vlog_config.h b/absl/log/vlog_config.h new file mode 100644 index 00000000..9ff56265 --- /dev/null +++ b/absl/log/vlog_config.h @@ -0,0 +1,162 @@ +// Copyright 2022 The Abseil Authors +// +// 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 +// +// https://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. +// +// ----------------------------------------------------------------------------- +// vlog_config.h +// ----------------------------------------------------------------------------- +// +// This header file defines `VLogSite`, a public primitive that represents +// a callsite for the `VLOG` family of macros and related libraries. +// It also declares and defines multiple internal utilities used to implement +// `VLOG`, such as `VLogSiteManager`. + +#ifndef ABSL_LOG_VLOG_CONFIG_H_ +#define ABSL_LOG_VLOG_CONFIG_H_ + +// IWYU pragma: private, include "absl/log/log.h" + +#include +#include +#include +#include +#include + +#include "absl/base/attributes.h" +#include "absl/base/config.h" +#include "absl/base/optimization.h" +#include "absl/base/thread_annotations.h" +#include "absl/strings/string_view.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN +class VLogSite; +namespace log_internal { +class SyntheticBinary; +int RegisterAndInitialize(VLogSite* v); +void UpdateVLogSites(); +constexpr int kUseFlag = (std::numeric_limits::min)(); +} // namespace log_internal + +// Represents a unique callsite for a `VLOG()` or `VLOG_IS_ON()` call. +// +// Libraries that provide `VLOG`-like functionality should use this to +// efficiently handle --vmodule. +// +// VLogSite objects must not be destroyed until the program exits. Doing so will +// probably yield nasty segfaults in VLogSiteManager::UpdateLogSites(). The +// recommendation is to make all such objects function-local statics. +class VLogSite final { + public: + // `f` must not be destroyed until the program exits. + explicit constexpr VLogSite(const char* f) + : file_(f), v_(kUninitialized), next_(nullptr) {} + VLogSite(const VLogSite&) = delete; + VLogSite& operator=(const VLogSite&) = delete; + + // Inlining the function yields a ~3x performance improvement at the cost of a + // 1.5x code size increase at the call site. + // Takes locks but does not allocate memory. + ABSL_ATTRIBUTE_ALWAYS_INLINE + bool IsEnabled(int level) { + int stale_v = v_.load(std::memory_order_relaxed); + if (ABSL_PREDICT_TRUE(level > stale_v)) { + return false; + } + + // We put everything other than the fast path, i.e. vlogging is initialized + // but not on, behind an out-of-line function to reduce code size. + // "level" is almost always a call-site constant, so we can save a bit + // of code space by special-casing for a few common levels. +#if ABSL_HAVE_BUILTIN(__builtin_constant_p) || defined(__GNUC__) + if (__builtin_constant_p(level)) { + if (level == 0) return SlowIsEnabled0(stale_v); + if (level == 1) return SlowIsEnabled1(stale_v); + if (level == 2) return SlowIsEnabled2(stale_v); + if (level == 3) return SlowIsEnabled3(stale_v); + if (level == 4) return SlowIsEnabled4(stale_v); + if (level == 5) return SlowIsEnabled5(stale_v); + } +#endif + return SlowIsEnabled(stale_v, level); + } + + private: + friend int log_internal::RegisterAndInitialize(VLogSite* v); + friend void log_internal::UpdateVLogSites(); + friend class log_internal::SyntheticBinary; + static constexpr int kUninitialized = (std::numeric_limits::max)(); + + // SlowIsEnabled performs slower checks to determine whether a log site is + // enabled. Because it is expected to be called somewhat rarely + // (comparatively), it is not inlined to save on code size. + // + // Prerequisites to calling SlowIsEnabled: + // 1) stale_v is uninitialized OR + // 2) stale_v is initialized and >= level (meaning we must log). + // Takes locks but does not allocate memory. + ABSL_ATTRIBUTE_NOINLINE + bool SlowIsEnabled(int stale_v, int level); + ABSL_ATTRIBUTE_NOINLINE bool SlowIsEnabled0(int stale_v); + ABSL_ATTRIBUTE_NOINLINE bool SlowIsEnabled1(int stale_v); + ABSL_ATTRIBUTE_NOINLINE bool SlowIsEnabled2(int stale_v); + ABSL_ATTRIBUTE_NOINLINE bool SlowIsEnabled3(int stale_v); + ABSL_ATTRIBUTE_NOINLINE bool SlowIsEnabled4(int stale_v); + ABSL_ATTRIBUTE_NOINLINE bool SlowIsEnabled5(int stale_v); + + // This object is too size-sensitive to use absl::string_view. + const char* const file_; + std::atomic v_; + std::atomic next_; +}; +static_assert(std::is_trivially_destructible::value, + "VLogSite must be trivially destructible"); + +namespace log_internal { +// Returns the current verbose log level of `file`. +// Does not allocate memory. +int VLogLevel(absl::string_view file); + +// Registers a site `v` to get updated as `vmodule` and `v` change. Also +// initializes the site based on their current values, and returns that result. +// Does not allocate memory. +int RegisterAndInitialize(VLogSite* v); + +// Allocates memory. +void UpdateVLogSites(); + +// Completely overwrites the saved value of `vmodule`. +// Allocates memory. +void UpdateVModule(absl::string_view vmodule); + +// Updates the global verbosity level to `v` and returns the prior value. +// Allocates memory. +int UpdateGlobalVLogLevel(int v); + +// Atomically prepends `module_pattern=log_level` to the start of vmodule. +// Returns the prior value for `module_pattern` if there was an exact match and +// `global_v` otherwise. +// Allocates memory. +int PrependVModule(absl::string_view module_pattern, int log_level); + +// Registers `on_update` to be called whenever `v` or `vmodule` change. +// Allocates memory. +void OnVLogVerbosityUpdate(std::function cb); + +// Does not allocate memory. +VLogSite* SetVModuleListHeadForTestOnly(VLogSite* v); +} // namespace log_internal +ABSL_NAMESPACE_END +} // namespace absl + +#endif // ABSL_LOG_VLOG_CONFIG_H_ diff --git a/absl/log/vlog_config_benchmark.cc b/absl/log/vlog_config_benchmark.cc new file mode 100644 index 00000000..78994b76 --- /dev/null +++ b/absl/log/vlog_config_benchmark.cc @@ -0,0 +1,187 @@ +// Copyright 2022 The Abseil Authors +// +// 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 +// +// https://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 +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "absl/base/config.h" +#include "absl/container/internal/layout.h" +#include "absl/log/vlog_config.h" +#include "absl/memory/memory.h" +#include "absl/random/distributions.h" +#include "absl/strings/str_cat.h" +#include "benchmark/benchmark.h" + +namespace absl { +ABSL_NAMESPACE_BEGIN +namespace log_internal { +// Performance of `UpdateLogSites` depends upon the number and organization of +// `VLogSite`s in the program. We can synthesize some on the heap to mimic +// their layout and linkage in static data. +class SyntheticBinary { + public: + explicit SyntheticBinary(const size_t num_tus, + const size_t max_extra_static_data_bytes_per_tu, + const size_t max_sites_per_tu, + const int num_shuffles) { + per_tu_data_.reserve(num_tus); + auto sites = absl::make_unique(num_tus * max_sites_per_tu); + for (size_t i = 0; i < num_tus; i++) { + const std::string filename = + absl::StrCat("directory-", i / 100, "/subdirectory-", i % 100 / 10, + "/file-", i % 10, ".cc"); + container_internal::Layout layout( + filename.size() + 1, + absl::LogUniform(bitgen_, 1, max_sites_per_tu), + absl::LogUniform(bitgen_, 0, + max_extra_static_data_bytes_per_tu)); + auto buf = absl::make_unique(layout.AllocSize()); + layout.PoisonPadding(buf.get()); + memcpy(layout.Pointer<0>(buf.get()), filename.c_str(), + filename.size() + 1); + for (VLogSite &site : layout.Slice<1>(buf.get())) { + sites[num_sites_++] = + new (&site) VLogSite(layout.Pointer<0>(buf.get())); + // The last one is a dangling pointer but will be fixed below. + site.next_.store(&site + 1, std::memory_order_seq_cst); + } + num_extra_static_data_bytes_ += layout.Size<2>(); + per_tu_data_.push_back(PerTU{layout, std::move(buf)}); + } + // Now link the files together back-to-front into a circular list. + for (size_t i = 0; i < num_tus; i++) { + auto &tu = per_tu_data_[i]; + auto &next_tu = per_tu_data_[(i + 1) % num_tus]; + tu.layout.Slice<1>(tu.buf.get()) + .back() + .next_.store(next_tu.layout.Pointer<1>(next_tu.buf.get()), + std::memory_order_seq_cst); + } + // Now do some shufflin'. + auto new_sites = absl::make_unique(num_sites_); + for (int shuffle_num = 0; shuffle_num < num_shuffles; shuffle_num++) { + // Each shuffle cuts the ring into three pieces and rearranges them. + const size_t cut_a = absl::Uniform(bitgen_, size_t{0}, num_sites_); + const size_t cut_b = absl::Uniform(bitgen_, size_t{0}, num_sites_); + const size_t cut_c = absl::Uniform(bitgen_, size_t{0}, num_sites_); + if (cut_a == cut_b || cut_b == cut_c || cut_a == cut_c) continue; + // The same cuts, sorted: + const size_t cut_1 = std::min({cut_a, cut_b, cut_c}); + const size_t cut_3 = std::max({cut_a, cut_b, cut_c}); + const size_t cut_2 = cut_a ^ cut_b ^ cut_c ^ cut_1 ^ cut_3; + VLogSite *const tmp = sites[cut_1]->next_.load(std::memory_order_seq_cst); + sites[cut_1]->next_.store( + sites[cut_2]->next_.load(std::memory_order_seq_cst), + std::memory_order_seq_cst); + sites[cut_2]->next_.store( + sites[cut_3]->next_.load(std::memory_order_seq_cst), + std::memory_order_seq_cst); + sites[cut_3]->next_.store(tmp, std::memory_order_seq_cst); + memcpy(&new_sites[0], &sites[0], sizeof(VLogSite *) * (cut_1 + 1)); + memcpy(&new_sites[cut_1 + 1], &sites[cut_2 + 1], + sizeof(VLogSite *) * (cut_3 - cut_2)); + memcpy(&new_sites[cut_1 + 1 + cut_3 - cut_2], &sites[cut_1 + 1], + sizeof(VLogSite *) * (cut_2 - cut_1)); + memcpy(&new_sites[cut_3 + 1], &sites[cut_3 + 1], + sizeof(VLogSite *) * (num_sites_ - cut_3 - 1)); + sites.swap(new_sites); + } + const char *last_file = nullptr; + for (size_t i = 0; i < num_sites_; i++) { + if (sites[i]->file_ == last_file) continue; + last_file = sites[i]->file_; + num_new_files_++; + } + absl::log_internal::SetVModuleListHeadForTestOnly(sites[0]); + sites[num_tus - 1]->next_.store(nullptr, std::memory_order_seq_cst); + } + ~SyntheticBinary() { + static_assert(std::is_trivially_destructible::value, ""); + absl::log_internal::SetVModuleListHeadForTestOnly(nullptr); + } + + size_t num_sites() const { return num_sites_; } + size_t num_new_files() const { return num_new_files_; } + size_t num_extra_static_data_bytes() const { + return num_extra_static_data_bytes_; + } + + private: + struct PerTU { + container_internal::Layout layout; + std::unique_ptr buf; + }; + + std::mt19937 bitgen_; + std::vector per_tu_data_; + size_t num_sites_ = 0; + size_t num_new_files_ = 0; + size_t num_extra_static_data_bytes_ = 0; +}; + +namespace { +void BM_UpdateVModuleEmpty(benchmark::State& state) { + SyntheticBinary bin(static_cast(state.range(0)), 10 * 1024 * 1024, + 256, state.range(1)); + for (auto s : state) { + absl::log_internal::UpdateVModule(""); + } + state.SetItemsProcessed(static_cast(bin.num_new_files())); +} +BENCHMARK(BM_UpdateVModuleEmpty) + ->ArgPair(100, 200) + ->ArgPair(1000, 2000) + ->ArgPair(10000, 20000); + +void BM_UpdateVModuleShort(benchmark::State& state) { + SyntheticBinary bin(static_cast(state.range(0)), 10 * 1024 * 1024, + 256, state.range(1)); + for (auto s : state) { + absl::log_internal::UpdateVModule("directory2/*=4"); + } + state.SetItemsProcessed(static_cast(bin.num_new_files())); +} +BENCHMARK(BM_UpdateVModuleShort) + ->ArgPair(100, 200) + ->ArgPair(1000, 2000) + ->ArgPair(10000, 20000); + +void BM_UpdateVModuleLong(benchmark::State& state) { + SyntheticBinary bin(static_cast(state.range(0)), 10 * 1024 * 1024, + 256, state.range(1)); + for (auto s : state) { + absl::log_internal::UpdateVModule( + "d?r?c?o?y2/*=4,d?*r?*c?**o?*y1/*=2,d?*rc?**o?*y3/*=2,," + "d?*r?*c?**o?*1/*=1,d?*r?**o?*y1/*=2,d?*r???***y1/*=7," + "d?*r?**o?*y1/aaa=6"); + } + state.SetItemsProcessed(static_cast(bin.num_new_files())); +} +BENCHMARK(BM_UpdateVModuleLong) + ->ArgPair(100, 200) + ->ArgPair(1000, 2000) + ->ArgPair(10000, 20000); +} // namespace +} // namespace log_internal +ABSL_NAMESPACE_END +} // namespace absl diff --git a/absl/log/vlog_is_on.h b/absl/log/vlog_is_on.h new file mode 100644 index 00000000..6e5abf56 --- /dev/null +++ b/absl/log/vlog_is_on.h @@ -0,0 +1,115 @@ +// Copyright 2022 The Abseil Authors. +// +// 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 +// +// https://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. +// +// ----------------------------------------------------------------------------- +// File: log/vlog_is_on.h +// ----------------------------------------------------------------------------- +// +// This header defines the `VLOG_IS_ON()` macro that controls the +// variable-verbosity conditional logging. +// +// It's used by `VLOG` in log.h, or it can also be used directly like this: +// +// if (VLOG_IS_ON(2)) { +// foo_server.RecomputeStatisticsExpensive(); +// LOG(INFO) << foo_server.LastStatisticsAsString(); +// } +// +// Each source file has an effective verbosity level that's a non-negative +// integer computed from the `--vmodule` and `--v` flags. +// `VLOG_IS_ON(n)` is true, and `VLOG(n)` logs, if that effective verbosity +// level is greater than or equal to `n`. +// +// `--vmodule` takes a comma-delimited list of key=value pairs. Each key is a +// pattern matched against filenames, and the values give the effective severity +// level applied to matching files. '?' and '*' characters in patterns are +// interpreted as single-character and zero-or-more-character wildcards. +// Patterns including a slash character are matched against full pathnames, +// while those without are matched against basenames only. One suffix (i.e. the +// last . and everything after it) is stripped from each filename prior to +// matching, as is the special suffix "-inl". +// +// Files are matched against globs in `--vmodule` in order, and the first match +// determines the verbosity level. +// +// Files which do not match any pattern in `--vmodule` use the value of `--v` as +// their effective verbosity level. The default is 0. +// +// SetVLOGLevel helper function is provided to do limited dynamic control over +// V-logging by appending to `--vmodule`. Because these go at the beginning of +// the list, they take priority over any globs previously added. +// +// Resetting --vmodule will override all previous modifications to `--vmodule`, +// including via SetVLOGLevel. + +#ifndef ABSL_LOG_VLOG_IS_ON_H_ +#define ABSL_LOG_VLOG_IS_ON_H_ + +#include "absl/base/attributes.h" +#include "absl/base/config.h" +#include "absl/log/vlog_config.h" // IWYU pragma: export +#include "absl/strings/string_view.h" + +// IWYU pragma: private, include "absl/log/log.h" + +// This is expanded at the callsite to allow the compiler to optimize +// always-false cases out of the build. +// An ABSL_MAX_VLOG_VERBOSITY of 2 means that VLOG(3) and above should never +// log. +#ifdef ABSL_MAX_VLOG_VERBOSITY +#define ABSL_LOG_INTERNAL_MAX_LOG_VERBOSITY_CHECK(x) \ + ((x) <= ABSL_MAX_VLOG_VERBOSITY)&& +#else +#define ABSL_LOG_INTERNAL_MAX_LOG_VERBOSITY_CHECK(x) +#endif + +// Each VLOG_IS_ON call site gets its own VLogSite that registers with the +// global linked list of sites to asynchronously update its verbosity level on +// changes to --v or --vmodule. The verbosity can also be set by manually +// calling SetVLOGLevel. +// +// VLOG_IS_ON is not async signal safe, but it is guaranteed not to allocate +// new memory. +#define VLOG_IS_ON(verbose_level) \ + (ABSL_LOG_INTERNAL_MAX_LOG_VERBOSITY_CHECK(verbose_level)[]() \ + ->::absl::VLogSite * \ + { \ + ABSL_CONST_INIT static ::absl::VLogSite site(__FILE__); \ + return &site; \ + }() \ + ->IsEnabled(verbose_level)) + +namespace absl { +ABSL_NAMESPACE_BEGIN + +// Sets the global `VLOG(_IS_ON)` level to `log_level`. This level is applied +// to any sites whose filename doesn't match any `module_pattern`. Returns the +// prior value. +inline int SetGlobalVLogLevel(int log_level) { + return absl::log_internal::UpdateGlobalVLogLevel(log_level); +} + +// Sets `VLOG(_IS_ON)` level for `module_pattern` to `log_level`. +// This lets us dynamically control what is normally set by the --vmodule flag. +// Returns the level that previously applied to module_pattern. +// Calling this with `log_level` of kUseFlag will have all sites for that +// pattern use the value of --v. +inline int SetVLogLevel(absl::string_view module_pattern, int log_level) { + return absl::log_internal::PrependVModule(module_pattern, log_level); +} + +ABSL_NAMESPACE_END +} // namespace absl + +#endif // ABSL_LOG_VLOG_IS_ON_H_ diff --git a/absl/log/vlog_is_on_test.cc b/absl/log/vlog_is_on_test.cc new file mode 100644 index 00000000..28a2eea1 --- /dev/null +++ b/absl/log/vlog_is_on_test.cc @@ -0,0 +1,175 @@ +// Copyright 2023 The Abseil Authors +// +// 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 +// +// https://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 "absl/log/vlog_is_on.h" + +#include "gmock/gmock.h" +#include "gtest/gtest.h" +#include "absl/base/log_severity.h" +#include "absl/flags/flag.h" +#include "absl/log/flags.h" +#include "absl/log/log.h" +#include "absl/log/scoped_mock_log.h" +#include "absl/types/optional.h" + +namespace { + +using ::testing::_; + +absl::optional MaxLogVerbosity() { +#ifdef ABSL_MAX_VLOG_VERBOSITY + return ABSL_MAX_VLOG_VERBOSITY; +#else + return absl::nullopt; +#endif +} + +absl::optional MinLogLevel() { +#ifdef ABSL_MIN_LOG_LEVEL + return static_cast(ABSL_MIN_LOG_LEVEL); +#else + return absl::nullopt; +#endif +} + +TEST(VLogIsOn, GlobalWorksWithoutMaxVerbosityAndMinLogLevel) { + if (MaxLogVerbosity().has_value() || MinLogLevel().has_value()) { + GTEST_SKIP(); + } + + absl::SetGlobalVLogLevel(3); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, _, "important")); + + log.StartCapturingLogs(); + VLOG(3) << "important"; + VLOG(4) << "spam"; +} + +TEST(VLogIsOn, FileWorksWithoutMaxVerbosityAndMinLogLevel) { + if (MaxLogVerbosity().has_value() || MinLogLevel().has_value()) { + GTEST_SKIP(); + } + + absl::SetVLogLevel("vlog_is_on_test", 3); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, _, "important")); + + log.StartCapturingLogs(); + VLOG(3) << "important"; + VLOG(4) << "spam"; +} + +TEST(VLogIsOn, PatternWorksWithoutMaxVerbosityAndMinLogLevel) { + if (MaxLogVerbosity().has_value() || MinLogLevel().has_value()) { + GTEST_SKIP(); + } + + absl::SetVLogLevel("vlog_is_on*", 3); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, _, "important")); + + log.StartCapturingLogs(); + VLOG(3) << "important"; + VLOG(4) << "spam"; +} + +TEST(VLogIsOn, GlobalDoesNotFilterBelowMaxVerbosity) { + if (!MaxLogVerbosity().has_value() || *MaxLogVerbosity() < 2) { + GTEST_SKIP(); + } + + // Set an arbitrary high value to avoid filtering VLOGs in tests by default. + absl::SetGlobalVLogLevel(1000); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, _, "asdf")); + + log.StartCapturingLogs(); + VLOG(2) << "asdf"; +} + +TEST(VLogIsOn, FileDoesNotFilterBelowMaxVerbosity) { + if (!MaxLogVerbosity().has_value() || *MaxLogVerbosity() < 2) { + GTEST_SKIP(); + } + + // Set an arbitrary high value to avoid filtering VLOGs in tests by default. + absl::SetVLogLevel("vlog_is_on_test", 1000); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, _, "asdf")); + + log.StartCapturingLogs(); + VLOG(2) << "asdf"; +} + +TEST(VLogIsOn, PatternDoesNotFilterBelowMaxVerbosity) { + if (!MaxLogVerbosity().has_value() || *MaxLogVerbosity() < 2) { + GTEST_SKIP(); + } + + // Set an arbitrary high value to avoid filtering VLOGs in tests by default. + absl::SetVLogLevel("vlog_is_on*", 1000); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, _, "asdf")); + + log.StartCapturingLogs(); + VLOG(2) << "asdf"; +} + +TEST(VLogIsOn, GlobalFiltersAboveMaxVerbosity) { + if (!MaxLogVerbosity().has_value() || *MaxLogVerbosity() >= 4) { + GTEST_SKIP(); + } + + // Set an arbitrary high value to avoid filtering VLOGs in tests by default. + absl::SetGlobalVLogLevel(1000); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + log.StartCapturingLogs(); + VLOG(4) << "dfgh"; +} + +TEST(VLogIsOn, FileFiltersAboveMaxVerbosity) { + if (!MaxLogVerbosity().has_value() || *MaxLogVerbosity() >= 4) { + GTEST_SKIP(); + } + + // Set an arbitrary high value to avoid filtering VLOGs in tests by default. + absl::SetVLogLevel("vlog_is_on_test", 1000); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + log.StartCapturingLogs(); + VLOG(4) << "dfgh"; +} + +TEST(VLogIsOn, PatternFiltersAboveMaxVerbosity) { + if (!MaxLogVerbosity().has_value() || *MaxLogVerbosity() >= 4) { + GTEST_SKIP(); + } + + // Set an arbitrary high value to avoid filtering VLOGs in tests by default. + absl::SetVLogLevel("vlog_is_on*", 1000); + absl::ScopedMockLog log(absl::MockLogDefault::kDisallowUnexpected); + + log.StartCapturingLogs(); + VLOG(4) << "dfgh"; +} + +} // namespace -- cgit v1.2.3