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 2595aab2 Make statistics on the AsyncAppender's queue length available
(#374)
2595aab2 is described below
commit 2595aab22ba5712869a51151ca2cb0b5841f4591
Author: Stephen Webb <[email protected]>
AuthorDate: Sat Apr 27 16:51:46 2024 +1000
Make statistics on the AsyncAppender's queue length available (#374)
---
src/main/cpp/asyncappender.cpp | 59 ++++++++++++++++++++++++--------
src/main/include/log4cxx/asyncappender.h | 10 ++++--
src/site/markdown/change-report-gh.md | 1 +
3 files changed, 53 insertions(+), 17 deletions(-)
diff --git a/src/main/cpp/asyncappender.cpp b/src/main/cpp/asyncappender.cpp
index ba35245a..1e019155 100644
--- a/src/main/cpp/asyncappender.cpp
+++ b/src/main/cpp/asyncappender.cpp
@@ -53,7 +53,7 @@ class DiscardSummary
/**
* First event of the highest severity.
*/
- ::LOG4CXX_NS::spi::LoggingEventPtr maxEvent;
+ LoggingEventPtr maxEvent;
/**
* Total count of messages discarded.
@@ -66,7 +66,7 @@ class DiscardSummary
*
* @param event event, may not be null.
*/
- DiscardSummary(const ::LOG4CXX_NS::spi::LoggingEventPtr& event);
+ DiscardSummary(const LoggingEventPtr& event);
/** Copy constructor. */
DiscardSummary(const DiscardSummary& src);
/** Assignment operator. */
@@ -77,18 +77,20 @@ class DiscardSummary
*
* @param event event, may not be null.
*/
- void add(const ::LOG4CXX_NS::spi::LoggingEventPtr& event);
+ void add(const LoggingEventPtr& event);
/**
- * Create event with summary information.
+ * Create an event with a discard count and the message from \c
maxEvent.
*
- * @return new event.
+ * @return the new event.
*/
- ::LOG4CXX_NS::spi::LoggingEventPtr
createEvent(::LOG4CXX_NS::helpers::Pool& p);
+ LoggingEventPtr createEvent(Pool& p);
+#if LOG4CXX_ABI_VERSION <= 15
static
::LOG4CXX_NS::spi::LoggingEventPtr
createEvent(::LOG4CXX_NS::helpers::Pool& p,
size_t discardedCount);
+#endif
};
typedef std::map<LogString, DiscardSummary> DiscardMap;
@@ -97,7 +99,14 @@ typedef std::map<LogString, DiscardSummary> DiscardMap;
}
#endif
-static const int CACHE_LINE_SIZE = 128;
+#ifdef __cpp_lib_hardware_interference_size
+ using std::hardware_constructive_interference_size;
+ using std::hardware_destructive_interference_size;
+#else
+ // 64 bytes on x86-64 │ L1_CACHE_BYTES │ L1_CACHE_SHIFT │
__cacheline_aligned │ ...
+ constexpr std::size_t hardware_constructive_interference_size = 64;
+ constexpr std::size_t hardware_destructive_interference_size = 64;
+#endif
struct AsyncAppender::AsyncAppenderPriv : public
AppenderSkeleton::AppenderSkeletonPrivate
{
@@ -131,7 +140,12 @@ struct AsyncAppender::AsyncAppenderPriv : public
AppenderSkeleton::AppenderSkele
/**
* Event buffer.
*/
- LoggingEventList buffer;
+ struct EventData
+ {
+ LoggingEventPtr event;
+ size_t pendingCount;
+ };
+ std::vector<EventData> buffer;
/**
* Mutex used to guard access to buffer and discardMap.
@@ -178,17 +192,17 @@ struct AsyncAppender::AsyncAppenderPriv : public
AppenderSkeleton::AppenderSkele
/**
* Used to calculate the buffer position at which to store the next
event.
*/
- alignas(CACHE_LINE_SIZE) std::atomic<size_t> eventCount;
+ alignas(hardware_constructive_interference_size) std::atomic<size_t>
eventCount;
/**
* Used to calculate the buffer position from which to extract the next
event.
*/
- alignas(CACHE_LINE_SIZE) std::atomic<size_t> dispatchedCount;
+ alignas(hardware_constructive_interference_size) std::atomic<size_t>
dispatchedCount;
/**
* Used to communicate to the dispatch thread when an event is
committed in buffer.
*/
- alignas(CACHE_LINE_SIZE) std::atomic<size_t> commitCount;
+ alignas(hardware_constructive_interference_size) std::atomic<size_t>
commitCount;
};
@@ -273,7 +287,7 @@ void AsyncAppender::append(const spi::LoggingEventPtr&
event, Pool& p)
while (priv->bufferSize <= oldEventCount -
priv->dispatchedCount)
;
// Write to the ring buffer
- priv->buffer[index] = event;
+ priv->buffer[index] =
AsyncAppenderPriv::EventData{event, pendingCount};
// Notify the dispatch thread that an event has been
added
auto savedEventCount = oldEventCount;
while
(!priv->commitCount.compare_exchange_weak(oldEventCount, oldEventCount + 1,
std::memory_order_release))
@@ -452,7 +466,7 @@ void DiscardSummary::add(const LoggingEventPtr& event)
}
LoggingEventPtr DiscardSummary::createEvent(Pool& p)
-{
+ {
LogString msg(LOG4CXX_STR("Discarded "));
StringHelper::toString(count, p, msg);
msg.append(LOG4CXX_STR(" messages due to a full event buffer including:
"));
@@ -464,6 +478,7 @@ LoggingEventPtr DiscardSummary::createEvent(Pool& p)
LocationInfo::getLocationUnavailable() );
}
+#if LOG4CXX_ABI_VERSION <= 15
::LOG4CXX_NS::spi::LoggingEventPtr
DiscardSummary::createEvent(::LOG4CXX_NS::helpers::Pool& p,
size_t discardedCount)
@@ -478,9 +493,12 @@ DiscardSummary::createEvent(::LOG4CXX_NS::helpers::Pool& p,
msg,
LocationInfo::getLocationUnavailable() );
}
+#endif
+
void AsyncAppender::dispatch()
{
+ std::vector<size_t> pendingCountHistogram(priv->bufferSize, 0);
bool isActive = true;
while (isActive)
@@ -501,7 +519,10 @@ void AsyncAppender::dispatch()
while (events.size() < priv->bufferSize &&
priv->dispatchedCount != priv->commitCount)
{
auto index = priv->dispatchedCount %
priv->buffer.size();
- events.push_back(priv->buffer[index]);
+ const auto& data = priv->buffer[index];
+ events.push_back(data.event);
+ if (data.pendingCount <
pendingCountHistogram.size())
+
++pendingCountHistogram[data.pendingCount];
++priv->dispatchedCount;
}
for (auto discardItem : priv->discardMap)
@@ -536,6 +557,16 @@ void AsyncAppender::dispatch()
}
}
}
+ if (!isActive)
+ {
+ LogString msg(LOG4CXX_STR("AsyncAppender
pendingCountHistogram"));
+ for (auto item : pendingCountHistogram)
+ {
+ msg += logchar(' ');
+ StringHelper::toString(item, p, msg);
+ }
+ LogLog::debug(msg);
+ }
}
}
diff --git a/src/main/include/log4cxx/asyncappender.h
b/src/main/include/log4cxx/asyncappender.h
index 0c6b3b05..b957d03a 100644
--- a/src/main/include/log4cxx/asyncappender.h
+++ b/src/main/include/log4cxx/asyncappender.h
@@ -35,17 +35,17 @@ and then returns control to the application.
A separate thread forwards events to the attached appender(s).
You can attach multiple appenders to an AsyncAppender.
-The AsyncAppender is useful when outputing to a slow event sink,
+The AsyncAppender is useful when outputting to a slow event sink,
for example, a remote SMTP server or a database.
Attaching a FileAppender to AsyncAppender is not recommended
as the inter-thread communication overhead
can exceed the time to write directly to a file.
When the application produces logging events faster
-than the backgound thread is able to process,
+than the background thread is able to process,
the bounded buffer can become full.
In this situation AsyncAppender will either
-block until the bounded buffer is emptied or
+block until the bounded buffer has a free slot or
discard the event.
The <b>Blocking</b> property controls which behaviour is used.
When events are discarded,
@@ -55,6 +55,10 @@ The output may contain one <i>Discarded</i> message per
logger name,
the logging event of the highest level for each logger
whose events have been discarded.
+To determine whether the application produces logging events faster
+than the background thread is able to process, enable [Log4cxx internal
debugging](internal-debugging.html).
+The AsyncAppender will output a histogram of queue length frequencies when
closed.
+
<b>Important note:</b> The <code>AsyncAppender</code> can only
be script configured using the {@link xml::DOMConfigurator DOMConfigurator}.
*/
diff --git a/src/site/markdown/change-report-gh.md
b/src/site/markdown/change-report-gh.md
index fac0390d..54a87af8 100644
--- a/src/site/markdown/change-report-gh.md
+++ b/src/site/markdown/change-report-gh.md
@@ -51,6 +51,7 @@ Change Log {#changelog}
Release 1.3.0 includes the following new features:
* Overhead reduction of upto 60% sending logging events to an appender
+* Statistics on the AsyncAppender's queue length (in Log4cxx debug output)
## Release 1.2.0 - 2024-01-01 {#rel_1_2_0}
