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를 연결해서 사용하도록 해 주면 된다. 아래의 예제를 확인해 보자.
 
 
 
<div>
<table border="0" style="background: #fbe5d5; border-collapse: collapse;"><colgroup><col style="width: 1553px;"></col></colgroup><tbody valign="top">
<tr><td style="border-bottom: solid #a3a3a3 1.0pt; border-left: solid #a3a3a3 1.0pt; border-right: solid #a3a3a3 1.0pt; border-top: solid #a3a3a3 1.0pt; padding-bottom: 5px; padding-left: 5px; padding-right: 5px; padding-top: 5px;"><?xml version="1.0" encoding="UTF-8" ?>
 
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
 
<log4j:configuration
 
<div style="margin-left: 27pt;">
xmlns:log4j="<a class="con_link" href="http://jakarta.apache.org/log4j/" target="_blank">http://jakarta.apache.org/log4j/</a>"
</div>
<div style="margin-left: 27pt;">
threshold="debug">
</div>
<div style="margin-left: 27pt;">
<appender
</div>
<div style="margin-left: 54pt;">
name="CONSOLE"
</div>
<div style="margin-left: 54pt;">
class="org.apache.log4j.ConsoleAppender">
</div>
<div style="margin-left: 54pt;">
<param
</div>
<div style="margin-left: 81pt;">
name="Target"
</div>
<div style="margin-left: 81pt;">
value="System.out" />
</div>
<div style="margin-left: 54pt;">
<layout class="org.apache.log4j.PatternLayout">
</div>
<div style="margin-left: 81pt;">
<param
</div>
<div style="margin-left: 108pt;">
name="ConversionPattern"
</div>
<div style="margin-left: 108pt;">
value="%d{ABSOLUTE} (%-5p) [%t] [%c{1}] %m%n" />
</div>
<div style="margin-left: 54pt;">
</layout>
</div>
<div style="margin-left: 27pt;">
</appender>
</div>
 
 
<div style="margin-left: 27pt;">
<appender
</div>
<div style="margin-left: 54pt;">
name="FILE"
</div>
<div style="margin-left: 54pt;">
class="org.apache.log4j.DailyRollingFileAppender">
</div>
<div style="margin-left: 54pt;">
<param
</div>
<div style="margin-left: 81pt;">
name="File"
</div>
<div style="margin-left: 81pt;">
value="C:\\temp\\logs\\search.log" />
</div>
<div style="margin-left: 54pt;">
<param
</div>
<div style="margin-left: 81pt;">
name="Append"
</div>
<div style="margin-left: 81pt;">
value="true" />
</div>
<div style="margin-left: 54pt;">
<param
</div>
<div style="margin-left: 81pt;">
name="DatePattern"
</div>
<div style="margin-left: 81pt;">
value="'.'yyyy-MM-dd" />
</div>
<div style="margin-left: 54pt;">
<layout class="org.apache.log4j.PatternLayout">
</div>
<div style="margin-left: 81pt;">
<param
</div>
<div style="margin-left: 108pt;">
name="ConversionPattern"
</div>
<div style="margin-left: 108pt;">
value="%d{ABSOLUTE} [%-5p] [%t] [%c{1}] %m%n" />
</div>
<div style="margin-left: 54pt;">
</layout>
</div>
<div style="margin-left: 27pt;">
</appender>
</div>
 
 
<div style="margin-left: 27pt;">
<appender
 </div>
<div style="margin-left: 54pt;">
name="ASYNC_CONSOLE"
 </div>
<div style="margin-left: 54pt;">
class="org.apache.log4j.AsyncAppender">
 </div>
<div style="margin-left: 54pt;">
<param
 </div>
<div style="margin-left: 81pt;">
name="BufferSize"
 </div>
<div style="margin-left: 81pt;">
value="8192" />
 </div>
<div style="margin-left: 54pt;">
<appender-ref ref="CONSOLE" />
 </div>
