<div id="readability-page-1" class="page"><div><h2 id="문제현상">문제현상</h2>
Spring, Java 기반의 지상국 서버 운영 중 Active Thread 개수가 점진적으로 증가하는 문제가 발생합니다. 
<img src="https://velog.velcdn.com/images/joosing/post/94d7b110-4154-43ed-b650-95f32a8226fa/image.png">
<h2 id="분석도구">분석도구</h2>
<h3 id="jconsole--visualvm">Jconsole &amp; VisualVM</h3>
Active Thread 증가 추이를 확인하는데 jconsole (JDK 설치 시 기본적으로 제공)을 활용하였고, 조금더 나은 뷰어를 위해 VisualVM을 사용하였습니다. VisualVM 은 jconsole 과 기능상 큰 차이는 없지만 쓰레드 증가 추이 보다는 Active Thread 하나하나의 상태를 확인하기 더 유용했습니다. 일단 Active Thread 목록을 이름별로 정렬해서 볼 수 있어서 좋았습니다. 
<img src="https://velog.velcdn.com/images/joosing/post/92d6047e-6800-409c-8cc1-8e74d575ce60/image.png">
<h3 id="active-thread-비교-api">Active Thread 비교 API</h3>
문제를 상세히 분석하기 위해 어떤 쓰레드가 새롭게 생성되고 있는지 확인이 필요했는데 두 프로그램으로는 확인이 쉽지 않았습니다. 그래서 서버 애플리케이션의 특정 시점 Active Thread 목록을 저장해 두었다가, 비교를 원하는 시점과의 차이를 조회해 올 수 있는 두개의 API를 구현하여 증가하고 있는 쓰레드를 확인하는데 사용하였습니다. 
<pre><code>@RestController
@AllArgsConstructor
public class ThreadMonitorController {
 private final ActiveThreadMonitorService activeThreadMonitorService;

 // 현시점의 Active 쓰레드 캡처
 @PutMapping(path = "/resource/capture/{tag}", produces = MediaType.APPLICATION_JSON_VALUE)
 public ResponseEntity&lt;Object&gt; captureThreadNow(@PathVariable String tag) {
 activeThreadMonitorService.captureThreadsNow(tag);
 return ResponseEntity.ok().build();
 }

 // 특점 시점과의 Active 쓰레드 차이 조회
 @GetMapping(path = "/resource/diff-threads-from/{tag}", produces = MediaType.APPLICATION_JSON_VALUE)
 public ResponseEntity&lt;List&lt;ThreadMonitorDto&gt;&gt; getDiffThreads(@PathVariable String tag) {
 return ResponseEntity.ok(activeThreadMonitorService.getDiffThreadsFrom(tag));
 }</code></pre>
<pre><code>@Service
public class ActiveThreadMonitorService {
 private final Map&lt;String, Set&lt;Thread&gt;&gt; threadSetTimeline = new HashMap&lt;&gt;();

 public void captureThreadsNow(String tag) {
 Set&lt;Thread&gt; currentThreadSet = getActiveThreadSet();
 threadSetTimeline.put(tag, currentThreadSet);
 }

