diff --git a/src/bench/logging.cpp b/src/bench/logging.cpp index 49a9e59893ab..a67e847c523e 100644 --- a/src/bench/logging.cpp +++ b/src/bench/logging.cpp @@ -6,9 +6,17 @@ #include #include +// All but 2 of the benchmarks should have roughly similar performance: +// +// LogPrintWithoutCategory should be ~3 orders of magnitude faster, as nothing is logged. +// +// LogWithoutWriteToFile should be ~2 orders of magnitude faster, as it avoids disk writes. static void Logging(benchmark::Bench& bench, const std::vector& extra_args, const std::function& log) { + // Reset any enabled logging categories from a previous benchmark run. + LogInstance().DisableCategory(BCLog::LogFlags::ALL); + TestingSetup test_setup{ CBaseChainParams::REGTEST, extra_args, @@ -17,32 +25,67 @@ static void Logging(benchmark::Bench& bench, const std::vector& ext bench.run([&] { log(); }); } -static void LoggingYoThreadNames(benchmark::Bench& bench) +static void LogPrintLevelWithThreadNames(benchmark::Bench& bench) { - Logging(bench, {"-logthreadnames=1"}, [] { LogPrintf("%s\n", "test"); }); + Logging(bench, {"-logthreadnames=1", "-debug=net"}, [] { + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", "test"); }); } -static void LoggingNoThreadNames(benchmark::Bench& bench) + +static void LogPrintLevelWithoutThreadNames(benchmark::Bench& bench) { - Logging(bench, {"-logthreadnames=0"}, [] { LogPrintf("%s\n", "test"); }); + Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", "test"); }); } -static void LoggingYoCategory(benchmark::Bench& bench) + +static void LogPrintWithCategory(benchmark::Bench& bench) { Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { LogPrint(BCLog::NET, "%s\n", "test"); }); } -static void LoggingNoCategory(benchmark::Bench& bench) + +static void LogPrintWithoutCategory(benchmark::Bench& bench) { Logging(bench, {"-logthreadnames=0", "-debug=0"}, [] { LogPrint(BCLog::NET, "%s\n", "test"); }); } -static void LoggingNoFile(benchmark::Bench& bench) + +static void LogPrintfCategoryWithThreadNames(benchmark::Bench& bench) +{ + Logging(bench, {"-logthreadnames=1", "-debug=net"}, [] { + LogPrintfCategory(BCLog::NET, "%s\n", "test"); + }); +} + +static void LogPrintfCategoryWithoutThreadNames(benchmark::Bench& bench) +{ + Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { + LogPrintfCategory(BCLog::NET, "%s\n", "test"); + }); +} + +static void LogPrintfWithThreadNames(benchmark::Bench& bench) +{ + Logging(bench, {"-logthreadnames=1"}, [] { LogPrintf("%s\n", "test"); }); +} + +static void LogPrintfWithoutThreadNames(benchmark::Bench& bench) +{ + Logging(bench, {"-logthreadnames=0"}, [] { LogPrintf("%s\n", "test"); }); +} + +static void LogWithoutWriteToFile(benchmark::Bench& bench) { + // Disable writing the log to a file, as used for unit tests and fuzzing in `MakeNoLogFileContext`. Logging(bench, {"-nodebuglogfile", "-debug=1"}, [] { LogPrintf("%s\n", "test"); LogPrint(BCLog::NET, "%s\n", "test"); }); } -BENCHMARK(LoggingYoThreadNames, benchmark::PriorityLevel::HIGH); -BENCHMARK(LoggingNoThreadNames, benchmark::PriorityLevel::HIGH); -BENCHMARK(LoggingYoCategory, benchmark::PriorityLevel::HIGH); -BENCHMARK(LoggingNoCategory, benchmark::PriorityLevel::HIGH); -BENCHMARK(LoggingNoFile, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintLevelWithThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintLevelWithoutThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintWithCategory, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintWithoutCategory, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintfCategoryWithThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintfCategoryWithoutThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintfWithThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintfWithoutThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogWithoutWriteToFile, benchmark::PriorityLevel::HIGH); diff --git a/src/init/common.cpp b/src/init/common.cpp index a1a9f0c31a51..21d8e337b127 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -59,7 +59,7 @@ bool SanityChecks() void AddLoggingArgs(ArgsManager& argsman) { - argsman.AddArg("-debuglogfile=", strprintf("Specify location of debug log file. Relative paths will be prefixed by a net-specific datadir location. (-nodebuglogfile to disable; default: %s)", DEFAULT_DEBUGLOGFILE), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS); + argsman.AddArg("-debuglogfile=", strprintf("Specify location of debug log file (default: %s). Relative paths will be prefixed by a net-specific datadir location. Pass -nodebuglogfile to disable writing the log to a file.", DEFAULT_DEBUGLOGFILE), ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS); argsman.AddArg("-debug=", "Output debug and trace logging (default: -nodebug, supplying is optional). " "If is not supplied or if = 1, output all debug and trace logging. can be: " + LogInstance().LogCategoriesString() + ". This option can be specified multiple times to output multiple categories.", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST); diff --git a/test/functional/feature_governance_cl.py b/test/functional/feature_governance_cl.py index 9b6ec2bca904..50c2a7c893aa 100755 --- a/test/functional/feature_governance_cl.py +++ b/test/functional/feature_governance_cl.py @@ -151,7 +151,7 @@ def run_test(self): def governance_tip_updated(node): with open(node.debug_log_path, encoding='utf-8') as dl: - seek_pos = node.debug_log_bytes() - 100 * 1024 # read the last 100 KiB only + seek_pos = node.debug_log_size(mode="rb") - 100 * 1024 # read the last 100 KiB only dl.seek(seek_pos if seek_pos > 0 else 0) debug_log_part = dl.read() return expected_msg in debug_log_part diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 52f785c14ce5..248ee8059e01 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -453,8 +453,8 @@ def chain_path(self) -> Path: def debug_log_path(self) -> Path: return self.chain_path / 'debug.log' - def debug_log_bytes(self) -> int: - with open(self.debug_log_path, encoding='utf-8') as dl: + def debug_log_size(self, **kwargs) -> int: + with open(self.debug_log_path, **kwargs) as dl: dl.seek(0, 2) return dl.tell() @@ -466,13 +466,13 @@ def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2): assert_equal(type(unexpected_msgs), list) time_end = time.time() + timeout * self.timeout_factor - prev_size = self.debug_log_bytes() + prev_size = self.debug_log_size(encoding="utf-8") # Must use same encoding that is used to read() below yield while True: found = True - with open(self.debug_log_path, encoding='utf-8') as dl: + with open(self.debug_log_path, encoding="utf-8", errors="replace") as dl: dl.seek(prev_size) log = dl.read() print_log = " - " + "\n - ".join(log.splitlines()) @@ -497,7 +497,7 @@ def wait_for_debug_log(self, expected_msgs, timeout=60): the number of log lines we encountered when matching """ time_end = time.time() + timeout * self.timeout_factor - prev_size = self.debug_log_bytes() + prev_size = self.debug_log_size(mode="rb") # Must use same mode that is used to read() below yield diff --git a/test/lint/lint-python-utf8-encoding.py b/test/lint/lint-python-utf8-encoding.py index 20dc5abea6c9..0377e12701ed 100755 --- a/test/lint/lint-python-utf8-encoding.py +++ b/test/lint/lint-python-utf8-encoding.py @@ -29,7 +29,7 @@ def check_fileopens(): if e.returncode > 1: raise e - filtered_fileopens = [fileopen for fileopen in fileopens if not re.search(r"encoding=.(ascii|utf8|utf-8).|open\([^,]*, ['\"][^'\"]*b[^'\"]*['\"]", fileopen)] + filtered_fileopens = [fileopen for fileopen in fileopens if not re.search(r"encoding=.(ascii|utf8|utf-8).|open\([^,]*, (\*\*kwargs|['\"][^'\"]*b[^'\"]*['\"])", fileopen)] return filtered_fileopens