<div style="margin-left: 27pt;">
</appender>
 </div>
 
 
<div style="margin-left: 27pt;">
<appender
 </div>
<div style="margin-left: 54pt;">
name="ASYNC_FILE"
 </div>
<div style="margin-left: 54pt;">
class="org.apache.log4j.AsyncAppender">
 </div>
<div style="margin-left: 54pt;">
<param
 </div>
<div style="margin-left: 81pt;">
name="BufferSize"
 </div>
<div style="margin-left: 81pt;">
value="8192" />
 </div>
<div style="margin-left: 54pt;">
<appender-ref ref="FILE" />
 </div>
<div style="margin-left: 27pt;">
</appender>
 </div>
 
 
<div style="margin-left: 27pt;">
<root>
</div>
<div style="margin-left: 54pt;">
<level value="DEBUG" />
</div>
<div style="margin-left: 54pt;">
<appender-ref ref="ASYNC_FILE" />
 </div>
<div style="margin-left: 27pt;">
</root>
</div>
</log4j:configuration></td></tr>
</tbody></table>
</div>
 
 
  위의 <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 에 대한 참고와 성능 비교는 <a class="con_link" href="http://logging.apache.org/log4j/2.0/manual/async.html" target="_blank">여기</a>에서 확인할 수 있다.
 
 
 
  그리고 Log4J2 Async 는 내부적으로 Disruptor를 사용하고 있으므로 아래와 같이 Maven 설정을 해 주어야 한다.
 
 
 
Log4J2 Maven
 
 
 
<div>
<table border="0" style="background: #fbe5d5; border-collapse: collapse;"><colgroup><col style="width: 1553px;"></col></colgroup><tbody valign="top">
<tr><td style="border-bottom: solid #a3a3a3 1.0pt; border-left: solid #a3a3a3 1.0pt; border-right: solid #a3a3a3 1.0pt; border-top: solid #a3a3a3 1.0pt; padding-bottom: 5px; padding-left: 5px; padding-right: 5px; padding-top: 5px;">…
 
<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>
 
...</td></tr>
</tbody></table>
</div>
 
 
All Async 를 사용하는 경우 설정
 
 
 
<div>
<table border="0" style="background: #fbe5d5; border-collapse: collapse;"><colgroup><col style="width: 1553px;"></col></colgroup><tbody valign="top">
<tr><td style="border-bottom: solid #a3a3a3 1.0pt; border-left: solid #a3a3a3 1.0pt; border-right: solid #a3a3a3 1.0pt; border-top: solid #a3a3a3 1.0pt; padding-bottom: 5px; padding-left: 5px; padding-right: 5px; padding-top: 5px;"><?xml version="1.0" encoding="UTF-8"?>
 
 

 
 
<Configuration status="WARN">
 
    <Appenders>
 
        
 
        <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></td></tr>
</tbody></table>
</div>
 
 
Async 와 Sync 를 섞어서 사용하는 경우 설정
 
 
 
<div>
<table border="0" style="background: #fbe5d5; border-collapse: collapse;"><colgroup><col style="width: 1553px;"></col></colgroup><tbody valign="top">
<tr><td style="border-bottom: solid #a3a3a3 1.0pt; border-left: solid #a3a3a3 1.0pt; border-right: solid #a3a3a3 1.0pt; border-top: solid #a3a3a3 1.0pt; padding-bottom: 5px; padding-left: 5px; padding-right: 5px; padding-top: 5px;"><?xml version="1.0" encoding="UTF-8"?>
 
 

 
 
<Configuration status="WARN">
 
    <Appenders>
 
        
 
        <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>
 
        
 
        <AsyncLogger name="com.foo.Bar" level="trace" includeLocation="true">
 
            <AppenderRef ref="RandomAccessFile"/>
 
        </AsyncLogger>
 
        <Root level="info" includeLocation="true">
 
            <AppenderRef ref="RandomAccessFile"/> 
        </Root>
 
    </Loggers>
 
