This is an automated email from the ASF dual-hosted git repository. swebb2066 pushed a commit to branch logging_from_high_priorty_thread in repository https://gitbox.apache.org/repos/asf/logging-log4cxx.git
commit 910ad64468dbd6c05bb79fad1d4bb09613bc6491 Author: Stephen Webb <[email protected]> AuthorDate: Tue Sep 30 11:07:39 2025 +1000 Add web-site recommendation for performant logging --- src/site/markdown/performance.md | 62 +++++++++++--------- src/test/cpp/benchmark/benchmark.cpp | 110 +++++++++++++++++++++++++++++++---- 2 files changed, 135 insertions(+), 37 deletions(-) diff --git a/src/site/markdown/performance.md b/src/site/markdown/performance.md index e5a309dd..e16b2543 100644 --- a/src/site/markdown/performance.md +++ b/src/site/markdown/performance.md @@ -74,33 +74,37 @@ The "Iterations" column derivation is explained in [Google Benchmark documentati L3 Unified 6144 KiB (x1) Load Average: 0.07, 0.03, 0.01 -| Benchmark | Time | CPU | Iterations | -| :----------- | -----------: | -----------: | -----------: | -| Testing disabled logging request | 0.473 ns | 0.473 ns | 1000000000 | -| Testing disabled logging request/threads:6 | 0.130 ns | 0.777 ns | 816416202 | -| Appending 5 char string using MessageBuffer, pattern: \%m\%n | 346 ns | 346 ns | 2014476 | -| Appending 5 char string using MessageBuffer, pattern: \%m\%n/threads:6 | 450 ns | 2522 ns | 287886 | -| Appending 49 char string using MessageBuffer, pattern: \%m\%n | 387 ns | 387 ns | 1805660 | -| Appending 49 char string using MessageBuffer, pattern: \%m\%n/threads:6 | 490 ns | 2691 ns | 235698 | -| Appending int value using MessageBuffer, pattern: \%m\%n | 538 ns | 538 ns | 1301436 | -| Appending int value using MessageBuffer, pattern: \%m\%n/threads:6 | 496 ns | 2775 ns | 238962 | -| Appending int+float using MessageBuffer, pattern: \%m\%n | 921 ns | 921 ns | 762785 | -| Appending int+float using MessageBuffer, pattern: \%m\%n/threads:6 | 576 ns | 3324 ns | 201900 | -| Appending int value using MessageBuffer, pattern: [\%d] \%m\%n | 566 ns | 566 ns | 1233924 | -| Appending int value using MessageBuffer, pattern: [\%d] [\%c] [\%p] \%m\%n | 624 ns | 624 ns | 1122040 | -| Appending 49 char string using FMT, pattern: \%m\%n | 360 ns | 360 ns | 1945236 | -| Appending 49 char string using FMT, pattern: \%m\%n/threads:6 | 489 ns | 2666 ns | 248046 | -| Appending int value using FMT, pattern: \%m\%n | 388 ns | 388 ns | 1804423 | -| Appending int value using FMT, pattern: \%m\%n/threads:6 | 496 ns | 2720 ns | 253938 | -| Appending int+float using FMT, pattern: \%m\%n | 519 ns | 519 ns | 1352503 | -| Appending int+float using FMT, pattern: \%m\%n/threads:6 | 515 ns | 2900 ns | 229374 | -| Async, Sending int+float using MessageBuffer | 1113 ns | 1113 ns | 633889 | -| Async, Sending int+float using MessageBuffer/threads:6 | 545 ns | 3254 ns | 211344 | -| Logging int+float using MessageBuffer, pattern: \%d \%m\%n | 1079 ns | 1078 ns | 641626 | -| Logging int+float using MessageBuffer, pattern: \%d \%m\%n/threads:6 | 1036 ns | 4715 ns | 144528 | -| Logging int+float using MessageBuffer, JSON | 1446 ns | 1446 ns | 487967 | -| Logging int+float using MessageBuffer, JSON/threads:6 | 2181 ns | 7102 ns | 85848 | -| Multiprocess logging int+float using MessageBuffer, pattern: \%d \%m\%n | 3456 ns | 3456 ns | 203235 | +| Benchmark | Time | CPU | Iterations | +| --------- | -------: | --: | ---------: | +| Testing disabled logging request | 0.472 ns | 0.472 ns | 1000000000 | +| Testing disabled logging request/threads:6 | 0.128 ns | 0.766 ns | 816161856 | +| Appending 5 char string using MessageBuffer, pattern: %m%n | 334 ns | 334 ns | 2094794 | +| Appending 5 char string using MessageBuffer, pattern: %m%n/threads:6 | 434 ns | 2437 ns | 281586 | +| Appending 49 char string using MessageBuffer, pattern: %m%n | 370 ns | 370 ns | 1886606 | +| Appending 49 char string using MessageBuffer, pattern: %m%n/threads:6 | 499 ns | 2736 ns | 228720 | +| Appending int value using MessageBuffer, pattern: %m%n | 509 ns | 509 ns | 1361391 | +| Appending int value using MessageBuffer, pattern: %m%n/threads:6 | 495 ns | 2776 ns | 251646 | +| Appending int+float using MessageBuffer, pattern: %m%n | 911 ns | 911 ns | 768870 | +| Appending int+float using MessageBuffer, pattern: %m%n/threads:6 | 581 ns | 3370 ns | 203220 | +| Appending int+10float using MessageBuffer, pattern: %m%n | 4579 ns | 4567 ns | 151798 | +| Appending int+10float using MessageBuffer, pattern: %m%n/threads:6 | 1694 ns | 10092 ns | 65982 | +| Appending int value using MessageBuffer, pattern: [%d] %m%n | 548 ns | 548 ns | 1276999 | +| Appending int value using MessageBuffer, pattern: [%d] [%c] [%p] %m%n | 600 ns | 600 ns | 1156877 | +| Appending 49 char string using FMT, pattern: %m%n | 346 ns | 346 ns | 2021907 | +| Appending 49 char string using FMT, pattern: %m%n/threads:6 | 488 ns | 2672 ns | 257544 | +| Appending int value using FMT, pattern: %m%n | 376 ns | 376 ns | 1863727 | +| Appending int value using FMT, pattern: %m%n/threads:6 | 486 ns | 2674 ns | 258096 | +| Appending int+float using FMT, pattern: %m%n | 508 ns | 508 ns | 1371269 | +| Appending int+float using FMT, pattern: %m%n/threads:6 | 537 ns | 3036 ns | 212844 | +| Appending int+10float using FMT, pattern: %m%n | 1671 ns | 1671 ns | 417402 | +| Appending int+10float using FMT, pattern: %m%n/threads:6 | 1275 ns | 7297 ns | 96222 | +| Async, Sending int+10float using FMT | 1663 ns | 1663 ns | 421796 | +| Async, Sending int+10float using FMT/threads:6 | 1286 ns | 7368 ns | 88308 | +| Logging int+float using MessageBuffer, pattern: %d %m%n | 1073 ns | 1073 ns | 656652 | +| Logging int+float using MessageBuffer, pattern: %d %m%n/threads:6 | 1083 ns | 4895 ns | 142776 | +| Logging int+float using MessageBuffer, JSON | 1394 ns | 1394 ns | 507493 | +| Logging int+float using MessageBuffer, JSON/threads:6 | 2110 ns | 6827 ns | 104646 | +| Multiprocess logging int+float using MessageBuffer, pattern: %d %m%n | 3253 ns | 3253 ns | 214839 | -# The "Appending" benchmarks just format the message (using PatternLayout) then discard the result. -# The "Async" benchmarks test [AsyncAppender](@ref log4cxx::AsyncAppender) throughput, with logging events discarded in the background thread. @@ -131,3 +135,7 @@ to the attached appenders. This moves the overhead of [the layout method](@ref log4cxx::Layout::format) and the blocking transfer of message data to the operating system from the calling thread to the background thread. + +When logging floating point values from a high priority thread, +the LOG4CXX_[level]_FMT series of macros impose the least overhead. + diff --git a/src/test/cpp/benchmark/benchmark.cpp b/src/test/cpp/benchmark/benchmark.cpp index 873d2cd7..ac792837 100644 --- a/src/test/cpp/benchmark/benchmark.cpp +++ b/src/test/cpp/benchmark/benchmark.cpp @@ -61,13 +61,13 @@ public: class BenchmarkFileAppender : public FileAppender { public: - BenchmarkFileAppender(const LayoutPtr& layout) + BenchmarkFileAppender(const LayoutPtr& layout, bool buffered = true) { setLayout(layout); auto tempDir = helpers::OptionConverter::getSystemProperty(LOG4CXX_STR("TEMP"), LOG4CXX_STR("/tmp")); setFile(tempDir + LOG4CXX_STR("/") + LOG4CXX_STR("benchmark.log")); setAppend(false); - setBufferedIO(true); + setBufferedIO(buffered); helpers::Pool p; activateOptions(p); } @@ -212,7 +212,6 @@ public: // Class methods writer->setLayout(std::make_shared<PatternLayout>(LOG4CXX_STR("%m%n"))); auto asyncAppender = std::make_shared<AsyncAppender>(); asyncAppender->addAppender(writer); - asyncAppender->setBlocking(false); result = r->getLogger(name); result->setAdditivity(false); result->setLevel(Level::getInfo()); @@ -233,7 +232,6 @@ public: // Class methods result->setLevel(Level::getInfo()); auto writer = std::make_shared<BenchmarkFileAppender>(std::make_shared<PatternLayout>(LOG4CXX_STR("%d %m%n"))); writer->setName(LOG4CXX_STR("FileAppender")); - writer->setBufferedIO(true); helpers::Pool p; writer->activateOptions(p); result->addAppender(writer); @@ -360,6 +358,41 @@ BENCHMARK_DEFINE_F(benchmarker, logIntPlusFloatMessageBuffer)(benchmark::State& BENCHMARK_REGISTER_F(benchmarker, logIntPlusFloatMessageBuffer)->Name("Appending int+float using MessageBuffer, pattern: %m%n"); BENCHMARK_REGISTER_F(benchmarker, logIntPlusFloatMessageBuffer)->Name("Appending int+float using MessageBuffer, pattern: %m%n")->Threads(benchmarker::threadCount()); +BENCHMARK_DEFINE_F(benchmarker, logIntPlus10FloatMessageBuffer)(benchmark::State& state) +{ + int x = 0; + for (auto _ : state) + { + float f[] = + { static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + }; + LOG4CXX_INFO( m_asyncLogger, "Hello: message number " << ++x + << " pseudo-random float" << std::setprecision(3) << std::fixed + << ' ' << f[0] + << ' ' << f[1] + << ' ' << f[2] + << ' ' << f[3] + << ' ' << f[4] + << ' ' << f[5] + << ' ' << f[6] + << ' ' << f[7] + << ' ' << f[8] + << ' ' << f[9] + ); + } +} +BENCHMARK_REGISTER_F(benchmarker, logIntPlus10FloatMessageBuffer)->Name("Appending int+10float using MessageBuffer, pattern: %m%n"); +BENCHMARK_REGISTER_F(benchmarker, logIntPlus10FloatMessageBuffer)->Name("Appending int+10float using MessageBuffer, pattern: %m%n")->Threads(benchmarker::threadCount()); + template <class ...Args> void logWithConversionPattern(benchmark::State& state, Args&&... args) { @@ -408,20 +441,77 @@ BENCHMARK_DEFINE_F(benchmarker, logIntPlusFloatValueFMT)(benchmark::State& state } BENCHMARK_REGISTER_F(benchmarker, logIntPlusFloatValueFMT)->Name("Appending int+float using FMT, pattern: %m%n"); BENCHMARK_REGISTER_F(benchmarker, logIntPlusFloatValueFMT)->Name("Appending int+float using FMT, pattern: %m%n")->Threads(benchmarker::threadCount()); + +BENCHMARK_DEFINE_F(benchmarker, logIntPlus10FloatValueFMT)(benchmark::State& state) +{ + int x = 0; + for (auto _ : state) + { + float f[] = + { static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + }; + LOG4CXX_INFO_FMT(m_logger, "Hello: msg number {} pseudo-random float {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f}" + , ++x + , f[0] + , f[1] + , f[2] + , f[3] + , f[4] + , f[5] + , f[6] + , f[7] + , f[8] + , f[9] + ); + } +} +BENCHMARK_REGISTER_F(benchmarker, logIntPlus10FloatValueFMT)->Name("Appending int+10float using FMT, pattern: %m%n"); +BENCHMARK_REGISTER_F(benchmarker, logIntPlus10FloatValueFMT)->Name("Appending int+10float using FMT, pattern: %m%n")->Threads(benchmarker::threadCount()); #endif -BENCHMARK_DEFINE_F(benchmarker, asyncIntPlusFloatValueMessageBuffer)(benchmark::State& state) +BENCHMARK_DEFINE_F(benchmarker, asyncIntPlus10FloatValueFmtBuffer)(benchmark::State& state) { int x = 0; for (auto _ : state) { - auto f = static_cast<float>(rand()) / static_cast<float>(RAND_MAX); - LOG4CXX_INFO( m_asyncLogger, "Hello: message number " << ++x - << " pseudo-random float " << std::setprecision(3) << std::fixed << f); + float f[] = + { static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + , static_cast<float>(rand()) / static_cast<float>(RAND_MAX) + }; + LOG4CXX_INFO_FMT(m_logger, "Hello: msg number {} pseudo-random float {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f} {:.3f}" + , ++x + , f[0] + , f[1] + , f[2] + , f[3] + , f[4] + , f[5] + , f[6] + , f[7] + , f[8] + , f[9] + ); } } -BENCHMARK_REGISTER_F(benchmarker, asyncIntPlusFloatValueMessageBuffer)->Name("Async, Sending int+float using MessageBuffer"); -BENCHMARK_REGISTER_F(benchmarker, asyncIntPlusFloatValueMessageBuffer)->Name("Async, Sending int+float using MessageBuffer")->Threads(benchmarker::threadCount()); +BENCHMARK_REGISTER_F(benchmarker, asyncIntPlus10FloatValueFmtBuffer)->Name("Async, Sending int+10float using FMT"); +BENCHMARK_REGISTER_F(benchmarker, asyncIntPlus10FloatValueFmtBuffer)->Name("Async, Sending int+10float using FMT")->Threads(benchmarker::threadCount()); BENCHMARK_DEFINE_F(benchmarker, fileIntPlusFloatValueMessageBuffer)(benchmark::State& state) {
