logback 사용시 대용량 배치 작업에서 성능 저하를 유발할 수도!

성능테스트를 어느정도 마친 배치 서비스에서 코드를 리펙터링하고 로그 포맷을 정리하여 배치 task 를 실행시켰을때 기존 테스트때보다 2배 정도 걸리는 것을 확인하였다. 어떤 부분이 영향을 미쳤을까 하나씩 확인해보던 중 logback.xml 을 설정을 다음과 같이 추가한 부분에 영향이 미침을 확인하였다. 

 

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

	...
    <springProfile name="prod">
        <include resource=".../tracer-console-appender.xml" />

        <logger name="CUSTOM_LOG" level="INFO">
            <appender-ref ref="CUSTOM_CONSOLE" />
        </logger>
        <logger name="CUSTOM_ERROR_LOG" level="ERROR">
            <appender-ref ref="CUSTOM_CONSOLE" />
        </logger>
    </springProfile>

</configuration>

 

다음과 같이 로그백 설정을 주어 INFO 나 ERROR 상태에 있는 로그를 콘솔로 출력하고 kibana 를 통해서 JSON 형태의 로그를 확인할 수 있도록 하였는데 INFO 수준에 레벨을 처리하는 CUSTOM_LOG 가 문제였다. 배치는 청크단위로 reader-processor-writer 로 처리되는데 INFO 수준에서 실제로 남기는 로그는 없었기에 이부분에 문제일 거라 생각하지 못했다.

 

그런데 실제로 콘솔에 출력되는 로그가 없다 하더라도, INFO 레벨로 로그 설정이 되어 있으면 성능에 영향을 미칠 가능성이 있다는 것을 확인했다. 그 이유는 로그백(Logback)이 내부적으로 로그 레벨에 맞는 로그 메시지를 평가하고 필터링하는 과정에서 리소스를 사용하기 때문이다. 이 과정이 누적되면 특히 대용량 배치 작업에서 성능 저하를 유발할 수 있다. 몇 가지 성능 저하를 유발할 수 있는 이유는 다음과 같다.

 

1. 로그 메시지 생성 과정: 로그 메시지를 기록할 때, 로그 레벨이 일치하지 않아 실제로 출력되지 않더라도, 메시지 자체를 만들기 위해 문자열 연산 및 로그 처리 작업이 발생한다. 특히 로그 메시지에 많은 정보가 포함될수록 이 연산의 비용이 커질 수 있다. 
2. 필터링 및 레벨 평가: 로그백은 로그가 출력되기 전에 현재 로그 레벨이 설정된 레벨에 맞는지 평가한다. 이 평가 작업도 성능 부하가 될 수 있다. 특히 많은 양의 로그가 기록될 경우, 필터링 비용이 쌓일 수 있다.
3. 동시성 및 스레드 관리: 많은 병렬 작업이 로그를 남기려 할 때, 콘솔 출력을 하지 않더라도 내부적으로 스레드와 자원 관리에 비용이 발생할 수 있다. 이 때문에 병렬 작업에서 성능 저하가 발생할 수 있다.

INFO 레벨의 로거가 설정된 상태에서 성능이 영향을 받을 가능성이 있는 이유는 이 과정들이 반복되기 때문. 따라서, 실제로 로그를 콘솔에 출력하지 않더라도 불필요한 INFO 레벨의 로거가 설정되어 있으면 성능에 영향을 미칠 수 있을 것 같다.