10. 로그는 반드시 필요한 내용만 찍자

10. 로그는 반드시 필요한 내용만 찍자

어떤 시스템을 개발하든 코딩을 하면 반드시 로그를 남겨야 한다. 로그를 남기는 방법에는 여러 가지가 있겠지만, 일반적으로 시스템 로그(System.out.println을 사용하여 로그를 처리하는 방법)나 Log4j 혹은 JDK 로거를 많이 사용한다. 어떤 로거를 사용하든 모두 성능상 이슈가 발생할 수 있다.

1. System.out.println()의 문제점

대부분의 개발자들은 로그를 찍기 위해서 System.out.println() 메서드를 사용한 시스템 로그를 많이 사용한다. 가장 편하고, 확인하기 좋은 방법이지만 성능에 영향을 많이 주는 경우가 빈번하게 발생한다. System.out.prinln() 메서드로 로그가 출력되는 윈도 콘솔을 활성화시키면 그렇지 않을 때와 현저하게 차이가 발생한다. 특히 커널 CPU가 많이 발생하는데, 윈도에서 화면을 출력할 때 커널 CPU를 많이 점유하기 때문이다. 그렇다면, 유닉스 기반의 시스템은 전혀 성능에 영향을 미치지 않는 것일까? 성능 튜닝 결과를 보자.

		응답 시간	개선율
화면 선택시 총 소요시간	변경 전	1,242ms	-
화면 선택시 총 소요시간	변경 1	893ms	39%
화면 선택시 총 소요시간	변경 2	504ms	146%

이 결과는 어느 사이트의 화면을 튜닝했을 때의 결과이다. 변경 1은 로거를 사용하면서 로그 사용 여부를 false로 했을 경우이며, 변경 2는 모든 로거를 주석 처리하고 System.out.println()을 제거한 경우이다. 변경 1을 반영하자 성능이 39% 개선되었고, 변경 2를 반영하자 146%가 개선되었다.

다음과 같은 사례도 있다. 한 번 요청할 때 5,000명의 사용자 정보를 요청하고, 처리하는 과정에서 응답 시간이 약 20초에 달하는 사이트가 있었다. 원인을 파악해 본 결과 애플리케이션이 5,000명의 정보를 모두 System.out.println()으로 처리하도록 되어 있다. 이 한 줄을 지우자 응답 시간은 6초로 개선되었다.

따라서 시스템 로그를 프린트하면 반드시 성능에 영향을 주게 된다.

개선율이란 튜닝 전과 후의 차이를 수치로 나타낸 것이다. 다음의 공식으로 구한다.
(튜닝 전 응답 속도 - 튜닝 후 응답 속도) * 100 / 튜닝 후 응답 속도 = 개선율(%)

왜 이러한 결과들이 발생했을까? 파일이나 콘솔에 로그를 남길 경우를 생각해보자. 내용이 완전히 프린트되거나 저장될 때까지, 뒤에 프린트하려는 부분은 대기할 수 밖에 없다. 특히 콘솔에 로그를 남길 경우는 더더욱 그렇다. 그렇게 되면 애플리케이션에서는 대기 시간이 발생한다. 이 대기 시간은 시스템의 속도에 의존적이다. 만약 시스템에 로그를 남긴다면, 서버 디스크의 RPM이 높을수록 로그의 처리 속도는 빨라질 것이다.

더 큰 문제는 System.out.println()으로 출력하는 로그가 개발할 때만 사용된다는 것이다. 운영할 때는 전혀 사용되지 않고, 볼 수도 없는 디버그용 로그를 운영 서버에서 고스란히 처리하고 있는 셈이다.

보통 소스를 보면, 하나의 메서드에서 한 번만 프린트하는 것이 아니라, 적게는 대여섯 번에서 많게는 수십 번 디버그용 로그를 프린트한다. 이 소스가 운영 중에 수행할 때는 어떻게 될까? 하나의 메서드에 한 개의 로그가 있다고 하더라도, 보통 운영 시스템에는 수천, 수백 개의 메서드가 사용되기 때문에 운영 중에는 시스템 로그를 보아도 뭐가 뭔지 확인이 불가능한 상태가 된다. 즉, 의미 없는 디버그용 로그를 프린트하기 위해서 아까운 서버의 리소스와 디스크가 낭비된다는 것이다.

