기본 콘텐츠로 건너뛰기

Log4J Async 설정하기

  현재 진행 중인 검색 (Solr + SolrJ) 프로젝트에서 Paging 처리를 하고 있는데 페이지를 랜덤으로 이동을 하게 되면 시간이 너무 오래 걸리는 증상이 발견이 되어, 이런 저런 테스트와 Solr 관리 화면을 통해서 start 와 rows 를 지정하고 검증을 해 보면 약간 느리다는 느낌을 받지만 그 다지 문제가 되지는 않을 정도로 결과가 나왔다. 그런데 막상 구현한 SolrJ 클라이언트를 통해서 검색을 하면 무려 11초 이상이 걸리는 증상이 계속되고 있다.
 
  여러 가지 의심되는 부분들을 조정하면서 검증을 수행한 결과 Log4J 의 Logging 처리 때문이라는 것이 확인이 되었다. 이유는 기본 Log4J 에 LogLevel을 Debug로 설정 상태에서 Solr 의 결과를 Debug 출력하고 있었던 것이 문제가 된 것이다. 로그 출력을 INFO 수준으로 높이고 실행한 결과 대략 Solr 관리 화면에서 수행한 것과 비슷한 수행 시간이 걸리는 것을 확인했다.
 
  검증을 위해서 결과 출력을 제외할 수는 없기 때문에 비 동기 방식으로 전환을 하여 적용하면 약간은 느리겠지만 정보를 확인하는데 문제는 없기 때문에 이번에는 비 동기 설정에 대해서 정리를 하도록 한다.
 
Log4J Async 설정
 
  Log4J 에서는 AsyncAppender를 제공하고 있으며 이를 통해서 로그를 비 동기로 처리하게 된다. 설정 방법은 기존에 사용하는 것과 크게 다르지 않다. 다만 CONSOLE 이나 FILE 등의 Appender 를 사용하고 있었다면 AsyncAppender로 기존 Appender를 연결해서 사용하도록 해 주면 된다. 아래의 예제를 확인해 보자.
 
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration
threshold="debug">
<appender
name="CONSOLE"
class="org.apache.log4j.ConsoleAppender">
<param
name="Target"
value="System.out" />
<layout class="org.apache.log4j.PatternLayout">
<param
name="ConversionPattern"
value="%d{ABSOLUTE} (%-5p) [%t] [%c{1}] %m%n" />
</layout>
</appender>
 
<appender
name="FILE"
class="org.apache.log4j.DailyRollingFileAppender">
<param
name="File"
value="C:\\temp\\logs\\search.log" />
<param
name="Append"
value="true" />
<param
name="DatePattern"
value="'.'yyyy-MM-dd" />
<layout class="org.apache.log4j.PatternLayout">
<param
name="ConversionPattern"
value="%d{ABSOLUTE} [%-5p] [%t] [%c{1}] %m%n" />
</layout>
</appender>
 
<appender
name="ASYNC_CONSOLE"
class="org.apache.log4j.AsyncAppender">
<param
name="BufferSize"
value="8192" />
<appender-ref ref="CONSOLE" />
</appender>
 
<appender
name="ASYNC_FILE"
class="org.apache.log4j.AsyncAppender">
<param
name="BufferSize"
value="8192" />
<appender-ref ref="FILE" />
</appender>
 
<root>
<level value="DEBUG" />
<appender-ref ref="ASYNC_FILE" />
</root>
</log4j:configuration>
 
  위의 <root> 요소에서 보이는 것과 같이 ASYNC_FILE Appender를 사용하고, ASYNC_APPENDER 는 내부에 FILE APPENDER를 참조해서 동작하게 된다. 비 동기 처리할 때의 기준은 위에서 "ASYNC_FILE" 이나 "ASYNC_CONSOLE" 설정과 같이 BufferSize 를 설정해 주면 된다. 해당 값에 따라서 메모리 상에 출력할 로그 정보를 관리하다가 Buffer가 모자라게 되면 지정된 FILE Appender에 출력을 진행하게 된다.
 
Log4J2 (v2.0) Async 설정
 
  참고로 현재는 대부분 slf4j 와 logback 등을 사용하는 것으로 보이지만 log4j 도 2.0 버전으로 log4j2 라는 이름으로 계속 진행되고 있다. Log4j2 에서는 Async Appender를 별도로 Configuration 설정에 추가하지 않고도 전체 Logger를 비동기 처리할 수 있도록 "-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector" 옵션을 설정해서 사용하면 된다. 물론 Sync 와 Async 모두 사용하도록 설정할 수도 있다. Log4j2 에 대한 Sync, Async, All Async 에 대한 참고와 성능 비교는 여기에서 확인할 수 있다.
 
  그리고 Log4J2 Async 는 내부적으로 Disruptor를 사용하고 있으므로 아래와 같이 Maven 설정을 해 주어야 한다.
 
Log4J2 Maven
 

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.1</version>
    </dependency>
<dependency>
    <groupId>com.lmax</groupId>
    <artifactId>disruptor</artifactId>
    <version>3.0.1</version>
</dependency>
...
 
All Async 를 사용하는 경우 설정


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

<!-- Don't forget to set system property "-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector" to make all loggers asynchronous. -->

<Configuration status="WARN">
    <Appenders>
        <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
        <RandomAccessFile name="RandomAccessFile" fileName="async.log" immediateFlush="false" append="false">
            <PatternLayout>
                <Pattern>%d %p %c{1.} [%t] %m %ex%n</Pattern>
            </PatternLayout>
        </RandomAccessFile>
    </Appenders>
    <Loggers>
        <Root level="info" includeLocation="false">
            <AppenderRef ref="RandomAccessFile"/>
        </Root>
    </Loggers>
