김영한님 Spring MVC 6장 - Logger 부분

Logging

• 자바 로깅 관련 라이브러리가 많은데 우리는 slf4j 쓴다
• 여기링크(http://www.slf4j.org/manual.html) 보면

slf4j

• 로거 구현체가 있는데, 수많은 로깅 구현체를 담을 수 있는 Logging 프레임워크
  • 추상 레이어를 제공 (=Facade 패턴)
• 로거를 추상화된 레이어로 제공하는 이유는 : DIP 를 지키기 위해서
  • 나중에 더 좋은 라이브러리가 생겨 교체하더라도 우리가 짠 application의 코드를 변경할 필요가 없다
  • 여러 로깅 라이브러리를 하나의 통일된 방식으로 사용
• 참고 : 구현체 로깅 프레임워크 3가지
  • log4j, JAVA.UTIL.LOGGING : 안씀 과거의 유물
  • logback-classic : 아무것도 설정을 안했을때 기본값, 지금 사용중인 프레임워크
  • log4j2 : logback에 비해 개선되었긴 한데..(왜안쓰지..?)

facade 패턴

• 소프트웨어의 일정 부분(=기능상의 모듈/라이브러리/프레임워크/표준) 에 대한 간략화된 인터페이스를 제공하는 패턴
  • 다시말해서 역할과 구현을 분리해내기 위해서 사용하고
  • 좋은 객체지향 프로그래밍 원칙으로, 유연해지고 변경이 쉬워지는데
    • 클라이언트가 FrameWork의 역할(interface)만 알고, 프레임워크 내부 구조를 몰라도 되면서, 내부 구조가 변경되어도 클라이언트 소스는 단한줄도 바꾸지 않아도 된다
• slf4j는 Java 진영에서 로깅을 하기 위한 표준, Logging 기능이 역할에 대해서만 정의만 있다면 (abstract)
• logback은 slf4j라는 역할에 맞춰서 log 동작을 실제로 돌아가게 하는 구현체 (implementation)
• 의존관계 역전 원칙 DIP(Dependency inversion principle) 을 지켜낼수 있다

DIP(Dependency inversion principle) : 의존관계 역전 원칙

• DIP는 인터페이스와 클래스를 분리해라! 역활과 구현을 분리해서 내부구조 변경에 유연하게 대응하자라는 취지인데, OCP와 결을 같이한다!
• 비슷한 맥락으로 Stable Depencies Principle (안정된 의존성 원칙) : 의존은 안정적인 쪽을 향해야 한다. 쉽게 말해서 구체화된 클래스보다는 추상화된 인터페이스에 의존하라는 의미
  • 인터페이스들 간에 안정된 의존성 관계 원칙과 탄탄한 구조를 갖게 만들면
  • 인터페이스를 구체화하는 패키지는 변화하고 바뀌더라도 전체적인 구조는 그대로 가져가고 변경은 최소화되면서 인터페이스 단위로 개선이 가능합니다
  • 이렇게 쉽게 바뀔 것이라고 예상되는 구체적인 패키지(클래스) 들은 바뀌기 어려운 패키지(인터페이스)의 의존 대상이 되어서는 안된다
• 더 읽어보기 : https://techblog.woowahan.com/2561/
  • ISP 랑은 맥락이 다른게 ,이건 SRP랑 엮여서 하나의 클래스는 하나의 일만 담당하게 하자! 라는 의미다

로깅에도 레벨이 있다

• 로그는 다섯 가지의 레벨로 나뉘고, Log Level 아래쪽으로 갈수록 심각한 오류를 의미하며 로그 레벨이 낮아도 출력이 된다

로깅레벨	trace출력레벨	debug 출력시	info출력시(default)	warn 출력시	error출력시
log.trace 출력여부	O	X	X	X	X
log.debug 출력여부	O	O	X	X	X
log.info 출력여부	O	O	O	X	X
log.warn 출력여부	O	O	O	O	X
log.error 출력여부	O	O	O	O	O

Spring boot 에서 사용법

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
// ... 중략
private Logger logger = LoggerFactory.getLogger(this.getClass());

• 이거 참고로 처음 하시는분들이 많이 겪는 문제인데, 자꾸 컴파일 에러가 뜬다고 하면 import를 확인해보자 Logger 를 잘못 임포트하는경우가 많다
• 일반적인 import 순서로 Logger >> LoggerFactory 순서로 하는데, 이를 뒤집어서 LoggerFactory 먼저 임포트 하면 Logger 를 잘못 임포트 하는경우가 있다

logger.trace("{} {} 출력", "값1", "값2");
logger.debug("{} {} 출력", "값1", "값2");
logger.info("{} {} 출력", "값1", "값2");
logger.warn("{} {} 출력", "값1", "값2");
logger.error("{} {} 출력", "값1", "값2");

• 로그를 찍을때는 위와같은 코드를 사용해 남기며면 된다!
• 로그를 콘솔출력 말고 파일로 저장할 수도 있다

로그에서 하지 말아야할 안티패턴1 - 표준입출력 사용

• System.out.println()으로 출력하는것과 Log로 출력하는것 사이에 어떤 차이가 있는지 생각해봤는데요
• System.out.println()의 내부구조를 살펴보면(open-JDK11) 아래와 같은 코드로 이루어져 있습니다

public void println(String x) {
    synchronized (this) {
        print(x);
        newLine();
    }
}

• synchronized 키워드가 붙어있는데요, 이 키워드는 크리티컬 섹션에 대한 동시접근을 막기 위해 Block Unblock 동작을 하는 일종의 single-Semaphore(혹은 MUTEX)로 동작하게 해주는 키워드 입니다.
• 그럼 println 같은 Console 출력이 왜 크리티컬 섹션이고, 꼭 synchronized 키워드를 붙여야할만큼 중요한 작업인지는 "그런일을 하지 않았을때 벌어지는 일" 이 끔찍하기 때문입니다.
• synchronized 키워드를 달아주지 않았을 경우 : 멀티스레드 상황에서 문자열이 뒤죽박죽 섞여서 나오는 현상이 발생할 수도 있는데요(랑데부 지점)
• 랑데부 지점에서 동시성 문제를 해결하기 위해 동시성 접근을 차단하기 위해 만들어놓은 장치가 synchronized 이며 Java라는 언어를 만든 사람들이 어느정도의 성능희생을 감수하고서라도 언어레벨에서 동시성 이슈가 책임지고 발생하지 않도록 print 함수를 만들어뒀기 때문입니다.
• Database에서도 많이 언급했지만 성능과 동시성은 항상 Trade-off관계이기 때문이죠
• Java언어에서의 println 함수와는 반대로, 동시성 이슈는 알아서 할테니, 최고의 IO 성능을 내고싶다면, 리눅스 시스템 프로그래밍에서배운 flock(2), fcntl(2) 등의 함수를 C언어로 호출해보면(아마 Java NIO로) 됩니다
• 여기서 한가지 얼렁뚱땅 넘어간 부분이 있는데요, 랑데부 상황에서 왜 문자열이 뒤죽박죽 섞여 나오냐면 리눅스는 IPC도 파일로 처리하고 공유될만한 대부분의 자원을 File로 처리하기 때문입니다. (근데 이건 설명하자면 한도끝도 없고 저도 잘 모르니까 Linux OS의 File과 표준입출력에 대해 공부하고 나중에 정리해보겠습니다)

• 너무 잡설이 길었는데... 그래서 이 println 함수롤 호출하는 순간 다른 쓰레드는 Block이 걸리게 되고, 다른 쓰레드에서는 println에서 Lock이 풀릴때까지 Blocking 상태가 되어 다음 일을 할 수가 없기 때문에 성능저하가 발생하게 됩니다.

public void println(String x) {
        synchronized (this) {
            print(x);
            newLine();
        }
    }

이외에 비슷한 기출변형도 안됩니다 ( Exception stack trace / String.format)

• Exception의 stack trace를 로깅할 때도 e.printStackTrace() 를 이용하면 안되는데 그 이유는 e.printStackTrace()은 내부적으로 java.lang.System.err 를 이용해서 로그를 남기게 됩니다. 즉 println과 같은 이유입니다

• 문자열 포멧팅(String.format)
  • Formatter, StringBuilder 클래스를 생성하기 때문에 인스턴스 생성/소멸에 엄청난 비용이 들어가게 됩니다.

logger.debug(String.format("Hello %s(%s)", user.getName(), user.getEmail()));

• 결론 : 그래서 로그를 쓰면 됩니다.

로그에서 하지 말아야할 안티패턴2 - 문자열 직접연산 사용

• 문자열 연산을 한다는 차원의 문제뿐 아니라
• Logging 출력레벨보다 낮은(예를들어 trace) 레벨의 로거함수 호출에 문자열 더하기 연산이 존재하면, 로그가 찍히는지랑 상관없이 문자열을 다 더해주고난 다음 완성하고 함수를 호출하기 때문에
• logger출력 메소드 실행 이전에 어떠한 연산이라도 일어나게 되면 동일한 낭비됩니다
• SLF4J의 치환문자({})를 사용하자 : 정식명칭은 Fluent Logging API : 링크참조(http://www.slf4j.org/manual.html#fluent)

안티패턴별 벤치마크 : https://github.com/d-h-k/mvc/blob/main/springmvc/src/test/java/hello/springmvc/basic/LogTestControllerTest.java

• 코드 스니핏 짤라서 설명을 같이 적어줘야하지만 너무 졸려서 나중에 할래요..

20:12:56.792 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - String Plus 방식 : 15308129ns
20:12:56.798 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - Lazy Replace 방식: 993902ns
20:12:56.798 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - 결론 : Replace 가 14314227ns 빠름
20:12:56.799 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - 결론 : Replace 가 15.402050705200311배 빠름

20:12:57.024 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - String Plus 방식 : 134234613ns
20:12:57.024 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - Lazy Replace 방식: 77698955ns
20:12:57.024 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - 결론 : Replace 가 56535658ns 빠름
20:12:57.024 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - 결론 : Replace 가 1.727624432014562배 빠름

20:17:12.765 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - print 방식 : 108410799ns
20:17:12.766 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - logger 방식: 80646422ns
20:17:12.766 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - 결론 : logger 가 27764377ns 빠름
20:17:12.766 [Test worker] INFO hello.springmvc.basic.LogTestControllerTest - 결론 : logger 가 1.3442728928507206배 빠름

• 근데 이건 항상 성공하지는 않는다 프로세스 상태, 컴퓨터 메모리공간 등에 따라 다른듯