또한 많은 서비스들이 통계성 데이터를 로그에 쌓고 처리하려고 한다. 적절한 로거를 사용해서 데이터를 쌓는 것은 좋겠지만, System.out.println()으로 로그를 쌓는 것은 적절하지 않다. 그런 데이터는 요즘 많이 나와 았는 오픈소스 저장소에 담고, 필요할 때 가져가도록 할 수 있다.

대부분의 사이트에서 사용자가 증가함에 따라 서버를 추가 구매하는 상황으로 이어지는 것을 본다면, 결국 서버를 낭비하는 것은 비용 낭비로 직결된다.

2. System.out.format() 메서드

JDK 5.0의 System 클래스에서 사용하는 out 객체 클래스인 PrintStream에 새로 추가된 메서드가 하나 있다. 바로 format() 메서드인데, 이 메서드는 C에서 프린트하던 방식으로 처리할 수 있어 소스가 더 간결해진다. format() 메서드는 두 가지 방식으로 사용할 수 있다.

• format(String format, Object...args) : 지정된 포맷으로 프린트를 한다. 뒤에 있는 매개변수를 쉼표로 나열하도록 되어 있다.
• format(Locale l, String format, Object...args) : 위의 메서드와 동일하되 가장 앞에 지역 정보를 포함한다. 지역에 따라 다른 형태의 데이터를 프린트할 수 있다.

간단한 사용법을 알아보면 다음과 같다.

package com.perf.log;

public class FormatSample {
    public static void main(String[] args) {
        System.out.format("Name=%s long value=%d floatvalue=%f\n", "Format", 1, 1.5)
    }
}

문자열을 사용할 경우에는 %s, int나 long과 같은 정수형을 나타낼 경우에는 %d, float이나 double을 나타낼 경우에는 %f를 사용하면 된다. 여기서 주의할 점은 print() 메서드와 동일하게 한 줄에 나타내도록 정의하기 때문에, 가장 뒤에 '\n'을 사용하여 줄바꿈해 주어야만 한다는 것이다.

참고로 그냥 String을 더해서 처리하는 것과 Formatter를 사용하는 것 중 어느 방식이 더 빠른지 살펴보자.

package com.perf.log;

import java.util.concurrent.TimeUnit;

import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.GenerateMicroBenchmark;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.State;

@State(Scope.Thread)
@BenchmarkMode({ Mode.AverageTime })
@OutputTimeUnit(TimeUnit.MICROSECONDS)
public class StringFormat {
    String a="aaa",b="bbb",c="ccc";
    long d=1,e=2,f=3;
    String data;
	
    @GenerateMicroBenchmark
    public void stringAdd() {
        data=a+" "+b+" "+c+" "+d+" "+e+" "+f;
    }
	
    @GenerateMicroBenchmark
    public void stringFormat() {
        data=String.format("%s %s %s %d %d %d",a,b,c,d,e,f);
    }
}

수행 결과는 System.out.println()을 사용하는 것보다는 응답 시간이 느리다는 것을 알 수 있다. 왜 이러한 결과가 나오는지는 이 코드를 컴파일한 클래스를 역 컴파일해 보면 이해할 수 있다.

String을 더하는 문장은 다음과 같이 변환된다.

(new StringBuilder(String.valueOf(a))).append(" ")
.append(b).append(" ").append(c).append(" ")
.append(d).append(" ").append(e).append(" ").append(f).toString();

그리고 format() 메서드를 사용하는 문장은 다음과 같이 변환된다.

