애플리케이션이 커지면 모니터링과 운영이 중요해지기 때문에 어떤 부분에서 병목이 발생하고, 어떤 부분에서 예외가 발생하는지 로그를 통해 확인하는 것이 중요하다.
[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem()
[796bccd9] | |-->OrderRepository.save()
[796bccd9] | |<--OrderRepository.save() time=1004ms
[796bccd9] |<--OrderService.orderItem() time=1014ms
[796bccd9] OrderController.request() time=1016ms
예외 발생
[b7119f27] OrderController.request()
[b7119f27] |-->OrderService.orderItem()
[b7119f27] | |-->OrderRepository.save()
[b7119f27] | |<X-OrderRepository.save() time=0ms
ex=java.lang.IllegalStateException: 예외 발생!
[b7119f27] |<X-OrderService.orderItem() time=10ms
ex=java.lang.IllegalStateException: 예외 발생!
[b7119f27] OrderController.request() time=11ms
ex=java.lang.IllegalStateException: 예외 발생!
AOP에 들어가기 앞서 로그 추적기에 대해서 배운다.
우선 V0 버전을 소개하는데 현재는 로그추적기가 적용되어 있지 않은 상태이다.
@RestController
@RequiredArgsConstructor
public class OrderControllerV0 {
private final OrderServiceV0 orderServiceV0;
@GetMapping("/v0/request")
public String request(String itemId){
orderServiceV0.orderItem(itemId);
return "ok";
}
}
@Service
@RequiredArgsConstructor // 파이널이 붙은 것을 생성자로 만들어준다.
public class OrderServiceV0 {
private final OrderRepositoryV0 orderRepositoryV0;
public void orderItem(String itemId){
orderRepositoryV0.save(itemId);
}
}
@Configuration의 차이
스프링에서 Bean을 수동으로 등록하기 위해서 설정하는 어노테이션이다. 외부 라이브러리 또는 내장 클래스를 Bean으로 등록하고자 할 경우 사용한다.
@Configuration안에는 Component가 선언되어 있다.
개발자가 직접 제어 가능 : @Component
개발자가 직접 제어 불가능 : @Configuration, @Bean
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV0 {
public void save(String itemId) {
if (itemId.equals("ex")){
throw new IllegalStateException("예외 발생!!");
}
sleep(1000);
}
private void sleep(int millis){
try {
Thread.sleep(millis);
}catch (InterruptedException e){
e.printStackTrace();
}
}
}
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;
}
}
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;
}
}
@Slf4j
@Component
public class HelloTraceV1 {
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
public TraceStatus begin(String message) {
TraceId traceId = new TraceId();
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
public void end(TraceStatus status) {
complete(status, null);
}
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());
}
}
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();
}
}
@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {
private final OrderServiceV1 orderServiceV1;
private final HelloTraceV1 traceV1; // 컴포넌트가 있기 때문에 자동 스프링 빈으로 등록이 된다.
@GetMapping("/v1/request")
public String request(String itemId) {
TraceStatus status = null;
try {
status = traceV1.begin("OrderController.request()");
orderServiceV1.orderItem(itemId);
traceV1.end(status);
return "ok";
} catch (Exception e) {
traceV1.exception(status, e);
throw e;
}
}
}
@Service
@RequiredArgsConstructor // 파이널이 붙은 것을 생성자로 만들어준다.
public class OrderServiceV1 {
private final OrderRepositoryV1 orderRepositoryV1;
private final HelloTraceV1 traceV1;
public void orderItem(String itemId){
TraceStatus status = null;
try {
status = traceV1.begin("OrderServiceV1.request()");
orderRepositoryV1.save(itemId);
traceV1.end(status);
} catch (Exception e) {
traceV1.exception(status, e);
throw e;
}
}
}
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV1 {
private final HelloTraceV1 traceV1;
public void save(String itemId) {
TraceStatus status = null;
try {
status = traceV1.begin("OrderRepositoryV1.request()");
// 저장 로직
if (itemId.equals("ex")){
throw new IllegalStateException("예외 발생!!");
}
sleep(1000);
traceV1.end(status);
} catch (Exception e) {
traceV1.exception(status, e);
throw e;
}
}
private void sleep(int millis){
try {
Thread.sleep(millis);
}catch (InterruptedException e){
e.printStackTrace();
}
}
}

