From 4684aa8733e831d7858d43bec4271d5d026ba183 Mon Sep 17 00:00:00 2001 From: Larry Ruane Date: Mon, 30 Jan 2023 07:21:36 -0800 Subject: [PATCH 1/6] bench: allow logging benchmarks to be order-independent The global logging object instance is not re-created for each run, so when multiple logging benchmarks are run, each one after the first one still has the logging categories enabled from the previous ones. This commit disables all categories at the start of each benchmark. --- src/bench/logging.cpp | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/bench/logging.cpp b/src/bench/logging.cpp index c38552f0b8c..edb81ed20b3 100644 --- a/src/bench/logging.cpp +++ b/src/bench/logging.cpp @@ -9,6 +9,9 @@ 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, From 4b3fdbf6fe20dc70c8dbdaacce161bc4e76b9c84 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Mon, 11 Jul 2022 11:15:26 +0200 Subject: [PATCH 2/6] bench: update logging benchmark naming for clarity to better track which benchmark corresponds to which log macro. --- src/bench/logging.cpp | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/src/bench/logging.cpp b/src/bench/logging.cpp index edb81ed20b3..59b89b1a797 100644 --- a/src/bench/logging.cpp +++ b/src/bench/logging.cpp @@ -20,23 +20,23 @@ static void Logging(benchmark::Bench& bench, const std::vector& ext bench.run([&] { log(); }); } -static void LoggingYoThreadNames(benchmark::Bench& bench) +static void LogPrintfWithThreadNames(benchmark::Bench& bench) { Logging(bench, {"-logthreadnames=1"}, [] { LogPrintf("%s\n", "test"); }); } -static void LoggingNoThreadNames(benchmark::Bench& bench) +static void LogPrintfWithoutThreadNames(benchmark::Bench& bench) { Logging(bench, {"-logthreadnames=0"}, [] { LogPrintf("%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 LogWithoutWriteToFile(benchmark::Bench& bench) { Logging(bench, {"-nodebuglogfile", "-debug=1"}, [] { LogPrintf("%s\n", "test"); @@ -44,8 +44,8 @@ static void LoggingNoFile(benchmark::Bench& bench) }); } -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(LogPrintfWithThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintfWithoutThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintWithCategory, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintWithoutCategory, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogWithoutWriteToFile, benchmark::PriorityLevel::HIGH); From 102b2033493f0d61e9763d094cb8a0017f7e3a10 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Mon, 11 Jul 2022 11:23:45 +0200 Subject: [PATCH 3/6] bench: order the logging benchmark code by output --- src/bench/logging.cpp | 24 ++++++++++++++---------- 1 file changed, 14 insertions(+), 10 deletions(-) diff --git a/src/bench/logging.cpp b/src/bench/logging.cpp index 59b89b1a797..a7162d09acb 100644 --- a/src/bench/logging.cpp +++ b/src/bench/logging.cpp @@ -20,22 +20,26 @@ static void Logging(benchmark::Bench& bench, const std::vector& ext bench.run([&] { log(); }); } -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 LogPrintWithCategory(benchmark::Bench& bench) { Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { LogPrint(BCLog::NET, "%s\n", "test"); }); } + static void LogPrintWithoutCategory(benchmark::Bench& bench) { Logging(bench, {"-logthreadnames=0", "-debug=0"}, [] { LogPrint(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) { Logging(bench, {"-nodebuglogfile", "-debug=1"}, [] { @@ -44,8 +48,8 @@ static void LogWithoutWriteToFile(benchmark::Bench& bench) }); } -BENCHMARK(LogPrintfWithThreadNames, benchmark::PriorityLevel::HIGH); -BENCHMARK(LogPrintfWithoutThreadNames, benchmark::PriorityLevel::HIGH); BENCHMARK(LogPrintWithCategory, benchmark::PriorityLevel::HIGH); BENCHMARK(LogPrintWithoutCategory, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintfWithThreadNames, benchmark::PriorityLevel::HIGH); +BENCHMARK(LogPrintfWithoutThreadNames, benchmark::PriorityLevel::HIGH); BENCHMARK(LogWithoutWriteToFile, benchmark::PriorityLevel::HIGH); From d8deba8c36a42481b1c1e73009d7c9cc2cb25f70 Mon Sep 17 00:00:00 2001 From: Jon Atack Date: Mon, 11 Jul 2022 10:58:29 +0200 Subject: [PATCH 4/6] bench: add LogPrintfCategory and LogPrintLevel benchmarks for these new macros that our logging is planned to migrate to. At some point it may be feasible to drop some of the previous logging benchmarks. --- src/bench/logging.cpp | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/src/bench/logging.cpp b/src/bench/logging.cpp index a7162d09acb..f6e5bc54e87 100644 --- a/src/bench/logging.cpp +++ b/src/bench/logging.cpp @@ -20,6 +20,18 @@ static void Logging(benchmark::Bench& bench, const std::vector& ext bench.run([&] { log(); }); } +static void LogPrintLevelWithThreadNames(benchmark::Bench& bench) +{ + Logging(bench, {"-logthreadnames=1", "-debug=net"}, [] { + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", "test"); }); +} + +static void LogPrintLevelWithoutThreadNames(benchmark::Bench& bench) +{ + Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { + LogPrintLevel(BCLog::NET, BCLog::Level::Error, "%s\n", "test"); }); +} + static void LogPrintWithCategory(benchmark::Bench& bench) { Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { LogPrint(BCLog::NET, "%s\n", "test"); }); @@ -30,6 +42,20 @@ static void LogPrintWithoutCategory(benchmark::Bench& bench) Logging(bench, {"-logthreadnames=0", "-debug=0"}, [] { LogPrint(BCLog::NET, "%s\n", "test"); }); } +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"); }); @@ -48,8 +74,12 @@ static void LogWithoutWriteToFile(benchmark::Bench& bench) }); } +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); From 20d89d6802b67e2b8c864bedf23673d008e3faab Mon Sep 17 00:00:00 2001 From: jonatack Date: Mon, 23 Jan 2023 07:49:46 -0800 Subject: [PATCH 5/6] bench: document expected results in logging benchmarks and clarify the intention behind the -nodebuglogfile bench. Co-authored-by: "kouloumos " Co-authored-by: "Larry Ruane " --- src/bench/logging.cpp | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/bench/logging.cpp b/src/bench/logging.cpp index f6e5bc54e87..9aedb26236d 100644 --- a/src/bench/logging.cpp +++ b/src/bench/logging.cpp @@ -6,6 +6,11 @@ #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) { @@ -68,6 +73,7 @@ static void LogPrintfWithoutThreadNames(benchmark::Bench& bench) 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"); From 8c47d599b87d6b2d43e7d37ce0aaf4f541535bb9 Mon Sep 17 00:00:00 2001 From: jonatack Date: Mon, 23 Jan 2023 10:34:00 -0800 Subject: [PATCH 6/6] doc: improve -debuglogfile help to be a bit clearer --- src/init/common.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/init/common.cpp b/src/init/common.cpp index e1a37d7db93..fa065d221f6 100644 --- a/src/init/common.cpp +++ b/src/init/common.cpp @@ -23,7 +23,7 @@ namespace init { 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);