Image by vectorjuice
문제에 접근하는 두 방향
소프트웨어에 문제가 발생했을 때, 가장 어렵고 오랜 시간이 걸리는 작업은 정확한 원인을 찾는 일이라 할 수 있습니다. 원인만 찾는다면 고치는 일은 크게 어렵지 않은 경우가 많습니다. 이 때 크게 두 가지 접근 방법을 생각할 수 있습니다. 하나는 문제의 단서가 될 수 있는 로그를 바탕으로 코드를 살피며 원인을 찾는 귀납적 방법이 있습니다. 의미있는 로그를 수집할 수 있는 경우에 효과적입니다. 또 다른 접근법으로는 문제의 이유가 될 만한 이론적 배경을 찾고 이를 뒷받침해 줄 수 있는 구체적인 로그나 코드를 찾는 연역적 적근법이 있습니다. 연역적 접근법은 적절한 로그 수집이 어려운 경우 또는 경험에 근거해 확실한 예상 원인이 존재하는 경우 효과적으로 활용할 수 있습니다. 검색을 통해 찾은 예상되는 원인이 코드와 실제로 연관되는지 확인하는 과정도 이에 해당됩니다. 그러나 현실에서는 두 방법이 혼용되곤 합니다. 처음에는 로그를 기반으로 문제에 접근하다가 중간에 이론적 배경을 깨닫고 다시 코드를 찾기도 합니다.
1. 시작하며
이 글은 Java, Netty 기반 서비스에서 일어난 쓰레드 누수 문제를 귀납적(상향식)으로 분석하고 해결한 과정을 객관화한 기록입니다. 귀납적으로 문제를 해결한 하나의 사례를 통해 각자의 다른 문제를 해결하는데 도움이 되면 좋겠습니다.
2. 문제현상
서비스의 서버 운영 중 활성 쓰레드(Active Thread) 개수가 점진적으로 증가하는 문제가 발생했습니다. 아래 그래프는 모니터링 도구를 사용해 운영 중인 서비스를 1주일 넘게 모니터링하며 측정한 활성 쓰레드 증가 추이입니다.
3. 상용 분석도구 활용 (JConsole & VisualVM)
모니터링 도구로는 JConsole과 VisualVM을 활용했습니다. 기능상의 큰 차이는 없지만 VisualVM이 특정 시점의 활성 쓰레드 목록을 정렬해서 볼 수 있어서 더 유용했습니다.
4. 직접 분석도구 만들기 (쓰레드 목록 비교 API)
문제를 분석하며 활성 쓰레드 개수가 증가하는 시점에 어떤 쓰레드가 새롭게 생성되었는지 확인이 필요했습니다. 그러나 두 프로그램으로는 확인이 어려워 직접 필요한 API를 구현하기로 합니다. API는 현재 시점의 활성 쓰레드 목록을 캡처해 두었다가, 이후 사용자가 원하는 시점에 이전 활성 쓰레드 목록과 비교 후 새롭게 생성된 활성 쓰레드 목록을 정렬하여 반환해 주도록 했습니다.
// 현재 Active 쓰레드를 캡처하고, 이전 조회 결과와 비교해 새롭게 생성된 Active 쓰레드만 조회하는 기능을 제공합니다.
@RestController
@RequestMapping(path = "/resource/thread/")
@AllArgsConstructor
public class ActiveThreadMonitorController {
private final ActiveThreadMonitorService activeThreadMonitorService;
// 현재 Active 쓰레드 캡처
@PutMapping(path = "/active/capture/{timeTag}", produces = MediaType.APPLICATION_JSON_VALUE)
public ResponseEntity<Object> captureActiveThreads(@PathVariable String timeTag) {
activeThreadMonitorService.captureActiveThreads(timeTag);
return ResponseEntity.ok().build();
}
// 이전 조회 결과와 비교해 새롭게 생성된 Active 쓰레드만 조회
@GetMapping(path = "/active/diff/{beforeTimeTag}", produces = MediaType.APPLICATION_JSON_VALUE)
public ResponseEntity<List<String>> getDiffActiveThreads(@PathVariable String beforeTimeTag) {
return ResponseEntity.ok(activeThreadMonitorService.getDiffActiveThreads(beforeTimeTag));
}
}
@Service
public class ActiveThreadMonitorService {
private final Map<String, Set<Thread>> activeThreadsTimeline = new HashMap<>();
// 현재 Active 쓰레드 캡처
public void captureActiveThreads(String timeTag) {
Set<Thread> activeThreads = getActiveThreads();
activeThreadsTimeline.put(timeTag, activeThreads);
}
// 이전 조회 결과와 비교해 새롭게 생성된 Active 쓰레드만 조회
public List<String> getDiffActiveThreads(String beforeTimeTag) {
Set<Thread> beforeActiveThreads = activeThreadsTimeline.get(beforeTimeTag);
Set<Thread> currentActiveThreads = getActiveThreads();
return currentActiveThreads.stream()
.filter(Thread::isAlive)
.filter(thread -> !beforeActiveThreads.contains(thread))
.map(Thread::getName)
.sorted()
.collect(Collectors.toList());
}
// 현재 Active 쓰레드 조회
private Set<Thread> getActiveThreads() {
Set<Thread> threads = Thread.getAllStackTraces().keySet();
return threads.stream()
.filter(Thread::isAlive)
.collect(Collectors.toSet());
}
}5. 증가하는 쓰레드 분석하기
어떤 쓰레드인가?
구현한 쓰레드 목록 비교 API를 활용하여 "nioEventLoopGroup-9-x" 라는 이름을 가지는 쓰레드가 증가하고 있음을 확인할 수 있었습니다. 저희 서비스는 내부적으로 외부 API 서버들과 통신을 위해 Netty 프레임워크를 사용하고 있었는데 쓰레드 이름을 보고 Netty에서 생성한 쓰레드임을 인지할 수 있었습니다.
쓰레드와 연관된 기능은?
증가하고 있는 쓰레드의 이름까지는 찾았는데 쓰레드가 어떤 기능을 수행하는 코드와 연관된 것인지 찾기가 막막합니다. 구글링 하던 중 특정 쓰레드가 실행하는 코드를 찾기 위해 특정 클래스 생성자에 실행하는 쓰레드 식별자를 로그로 남기게 했다는 Stack Overflow 글을 읽고 무릎을 칩니다. 그러고 보니 외부 API 서버와 연결이 수립되면 쓰레드 식별자를 확인할 수 있는 로그를 찍어두었던게 기억납니다. 콘솔 로그를 뒤져보니 "nioEventLoopGroup-9-x" 쓰레드는 A라는 외부 API 서버와의 메시지를 주고 받기 위해 생성된 쓰레드임을 확인할 수 있었습니다.
[ntLoopGroup-9-1] inbound.RxMessageLogger : Device Remote Address :/xxx.xxx.xxx.xxx:n어떤 이벤트에서, 왜 쓰레드가 증가하는가?
여기까지 어떤 쓰레드가 증가하고 있고, 증가된 쓰레드와 관련된 기능까지 확인할 수 있었지만 조금 더 나아가 어떤 이벤트에서 왜 쓰레드가 증가하고 있는지 알아야 했습니다. 정확한 원인을 한정할 수 없어 어려움을 겪었는데 우연히 로그를 확인하다가 일정 시간 동안 증가한 쓰레드 개수와 위에서 찾은 외부 API 서버와 통신이 끊어졌다가 복구된 로그 개수가 일치하는 것을 발견하였습니다. 몇 가지 테스트를 진행하며 통신이 끊어졌다가 재연결되는 경우 해당 쓰레드가 하나씩 증가하는 것을 확인할 수 있었습니다.
종종 트러블슈팅 과정에서는 위 경우 처럼 어떤 논리적인 추론이나 유도에 의해서가 아니라 우발적으로 갑자기 어떤 원인을 발견하게 될 때가 있습니다.
6. 코드에서 문제 바라보기
문제가 발생하는 A 서버와의 통신 복구 코드를 살펴보니 끊어진 이전 연결에서 사용하던 I/O 쓰레드(EventLoop)는 해제 하지 않고, 새로운 연결을 위해 새로운 I/O 쓰레드(EventLoop)를 할당하고 있었습니다. 여기까지 오는 험난한 과정에 비해 문제의 원인은 간단했습니다.
@Override
public void channelInactive() {
...
// 이전 채널 자원 해제 필요!!!
// 연결 복구 시작
if (recoverSwitch) {
connectUntilSuccess.begin(targetIp, targetPort);
}
}7. 버그 고치기
수정 역시 간단합니다. 연결이 끊어진 경우 이전 연결에서 사용하던 I/O 쓰레드(EventLoop)를 해제해 주고 새로운 연결을 시도하도록 했습니다.
@Override
public void channelInactive() {
...
// 이전 채널 자원 해제
shutdownPreviousChannel()
// 연결 복구 시작
if (recoverSwitch) {
connectUntilSuccess.begin(targetIp, targetPort);
}
}8. 최종 결과
최종적으로 서비스 운영 중 모니터링 결과를 비교해 보면 확연히 차이가 드러납니다. 몇 일 더 지켜봐야 겠지만 문제가 잘 정리된 것 같습니다.
After
Before
9. 시행착오
그러나 여기까지 사실은 큰 시행착오 하나가 있었는데 생략하고 결과만 기록했습니다.
문제 인식의 혼란
아래는 이 문제를 처음 해결하던 시점에 썻던 블로그 글의 일부 내용을 발췌한 것입니다. 1번 내용을 보면 문제에 제대로 접근했습니다. 이전 연결에서 사용하던 쓰레드를 해제해 주면되는 것이 맞습니다. 그런데 이어지는 2번 설명에서는 뜬금 없이 연결이 수립된 후에 연결이 끊어진 상황이 아니라, 연결을 시도했는데 실패한 상황에 대한 내용이 나옵니다. 연결이 된 상태에서 연결이 끊어진 것과 연결 시도부터 실패한 상황은 다릅니다. 돌이켜 보니 그때 당시 두 문제를 섞어서 생각하는 오류가 있었던 것 같습니다.
적절하지 못한 해법
뿐만 아니라 해법을 찾는 부분에서도 오류가 있었습니다. 2번 내용을 보면 연결이 실패한 경우 Channel 참조를 얻을 수 없어서 다른 방법을 사용하겠다고 설명합니다. 그러나 실제로는 연결이 실패한 경우 실패한 연결에 사용된 Channel을 참조할 수 있습니다. 아래처럼 연결 시에 리스너를 함께 등록하면 비동기적인 연결 실패 이벤트에 대한 처리를 수행할 수 있었습니다. 대신에 저는 굉장히 큰 수정을 단행해서 결론적으로는 잘 동작하는 프로그램으로 바꿀 수 있었지만 1시간이면 수정할 수 있는 일을 많이 돌아서 간 것 같습니다.
bootstrap.connect(ip, port).addListener((ChannelFutureListener) future -> {
if (!future.isSuccess()) {
future.channel().eventLoop().shutdownGracefully();
}
});10. 마치며
지금까지 Java, Netty 기반 서비스에서 발생한 쓰레드 누수 이슈를 밑바닥에 있는 로그에서 시작해서 진짜 원인을 찾아서 해결한 귀납적 과정을 기록하며 객관화해 보았습니다. 인상적인 점은 문제 해결의 결정적인 단서는 쓰레드 증가 개수와 통신이 끊어졌다 복구되는 이벤트 개수가 같았다는 점인데 이는 어떤 논리적인 인과관계 보다 우발적으로 발견하게 된 것이라는 겁니다. 트러블슈팅 과정에는 종종 이렇게 우발적으로 주어진 단서가 결정적인 힌트가 되곤 하는 것 같습니다. 그리고 제가 처음 문제를 해결할 당시 기술적으로 잘못된 이해를 하고 있어서 엄청 어렵게 문제를 해결했다는 것을 오늘에서야 알게 되었습니다. 바쁜 사업일정 때문에 깊이 기술을 살펴볼 여유가 없었단 건 핑계겠죠. 잠시 여유로운 시간을 보내고 있어 지난 일들과 사용했던 기술들을 천천히 다시 객관화해서 돌아보고 있습니다. 바쁘게 달리는 중간중간 휴식과 정리의 시간들이 우리에게 꼭 필요하다는 생각이 듭니다.
관련 블로그 글
