This is an automated email from the ASF dual-hosted git repository.
swebb2066 pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/logging-log4cxx.git
The following commit(s) were added to refs/heads/master by this push:
new 12f4842c Add web-site recommendation for performant logging (#547)
12f4842c is described below
commit 12f4842c9c97d8b21b35a833c0b9e09c71aa87c4
Author: Stephen Webb <[email protected]>
AuthorDate: Wed Oct 1 12:29:01 2025 +1000
Add web-site recommendation for performant logging (#547)
---
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..56723501 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)
{