data = String.format("%s %s %s %d %d %d, new Object[] {a, b, c, Long.valueOf(d), Long.valueOf(e), Long.valueOf(f) });

컴파일시 변환된 부분은 새로운 Object 배열을 생성하여 그 값을 배열에 포함시키도록 되어있다. 게다가 long 값을 Object 형태로 나타내기 위해서 Long 클래스의 valueOf() 메서드를 사용하고 있다. 그렇다고 소스의 성능을 좋게 하기 위해서 long을 Long으로 변환하고, 뒤에 추가될 값을 Object의 배열로 처리하는 것은 그리 좋은 방법이 아니다.

실제 String.format() 메서드의 소스를 보면, 그 내부에서 java.util 패키지에 있는 Formatter 클래스를 호출한다. Formatter 클래스에서는 %가 들어가 있는 format 문자열을 항상 파싱(parsing)하기 때문에 문자열을 그냥 더하는 것보다 성능이 좋을 수 없다.

만약 디버그용으로 사용한다면, format 메서드를 사용하는 것이 좋다. 더 편리하고 소스의 가독성도 높아지기 때문이다. 다만 운영 시에는 디버그용 로그를 제거해야 한다.

3. 로그를 더 간결하게 처리하는 방법

디버그용 로그가 꼭 필요할 때는 어떻게 해야 할까? 가장 좋은 방법으로는 로거(Logger)를 사용하여 로그를 처리하는 것이다. 그런데 만약 로거를 사용하기 힘든 상황이면 어떻게 해야 할까?

두 가지 방법이 있다. 자체 로거 클래스를 만드는 방법과 시스템 로그를 컴파일할 때 삭제되도록 하는 방법이다. 자체 로거 클래스를 만드는 방법보다는 이미 만들어져 있는 로거를 사용하는 것이 훨씬 효율적이므로 이 방법은 추천되지 않기 때문에 시스템 로그를 컴파일할 때 삭제되도록 하는 방법을 보자.

그러면 먼저 어떻게 해야 컴파일할 때 시스템 로그가 삭제되는지 알아보자. 아래와 같은 간단한 소스가 있다. 참고로 파일에 쓰는 로그는 Log4j나 JDK에서 제공하는 로거를 사용하는 것이 직접 구현하는 것보다 낫다.

package com.perf.log;

import java.util.ArrayList;

public class LogRemoveSample {
    public LogRemoveSample() {}
    public ArrayList getList() {
        ArrayList retList = new ArrayList(10);
        // 중간 생략
        System.out.format("LogRemoveSample.getList():size=%d\n", retList.size());
        return retList;
    }
}

이 클래스의 getList() 클래스를 호출할 때마다, 클래스 이름 및 메서드 이름, 리턴되는 데이터의 크기를 콘솔에 프린트를 한다. 보통 한 메서드에 로그를 대여섯번 프린트 하지만, 위와 같이 하나만 있다고 가정하자. 클래스가 컴파일될 때 시스템 로그가 삭제되도록 하려면 아래와 같이 해볼 수 있다.

package com.perf.log;

import java.util.ArrayList;

public class LogRemoveSample {
    private final boolean printFlag = false;
    public LogRemoveSample() {}
    public ArrayList getList() {
        ArrayList retList = new ArrayList(10);
        // 중간 생략
        if(printFlag) {
            System.out.format("LogRemoveSample.getList():size=%d\n", retList.size());
        }
        return retList;
    }
}

private final boolean으로 printFlag라는 변수를 하나 만들어 놓고, 시스템 로그가 있는 부분을 if 문장으로 감쌌다. 여기서 중요한 것을 final로 printFlag를 선언했기 때문에, 절대로 이 값은 실행 시 변경될 수 없다는 점이다. printFlag를 변경하려는 코드가 있다면, 코드는 컴파일 자체가 되지 않는다.

이 소스를 컴파일한 클래스를 역 컴파일해 보면, if 문장과 그 안에 있는 문장은 눈 씻고 찾아봐도 찾을 수 없다. 이미 컴파일러에서 그 부분은 실행 시 필요가 없다고 생각하고 삭제하기 때문이다. 대신 이렇게 해 놓으면, 모든 소스를 찾아다니면서 printFlag를 변경해 주어야 한다는 단점이 있다. 그래서 다음과 같이 간단한 flag 정보를 찾는 클래스를 만들어 관리하면 약간 더 편리하다.

package com.perf.log;

public class LogFlag {
    public static final boolean printFlag = false;
}

이렇게 클래스를 만들고 다음과 같이 간단하게 사용하면 된다.

if(LogFlag.printFlag) {
    System.out.format("LogRemoveSample.getList():size=%d\n", retList.size());
}

매번 if 문장으로 막는 것보다 간단하게 사용하기 위해서는 좀 더 보완을 해서 다음과 같이 클래스를 만들면 된다. 하지만 이 또한 단점은 존재한다.

package com.perf.log;

public class SimpleLogger {
    private static final boolean printFlag = false;
    public static void log(String message) {
        if (printFlag) {
            System.out.println(message);
        } 
    }
}

이 소스처럼 만들면 System.out.println()를 매번 입력하거나 복사해서 붙여 넣을 필요가 없다. SimpleLogger.log("...");와 같은 방식으로 소스를 작성하면 되므로 편리하다. 또한 printFlag에 따라서 로그를 남길지, 남기지 않을지를 결정할 수 있다. 다만 이 소스의 단점은 printFlag를 수정하기 위해서 다시 컴파일해야 한다는 점과 어짜피 log() 메서드 요청을 하기 위해서 메시지 문자열을 생성해야 한다는 것이다.

4. 로거 사용 시의 문제점

로거를 사용할 때 문제는 뭘까? 앞서 설명한 대로 컴파일 시에 로그를 제거하는 방법을 사용하지 않는 한, 로그를 프린트하든 하지 않든, 로그를 삭제하기 위한 한 줄을 처리하기 위해서는 어차피 객체를 생성해야 한다. 즉 운영 시 로그 레벨을 올려 놓는다고 해도, 디버그용 로그 메시지는 간단한 문자든 간단한 쿼리든 상관 없이 하나 이상의 객체가 필요하다. 그러면 그 객체를 생성하는 데 메모리와 시간이 소요된다. 또한 메모리에서 제거하기 위해 GC를 수행해야 하고, GC 수행 시간이 또 소요된다. 예를 들면 다음과 같은 소스들이다.

logger.info("query="+query);
logger.info("result="+resultHashMap);

로그를 이렇게 처리하면, 분명히 info() 메서드가 호출이 될 것이다. 또한 호출되는 메서드에 문자열이 전달되어야 하기 때문에 괄호 안에 있는 값들을 문자열로 변환하는 작업이 반드시 수행된 다음, 메서드 호출이 진행된다. 만약 쿼리가 한두줄이라면 상관 없겠지만, 일반적으로 쿼리는 한 페이지에서 네 페이지 정도 된다. 그만큼의 객체가 생성되었다가 아무 일도 안하고 사라지는 것이다.

두 번째에 있는 resultHashMap과 같이 HashMap의 더하기 연산을 위해서는 HashMap에 있는 모든 데이터를 확인한다. 그리고 "result="라는 문자열과 더하는 연산이 수행되는데 이는 불필요한 작업이다.

그러므로 가장 좋은 방법은 디버그용 로그를 제거하는 것이다. 하지만 그렇지 못한 것이 현실이기 때문에 시스템 로그의 경우처럼 로그 처리 여부를 처리하는 것이 좋다. 다음의 예를 보자.

if(logger.isLoggable(Level.INFO)) {
    // 로그처리
}

이렇게 if 문장으로 처리하면 로그를 위한 불필요한 메모리 사용을 줄일 수 있어, 더 효율적으로 메시지를 처리할 수 있따.

또한 로그를 처리하는 데 발생할 수 있는 문제점을 해결하는 데 도움을 주는 slf4j라는 로거가 있다. 간단하게 slf4j에 대해 알아보자.

5. 로그를 깔끔하게 처리해주는 slf4j와 LogBack

slf4j의 전체 이름은 Simple Logging Facade for Java (SLF4J)이다.

즉, 간단히 로그를 처리해 주는 프레임워크라고 보면 된다. 그러면 log4j와 어떤점이 다를까? slj4j의 홈페이지에 있는 사용자 매뉴얼을 보면 다음 예제 코드를 확인할 수 있다.

 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
  
 public class Wombat {
   
     final Logger logger = LoggerFactory.getLogger(Wombat.class);
     Integer t;
     Integer oldT;

     public void setTemperature(Integer temperature) {    
         oldT = t;        
         t = temperature;

         logger.debug("Temperature set to {}. Old temperature was {}.", t, oldT);

         if(temperature.intValue() > 50) {
             logger.info("Temperature has risen above 50 degrees.");
         }
    }
}

logger.debug()와 logger.info() 부분이 바로 slf4j를 적용한 부분이다. 아래에 있는 logger.info() 메서드 내용은 기존의 메서드 부분과 별 차이가 없지만, 위에 있는 logger.debug() 메서드 내용을 보면 확연히 차이가 나는 것을 볼 수 있다.

기존의 로거들은 앞 절에서 이야기한 대로 출력을 위해서 문자열을 더해 전달해 줘야만 했다. 하지만, slf4j는 format 문자열에 중괄호를 넣고, 그 순서대로 출력하고자 하는 데이터들을 콤마로 구분하여 전달해준다. 이렇게 전달해 주면 로그를 출력하지 않을 경우 필요 없는 문자열 더하기 연산이 발생하지 않는다.

게다가 slf4j는 자바의 기본 로거를 비롯하여 Log4j, 아파치 commons 로깅 등과 연계하여 사용할 수 있도록 되어 있다. 왜 많은 아파치 프로젝트들이 이 slf4j를 적용했는지 이해할 수 있을 것이다.

추가로 최근에는 LogBack이라는 로거도 많이 사용되고 있다. 이 로거는 예외의 스택 정보를 출력할 때 해당 클래스가 어떤 라이브러리(jar 파일)를 참고하고 있는지도 포함하여 제공하기 때문에 쉽게 관련된 클래스를 확인할 수 있다.

6. 예외 처리는 이렇게

예외 처리할 때에도 성능에 많은 영향을 줄 수 있다. 일반적으로 예외가 발생하면, 다음과 같이 처리한다.

try {
    ...
} catch(Exception e) {
    e.printStackTrace();
}

이렇게 예외를 처리하면 어떻게 될까? 예외가 발생하면 Exception 클래스에 기본 정보가 전달된다. 그때는 스택 정보(어떤 클래스의 어떤 메서드가 어떤 클래스의 어떤 메서드를 호출했는지에 대한 관계를 나타내는 정보)를 찾아보지 않는다. 하지만 만약 e.printStackTrace()를 호출하게 되면 스택 정보를 확인하고, 확인된 정보를 콘솔에 프린트한다.

운영해 본 사람은 알겠지만 콘솔에 찍힌 이 로그를 알아보기가 힘들다. 왜냐하면 여러 스레드에서 콘솔에 로그를 프린트하면 데이터가 섞이기 때문이다. 자바의 예외 스택 정보는 로그를 최대 100개까지 프린트하기 때문에 서버의 성능에도 많은 부하를 준다. 스택 정보를 가져오는 부분에서는 거의 90% 이상이 CPU를 사용하는 시간이고, 나머지 프린트하는 부분에서는 대기 시간이 소요된다.

그래도 printStackTrace()에서 출력해주는 데이터가 필요할 때가 있다. 예외 메시지로 처리하면 실제 사용자들은 한 줄의 오류 메시지나 오류 코드만을 보게 되기 때문에 장애를 처리하기가 쉽지 않다. 스택 정보를 보고 싶을 경우에는 다음과 같이 처리하는 방법도 있다.

try {
    ...
} catch (Exception e) {
    StackTraceElement[] ste = e.getStackTrace();
    String className = ste[0].getClassName();
    String methodName = ste[0].getMethodName();
    int lineNumber = ste[0].getLineNumber();
    String fileName = ste[0].getFileName();
    logger.severe("Exception : " + e.getMessage());
    logger.severe(className + "." + methodName + " " + fileName = " " + lineNumber + "line");

마지막 라인의 문자열 더하는 구문들은 어짜피 StringBuilder로 변환되므로 큰 성능 저하를 발생시키지는 않는다. 이와 같이 임의로 만든 예외(Exception) 클래스에서 원하는 스택 정보를 가공하여 메시지 처리하는 것도 좋은 방법이다.

참고로 StackTraceElement 배열의 0번째에는 예외가 발생한 클래스 정보가 있으며, 마지막에는 최초 호출된 클래스의 정보가 있다. 일반적인 WAS에서는 WAS 관련 클래스 정보가 포함될 것이므로, 자기가 만든 프로그램만 필터링되게 하면 더 깔끔하게 에러 로그를 정리할 수 있을 것이다.

참고

• 자바 성능 튜닝 이야기