@Slf4j
@Component
public class HelloTraceV2 {
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
public TraceStatus begin(String message) {
TraceId traceId = new TraceId();
Long startTimeMs = System.currentTimeMillis();
log.info("[" + traceId.getId() + "] " + addSpace(START_PREFIX, traceId.getLevel()) + message);
return new TraceStatus(traceId, startTimeMs, message);
}
//V2에서 추가
public TraceStatus beginSync(TraceId beforeTraceId, String message) {
TraceId nextId = beforeTraceId.createNextId();
Long startTimeMs = System.currentTimeMillis();
log.info("[" + nextId.getId() + "] " + addSpace(START_PREFIX, nextId.getLevel()) + message);
return new TraceStatus(nextId, startTimeMs, message);
}
public void end(TraceStatus status) {
complete(status, null);
}
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("[" + traceId.getId() + "] " + addSpace(COMPLETE_PREFIX, traceId.getLevel()) + status.getMessage() + " time=" + resultTimeMs + "ms");
} else {
log.info("[" + traceId.getId() + "] " + addSpace(EX_PREFIX, traceId.getLevel()) + status.getMessage() + " time=" + resultTimeMs + "ms" + " ex=" + e);
}
}
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();
}
}
@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {
private final OrderServiceV2 orderService;
private final HelloTraceV2 trace;
@GetMapping("/v2/request")
public String request(String itemId) {
TraceStatus status = null;
try {
status = trace.begin("OrderController.request()");
orderService.orderItem(status.getTraceId(), itemId);
trace.end(status);
return "ok";
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}
@Service
@RequiredArgsConstructor // 파이널이 붙은 것을 생성자로 만들어준다.
public class OrderServiceV2 {
private final OrderRepositoryV2 orderRepository;
private final HelloTraceV2 trace;
public void orderItem(TraceId traceId, String itemId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "OrderService.orderItem()");
orderRepository.save(status.getTraceId(), itemId);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {
private final HelloTraceV2 trace;
public void save(TraceId traceId, String itemId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "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) {
e.printStackTrace();
}
}
}

public interface LogTrace {
TraceStatus begin(String message);
void end(TraceStatus status);
void exception(TraceStatus status, Exception e);
}
@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);
}
@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 syncTraceId() {
if (traceIdHolder == null) {
traceIdHolder = new TraceId();
} else {
traceIdHolder = traceIdHolder.createNextId();
}
}
private void releaseTraceId() {
if (traceIdHolder.isFirstLevel()) {
traceIdHolder = null; //destroy
} 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();
}
}
beginSync가 사라지고 TraceIdHolder를 선언한다.
sycnTraceId()를 만들어 traceIdHolder가 null인지 아닌지를 체크해준다.
@Configuration
public class LogTraceConfig {
@Bean
public LogTrace logTrace() {
return new ThreadLocalLogTrace();
}
}
- @Configuration을 통해 @Bean이 붙어있는 것을 수동으로 등록해준다.
```java
@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;
}
}
}
@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.orderItem()");
orderRepository.save(itemId);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}
@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) {
e.printStackTrace();
}
}
}
동시성 문제라는 큰 오류가 하나 있다. 동시성 문제는 무엇일까?[nio-8080-exec-3] [f9ae6789] OrderController.request()
[nio-8080-exec-3] [f9ae6789] |-->OrderService.orderItem()
[nio-8080-exec-3] [f9ae6789] | |-->OrderRepository.save()
[nio-8080-exec-4] [f9ae6789] | | |-->OrderController.request()
[nio-8080-exec-4] [f9ae6789] | | | |-->OrderService.orderItem()
[nio-8080-exec-4] [f9ae6789] | | | | |-->OrderRepository.save()
[nio-8080-exec-3] [f9ae6789] | |<--OrderRepository.save() time=1005ms
[nio-8080-exec-3] [f9ae6789] |<--OrderService.orderItem() time=1005ms
[nio-8080-exec-3] [f9ae6789] OrderController.request() time=1005ms
[nio-8080-exec-4] [f9ae6789] | | | | |<--OrderRepository.save()
time=1005ms
[nio-8080-exec-4] [f9ae6789] | | | |<--OrderService.orderItem()
time=1005ms
[nio-8080-exec-4] [f9ae6789] | | |<--OrderController.request() time=1005ms
위와 같이 동시성 문제가 발생한다.
3번 쓰레드가 들어오고 바로 4번 쓰레드가 들어와 동시성 문제가 발생하게 되서 쓰레드를 구별할 수 없게 된다.
ㅇ 🎄 그렇다면 V3에서 동시성문제를 어떻게 해결해야할까?
@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<>();
@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);
}
@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 syncTraceId() {
TraceId traceId = traceIdHolder.get();
if (traceId == null) {
traceIdHolder.set(new TraceId());
} else {
traceIdHolder.set(traceId.createNextId());
}
}
private void releaseTraceId() {
TraceId traceId = traceIdHolder.get();
if (traceId.isFirstLevel()) {
traceIdHolder.remove(); // destroy
} 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();
}
}
private TraceId traceIdHolder; 이 부분을 지우고 ThreadLocal을 사용하기 위해서 private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>(); 로 바꿔준다.@Configuration
public class LogTraceConfig {
@Bean
public LogTrace logTrace() {
return new ThreadLocalLogTrace();
}
}

ㅇ 여러 쓰레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제가 동시성 문제라 한다. 이런 동시성 문제는 여러 쓰레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 적을 경우 잘 나타나지 않지만 트래픽이 점점 많아질 수 록 자주 발생한다. 스프링 빈 처럼 싱글톤 객체의 필드를 변경하며 사용할 때 이러한 동시성 문제를 조심해야 한다.
하지만 이런 동시성 문제는 지역 변수에서는 발생하지 않는다. 지역 변수는 쓰레드마다 각각 다른 메모리 영역이 할당되기 때문이다. 또한 동시성 문제는 값을 읽을 때는 발생하지 않고 값을 변경할 때 발생한다.
ㅇ 동시성 이슈의 문제점
ㅇ 동시성 문제를 해결하기 위한 다른 방안
ㅇ 해당 쓰레드만 접근할 수 있는 특별한 저장소

ㅇ ThreadLocal을 사용할 때 지켜야할 것!
ㅇ ThreadLocal의 기본 사용법
1, ThreadLocal 객체 생성
2, ThreadLocal.set() 이용하여 현재 쓰레드의 로컬 변수에 값 저장
3, ThreadLocal.get() 이용해 현재 쓰레드의 로컬 변수 값 읽기
4, ThraedLocal.remove() 이용하여 현재 쓰레드의 로컬 변수 값 제거
ㅇ ThreadLocal 동작 방식
public void set(T value) {
Thread t = Thread.currentThread();
ThreadLocalMap map = getMap(t);
if (map != null) {
map.set(this, value);
} else {
createMap(t, value);
}
}
Thread에서 ThreadLocalMap이란 것을 꺼내 그 안에서 저장해놓은 변수를 꺼내는 식으로 처리. ThreadLocal에서 지금 현재 스레드의 table에서 현재 ThreadLocal 클래스를 키 값으로 map에 값을 저장
public T get() {
Thread t = Thread.currentThread();
ThreadLocalMap map = getMap(t);
if (map != null) {
ThreadLocalMap.Entry e = map.getEntry(this);
if (e != null) {
@SuppressWarnings("unchecked")
T result = (T)e.value;
return result;
}
}
return setInitialValue();
}
해당 스레드의 ThreadLocalMap에서 가져온다. 그리고 map에서 값을 꺼내 그 값을 반환해야하는 클래스로 형변환하여 반환
1, set()을 통해 변수 값을 해당 스레드가 가지고 있는 Map에 생성한 ThreadLocal 클래스 키를 값으로 저장
2, get()을 통해 변수 값을 해당 스레드가 가지고 있는 Map에서 현재 ThreadLocal 클래스 키 값으로 가지고 옴