You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by sw...@apache.org on 2025/09/18 02:11:59 UTC
(logging-log4cxx) branch master updated: Include sample performance measurement data in web-site information (#539)
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 0389045b Include sample performance measurement data in web-site information (#539)
0389045b is described below
commit 0389045bac82e04b70810155143838f1964dc161
Author: Stephen Webb <st...@ieee.org>
AuthorDate: Thu Sep 18 12:11:54 2025 +1000
Include sample performance measurement data in web-site information (#539)
* Quantify the significance of using buffered output
* Add an explaination for lock contention when logging from multiple threads
---
src/main/cpp/appenderskeleton.cpp | 19 ++++----
src/main/include/log4cxx/appenderskeleton.h | 23 ++++++---
src/site/markdown/performance.md | 75 ++++++++++++++++++++++++-----
3 files changed, 90 insertions(+), 27 deletions(-)
diff --git a/src/main/cpp/appenderskeleton.cpp b/src/main/cpp/appenderskeleton.cpp
index 76eb3dfd..f44b8ced 100644
--- a/src/main/cpp/appenderskeleton.cpp
+++ b/src/main/cpp/appenderskeleton.cpp
@@ -95,40 +95,39 @@ void AppenderSkeleton::doAppend(const spi::LoggingEventPtr& event, Pool& pool1)
doAppendImpl(event, pool1);
}
-void AppenderSkeleton::doAppendImpl(const spi::LoggingEventPtr& event, Pool& pool1)
+void AppenderSkeleton::doAppendImpl(const spi::LoggingEventPtr& event, Pool& pool)
{
if (m_priv->closed)
{
LogLog::warn(LOG4CXX_STR("Attempted to append to closed appender named [")
+ m_priv->name + LOG4CXX_STR("]."));
- return;
}
-
- if (!isAsSevereAsThreshold(event->getLevel()))
+ else if (isAsSevereAsThreshold(event->getLevel()) && isAccepted(event))
{
- return;
+ append(event, pool);
}
+}
+bool AppenderSkeleton::isAccepted(const spi::LoggingEventPtr& event) const
+{
FilterPtr f = m_priv->headFilter;
-
-
while (f != 0)
{
switch (f->decide(event))
{
case Filter::DENY:
- return;
+ return false;
case Filter::ACCEPT:
f = nullptr;
break;
+ default:
case Filter::NEUTRAL:
f = f->getNext();
}
}
-
- append(event, pool1);
+ return true;
}
bool AppenderSkeleton::AppenderSkeletonPrivate::checkNotClosed()
diff --git a/src/main/include/log4cxx/appenderskeleton.h b/src/main/include/log4cxx/appenderskeleton.h
index 5679a3e8..3a47214d 100644
--- a/src/main/include/log4cxx/appenderskeleton.h
+++ b/src/main/include/log4cxx/appenderskeleton.h
@@ -44,13 +44,23 @@ class LOG4CXX_EXPORT AppenderSkeleton :
AppenderSkeleton(LOG4CXX_PRIVATE_PTR(AppenderSkeletonPrivate) priv);
/**
- Subclasses of <code>AppenderSkeleton</code> should implement this
+ Subclasses of <code>AppenderSkeleton</code> must implement this
method to perform actual logging. See also AppenderSkeleton::doAppend
method.
*/
- virtual void append(const spi::LoggingEventPtr& event, LOG4CXX_NS::helpers::Pool& p) = 0;
+ virtual void append(const spi::LoggingEventPtr& event, helpers::Pool& p) = 0;
- void doAppendImpl(const spi::LoggingEventPtr& event, LOG4CXX_NS::helpers::Pool& pool);
+ /**
+ * Compare \c event level against the appender threshold and check that \c event is accepted.
+ * If \c event is accepted, delegate log output to the subclass implementation of
+ * the AppenderSkeleton#append method.
+ * */
+ void doAppendImpl(const spi::LoggingEventPtr& event, helpers::Pool& pool);
+
+ /**
+ * Does no attached filter deny \c event or does an attached filter accept \c event?
+ */
+ bool isAccepted(const spi::LoggingEventPtr& event) const;
public:
DECLARE_ABSTRACT_LOG4CXX_OBJECT(AppenderSkeleton)
@@ -141,9 +151,10 @@ class LOG4CXX_EXPORT AppenderSkeleton :
/**
- * This method performs threshold checks and invokes filters before
- * delegating actual logging to the subclasses specific
- * AppenderSkeleton#append method.
+ * Call AppenderSkeleton#doAppendImpl after acquiring a lock
+ * that prevents other threads from concurrently executing AppenderSkeleton#doAppendImpl.
+ *
+ * Reimplement this method in your appender if you use a different concurrency control technique.
* */
void doAppend(const spi::LoggingEventPtr& event, helpers::Pool& pool) override;
diff --git a/src/site/markdown/performance.md b/src/site/markdown/performance.md
index f64655c4..424876c1 100644
--- a/src/site/markdown/performance.md
+++ b/src/site/markdown/performance.md
@@ -21,23 +21,17 @@ Log4cxx Performance {#performance}
limitations under the License.
-->
-One important question with a logging library is: is it fast enough? While
-Log4cxx may not be the fastest logging implementation, it is more than fast
+One important question with a logging library is: is it fast enough?
+While Log4cxx may not be the fastest logging implementation, it is more than fast
enough for the vast majority of cases.
-In performance testing done on a developer's system(utilising an Intel
-i5-8400 processor and a virtual machine), it is possible for Log4cxx to handle
-over 2,000,000 messages/second in a single-threaded application. Since
-Log4cxx is designed to be multithread-safe, logging from multiple threads makes
-this throughput much lower. Delays in writing messages to disk can also
-greatly decrease performance, depending on how much data is being logged.
-
-If the logging of a particular level is disabled, performance can also be
-a lot better. While Log4cxx can generate 2,000,000 log messages/second,
+While Log4cxx can generate 2,000,000 log messages/second,
skipping a disabled logging request requires only a few nano-seconds,
so application performance is not affected when
logging requests are not removed from the release build.
+Benchmark testing shows MessageBuffer (i.e. std::stringstream) filling
+consumes the majority of CPU time when the logging request is not disabled.
For the best performance, use the `LOG4CXX_[level]_FMT` series of macros,
as the [{fmt}](https://fmt.dev/latest/index.html) library
they use is significantly faster
@@ -65,3 +59,62 @@ The throughput tests may be built by
specifying `BUILD_THROUGHPUT` with CMake when building Log4cxx.
The benckmark tests require Google's [Benchmark](https://github.com/google/benchmark) library
and may be built by specifying `BUILD_BENCHMARK_CHECKS` with CMake when building Log4cxx.
+
+The following table shows some timing tests using Google's benchmarking library.
+The "Time" column shows the average elapsed time, i.e real_accumulated_time / iteration_count.
+The "CPU" column is also an average, the cpu_accumulated_time / iteration_count.
+The "Iterations" column derivation is explained in [Google Benchmark documentation](https://google.github.io/benchmark/user_guide.html#runtime-and-reporting-considerations).
+
+ g++ (Ubuntu 11.4.0-1ubuntu1~22.04.2) 11.4.0
+ Run on (8 X 2328.61 MHz CPU s)
+ CPU Caches:
+ L1 Data 32 KiB (x4)
+ L1 Instruction 32 KiB (x4)
+ L2 Unified 256 KiB (x4)
+ 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 |
+
+-# The "Appending" benchmarks just format the message (using PatternLayout) then discard the result.
+-# The "Async" benchmarks test AsyncAppender throughput, with logging events discarded in the background thread.
+-# The "Logging" benchmarks write to a file using buffered output. Overhead is 2-3 times more when not using buffered output.
+
+The above table shows that the overhead of an enabled logging request
+varies greatly with the message content.
+A single operations-per-second number is not meaningful.
+Most importantly note that [using buffered output](@ref log4cxx::FileAppender::setOption)
+reduces overhead more than any other detail.
+
+Note also that logging from multiple threads concurrently
+to a common appender does not increase throughput due to lock contention.
+To simplify the work of an appender implementator,
+the [doAppend method](@ref log4cxx::AppenderSkeleton::doAppend) currently prevents multiple threads
+concurrently entering [the append method](@ref log4cxx::AppenderSkeleton::append),
+which is the method required to be implemented by a concrete appender class.