Add web-site recommendation for performant logging (#547)
diff --git a/src/site/markdown/performance.md b/src/site/markdown/performance.md
index e5a309d..5672350 100644
--- a/src/site/markdown/performance.md
+++ b/src/site/markdown/performance.md
@@ -74,33 +74,37 @@
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 @@
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 873d2cd..ac79283 100644
--- a/src/test/cpp/benchmark/benchmark.cpp
+++ b/src/test/cpp/benchmark/benchmark.cpp
@@ -61,13 +61,13 @@
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 @@
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 @@
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_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_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());
-#endif
-BENCHMARK_DEFINE_F(benchmarker, asyncIntPlusFloatValueMessageBuffer)(benchmark::State& state)
+BENCHMARK_DEFINE_F(benchmarker, logIntPlus10FloatValueFMT)(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, 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, asyncIntPlus10FloatValueFmtBuffer)(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, 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)
{
