요구사항 분석
만약, 새로운 회사에 입사했는데, 수 년간 운영중인 거대한 프로젝트에 투입되었다.
전체 소스 코드는 수 십만 라인 이고, 클래스 수도 수 백개 이상이다.
나에게 처음 맡겨진 요구사항은 로그 추적기를 만드는 것이다.
하물며, 애플리케이션이 커지면서 점점 모니터링과 운영이 중요해지는 단계이다.
특히 최근 자주 병목이 발생하고 있다. 어떤 부 분에서 병목이 발생하는지,
그리고 어떤 부분에서 예외가 발생하는지를 로그를 통해 확인하는 것이 점점 중요해지고 있다.
기존에는 개발자가 문제가 발생한 다음에 관련 부분을 어렵게 찾아서 로그를 하나하나 직접 만들어서 남겼다.
로그를 미리 남겨둔다면 이런 부분을 손쉽게 찾을 수 있을 것이다. 이 부분을 개선하고 자동화 하는 것이 나의 미션이다.
요구사항
- 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력
- 애플리케이션의 흐름을 변경하면 안됨
- 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨 메서드 호출에 걸린 시간
- 정상 흐름과 예외 흐름 구분
- 예외 발생시 예외 정보가 남아야 함 메서드 호출의 깊이 표현
- HTTP 요청을 구분
- HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
- 트랜잭션 ID (DB 트랜잭션X), 여기서는 하나의 HTTP 요청이 시작해서 끝날 때 까지를 하나의 트랜잭션이라함
우리에게 주어진 요구사항은 위와 같다고 한다.
일단은 위의 요구사항을 어떻게든 맞추기만을 위한 로그 추적기를 만들어보자.
TraceId
로그 추적기를 위한 기반 데이터를 가지고 있는 TraceId 클래스이다.
로그 추적기는 트랜잭션ID와 깊이를 표현하는 방법이 필요하다.
여기서는 트랜잭션ID와 깊이를 표현하는 level을 묶어서 TraceId 라는 개념을 만들었다.
TraceId 는 단순히 id (트랜잭션ID)와 level 정보를 함께 가지고 있다.
package hello.advanced.trace;
import java.util.UUID;
public class TraceId {
private String id;
private int level;
public TraceId(){
this.id = createId();
this.level = 0;
}
private TraceId(String id, int level){
this.id = id;
this.level = level;
}
private String createId() {
return UUID.randomUUID().toString().substring(0, 8);
}
public TraceId createNextId(){
return new TraceId(id, level + 1);
}
public TraceId createPreviousId(){
return new TraceId(id, level - 1);
}
public boolean isFirstLevel(){
return level == 0;
}
public String getId() {
return id;
}
public int getLevel() {
return level;
}
}
UUID
- TraceId를 처음 생성하면 createId() 를 사용해서 UUID를 만들어낸다.
- UUID가 너무 길어서 여기서는 앞 8자리만 사용한다. 이 정도면 로그를 충분히 구분할 수 있다.
- 여기서는 이렇게 만들어진 값을 트랜잭션ID로 사용한다.
createNextId()
- 다음 TraceId 를 만든다. 예제 로그를 잘 보면 깊이가 증가해도 트랜잭션ID는 같다. 대신에 깊이가 하나 증가한다.
- 따라서, createNextId() 를 사용해서 현재 TraceId 를 기반으로 다음
- TraceId 를 만들면 id는 기존과 같고, level은 하나 증가한다.
createPreviousId()
- createNextId() 의 반대 역할을 한다.
- id는 기존과 같고, level은 하나 감소한다.
isFirstLevel()
- 첫 번째 레벨 여부를 편리하게 확인할 수 있는 메서드
TraceStatus
마찬가지로, 로그 추적기를 위한 기반 데이터를 가지고 있는 TraceStatus 클래스이다.
로그의 상태 정보를 가지고 있으며, 이 상태 정보는 로그를 종료할 때 사용된다.
- traceId : 내부에 트랜잭션ID와 level을 가지고 있다.
- startTimeMs : 로그 시작시간이다. 로그 종료시 이 시작 시간을 기준으로 시작~종료까지 전체 수행 시간을 구할 수 있다.
- message : 시작시 사용한 메시지이다. 이후 로그 종료시에도 이 메시지를 사용해서 출력한다.
package hello.advanced.trace;
public class TraceStatus {
private TraceId traceId;
private Long startTimeMs;
private String message;
public TraceStatus(TraceId traceId, Long startTimeMs, String message) {
this.traceId = traceId;
this.startTimeMs = startTimeMs;
this.message = message;
}
public TraceId getTraceId() {
return traceId;
}
public Long getStartTimeMs() {
return startTimeMs;
}
public String getMessage() {
return message;
}
}
LogTrace
LogTrace 인터페이스에는 로그 추적기를 위한 최소한의 기능인 begin(), end(), exception()를 정의했다.
트랜잭션의 시작/종료/예외에 관여하는 인터페이스이다.
public interface LogTrace {
TraceStatus begin(String message);
void end(TraceStatus status);
void exception(TraceStatus status, Exception ex);
}
FieldLogTrace
LogTrace 인터페이스의 구현체로써 메소드를 오버라이드하고 기타 다른 메소드들,
동기화 작업을 위한 syncTraceId(), 트랜잭션이 끝마쳤을 때 처리를 위한 releaseTranceId() 등의 메소드를 새롭게 구현한다.
package hello.advanced.trace.logtrace;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
@Slf4j
public class FieldLogTrace implements LogTrace{
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
private TraceId traceIdHolder; // traceId 동기화, 동시성 이슈 발생
@Override
public TraceStatus begin(String message) {
syncTraceId();
TraceId traceId = traceIdHolder;
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
private void syncTraceId(){
if(traceIdHolder == null){
traceIdHolder = new TraceId();
} else {
traceIdHolder = traceIdHolder.createNextId();
}
}
@Override
public void end(TraceStatus status) {
complete(status, null);
}
@Override
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
private void complete(TraceStatus status, Exception e) {
Long stopTimeMs = System.currentTimeMillis();
long resultTimeMs = stopTimeMs - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) {
log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
} else {
log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs, e.toString());
}
releaseTraceId();
}
private void releaseTraceId() {
if(traceIdHolder.isFirstLevel()){
traceIdHolder = null;
} else {
traceIdHolder = traceIdHolder.createPreviousId();
}
}
private static String addSpace(String prefix, int level) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level; i++) {
sb.append((i == level - 1) ? "|" + prefix : "| ");
}
return sb.toString();
}
}
begin()`
- 로그를 시작한다.
- 로그 메시지를 파라미터로 받아서 시작 로그를 출력한다.
- 응답 결과로 현재 로그의 상태인 `TraceStatus` 를 반환한다.
end()`
- 로그를 정상 종료한다.
- 파라미터로 시작 로그의 상태( TraceStatus )를 전달 받는다.
- 이 값을 활용해서 실행 시간을 계산하고, 종 료시에도 시작할 때와 동일한 로그 메시지를 출력할 수 있다.
- 정상 흐름에서 호출한다.
exception()
- 로그를 예외 상황으로 종료한다.
- TraceStatus , Exception 정보를 함께 전달 받아서 실행시간, 예외 정보를 포함한 결과 로그를 출력 한다.
- 예외가 발생했을 때 호출한다.
complete()`
- end() , exception()의 요청 흐름을 한곳에서 편리하게 처리한다.
- 실행 시간을 측정하고 로그를 남긴 다.
addSpace()
- 다음과 같은 결과를 출력한다.("|-->, |, <--" 등)
syncTraceId()
- 앞선 로그의 TraceId를 참고해서 동기화하고, level도 증가한다.
- 최초 호출이면 TraceId 를 새로 만든다.
- 직전 로그가 있으면 해당 로그의 TraceId를 참고해서 동기화하고, level도 하나 증가한다.
- 결과를 traceIdHolder에 보관한다.
releaseTraceId()
- 메서드를 추가로 호출할 때는 level이 하나 증가해야 하지만, 메서드 호출이 끝나면 level이 하나 감소 해야 한다.
- releaseTraceId()는 level을 하나 감소한다.
- 만약 최초 호출(level==0)이면 내부에서 관리하는 traceId를 제거한다.
LogTraceConfig
제작한 FieldLogTrace를 Bean으로 설정해서 전체에서 접근할 수 있도록 한다.
@Configuration
public class LogTraceConfig {
@Bean // 싱글톤으로 등록이 됨
public LogTrace logTrace(){
return new FieldLogTrace();
}
}
OrderControllerV3
LogTrace를 적용한 Controller
@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {
private final OrderServiceV3 orderService;
private final LogTrace trace;
@GetMapping("/v3/request")
public String request(String itemId){
TraceStatus status = null;
try{
status = trace.begin("OrderController.request()");
orderService.orderItem(itemId);
trace.end(status);
return "ok";
} catch (Exception e){
trace.exception(status, e);
throw e;
}
}
}
OrderServiceV3
LogTrace를 적용한 Service
@Service
@RequiredArgsConstructor
public class OrderServiceV3 {
private final OrderRepositoryV3 orderRepository;
private final LogTrace trace;
public void orderItem(String itemId){
TraceStatus status = null;
try{
status = trace.begin("OrderService.request()");
orderRepository.save(itemId);
trace.end(status);
} catch (Exception e){
trace.exception(status, e);
throw e;
}
}
}
OrderRepositoryV3
LogTrace를 적용한 Repository
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {
private final LogTrace trace;
public void save(String itemId){
TraceStatus status = null;
try{
status = trace.begin("OrderRepository.save()");
if(itemId.equals("ex")){
throw new IllegalStateException("예외 발생!");
}
sleep(1000);
trace.end(status);
} catch (Exception e){
trace.exception(status, e);
throw e;
}
}
private void sleep(int millis) {
try{
Thread.sleep(millis);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
}
결과
http://localhost:9000/v3/request?itemId=hello
http://localhost:9000/v3/request?itemId=ex
이런식으로 우리가 원하는데로 출력이 나오는 것을 확인할 수 있다.
또한, 위에서 말했던 요구사항도 전부 다 만족하게 된다.
- 트랜잭션 ID 동일
- 비즈니스 로직을 건드리지 않음
- 등
하지만, 여기서 문제가 존재한다. 우리는 LogTrace를 FieldLogTrace라는 구현체로 구현했다.
그리고 해당 구현체를 빈으로 등록해서 싱글톤 객체로 사용을 했다.
해당 싱글톤 객체에는 TraceId가 생성되었을 때 한개만 존재한다.
그렇다면 실제 환경에서 여러 유저가 동시에 접속하면 어떻게 될까?
http://localhost:9000/v3/request?itemId=hello
위의 주소로 빠르게 여러 요청을 보내면 다음과 같은 결과가 나온다.
로그 추적기가 관여하는 부분은 고작 Controller - Service - Repository인데 엄청난 Level로 동작한다.
심지어 우리가 UUID로 생성한 트랜잭션ID도 계속 동일하다.
이것은 앞서, 설명했던 구현체인 FieldLogTrace 클래스를 싱글톤 객체로 한 개만 사용해서
Race Condition 한정된 자원에 여러 스레드가 접근하면서 생기는 문제라고 할 수 있다.
만약, 이게 실제 배포 환경에서 일어난 문제라면 많은 유저가 오류를 경험할 것이다.
그렇다면 어떻게 해결해야 할까?
ThreadLocal
스레드 로컬은 해당 스레드만 접근할 수 있는 특별한 저장소를 말한다.
쉽게 이야기해서 발렛 파킹을 떠올리면 된다. 여러 사람이 같은 주차장를 사용하더라도
직원은 사용자를 인식해서 사용자별로 확실하게 차를 구분 해준다.
사용자A, 사용자B 모두 직원을 통해서 차를 주차하고, 꺼내지만 직원이 사용자에 따라 보관한 물건을 구분 해주는 것이다.
일반적인 변수 필드
여러 스레드가 같은 인스턴스의 필드에 접근하면 처음 쓰레드가 보관한 데이터가 사라질 수 있다.
Thread-A가 userA라는 내용을 일반 변수 필드에 저장하고
Thread-B가 userB라는 내용을 일반 변수 필드에 저장하면 이전 값은 지워진다.
하지만, ThreadLocal를 사용하면?
ThreadLocal를 사용하면각 레드마다 별도의 내부 저장소를 제공한다.
따라서, 같은 인스턴스의 스레드 로컬 필드에 접근해도 문제 없다.
ThreadLocal을 통해서 데이터를 조회할 때도 thread-A가 조회하면
ThreadLocal은 thread-A 전용 보관소에서 userA 데이터를 반환해준다.
물론 thread-B가 조회하면 thread-B 전용 보관소에서 userB 데이터를 반환해준다.
자바는 언어차원에서 쓰레드 로컬을 지원하기 위한 java.lang.ThreadLocal 클래스를 제공한다.
이제 ThreadLocal를 사용하여 동시성 문제가 있었던 FieldLogTrace를 재구성해보자
FieldLogTrace -> ThreadLocalLogTrace
기존에 사용했던 TraceId traceIdHolder 필드를 ThreadLocal을 사용하도록
ThreadLocal<TraceId> traceIdHolder로 변경하면 된다.
@Slf4j
public class ThreadLocalLogTrace implements LogTrace{
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>(); // traceId 동기화, 동시성 이슈 발생
@Override
public TraceStatus begin(String message) {
syncTraceId();
TraceId traceId = traceIdHolder.get();
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
private void syncTraceId(){
TraceId traceId = traceIdHolder.get();
if(traceId == null){
traceIdHolder.set(new TraceId());
} else {
traceIdHolder.set(traceId.createNextId());
}
}
@Override
public void end(TraceStatus status) {
complete(status, null);
}
@Override
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
private void complete(TraceStatus status, Exception e) {
Long stopTimeMs = System.currentTimeMillis();
long resultTimeMs = stopTimeMs - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) {
log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
} else {
log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs, e.toString());
}
releaseTraceId();
}
private void releaseTraceId() {
TraceId traceId = traceIdHolder.get();
if(traceId.isFirstLevel()){
traceIdHolder.remove();
} else {
traceIdHolder.set(traceId.createPreviousId());
}
}
private static String addSpace(String prefix, int level) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level; i++) {
sb.append((i == level - 1) ? "|" + prefix : "| ");
}
return sb.toString();
}
}
또한, 조회하는 부분에서는 .get() 메소드를 사용하여 스레드의 전용 보관소에서 데이터를 가져오도록 수정한다.
LogTraceConfig
우리는 앞서, Controller - Service - Repository에서 LogTrace 인터페이스를 사용했기에
컨트롤러-서비스-레포지토리에서 관련된 코드를 수정할 필요 없이
ThreadLocalLogTrace를 빈으로 사용하게 변경만 해주면 된다.
이건 SOLID의 DIP(의존성 역전 원칙) -> 전략 패턴을 잘 사용한 예시인 것 같다.
@Configuration
public class LogTraceConfig {
@Bean // 싱글톤으로 등록이 됨
public LogTrace logTrace(){
return new ThreadLocalLogTrace();
}
}
그럼 위처럼 클래스를 변경한 뒤 동시성 문제가 발생하는지 실험해보자.
http://localhost:9000/v3/request?itemId=hello마찬가지로, 위의 주소로 빠르게 요청을 보내보자.
결과
순서는 보장하진 않지만, 결과적으로 다른 트랜잭션ID를 침범하지 않고 level도 정상적으로 출력되는 것을 확인할 수 있다.
동시성 문제를 해결했다!
하지만, 주의해야 할 점이 남아있다.
상황
- WAS 서버는 사용자 요청시 스레드 풀에서 스레드를 하나 가져와서 작업을 한다.
- 이 상황에서 만약 사용자A의 정보가 스레드 지역 저장소에서 제거되지 않았다면?
- 지역 저장소의 내용이 제거되지 않은 스레드가 스레드 풀로 되돌아 갔다면?
- 다른 사용자가 같은 요청을 했을 때 사용자B가 사용자A의 정보를 받을 수 있게 된다.
위의 상황에 관한 모식도는 다음과 같다.
- 사용자B가 조회를 위한 새로운 HTTP 요청을 한다.
- WAS는 스레드 풀에서 Thread를 하나 조회한다.
- Thread thread-A 가 할당되었다. (물론 다른 Thread가 할당될 수 도 있다.)
- 이번에는 조회하는 요청이다. thread-A는 ThreadLocal에서 데이터를 조회한다.
- ThreadLocal은 thread-A 전용 보관소에 있는 사용자A 값을 반환한다.
- 결과적으로 사용자A 값이 반환된다.
- 사용자B는 사용자A의 정보를 조회하게 된다.
정리
결과적으로, 사용자B는 사용자A의 데이터를 확인하게 되는 심각한 문제가 발생하게 된다.
이런 문제를 예방하려면 사용자A의 요청이 끝날 때 ThreadLocal의 값을 ThreadLocal.remove()를 통해서 꼭 제거해야 한다.
ThreadLocal을 사용할 때는 이 부분을 꼭 유의해야 한다.
마무리하며
스프링 AOP를 학습하기 앞서 로그 추적기를 직접 구현해보고 ThreadLocal를 사용해보았다.
로그는 모니터링에 있어서 굉장히 중요한 파트이다. 따라서, 효율적인 로그 추적기를 잘 구성해야 한다고 할 수 있다.
큰 프로젝트는 접해본 적이 없어 동시성 문제와 같은 오류를 만나본적은 없지만, 이번 기회에 ThreadLocal에 관해 공부하며
싱글톤 객체를 사용하면서 얻을 수 있는 동시성 문제에 관해 학습하게 되었다.