Skip to content

Commit

Permalink
Reduce MultiprocessRollingFileAppender overhead (#443)
Browse files Browse the repository at this point in the history 
* 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
  • Loading branch information
@swebb2066
swebb2066 authored Dec 17, 2024
1 parent e096ae3 commit 4b50a6f
Show file tree
Hide file tree
Showing 6 changed files with 175 additions and 128 deletions.
177 changes: 55 additions & 122 deletions src/main/cpp/multiprocessrollingfileappender.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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
Expand Down Expand Up @@ -198,39 +129,6 @@ struct MultiprocessRollingFileAppender::MultiprocessRollingFileAppenderPriv
};
};

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)
Expand All @@ -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"));
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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))
{
Expand Down Expand Up @@ -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;
}

/**
Expand All @@ -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
Expand All @@ -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);
}
Expand All @@ -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);
}


Expand Down
20 changes: 20 additions & 0 deletions src/main/cpp/timebasedrollingpolicy.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
22 changes: 17 additions & 5 deletions src/main/include/log4cxx/rolling/multiprocessrollingfileappender.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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
Expand All @@ -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);
Expand Down
5 changes: 5 additions & 0 deletions src/main/include/log4cxx/rolling/timebasedrollingpolicy.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
Loading

0 comments on commit 4b50a6f

Please sign in to comment.