Log4J Asyncやったら遅くなるんだけど

みんな大好きLog4J。この記事は非同期の設定
作者はロギングのシステムについてはあんまりわかってない。
WEBでまよったりして動かなかったので記事まとめる。

結論

なんか私の環境ではAsyncじゃないほうが速い。

動機

WEBアプリケーションのボトルネックはロギングとDBなので速いものを求めた。

公式

http://logging.apache.org/log4j/2.x/manual/async.html
6-68倍速とのこと。すごい。
監査証跡ログとかExceptionログとかに使わないほうが良いよ！っていってるけどまぁ大丈夫だよね。使う。

要求

IPAの文書に従うと(プロジェクトメンバーが読んでくれてスペック教えてくれた)、

• SQLのログ
• アクセスログ
• アプリのログ(自由形式？)
  を作っておけとのこと。
  アクセスログはWEBサーバーで出しても良いんだろうけどアプリ側でも出すことにする
  よって一旦3つのロガーを設定する例を考えた

書き方

Asyncで囲むAsyncLoggerと書く

前者だと私が試した感じでうまく行かなかった。なんで？→AsyncLogger使う

RollingRandomAccessFileAppenderとFileAppenderとRollingFileAppender

RandomAccessFileが速いらしいので採用

log4j2.xml

実際わからんよね。むずい。

の前にlog4j.properties

log4j.properties作って置かないとおこられるので雑に置く。多分FWのVert.xの要求だとおもうんだけど追いかけていない

log4j.rootLogger=ERROR, console
log4j.logger.xxx=ERROR, console
log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d [%-5p-%c] %m%n

log4j.xml

愚直に書くよ

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <Console name="Console">
      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
    </Console>
    <RollingRandomAccessFile name="AppLog" fileName="logs/app.log" filePattern="logs/old/app-%d{yyyy-MM-dd}.log.gz"
                 ignoreExceptions="false">
      <PatternLayout>
        <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
      </PatternLayout>
      <TimeBasedTriggeringPolicy/>
    </RollingRandomAccessFile>
    <RollingRandomAccessFile name="AccessLog" fileName="logs/access.log" filePattern="logs/old/access-%d{yyyy-MM-dd}.log.gz"
                 ignoreExceptions="false">
      <PatternLayout>
        <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
      </PatternLayout>
      <TimeBasedTriggeringPolicy/>
    </RollingRandomAccessFile>
    <RollingRandomAccessFile name="ErrorLog" fileName="logs/error.log" filePattern="logs/old/error-%d{yyyy-MM-dd}.log.gz"
                 ignoreExceptions="false">
      <PatternLayout>
        <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
      </PatternLayout>
      <TimeBasedTriggeringPolicy/>
    </RollingRandomAccessFile>
    <RollingRandomAccessFile name="SQLLog" fileName="logs/sql.log" filePattern="logs/old/sql-%d{yyyy-MM-dd}.log.gz"
                 ignoreExceptions="false">
      <PatternLayout>
        <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
      </PatternLayout>
      <TimeBasedTriggeringPolicy/>
    </RollingRandomAccessFile>
    <Async name="AppAsync">
      <AppenderRef ref="Console"/>
    </Async>
  </Appenders>
  <Loggers>
    <Root level="info">
      <AppenderRef ref="AppAsync"/>
    </Root>
    <AsyncLogger level="debug" name="access-log">
      <AppenderRef ref="AccessLog"/>
    </AsyncLogger>
    <AsyncLogger level="debug" name="error-log">
      <AppenderRef ref="ErrorLog"/>
    </AsyncLogger>
    <AsyncLogger level="debug" name="sql-log">
      <AppenderRef ref="SQLLog"/>
    </AsyncLogger>
  </Loggers>
</Configuration>

パフォーマンス

abコマンドで雑に叩く
セレロンの超遅いファイルサーバーマシンで確認

非同期

Requests per second:    347.96 [#/sec] (mean)

同期

Requests per second:    2830.04 [#/sec] (mean)

同期のほうが速いですやん。嘘やん。なんか間違っている気がする。

計測大事

同期のほうが速いという状況。よくわからん。ちゃんと計測しないとだめですねー
以上です。