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 4b50a6f8 Reduce MultiprocessRollingFileAppender overhead (#443)
4b50a6f8 is described below
commit 4b50a6f83e7a3814502685c6d8139ea5ce267cf0
Author: Stephen Webb <stephen.w...@ieee.org>
AuthorDate: Tue Dec 17 13:32:53 2024 +1100
Reduce MultiprocessRollingFileAppender overhead (#443)
* Reduce the number of apr_stat calls
* Log extra behavioral data in multiprocess unit test
* Only check for a rollover when shared memory was changed on Windows
systems
* Document the overhead of MultiprocessRollingFileAppender
---
src/main/cpp/multiprocessrollingfileappender.cpp | 177 +++++++--------------
src/main/cpp/timebasedrollingpolicy.cpp | 20 +++
.../rolling/multiprocessrollingfileappender.h | 22 ++-
.../log4cxx/rolling/timebasedrollingpolicy.h | 5 +
src/test/cpp/benchmark/benchmark.cpp | 61 +++++++
src/test/cpp/rolling/multiprocessrollingtest.cpp | 18 ++-
6 files changed, 175 insertions(+), 128 deletions(-)
diff --git a/src/main/cpp/multiprocessrollingfileappender.cpp
b/src/main/cpp/multiprocessrollingfileappender.cpp
index 881c2af8..1c8d5651 100644
--- a/src/main/cpp/multiprocessrollingfileappender.cpp
+++ b/src/main/cpp/multiprocessrollingfileappender.cpp
@@ -37,76 +37,6 @@
#include <mutex>
#include <thread>
-namespace LOG4CXX_NS
-{
-
-using namespace helpers;
-
-namespace rolling
-{
-/**
- * Wrapper for OutputStream that will report all log file
- * size changes back to the appender for file length calculations.
- */
-class MultiprocessOutputStream : public OutputStream
-{
- /**
- * Wrapped output stream.
- */
-private:
- OutputStreamPtr os;
-
- /**
- * Rolling file appender to inform of stream writes.
- */
- MultiprocessRollingFileAppender* rfa;
-
-public:
- /**
- * Constructor.
- * @param os output stream to wrap.
- * @param rfa rolling file appender to inform.
- */
- MultiprocessOutputStream(const OutputStreamPtr& os1,
MultiprocessRollingFileAppender* rfa1)
- : os(os1), rfa(rfa1)
- {
- }
-
- /**
- * {@inheritDoc}
- */
- void close(Pool& p) override
- {
- os->close(p);
- rfa = 0;
- }
-
- /**
- * {@inheritDoc}
- */
- void flush(Pool& p) override
- {
- os->flush(p);
- }
-
- /**
- * {@inheritDoc}
- */
- void write(ByteBuffer& buf, Pool& p) override
- {
- os->write(buf, p);
-
- if (rfa != 0)
- {
-
rfa->setFileLength(File().setPath(rfa->getFile()).length(p));
- }
- }
-
- static FileOutputStreamPtr
getFileOutputStream(MultiprocessRollingFileAppender* rfa);
-};
-} // namespace rolling
-} // namespace LOG4CXX_NS
-
using namespace LOG4CXX_NS;
using namespace LOG4CXX_NS::rolling;
using namespace LOG4CXX_NS::helpers;
@@ -121,6 +51,7 @@ struct
MultiprocessRollingFileAppender::MultiprocessRollingFileAppenderPriv
apr_file_close(lock_file);
}
+ apr_file_t* log_file = NULL;
apr_file_t* lock_file = NULL;
public: // Support classes
@@ -198,39 +129,6 @@ public: // Support classes
};
};
- FileOutputStreamPtr
-MultiprocessOutputStream::getFileOutputStream(MultiprocessRollingFileAppender*
rfa)
-{
- auto writer = rfa->getWriter();
- FileOutputStreamPtr result;
- auto osw = LOG4CXX_NS::cast<OutputStreamWriter>(writer);
- if( !osw )
- {
- if (auto bw = LOG4CXX_NS::cast<BufferedWriter>(writer))
- osw =
LOG4CXX_NS::cast<OutputStreamWriter>(bw->getWriter());
- }
- if( !osw ){
- LogString msg(LOG4CXX_STR("Can't cast writer to
OutputStreamWriter"));
- msg += LOG4CXX_STR(" - Rollover synchronization will be
degraded.");
- rfa->m_priv->errorHandler->error(msg);
- return result;
- }
- auto cos =
LOG4CXX_NS::cast<MultiprocessOutputStream>(osw->getOutputStreamPtr());
- if( !cos ){
- LogString msg(LOG4CXX_STR("Can't cast stream to
MultiprocessOutputStream"));
- msg += LOG4CXX_STR(" - Rollover synchronization will be
degraded.");
- rfa->m_priv->errorHandler->error(msg);
- return result;
- }
- result = LOG4CXX_NS::cast<FileOutputStream>(cos->os);
- if( !result ){
- LogString msg(LOG4CXX_STR("Can't cast stream to
FileOutputStream"));
- msg += LOG4CXX_STR(" - Rollover synchronization will be
degraded.");
- rfa->m_priv->errorHandler->error(msg);
- }
- return result;
-}
-
#define _priv static_cast<MultiprocessRollingFileAppenderPriv*>(m_priv.get())
IMPLEMENT_LOG4CXX_OBJECT(MultiprocessRollingFileAppender)
@@ -254,19 +152,31 @@ void
MultiprocessRollingFileAppender::activateOptions(Pool& p)
pTimeBased->setMultiprocess(true);
}
+/**
+ * Is it possible the current log file was renamed?
+ */
+bool MultiprocessRollingFileAppender::isRolloverCheckNeeded()
+{
+ bool result = true;
+#ifdef WIN32 // apr_stat is slow on Windows
+ if (auto pTimeBased =
LOG4CXX_NS::cast<TimeBasedRollingPolicy>(_priv->rollingPolicy))
+ result = !pTimeBased->isLastFileNameUnchanged();
+#endif
+ return result;
+}
+
/**
* Was \c fileName renamed?
*/
bool MultiprocessRollingFileAppender::isAlreadyRolled(const LogString&
fileName, size_t* pSize)
{
- auto fos = MultiprocessOutputStream::getFileOutputStream(this);
- if( !fos )
+ if( !_priv->log_file )
return false;
apr_int32_t wantedInfo = APR_FINFO_IDENT;
if (pSize)
wantedInfo |= APR_FINFO_SIZE;
apr_finfo_t finfo1;
- apr_status_t st1 = apr_file_info_get(&finfo1, wantedInfo,
fos->getFilePtr());
+ apr_status_t st1 = apr_file_info_get(&finfo1, wantedInfo,
_priv->log_file);
if (st1 != APR_SUCCESS)
LogLog::warn(LOG4CXX_STR("apr_file_info_get failed"));
@@ -294,6 +204,24 @@ bool
MultiprocessRollingFileAppender::isAlreadyRolled(const LogString& fileName,
((finfo1.device != finfo2.device) || (finfo1.inode !=
finfo2.inode)));
}
+/**
+ * Put the current size of the log file into \c pSize.
+ */
+bool MultiprocessRollingFileAppender::getCurrentFileSize(size_t* pSize)
+{
+ if( !_priv->log_file )
+ return false;
+ apr_int32_t wantedInfo = APR_FINFO_SIZE;
+ apr_finfo_t finfo;
+ if (apr_file_info_get(&finfo, wantedInfo, _priv->log_file) !=
APR_SUCCESS)
+ {
+ LogLog::warn(LOG4CXX_STR("apr_file_info_get failed"));
+ return false;
+ }
+ *pSize = finfo.size;
+ return true;
+}
+
/**
Implements the usual roll over behaviour.
@@ -324,19 +252,18 @@ bool
MultiprocessRollingFileAppender::synchronizedRollover(Pool& p, const Trigge
{
bool result = false;
LogString fileName = getFile();
- size_t fileLength = 0;
if (!_priv->rollingPolicy)
; // can't roll without a policy
- else if (isAlreadyRolled(fileName, &fileLength))
- reopenFile(fileName, fileLength);
+ else if (isAlreadyRolled(fileName, &_priv->fileLength))
+ reopenFile(fileName);
else
{
MultiprocessRollingFileAppenderPriv::Lock lk(_priv, fileName);
if (!lk.hasLock())
LogLog::warn(LOG4CXX_STR("Failed to lock ") + fileName);
- else if (isAlreadyRolled(fileName, &fileLength))
- reopenFile(fileName, fileLength);
- else if (trigger && !trigger->isTriggeringEvent(this,
_priv->_event, fileName, fileLength))
+ else if (isAlreadyRolled(fileName, &_priv->fileLength))
+ reopenFile(fileName);
+ else if (trigger && !trigger->isTriggeringEvent(this,
_priv->_event, fileName, _priv->fileLength))
;
else if (auto rollover1 =
_priv->rollingPolicy->rollover(fileName, getAppend(), p))
{
@@ -437,14 +364,13 @@ bool
MultiprocessRollingFileAppender::synchronizedRollover(Pool& p, const Trigge
/**
* re-open \c fileName (used after it has been renamed)
*/
-void MultiprocessRollingFileAppender::reopenFile(const LogString& fileName,
size_t fileLength)
+void MultiprocessRollingFileAppender::reopenFile(const LogString& fileName)
{
closeWriter();
OutputStreamPtr os = std::make_shared<FileOutputStream>(fileName, true);
WriterPtr newWriter(createWriter(os));
setFile(fileName);
setWriter(newWriter);
- _priv->fileLength = fileLength;
}
/**
@@ -454,9 +380,8 @@ void MultiprocessRollingFileAppender::subAppend(const
LoggingEventPtr& event, Po
{
// The rollover check must precede actual writing. This is the
// only correct behavior for time driven triggers.
- size_t fileLength = getFileLength();
LogString fileName = getFile();
- if (_priv->triggeringPolicy->isTriggeringEvent(this, event, fileName,
fileLength))
+ if (_priv->triggeringPolicy->isTriggeringEvent(this, event, fileName,
_priv->fileLength))
{
//
// wrap rollover request in try block since
@@ -476,10 +401,10 @@ void MultiprocessRollingFileAppender::subAppend(const
LoggingEventPtr& event, Po
_priv->errorHandler->error(msg, ex, 0);
}
}
- else if (isAlreadyRolled(fileName, &fileLength))
- {
- reopenFile(fileName, fileLength);
- }
+ else if (!isRolloverCheckNeeded())
+ getCurrentFileSize(&_priv->fileLength);
+ else if (isAlreadyRolled(fileName, &_priv->fileLength))
+ reopenFile(fileName);
FileAppender::subAppend(event, p);
}
@@ -495,8 +420,16 @@ void MultiprocessRollingFileAppender::subAppend(const
LoggingEventPtr& event, Po
*/
WriterPtr MultiprocessRollingFileAppender::createWriter(OutputStreamPtr& os)
{
- OutputStreamPtr cos = std::make_shared<MultiprocessOutputStream>(os,
this);
- return FileAppender::createWriter(cos);
+ auto fos = LOG4CXX_NS::cast<FileOutputStream>(os);
+ if( fos )
+ _priv->log_file = fos->getFilePtr();
+ else
+ {
+ LogString msg(LOG4CXX_STR("Can't cast stream to
FileOutputStream"));
+ msg += LOG4CXX_STR(" - Rollover synchronization will be
degraded.");
+ _priv->errorHandler->error(msg);
+ }
+ return RollingFileAppender::createWriter(os);
}
diff --git a/src/main/cpp/timebasedrollingpolicy.cpp
b/src/main/cpp/timebasedrollingpolicy.cpp
index 711684dd..04c6ae52 100644
--- a/src/main/cpp/timebasedrollingpolicy.cpp
+++ b/src/main/cpp/timebasedrollingpolicy.cpp
@@ -530,3 +530,23 @@ void TimeBasedRollingPolicy::setOption(const LogString&
option,
RollingPolicyBase::setOption(option, value);
}
}
+
+/**
+ * Was the name in shared memory set by this process?
+ */
+bool TimeBasedRollingPolicy::isLastFileNameUnchanged()
+{
+ bool result = true;
+ if( m_priv->multiprocess ){
+#if LOG4CXX_HAS_MULTIPROCESS_ROLLING_FILE_APPENDER
+ if (m_priv->_mmap)
+ {
+ lockMMapFile(APR_FLOCK_SHARED);
+ LogString mapCurrent((char*)m_priv->_mmap->mm);
+ unLockMMapFile();
+ result = (mapCurrent == m_priv->lastFileName);
+ }
+#endif
+ }
+ return result;
+}
diff --git a/src/main/include/log4cxx/rolling/multiprocessrollingfileappender.h
b/src/main/include/log4cxx/rolling/multiprocessrollingfileappender.h
index 98eaca4f..8492c12d 100644
--- a/src/main/include/log4cxx/rolling/multiprocessrollingfileappender.h
+++ b/src/main/include/log4cxx/rolling/multiprocessrollingfileappender.h
@@ -29,7 +29,11 @@ namespace rolling
/**
- * A special version of the RollingFileAppender that acts properly with
multiple processes
+ * A special version of the RollingFileAppender that acts properly with
multiple processes.
+ *
+ * Coordinating with other processes adds significant overhead compared to
RollingFileAppender.
+ * Benchmarks show the overhead of this appender is more than 4 and 10 times
+ * the overhead of RollingFileAppender on Linux and Windows respectively.
*
* Note: Do *not* set the option <code>Append</code> to <code>false</code>.
* Rolling over files is only relevant when you are appending.
@@ -102,6 +106,11 @@ class LOG4CXX_EXPORT MultiprocessRollingFileAppender :
public RollingFileAppende
*/
void setFileLength(size_t length);
+ /**
+ * Is it possible the current log file was renamed?
+ */
+ bool isRolloverCheckNeeded();
+
/**
* Was \c fileName renamed?
* @param pSize if not NULL, receives the log file size
@@ -110,12 +119,15 @@ class LOG4CXX_EXPORT MultiprocessRollingFileAppender :
public RollingFileAppende
bool isAlreadyRolled(const LogString& fileName, size_t* pSize =
0);
/**
- * re-open \c fileName (used after it has been renamed)
+ * Put the current size of the log file into \c pSize.
+ * @return true if the log file size was put into \c pSize
*/
- void reopenFile(const LogString& fileName, size_t fileLength);
-
- friend class MultiprocessOutputStream;
+ bool getCurrentFileSize(size_t* pSize);
+ /**
+ * re-open \c fileName (used after it has been renamed)
+ */
+ void reopenFile(const LogString& fileName);
};
LOG4CXX_PTR_DEF(MultiprocessRollingFileAppender);
diff --git a/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
b/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
index f191e569..696f53b2 100755
--- a/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
+++ b/src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
@@ -209,6 +209,11 @@ class LOG4CXX_EXPORT TimeBasedRollingPolicy : public
virtual RollingPolicyBase,
*/
void setOption(const LogString& option, const LogString& value)
override;
+ /**
+ * Was the name in shared memory set by this process?
+ */
+ bool isLastFileNameUnchanged();
+
protected:
/**
* A map from "d" and "date" to a date conversion formatter.
diff --git a/src/test/cpp/benchmark/benchmark.cpp
b/src/test/cpp/benchmark/benchmark.cpp
index 4b8c79ae..4fce4434 100644
--- a/src/test/cpp/benchmark/benchmark.cpp
+++ b/src/test/cpp/benchmark/benchmark.cpp
@@ -7,6 +7,10 @@
#include <log4cxx/asyncappender.h>
#include <log4cxx/net/smtpappender.h>
#include <log4cxx/fileappender.h>
+#if LOG4CXX_HAS_MULTIPROCESS_ROLLING_FILE_APPENDER
+#include <log4cxx/rolling/multiprocessrollingfileappender.h>
+#include <log4cxx/rolling/timebasedrollingpolicy.h>
+#endif
#include <log4cxx/private/appenderskeleton_priv.h>
#if LOG4CXX_USING_STD_FORMAT
#include <format>
@@ -65,6 +69,25 @@ public:
}
};
+#if LOG4CXX_HAS_MULTIPROCESS_ROLLING_FILE_APPENDER
+class BenchmarkMultiprocessFileAppender : public
rolling::MultiprocessRollingFileAppender
+{
+public:
+ BenchmarkMultiprocessFileAppender(const LayoutPtr& layout)
+ {
+ setLayout(layout);
+ auto tempDir =
helpers::OptionConverter::getSystemProperty(LOG4CXX_STR("TEMP"),
LOG4CXX_STR("/tmp"));
+ auto policy =
std::make_shared<rolling::TimeBasedRollingPolicy>();
+ policy->setFileNamePattern(tempDir + LOG4CXX_STR("/") +
LOG4CXX_STR("multiprocess-%d{yyyy-MM-dd-HH-mm-ss-SSS}.log"));
+ setRollingPolicy(policy);
+ setFile(tempDir + LOG4CXX_STR("/") +
LOG4CXX_STR("multiprocess.log"));
+ setBufferedIO(true);
+ helpers::Pool p;
+ activateOptions(p);
+ }
+};
+#endif
+
void disableThousandSeparatorsInJSON()
{
std::setlocale(LC_ALL, "C"); /* Set locale for C functions */
@@ -77,6 +100,9 @@ public: // Attributes
LoggerPtr m_logger = getLogger();
LoggerPtr m_asyncLogger = getAsyncLogger();
LoggerPtr m_fileLogger = getFileLogger();
+#if LOG4CXX_HAS_MULTIPROCESS_ROLLING_FILE_APPENDER
+ LoggerPtr m_multiprocessLogger = getMultiprocessLogger();
+#endif
public: // Class methods
static int threadCount()
@@ -175,6 +201,27 @@ public: // Class methods
}
return result;
}
+
+#if LOG4CXX_HAS_MULTIPROCESS_ROLLING_FILE_APPENDER
+ static LoggerPtr getMultiprocessLogger()
+ {
+ LogString name = LOG4CXX_STR("benchmark.fixture.multiprocess");
+ auto r = LogManager::getLoggerRepository();
+ LoggerPtr result;
+ if (!(result = r->exists(name)))
+ {
+ result = r->getLogger(name);
+ result->setAdditivity(false);
+ result->setLevel(Level::getInfo());
+ auto writer =
std::make_shared<BenchmarkMultiprocessFileAppender>(std::make_shared<PatternLayout>(LOG4CXX_STR("%d
%m%n")));
+
writer->setName(LOG4CXX_STR("MultiprocessFileAppender"));
+ helpers::Pool p;
+ writer->activateOptions(p);
+ result->addAppender(writer);
+ }
+ return result;
+ }
+#endif
};
BENCHMARK_DEFINE_F(benchmarker, logDisabledTrace)(benchmark::State& state)
@@ -310,5 +357,19 @@ BENCHMARK_DEFINE_F(benchmarker,
fileIntPlusFloatValueMessageBuffer)(benchmark::S
BENCHMARK_REGISTER_F(benchmarker,
fileIntPlusFloatValueMessageBuffer)->Name("Logging int+float using
MessageBuffer, pattern: %d %m%n");
BENCHMARK_REGISTER_F(benchmarker,
fileIntPlusFloatValueMessageBuffer)->Name("Logging int+float using
MessageBuffer, pattern: %d %m%n")->Threads(benchmarker::threadCount());
+#if LOG4CXX_HAS_MULTIPROCESS_ROLLING_FILE_APPENDER
+BENCHMARK_DEFINE_F(benchmarker,
multiprocessFileIntPlusFloatValueMessageBuffer)(benchmark::State& state)
+{
+ int x = 0;
+ for (auto _ : state)
+ {
+ auto f = static_cast<float>(rand()) /
static_cast<float>(RAND_MAX);
+ LOG4CXX_INFO( m_multiprocessLogger, "Hello: message number " <<
++x
+ << " pseudo-random float " << std::setprecision(3) <<
std::fixed << f);
+ }
+}
+BENCHMARK_REGISTER_F(benchmarker,
multiprocessFileIntPlusFloatValueMessageBuffer)->Name("Multiprocess logging
int+float using MessageBuffer, pattern: %d %m%n");
+#endif
+
BENCHMARK_MAIN();
diff --git a/src/test/cpp/rolling/multiprocessrollingtest.cpp
b/src/test/cpp/rolling/multiprocessrollingtest.cpp
index 6c416ae5..4a57d0b8 100644
--- a/src/test/cpp/rolling/multiprocessrollingtest.cpp
+++ b/src/test/cpp/rolling/multiprocessrollingtest.cpp
@@ -173,7 +173,10 @@ public:
{
std::string expectedPrefix("multiprocess-3");
// remove any previously generated files
- for (auto const& dir_entry :
std::filesystem::directory_iterator{"output/rolling"})
+ std::filesystem::path outputDir("output/rolling");
+ if (!exists(outputDir))
+ ;
+ else for (auto const& dir_entry :
std::filesystem::directory_iterator{outputDir})
{
std::string
filename(dir_entry.path().filename().string());
if (expectedPrefix.size() < filename.size() &&
@@ -207,6 +210,7 @@ public:
&& filename.substr(0, expectedPrefix.size()) ==
expectedPrefix
&& filename.substr(filename.size() -
expectedSuffix.size()) == expectedSuffix)
{
+ auto initialPerThreadMessageCount =
perThreadMessageCount;
std::ifstream input(dir_entry.path());
for (std::string line; std::getline(input,
line);)
{
@@ -247,6 +251,18 @@ public:
}
}
}
+ if (helpers::LogLog::isDebugEnabled())
+ {
+ LogString msg;
+
helpers::Transcoder::decode(dir_entry.path().filename().string(), msg);
+ msg += LOG4CXX_STR(":
perThreadMessageCount ");
+ for (auto item : perThreadMessageCount)
+ {
+ msg += logchar(' ');
+
helpers::StringHelper::toString(item.second -
initialPerThreadMessageCount[item.first], p, msg);
+ }
+ helpers::LogLog::debug(msg);
+ }
}
}
if (helpers::LogLog::isDebugEnabled())