 public List&lt;ThreadMonitorDto&gt; getDiffThreadsFrom(String baseTag) {
 Set&lt;Thread&gt; taggedThreadSet = threadSetTimeline.get(baseTag);
 Set&lt;Thread&gt; currentThreadSet = getActiveThreadSet();

 List&lt;ThreadMonitorDto&gt; activeThreadDtoList = currentThreadSet.stream()
 .filter(Thread::isAlive)
 .filter(thread -&gt; !taggedThreadSet.contains(thread))
 .sorted(Comparator.comparing(Thread::getName))
 .map(thread -&gt; ThreadMonitorDto.builder()
 .name(thread.getName())
 .state(thread.getState().toString())
 .priority(thread.getPriority())
 .isDaemon(thread.isDaemon())
 .build())
 .collect(Collectors.toList());
 return activeThreadDtoList;
 }</code></pre>
<h2 id="분석과정">분석과정</h2>
<h3 id="어떤-쓰레드가-증가하고-있나">어떤 쓰레드가 증가하고 있나?</h3>
구현한 Active Thread 비교 API 를 활용하여 "nioEventLoopGroup-x-x" 라는 이름을 가지는 쓰레드가 눈에 띄게 증가하고 있음을 확인할 수 있었습니다. 지상국 서버는 내부적으로 하드웨에 API 서버들과 통신을 위해 Netty 프레임워크를 사용하고 있었는데 쓰레드 이름을 보고 Netty 에서 생성한 쓰레드임을 인지할 수 있었습니다. 
<pre><code>{
	"name": "nioEventLoopGroup-9-2",
	"state": "RUNNABLE",
	"priority": 10,
	"isDaemon": false
},</code></pre>
<h3 id="쓰레드-이름만-보고-우리-코드-연관짓기">쓰레드 이름만 보고 우리 코드 연관짓기</h3>
증가하고 있는 쓰레드의 이름까지는 찾았는데 프레임워크에서 생성하는 쓰레드다 보니 우리의 소스코드 어디와 연관된 건지 찾기 어렵습니다. 구글링 하던중 연관된 클래스의 생성부에 로그를 찍어 두면 특정 쓰레드에 의해 실행되는 클래스를 찾을 수 있다는 Stack Overflow 글을 읽고 무릎을 칩니다. 그러고 보니 하드웨어 API 서버와 연결이 수립되면 로그를 찍어두었던게 기억납니다. 콘솔 로그를 뒤져보니 "nioEventLoopGroup-9-x" 쓰레드는 특정 장비와의 통신에 사용되는 쓰레드임을 확인할 수 있었습니다. 
<pre><code>[ntLoopGroup-9-1] inbound.RxMessageLogger : Device Remote Address :/xxx.xxx.xxx.xxx:n</code></pre>
<h3 id="언제-쓰레드가-증가하는-건가">언제 쓰레드가 증가하는 건가?</h3>
그럼 언제 왜 해당 쓰레드가 점점 증가하고 있는지 확인이 필요했습니다. 정확한 원인을 한정할 수 없어 어려움을 겪었는데 우연히 로그를 확인하다가 일정 시간 동안 증가한 쓰레드 개수와 운영 중 위 장비와 통신에 문제가 생겨서 통신이 복구된 로그 개수와 일치하는 것을 발견하였습니다. 그래서 몇 가지 테스트를 통해 아래의 케이스에서 쓰레드 개수가 하나씩 증가함을 확인할 수 있었습니다.
<ul>
<li>통신에 문제가 생겨서 통신이 자동으로 복구되는 경우</li>
<li>사용자가 연결을 수동으로 끊었다가 새롭게 연결하는 경우</li>
<li>처음 서비스가 켜진 후 하드웨어 전원이 내려가 있어 자동으로 반복 연결 시도하는 경우</li>
</ul>
<blockquote>
<h4 id="eventloopgroup-에서-허용하는-최대-쓰레드-개수">EventLoopGroup 에서 허용하는 최대 쓰레드 개수</h4>
추가적으로 확인해 보니 Netty 는 기본적으로 채널과 연관된 EventLoopGroup에서 CPU Core X 2개의 최대 쓰레드 할당을 허용하고 있었고, 저희 서버의 CPU 코어는 32개여서 최대 64개까지의 쓰레드를 할당해서 사용할 수 있도록 허용하고 있었습니다. 그래서 쓰레드가 무한히 증가하고 있는 것은 아니고 최대치까지 증가하고 있는 것일 수 있다는 생각을 할수 있었는데, 그럼에도 불구하고 이미 사용이 종료된 이전 채널이 사용하던 쓰레드가 남아있는 것은 문제이기 때문에 문제를 해결하는 것이 좋겠다고 생각했습니다.
</blockquote>
<h2 id="원인">원인</h2>
위 문제 케이스들과 관련된 코드들을 살펴보니 동일한 하드웨어 API 서버로 연결을 재시도할 때 기존에 한 번 생성된 EventLoop 쓰레드 그룹을 반복해서 사용하고 있었습니다. 그래서 연결을 새롭게 시도할 때 마다 쓰레드 그룹 내 쓰레드가 하나씩 증가하고 있었습니다. 찾을 때는 어려웠지만 찾고보니 문제의 원인이 간단하네요.
<h2 id="개선">개선</h2>
간단하게 이전 연결에서 사용하던 쓰레드를 할당해제 해주면 되겠다고 생각했습니다. 그러나 연결을 시도하고 연결이 실패한 케이스에서 내부적으로 생성된 쓰레드를 참조할 방법이 막막합니다. 연결이 실패하면 Channel 참조를 반환해 주지 않기 때문입니다. 그래서 EventLoop 쓰레드 그룹 자체를 연결을 갱신할 때 마다 매번 새롭게 생성하고, 연결이 끊어지면 할당 해제해 주도록 간단히 수정 방향을 정했습니다. 
<h2 id="부수효과">부수효과</h2>
위 방향으로 수정하다보니 다른 부수효과가 하나 있습니다. 기존 코드에는 1초마다 하드웨어의 상태를 요청하는 태스크를 EventLoop 그룹 내 특정 쓰레드에 한번 등록되고 연결이 새롭게 수립되어도 변경 없이 사용하고 있었는데 연결할 때마다 EventLoop 그룹을 새롭게 생성하니 해당 태스크들도 매번 새롭게 등록해 주어야 했습니다. 위 태스크들 역시 연결이 새롭게 수립될 때 마다 등록해 주도록 수정해 주었습니다. 이 <a href="https://velog.io/@joosing/today-i-made-bug-and-learn-1">블로그 글</a>에 그 날의 기록을 정리해 두었네요. 
<h2 id="결과">결과</h2>
부수효과까지 수정하고 기존 코드와 새로운 코드의 동작을 모니터링해 봅니다. 확연히 차이가 드러나에요. 몇 일 더 지켜봐야 겠지만 문제가 잘 정리된 것 같습니다. 
<h3 id="after">After</h3>
<img src="https://velog.velcdn.com/images/joosing/post/f9df9523-2445-42e3-bdcb-9e412ff98bb3/image.png">
<h3 id="before">Before</h3>
<img src="https://velog.velcdn.com/images/joosing/post/32114f0f-6879-44e4-af21-22fc4aded74c/image.png"></div></div>

Joo's Work

JooSing

문제현상
Spring, Java 기반의 지상국 서버 운영 중 Active Thread 개수가 점진적으로 증가하는 문제가 발생합니다. 
분석도구
Jconsole & VisualVM
Active Thread 증가 추이를 확인하는데 jconsole (JDK 설치 시 기본적으로 제공)을 활용하였고, 조금더 나은 뷰어를 위해 VisualVM을 사용하였습니다. VisualVM 은 jconsole 과 기능상 큰 차이는 없지만 쓰레드 증가 추이 보다는 Active Thread 하나하나의 상태를 확인하기 더 유용했습니다. 일단 Active Thread 목록을 이름별로 정렬해서 볼 수 있어서 좋았습니다. 
Active Thread 비교 API
문제를 상세히 분석하기 위해 어떤 쓰레드가 새롭게 생성되고 있는지 확인이 필요했는데 두 프로그램으로는 확인이 쉽지 않았습니다. 그래서 서버 애플리케이션의 특정 시점 Active Thread 목록을 저장해 두었다가, 비교를 원하는 시점과의 차이를 조회해 올 수 있는 두개의 API를 구현하여 증가하고 있는 쓰레드를 확인하는데 사용하였습니다. 
@RestController
@AllArgsConstructor
public class ThreadMonitorController {
 private final ActiveThreadMonitorService activeThreadMonitorService;
 // 현시점의 Active 쓰레드 캡처
 @PutMapping(path = "/resource/capture/{tag}", produces = MediaType.APPLICATION_JSON_VALUE)
 public ResponseEntity<Object> captureThreadNow(@PathVariable String tag) {
 activeThreadMonitorService.captureThreadsNow(tag);
 return ResponseEntity.ok().build();
 }
 // 특점 시점과의 Active 쓰레드 차이 조회
 @GetMapping(path = "/resource/diff-threads-from/{tag}", produces = MediaType.APPLICATION_JSON_VALUE)
 public ResponseEntity<List<ThreadMonitorDto>> getDiffThreads(@PathVariable String tag) {
 return ResponseEntity.ok(activeThreadMonitorService.getDiffThreadsFrom(tag));
 }
@Service
public class ActiveThreadMonitorService {
 private final Map<String, Set<Thread>> threadSetTimeline = new HashMap<>();
 public void captureThreadsNow(String tag) {
 Set<Thread> currentThreadSet = getActiveThreadSet();
 threadSetTimeline.put(tag, currentThreadSet);
 }
 public List<ThreadMonitorDto> getDiffThreadsFrom(String baseTag) {
 Set<Thread> taggedThreadSet = threadSetTimeline.get(baseTag);
 Set<Thread> currentThreadSet = getActiveThreadSet();
 List<ThreadMonitorDto> activeThreadDtoList = currentThreadSet.stream()
 .filter(Thread::isAlive)
 .filter(thread -> !taggedThreadSet.contains(thread))
 .sorted(Comparator.comparing(Thread::getName))
 .map(thread -> ThreadMonitorDto.builder()
 .name(thread.getName())
 .state(thread.getState().toString())
 .priority(thread.getPriority())
 .isDaemon(thread.isDaemon())
 .build())
 .collect(Collectors.toList());
 return activeThreadDtoList;
 }
분석과정
어떤 쓰레드가 증가하고 있나?
구현한 Active Thread 비교 API 를 활용하여 "nioEventLoopGroup-x-x" 라는 이름을 가지는 쓰레드가 눈에 띄게 증가하고 있음을 확인할 수 있었습니다. 지상국 서버는 내부적으로 하드웨에 API 서버들과 통신을 위해 Netty 프레임워크를 사용하고 있었는데 쓰레드 이름을 보고 Netty 에서 생성한 쓰레드임을 인지할 수 있었습니다. 
{
 "name": "nioEventLoopGroup-9-2",
 "state": "RUNNABLE",
 "priority": 10,
 "isDaemon": false
},
쓰레드 이름만 보고 우리 코드 연관짓기
증가하고 있는 쓰레드의 이름까지는 찾았는데 프레임워크에서 생성하는 쓰레드다 보니 우리의 소스코드 어디와 연관된 건지 찾기 어렵습니다. 구글링 하던중 연관된 클래스의 생성부에 로그를 찍어 두면 특정 쓰레드에 의해 실행되는 클래스를 찾을 수 있다는 Stack Overflow 글을 읽고 무릎을 칩니다. 그러고 보니 하드웨어 API 서버와 연결이 수립되면 로그를 찍어두었던게 기억납니다. 콘솔 로그를 뒤져보니 "nioEventLoopGroup-9-x" 쓰레드는 특정 장비와의 통신에 사용되는 쓰레드임을 확인할 수 있었습니다. 
[ntLoopGroup-9-1] inbound.RxMessageLogger : Device Remote Address :/xxx.xxx.xxx.xxx:n
언제 쓰레드가 증가하는 건가?
그럼 언제 왜 해당 쓰레드가 점점 증가하고 있는지 확인이 필요했습니다. 정확한 원인을 한정할 수 없어 어려움을 겪었는데 우연히 로그를 확인하다가 일정 시간 동안 증가한 쓰레드 개수와 운영 중 위 장비와 통신에 문제가 생겨서 통신이 복구된 로그 개수와 일치하는 것을 발견하였습니다. 그래서 몇 가지 테스트를 통해 아래의 케이스에서 쓰레드 개수가 하나씩 증가함을 확인할 수 있었습니다.
통신에 문제가 생겨서 통신이 자동으로 복구되는 경우
사용자가 연결을 수동으로 끊었다가 새롭게 연결하는 경우
처음 서비스가 켜진 후 하드웨어 전원이 내려가 있어 자동으로 반복 연결 시도하는 경우
EventLoopGroup 에서 허용하는 최대 쓰레드 개수
추가적으로 확인해 보니 Netty 는 기본적으로 채널과 연관된 EventLoopGroup에서 CPU Core X 2개의 최대 쓰레드 할당을 허용하고 있었고, 저희 서버의 CPU 코어는 32개여서 최대 64개까지의 쓰레드를 할당해서 사용할 수 있도록 허용하고 있었습니다. 그래서 쓰레드가 무한히 증가하고 있는 것은 아니고 최대치까지 증가하고 있는 것일 수 있다는 생각을 할수 있었는데, 그럼에도 불구하고 이미 사용이 종료된 이전 채널이 사용하던 쓰레드가 남아있는 것은 문제이기 때문에 문제를 해결하는 것이 좋겠다고 생각했습니다.
원인
위 문제 케이스들과 관련된 코드들을 살펴보니 동일한 하드웨어 API 서버로 연결을 재시도할 때 기존에 한 번 생성된 EventLoop 쓰레드 그룹을 반복해서 사용하고 있었습니다. 그래서 연결을 새롭게 시도할 때 마다 쓰레드 그룹 내 쓰레드가 하나씩 증가하고 있었습니다. 찾을 때는 어려웠지만 찾고보니 문제의 원인이 간단하네요.
개선
간단하게 이전 연결에서 사용하던 쓰레드를 할당해제 해주면 되겠다고 생각했습니다. 그러나 연결을 시도하고 연결이 실패한 케이스에서 내부적으로 생성된 쓰레드를 참조할 방법이 막막합니다. 연결이 실패하면 Channel 참조를 반환해 주지 않기 때문입니다. 그래서 EventLoop 쓰레드 그룹 자체를 연결을 갱신할 때 마다 매번 새롭게 생성하고, 연결이 끊어지면 할당 해제해 주도록 간단히 수정 방향을 정했습니다. 
부수효과
위 방향으로 수정하다보니 다른 부수효과가 하나 있습니다. 기존 코드에는 1초마다 하드웨어의 상태를 요청하는 태스크를 EventLoop 그룹 내 특정 쓰레드에 한번 등록되고 연결이 새롭게 수립되어도 변경 없이 사용하고 있었는데 연결할 때마다 EventLoop 그룹을 새롭게 생성하니 해당 태스크들도 매번 새롭게 등록해 주어야 했습니다. 위 태스크들 역시 연결이 새롭게 수립될 때 마다 등록해 주도록 수정해 주었습니다. 이 블로그 글에 그 날의 기록을 정리해 두었네요. 
결과
부수효과까지 수정하고 기존 코드와 새로운 코드의 동작을 모니터링해 봅니다. 확연히 차이가 드러나에요. 몇 일 더 지켜봐야 겠지만 문제가 잘 정리된 것 같습니다. 
After
Before

Spring, Java 서버 애플리케이션 쓰레드 누수 문제 개선기

댓글