현재 진행 중인 검색 (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를 연결해서 사용하도록 해 주면 된다. 아래의 예제를 확인해 보자.
|
xmlns:log4j="http://jakarta.apache.org/log4j/"
threshold="debug">
name="CONSOLE"
class="org.apache.log4j.ConsoleAppender">
name="Target"
value="System.out" />
name="ConversionPattern"
value="%d{ABSOLUTE} (%-5p) [%t] [%c{1}] %m%n" />
name="FILE"
class="org.apache.log4j.DailyRollingFileAppender">
name="File"
value="C:\\temp\\logs\\search.log" />
name="Append"
value="true" />
name="DatePattern"
value="'.'yyyy-MM-dd" />
name="ConversionPattern"
value="%d{ABSOLUTE} [%-5p] [%t] [%c{1}] %m%n" />
name="ASYNC_CONSOLE"
class="org.apache.log4j.AsyncAppender">
name="BufferSize"
value="8192" />
name="ASYNC_FILE"
class="org.apache.log4j.AsyncAppender">
name="BufferSize"
value="8192" />
|
위의
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
| …
... |
All Async 를 사용하는 경우 설정
|
|
Async 와 Sync 를 섞어서 사용하는 경우 설정
|
immediateFlush="false" append="false"> |
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 처리된 값보다 큰 상태가 된다.
실제 운영 중인 시스템에서 문제가 발생한 것과 문제 원인을 파악하는데 로그를 사용할 수 밖에는 없다. 따라서 위와 같은 상황이 되면 로그 자체가 정확한 상태를 반영하지 못하는 것이 될 수 밖에는 없기 때문에 비 동기 출력을 사용하는 경우에는 로그에 출력된 값이 정확한 상태를 나타낼 수 있도록 불변의 값을 사용해야 한다는 점을 이해하고 사용해야 한다.
댓글
댓글 쓰기