非同期ロガー

非同期ロギング

Javaはlog4jから始まってslf4j, logbackとロギングAPIの歴史の立役者が揃っている．
そのようなロギングAPIはサイズまたは日付にによる自動ローリング，仔細なフォーマッティングの指定等といった必要不可欠でかつ極めて有用な機能をすべて提供してくれている．

そういった機能の中で私が注目したいのが非同期ロギングである．マルチスレッディングのアプリケーションにおいてロギングは避けることの出来ないクリティカルセクションである．しかしながら，非同期ロガーを使えばロギングはもはやクリティカルセクションではなくなるlog．

ここでは実装はlogback,インターフェースはslf4j-apiの組み合わせによる非同期ロガーの例を紹介してみる．

logback Async Logger

使い方は単純．logback.xml (ユニットテストにはlogback-test.xml )にAsyncAppenderの定義をして，そのappenderをrootの入れ子要素として宣言すればよい．
以下は実際のlogback.xmlの一例．
ここではASYNCアペンダーにFILEアペンダーを宣言して，ファイルへのロギングを非同期化している．


<?xml version="1.0" encoding="UTF-8"?>

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{5} - %msg%n</pattern>
    </encoder>
  </appender>
  
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <!-- <file>${LOGBACK_LOGDIR}/sample.log</file> -->
    <file>${LOGBACK_HOMEDIR}/samplelog.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${LOGBACK_HOMEDIR}/samplelog-%d{yyyy-MM-dd}.log</fileNamePattern>
      <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
        <maxFileSize>20MB</maxFileSize>
        <maxHistory>2</maxHistory>
      </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{5} - %msg%n</pattern>    
    </encoder>
  </appender>
  
  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
      <appender-ref ref="FILE"/>
      <!-- discardingThreashold == 0 means it won't drop TRACE, DEBUG and INFO level log even when the remaining capacity of blocking queue is less than 20% -->
      <discardingThreshold>0</discardingThreshold>
  </appender>

  <!-- Strictly speaking, the level attribute is not necessary since -->
  <!-- the level of the root level is set to DEBUG by default.       -->
  <root level="INFO">          
    <appender-ref ref="STDOUT" />
    <appender-ref ref="ASYNC" />
  </root>  
  
</configuration>

考慮すべきこと

ASYNCロガーは色々便利そうではあるが，非同期の常，扱いは同期のものよりやや手数がかかる．一番気をつけなければいけないのはやはりブロッキングキューのサイズだろう．

もし大量のスレッドが(大量ではないにせよ)沢山のログを非同期ロガーに送り込んだ場合，言い換えるならば沢山のログをロガーのブロッキングキューに追加した場合，最悪の場合ブロッキングキューがフルになってしまう．そのような場合，非同期ロガーはブロッキングキューに空きが出るまでアプリケーションスレッドをブロックさせる．この振る舞いをlogbackはpseudo synchronous (疑似同期)と呼んでいる．logbackでは以下のポイントがpseudo synchronousを引き起こしやすいとしている．

 logback 公式ページより引用

• Large numbers of application threads (沢山のスレッド)
• Large numbers of logging events per application call (沢山のロギング)
• Large amounts of data per logging event (各ロギングイベントでの沢山のデータ)
• High latency of child appenders (レイテイシの大きい子アペンダー)

上記いずれかに当てはまると思ったならば，是非改善したいところである．