VisualVM을 이용한 log4j2 로그 수준 변경 및 모니터링

| VisualVM

VisualVM은 JVM 에서 동작하는 어플리케이션의 프로파일링 및 모니터링을 제공하는 GUI 툴입니다. 현재 다니고 있는 회사에서는 다른 JVM 모니터링 툴을 사용하지 않고 VisualVM을 통해 모니터링 및 프로파일링을 하고 있습니다. 

다른 상용 툴(ex. 제니퍼소프트 제품들)들을 써보지 않아서 모르겠지만 VisualVM 만으로 아직까지는 큰 불편없이 19만줄 가량되는 마이크로아키텍처 기반 데이터 파이프라이닝 프로젝트를 운영하고 있습니다.

| 실행 환경

• Window 10 home
• Java 1.8 
• IntelliJ IDE( Not Required )

| VisualVM을 이용한 log4j2 로그 수준 변경

운영을 하는 도중에 특정 Logger의 로깅 레벨 수준을 높여 DEBUG 및 TRACE 성 로그를 추적하고 싶을 때가 있습니다. 이 때 VisualVM을 이용하여 로컬 개발 PC에서 원격으로 운영 서버에 접속하여 어플리케이션 로깅 시스템의 로깅 레벨 수준을 높일 수 있습니다.

그 중에서 log4j2 기반인 로깅 시스템에서 VisualVM을 통해 어떻게 로그 수준을 변경하고 어플리케이션이 어떻게 동작하는 지 알아 보겠습니다.

프로젝트 구조

+---src
|   +---main
|   |   +---java
|   |   |   \---com
|   |   |       |   Com.java
|   |   |       |
|   |   |       \---dev
|   |   |               ComDev.java
|   |   |
|   |   \---resources
|   |           log4j2.xml

의존성 설정

<dependencies>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>2.11.2</version>
    </dependency>
</dependencies>

• slf4j의 log4j2의 구현체를 쓰게되면 바로 log4j2 기반인 로깅시스템을 쓸 수 있습니다.

log4j2.xml 설정 파일

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{yyyy-MM-dd'T'HH:mm:ss.SSS} [%t] %p %m%n"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="WARN" additivity="false">
            <appender-ref ref="console"/>
        </Root>
        <Logger name="com" level="WARN" additivity="false">
            <appender-ref ref="console"/>
        </Logger>
        <Logger name="com.dev" level="TRACE">
            <appender-ref ref="console"/>
        </Logger>
    </Loggers>

</Configuration>

• log4j2.xml 파일에서 로거들은 루트 로거와 com 및 com.dev 패키지 경로를 기반으로 하는 com.dev 로거 정보들을 설정해 놓았습니다. com은 WARN, com.dev 는 TRACE 레벨입니다.

소스 코드

package com;

import com.dev.ComDev;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Com {

    private static Logger logger = LoggerFactory.getLogger(Com.class);

    public static void main(String[] args) {
        while(true) {
            logger.warn("This is [com] main warning ");
            new ComDev();
            Thread.sleep(3000);
        }
    }

}

package com.dev;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class ComDev {

    private static Logger logger = LoggerFactory.getLogger(ComDev.class);

    public ComDev() {
        logger.trace("This is [com.dev] trace warning ");
    }

}

• 단순 로그 메세지를 띄우는 코드입니다. 두 코드모두 자신의 로그 레벨에 맞는 로그 메시지를 출력하기 때문에 아래와 같이 콘솔에 출력화면이 뜰 수 있습니다. ( Com 클래스는 WARN, ComDev 클래스는 TRACE )
• main 진입점에서 while 문으로 계속해서 로그 메세지를 출력하는 코드를 작성하였습니다.

실행 설정

IntelliJ 기준으로 Run Configuration에서 VM Option을 다음과 같이 줍니다.

-Dcom.sun.management.jmxremote.port=3000 -Dcom.sun.management.jmxremote.authenticate=false

만일 IntelliJ 가 아닌 다른 IDE거나 명령어창으로 실행할 경우 아래와 같이 VM Option을 준 후 실행합니다.

java.exe -Dcom.sun.management.jmxremote.port=3000 -Dcom.sun.management.jmxremote.authenticate=false

위에서 -Dcom.sun.management.jmxremote.port 는 jmx 포트를 설정하는 옵션이고 -Dcom.sun.management.jmxremote.authenticate 옵션은 jmx 접속시 권한이 있는 지를 체크하는 옵션입니다. 지금은 단순 테스트라서 옵션을 꺼놓았습니다.

결과 화면

2019-05-30T23:26:17.031 [main] WARN This is [com] main warning
2019-05-30T23:26:17.047 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:26:17.047 [main] TRACE This is [com.dev] trace warning 
...

VisualVM 

• VisualVM은 보통 JDK를 설치할 때 번들로 제공되며 JDK가 인스톨된 디렉터리의 bin 디렉터리에 있습니다.
• VisualVM을 키면 왼쪽의 Application 탭에 위에서 실행했던 어플리케이션이 Application 탭에 나타난 것을 볼 수 있습니다.
• 처음 VisualVM을 실행하게 되면 MBeans를 VisualVM에서 제어할 Plugin이 설치가 안 된 상태입니다. Tools -> Plugins 에서 VisualVM-MBeans Plugin을 설치합니다.
• MBean은 Managed Bean이라하며 표준 스펙에 맞춰 개발된 관리 인터페이스라고 생각하시면 됩니다. 이 인터페이스를 통해 JMX 상에서 어플리케이션을 제어할 수 있게 됩니다.

• Plugin을 설치하면 아래와 같이 VisualVM에서 MBean을 통해 어플리케이션을 제어하게 됩니다. log4j2는 MBean 스펙을 준수하여 작성되었기 때문에 VisualVM 상에서 log4j2 로깅 시스템의 속성들을 제어할 수 있습니다.

• 아래와 같이 com 로거의 로그 수준을 ERROR로 낮추게 되면 WARN 메세지를 출력하는 com 로거는 로그 수준이 높기 때문에 메세지가 출력되지 않게 됩니다.

2019-05-30T23:55:21.149 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:21.149 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:24.149 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:24.149 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:27.150 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:27.150 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:30.150 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:30.150 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:33.155 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:33.155 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:36.155 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:36.155 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:39.156 [main] TRACE This is [com.dev] trace warning
2019-05-30T23:55:39.156 [main] TRACE This is [com.dev] trace warning 

• 또한 com.dev 로거의 로그 수준을 DEBUG로 낮추게 되면 TRACE 메세지를 출력하는 com.dev 로거의 로그들이 출력되지 않습니다. 

위와 같은 VisualVM의 기능을 이용하여 평소 WARN 레벨 수준의 로그만 관리하는 어플리케이션에서 어떤 특정 TRACE 정보가 궁금할 때 TRACE 레벨로 수준을 높여 DEBUG 및 TRACE 레벨의 로그를 볼 수 있습니다.