오픈소스 - Naver scavenger - 로깅 문자열 연결 vs 파라미터 치환

오늘은 Naver scavenger 오픈소스 프로젝트를 살펴보았습니다. scavenger는 런타임 Dead Code 분석 도구입니다. 디버깅 또는 로그를 추가하지 않고 메서드 호출이 확인 가능하고 이를 시각화해 유저들에게 보여줍니다. 이를 통해서 손쉽게 Dead Code를 파악하고 리팩토링할 수 있습니다. 

 

1. 분석 대상

분석 대상은 프로젝트 전체에서 발견되는 log 코드였습니다. 이번에 인공지능 알고리즘을 활용하는 프로젝트를 진행하면서 수많은 연산이 발생하는 경우 중간에 로그를 하나 찍더라도 성능에 많은 영향을 주는 것을 경험하였기에 프로젝트 전반에 걸쳐서 작성되어 있는 로그 코드를 유심하게 보게 되었습니다. 그러다가 scavenger는 거의 대부분의 로그들이 문자열 연결 방식으로 만들어져있다는 것을 발견하게 되었습니다.

 

scavenger-agent-java의 Scanner 부분의 로그 코드

 

2. 문자열 연결 방식 로그의 문제점?

위 코드처럼 문자열 연결 방식으로 로그를 찍게 되면 로그 레벨 비활성화 시에도 모든 메서드 호출이 발생하고

StringBuilder sb = new StringBuilder();
sb.append("[scavenger] codebase(");
sb.append(codeBase.getCodeBaseFingerprint());  // 메서드 호출 1
sb.append(") scanned in ");
sb.append(System.currentTimeMillis() - startedAt);  // 메서드 호출 2
sb.append(" ms: ");
sb.append(methods.size());  // 메서드 호출 3
sb.append(" methods");
log.info(sb.toString());

 

위와 같은 과정들을 거치게 됩니다. 이를 파라미터 치환 방식으로 바꾸면 로그 레벨을 체크하고 비활성화 시에는 문자열 연산을 건너뛸 수 있습니다. 또한 가독성이 더 뛰어나며 MessageFormatter가 패턴과 인자 배열을 처리하고 내부 버퍼에서 효율적으로 문자열을 처리하여 최종 문자열을 생성하게 됩니다.

 

//파라미터 치환 방식으로 리팩토링한 로그

log.info("[scavenger] codebase({}) scanned in {} ms: {} methods",
    codeBase.getCodeBaseFingerprint(),
    System.currentTimeMillis() - startedAt,
    methods.size()
);

  

관련 자료 : https://dveamer.github.io/backend/HowToUseSlf4j.html 

3. 성능 비교

간단하게 테스트 코드를 만들어서 기존 scavenger에서 사용하는 @Log 방식과 @Slf4j의 성능 비교와 문자열 연결 방식, 파라미터 치환 방식의 성능 비교를 진행했습니다.

 

- @Log 방식과 @Slf4j의 성능 차이

@Log  : String concatenation: 1013ms
@Slf4j : String concatenation: 204ms

 

 @Slf4j가  @Log 보다 거의 5배 가량 빠른 성능 차이를 보여줍니다. 이는 단순하게 한번 로그를 찍을 때는 상관이 없겠지만 수많은 연산을 진행해야 하는 경우 거의 5배에 가까운 성능 차이가 발생할 수 있음을 알 수 있습니다. 

 

- 문자열 연결 방식 VS 파라미터 치환 방식 

문자열 연결 방식 : String concatenation: 208ms
파라미터 치환 방식 : Parameter substitution: 168ms

 

@Log에서는 파라미터 치환 방식을 지원하지 않기에 @Slf4j로 변경하여 로깅을 진행했습니다. 그 결과 위와 같이 역시 @Log와 @Slf4j의 성능 차이만큼 큰 성능 차이는 아니지만 파라미터 치환 방식이 더 우세한 것을 볼 수 있습니다.

 

4. savenger의 로그 방식을 @Slf4j 파라미터 치환 방식으로 변환하면서 생긴 문제

벤치마킹을 마치고 성능뿐만 아니라 가독성에서도 우수함을 보이는 파라미터 치환 방식으로 변환하기 위해서 결정을 하였으나 기존의 scavenger는 @Log 방식으로 로깅을 진행하고 있었고 @Log 방식에서는 파라미터 치환 방식이 사용 불가능하다는 것을 알게 되었습니다. 이를 해결하기 위해서 @Log를 @Slf4j로 변경을 하고자 scavenger 프로젝트의 gradle에 의존성을 추가하고 변경을 진행하였으나 단순하게 하나의 클래스에서 @Log를 사용한 것이 아니라 전체적인 코드들에 @Log를 사용하신 것을 알게 되었습니다. 또한 그러면서 @Log의 로그 레벨이 @Slf4j에서 사용하는 info, error, debug, warn, trace 같은 5가지의 로그 레벨 보다 더 다양한 로그 레벨이 있고 이를 적절하게 코드에 사용을 하고 있는 것을 확인했습니다. 따라서 @Slf4j로 로그를 변경하게 되면 팀 단위로 결정한 로그 레벨을 단순화 시켜야 했기 때문에 더는 리팩토링을 진행할 수 없겠다는 판단을 하게 되었습니다.

 

@Log가 @Slf4j보다 다양한 로그 레벨을 가지고 있음

5. 결론

@Slf4j 로깅 뿐만 아니라 @Log를 활용한 로깅에 대해서 알게 되었고 둘의 로그 레벨의 차이에 대한 점을 알게 되었습니다. 또한 문자열 연결 방식 로깅의 동작 과정과 파라미터 치환 방식 로깅의 동작 과정에 대해서 알게 되었습니다. 그리고 둘의 성능 차이에 대해서 알게 되었습니다. 비록 리팩토링을 하고 PR을 올리는 것까지 이어지지는 못했지만 오픈소스 코드들을 들여다보고 분석을 하기 시작하면서 좋은 코드란 무엇인가?에 대한 기준이 조금씩 생기고 있는 것 같습니다.  

 

+