This is an automated email from the ASF dual-hosted git repository. swebb2066 pushed a commit to branch async_queue_stats in repository https://gitbox.apache.org/repos/asf/logging-log4cxx.git
commit e3b979974058c8a770ee681d665cd5254bb28674 Author: Stephen Webb <[email protected]> AuthorDate: Fri Apr 26 16:23:53 2024 +1000 Make statistics on the AsyncAppender's queue length available --- src/main/cpp/asyncappender.cpp | 73 +++++++++++++++++++------------- src/main/include/log4cxx/asyncappender.h | 13 +++--- 2 files changed, 50 insertions(+), 36 deletions(-) diff --git a/src/main/cpp/asyncappender.cpp b/src/main/cpp/asyncappender.cpp index ba35245a..3ea9293a 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); + 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 alignas(hardware_constructive_interference_size) 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,23 +478,9 @@ LoggingEventPtr DiscardSummary::createEvent(Pool& p) LocationInfo::getLocationUnavailable() ); } -::LOG4CXX_NS::spi::LoggingEventPtr -DiscardSummary::createEvent(::LOG4CXX_NS::helpers::Pool& p, - size_t discardedCount) -{ - LogString msg(LOG4CXX_STR("Discarded ")); - StringHelper::toString(discardedCount, p, msg); - msg.append(LOG4CXX_STR(" messages due to a full event buffer")); - - return std::make_shared<LoggingEvent>( - LOG4CXX_STR(""), - LOG4CXX_NS::Level::getError(), - msg, - LocationInfo::getLocationUnavailable() ); -} - void AsyncAppender::dispatch() { + std::vector<size_t> pendingCountHistogram(priv->bufferSize, 0); bool isActive = true; while (isActive) @@ -501,7 +501,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 +539,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..9fb8ea1c 100644 --- a/src/main/include/log4cxx/asyncappender.h +++ b/src/main/include/log4cxx/asyncappender.h @@ -35,17 +35,14 @@ 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 especially 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 +52,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}. */