</Configuration>
 
Async 와 Sync 를 섞어서 사용하는 경우 설정


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

<!-- No need to set system property "Log4jContextSelector" to any value when using <asyncLogger> or <asyncRoot>. -->

<Configuration status="WARN">
    <Appenders>
        <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
        <RandomAccessFile name="RandomAccessFile" fileName="asyncWithLocation.log"
immediateFlush="false" append="false">
            <PatternLayout>
                <Pattern>%d %p %class{1.} [%t] %location %m %ex%n</Pattern>
            </PatternLayout>
        </RandomAccessFile>
    </Appenders>
    <Loggers>
        <!-- pattern layout actually uses location, so we need to include it -->
        <AsyncLogger name="com.foo.Bar" level="trace" includeLocation="true">
            <AppenderRef ref="RandomAccessFile"/>
        </AsyncLogger>
        <Root level="info" includeLocation="true">
            <AppenderRef ref="RandomAccessFile"/>
        </Root>
    </Loggers>
</Configuration>
 
Async 처리할 때 주의할 점
 
  우선 비 동기 처리를 할 때의 한 가지 주의할 점은 로그를 출력을 요청하는 시점과 실제 로그 매체로 정보를 쓰는 시점이 다르다는 것 때문에 발생하는 데이터의 불변성 문제를 이해하는 것이다. 예를 들어 어떤 객체를 로그 처리하는데 그 시점의 객체가 100 이라는 값을 가지고 있었지만, 실제 매체에 출력될 때 객체의 값이 200으로 변경이 되었거나 아니면 객체가 제거된 상태라면 로그 출력은 정확하지 않은 정보를 출력하거나 출력하지 못하는 null 참조 오류가 발생하게 된다. (물론 비 동기 오류이기 때문에 발생했는지도 모르겠지만, 원하는 로그 정보가 존재하지 않게 된다)
 
  아래와 같이 단적인 사례를 확인해 볼 수 있다.


public class AsyncLog4jTest {
    private static final AtomicLong value = new AtomicLong();
 
    @Override
    public String toString() {
        return Long.toString(value.get());
    }
 
    public long next() {
        return value.incrementAndGet();
    }
 
    public static void main(String[] args) {
        for (int i = 0; i < 32; i++) {
            new Thread() {
                final Logger logger = LogManager.getLogger(AsyncLog4jTest.class);
                final AsyncLog4jTest ins = new AsyncLog4jTest();
 
                @Override
                public void run() {
                    for (int i = 0; i < 100; i++) {
                            logger.warn("increment: {} == current: {}", ins.next(), ins); // 객체 사용
                            // logger.warn("increment: {} == current: {}", ins.next(), ins.toString()); // 불변의 문자열 사용
                    }
                }
            }.start();
        }
    }
}
 
  위의 예제는 32개의 쓰레드를 생성해서 각각 100번씩 루프를 돌면서 인스턴스의 Long 값을 로그로 남기는 예제다. 여기서 중요한 부분은 로그를 Async 로 설정 (위에서 설명한 Async 옵션을 log4j2 에 적용) 한 상태에서 객체를 로그로 보내는 경우와 문자열을 객체로 보내는 경우를 비교한 것이다. 위의 코드를 객체와 문자열로 처리한 결과는 다음과 같다.
 
>>> 객체를 사용한 경우 (서로 다른 값 발생)
 
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-10] increment: 10 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-2] increment: 2 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-4] increment: 4 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-8] increment: 8 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-0] increment: 1 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-6] increment: 6 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-3] increment: 3 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-9] increment: 9 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-5] increment: 5 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-7] increment: 7 == current: 10
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-9] increment: 11 == current: 14
2014-11-29 15:38:00,351 WARN c.m.s.l.AsyncLog4jTest [Thread-10] increment: 13 == current: 14
 
>>> 문자열을 사용한 경우 (모든 값 일치)
 
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-9] increment: 9 == current: 9
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-2] increment: 2 == current: 2
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-3] increment: 3 == current: 3
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-5] increment: 5 == current: 5
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-10] increment: 10 == current: 10
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-4] increment: 4 == current: 4
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-7] increment: 7 == current: 7
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-9] increment: 11 == current: 11
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-6] increment: 6 == current: 6
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-0] increment: 1 == current: 2
2014-11-29 15:32:39,767 WARN c.m.s.l.AsyncLog4jTest [Thread-3] increment: 12 == current: 12
 
  위의 결과에서 볼 수 있듯이 next() 의 결과는 Long 이기 때문에 불변 값에 속해서 출력이 되었지만 ins 객체를 사용한 경우는 출력이 되는 시점에 객체의 값을 출력하기 때문에 항상 next 처리된 값보다 큰 상태가 된다.
 
  실제 운영 중인 시스템에서 문제가 발생한 것과 문제 원인을 파악하는데 로그를 사용할 수 밖에는 없다. 따라서 위와 같은 상황이 되면 로그 자체가 정확한 상태를 반영하지 못하는 것이 될 수 밖에는 없기 때문에 비 동기 출력을 사용하는 경우에는 로그에 출력된 값이 정확한 상태를 나타낼 수 있도록 불변의 값을 사용해야 한다는 점을 이해하고 사용해야 한다.

댓글