0

我正在对 log4cxx 进行性能测试。当我直接调用 LOG4CXX_XXXXX 时，以下代码大约需要 10 秒才能完成记录所有内容。但是当我用 boost::lockguard （我认为这是一个关键部分）来结束调用时，大约需要 5 秒。有人可以解释为什么会这样，而不是相反。

#include "log4cxx/logger.h"
#include "log4cxx/xml/domconfigurator.h"
#include <boost/thread/thread.hpp>
#include <boost/timer/timer.hpp>
#include <boost/thread/recursive_mutex.hpp>

//#define ENHANCEDLOGGING

using namespace log4cxx;
using namespace log4cxx::helpers;

#define LOG_TMP_BUF_SIZE        3000
LoggerPtr logger(Logger::getRootLogger());

#ifdef ENHANCEDLOGGING
void LOG_DEBUG(const char *format)
{
    LOG4CXX_DEBUG(logger, format);
}
#else
boost::recursive_mutex m_guard;
#define LOG_COMM 0

void LOG_DEBUG(const char *format)
{
    boost::lock_guard<boost::recursive_mutex> lock(m_guard);
    LOG4CXX_DEBUG(logger, format);
}
#endif

const int thread_count = 100;

void printer(void)
{
    for (int i = 0; i < 4000; i++)
        LOG_DEBUG("Logging performance check");
}

int main(int argc, char **argv)
{
    boost::timer::auto_cpu_timer t;
    xml::DOMConfigurator::configure("config.xml");

    boost::thread_group threads;
    for (int i = 0; i != thread_count; ++i)
        threads.create_thread(printer);

    threads.join_all();

    std::cout << t.elapsed().user << std::endl;
    std::cout << t.elapsed().wall << std::endl;
    std::cout << t.elapsed().system << std::endl;
    return 0;
}

我正在使用以下配置。使用/不使用 org.apache.log4j.AsyncAppender 运行没有区别

<appender name="appxNormalAppender" class="org.apache.log4j.FileAppender">
    <param name="file" value="appxLogFile.log" />
    <param name="append" value="true" />
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d %-5p %C{2} (%F:%L) %t - %m%n" />
    </layout>
</appender>
<appender name="async" class="org.apache.log4j.AsyncAppender">
    <param name="BufferSize" value="1000"/>
    <appender-ref ref="appxNormalAppender"/>
</appender>
<root>
    <priority value="all" />
        <appender-ref ref="appxNormalAppender"/>
</root>
</log4j:configuration>
4

1 回答 1

0

编辑：

好的，我把时间弄错了 1000 倍，所以我认为记录器没有输出任何东西。

您所看到的是隐藏在日志调度程序线程下的条件变量的成本。

如果您想了解更多细节，可以阅读这篇出色的分析。

基本上，当您在调用记录器之前同步打印机任务时，所有打印机将在您自己的锁上排队，并且记录器将被更有效地调用。

如果你的打印机是异步访问logger，那么在完成最后一个输出后，logger会发现没有工作要做，所以logger线程会在条件变量上进入睡眠状态，这样会消耗更多的CPU。下一台打印机必须唤醒记录仪。

请参阅这个模拟使用条件变量实现的准系统等待队列的示例程序。
这里记录器线程队列的长度为 1，但是当您将数千条消息塞入系统时，真正记录器的队列将立即被填满，因此您的大多数测试程序将在一个饱和队列中运行，从而重现了这个小例子中的条件。

#include <mutex>
#include <condition_variable>
#include <thread>
#include <ctime>
#include <vector>
#include <iostream>

#define thread_count 100
#define log_count 600000/thread_count

const char * pending;
bool kill = false;
std::mutex              lock;
std::condition_variable work;
int logger_waits;
void logger (void)
{ 
    // process requests
    for (;;)
    {
        std::unique_lock<std::mutex> waiter(lock);
        while (pending == nullptr && !kill)
        {
            logger_waits++;
            work.wait(waiter);
        }
        if (kill) break;
        std::cout << pending << std::endl;
        pending = nullptr;       
    }
}

void console_log (const char * format)
{
    std::unique_lock<std::mutex> waiter(lock);
    pending = format;
    work.notify_one();
}

void printer1(void)
{
    for (int i = 0; i < log_count; i++)
    {
        console_log("Logging check");
    }
}

std::mutex m_guard;
void printer2(void)
{
    for (int i = 0; i < log_count; i++)
    {
        std::unique_lock<std::mutex> waiter(m_guard);
        console_log("Logging check");
    }
}

int bench (void (*printer)(void))
{
    std::vector<std::thread> printers;
    printers.resize(thread_count);
    logger_waits = 0;

    clock_t start =clock();

    for (int i = 0; i != thread_count; ++i)
        printers[i] = std::thread(printer);

    for (int i = 0; i != thread_count; ++i)
        printers[i].join();

    return (clock()-start)/(CLOCKS_PER_SEC/1000);

}

int main(int argc, char **argv)
{  
    std::thread logthread (logger);

    int time2 = bench (printer2);
    int lw2 = logger_waits;
    int time1 = bench (printer1);
    int lw1 = logger_waits;
    fprintf (stderr, "\n   lock : %d ms %d waits\n", time1, lw1);
    fprintf (stderr,   "no lock : %d ms %d waits\n", time2, lw2);

    kill = true;
    work.notify_one();
    logthread.join();

    return 0;
}

典型输出：

   lock : 3940 ms 183 waits
no lock : 4820 ms 16093 waits

尽管如此，这个测试用例并没有反映日志系统的正确使用。它旨在一次输出几条消息，以便主应用程序永远不会因日志输出而减慢。

于 2014-02-04T16:35:54.890 回答