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

編集：

OK、タイミングを1000倍間違えたので、ロガーが何も出力していないと思っていました。

目にしているのは、ログ ディスパッチャ スレッドの下に隠されている条件変数のコストです。

さらに詳しく知りたい場合は、この優れた分析を読むことができます。

基本的に、ロガーを呼び出す前にプリンター タスクを同期すると、すべてのプリンターが独自のロックでキューに入れられ、ロガーがより効率的に呼び出されます。

プリンターがロガーに非同期でアクセスしている場合、ロガーが最後の出力を終了した後に行うべき作業がないことを検出する回数が増えるため、ロガー スレッドは条件変数でスリープ状態になり、次の場合により多くの 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 に答える