</Configuration></td></tr>
</tbody></table>
</div>
 
 
Async 처리할 때 주의할 점
 
 
 
  우선 비 동기 처리를 할 때의 한 가지 주의할 점은 로그를 출력을 요청하는 시점과 실제 로그 매체로 정보를 쓰는 시점이 다르다는 것 때문에 발생하는 데이터의 불변성 문제를 이해하는 것이다. 예를 들어 어떤 객체를 로그 처리하는데 그 시점의 객체가 100 이라는 값을 가지고 있었지만, 실제 매체에 출력될 때 객체의 값이 200으로 변경이 되었거나 아니면 객체가 제거된 상태라면 로그 출력은 정확하지 않은 정보를 출력하거나 출력하지 못하는 null 참조 오류가 발생하게 된다. (물론 비 동기 오류이기 때문에 발생했는지도 모르겠지만, 원하는 로그 정보가 존재하지 않게 된다)
 
 
 
  아래와 같이 단적인 사례를 확인해 볼 수 있다.
 
 
 
<div>
<table border="0" style="background: #fbe5d5; border-collapse: collapse;"><colgroup><col style="width: 1553px;"></col></colgroup><tbody valign="top">
<tr><td style="border-bottom: solid #a3a3a3 1.0pt; border-left: solid #a3a3a3 1.0pt; border-right: solid #a3a3a3 1.0pt; border-top: solid #a3a3a3 1.0pt; padding-bottom: 5px; padding-left: 5px; padding-right: 5px; padding-top: 5px;">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();
 
        }
 
    }
 
}</td></tr>
</tbody></table>
</div>
 
 
  위의 예제는 32개의 쓰레드를 생성해서 각각 100번씩 루프를 돌면서 인스턴스의 Long 값을 로그로 남기는 예제다. 여기서 중요한 부분은 로그를 Async 로 설정 (위에서 설명한 Async 옵션을 log4j2 에 적용) 한 상태에서 객체를 로그로 보내는 경우와 문자열을 객체로 보내는 경우를 비교한 것이다. 위의 코드를 객체와 문자열로 처리한 결과는 다음과 같다.
 
 
 
<div>
<table border="0" style="background: #fbe5d5; border-collapse: collapse;"><colgroup><col style="width: 1553px;"></col></colgroup><tbody valign="top">
<tr><td style="border-bottom: solid #a3a3a3 1.0pt; border-left: solid #a3a3a3 1.0pt; border-right: solid #a3a3a3 1.0pt; border-top: solid #a3a3a3 1.0pt; padding-bottom: 5px; padding-left: 5px; padding-right: 5px; padding-top: 5px;">>>> 객체를 사용한 경우 (서로 다른 값 발생)
 
 
 
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 </td></tr>
</tbody></table>
</div>
 
 
  위의 결과에서 볼 수 있듯이 next() 의 결과는 Long 이기 때문에 불변 값에 속해서 출력이 되었지만 ins 객체를 사용한 경우는 출력이 되는 시점에 객체의 값을 출력하기 때문에 항상 next 처리된 값보다 큰 상태가 된다. 
 
 
 
  실제 운영 중인 시스템에서 문제가 발생한 것과 문제 원인을 파악하는데 로그를 사용할 수 밖에는 없다. 따라서 위와 같은 상황이 되면 로그 자체가 정확한 상태를 반영하지 못하는 것이 될 수 밖에는 없기 때문에 비 동기 출력을 사용하는 경우에는 로그에 출력된 값이 정확한 상태를 나타낼 수 있도록 불변의 값을 사용해야 한다는 점을 이해하고 사용해야 한다.

MSFL :: 모리스 소프트웨어 공작소

이 블로그 검색

Log4J Async 설정하기

태그

댓글

댓글 쓰기