인스턴스 상태검사 실패, Thread starvation or clock leap detected, Dead Lock, hikari 오류-1

EC2 서버에 배포한 스프링 부트 프로젝트가 오늘 아침까지는 잘 돌아가다가 저녁에 확인을 해보니 요청을 처리 못하고 있었다. 바로 EC2서버를 확인해보니 인스턴스 상태 검사에서 CPU사용량 99.9% 때문에 오류를 경고하고 있었고, 서버가 죽어있었다. 서버를 다시 재부팅하고 스프링 부트 프로젝트의 로그를 확인해보니 글 아래에 첨부한 Thread Starvation 로그를 엄청 뿜어대고 있었다. 원인을 파악해보려고 상황을 분석했다. Thread Starvation의 발생 시간과 CPU 사용량이 99.9%로 증가시간이 일치하였다. 스프링 부트 프로젝트의 Thread Starvation 현상 때문에 EC2서버가 죽은 것으로 보였다.

• 블로그 링크
  • https://jaehun2841.github.io/2020/01/27/2020-01-27-hikaricp-maximum-pool-size-tuning/#generatedvaluestrategy-generationtypeauto
  • https://velog.io/@sihyung92/how-does-springboot-handle-multiple-requests
• Spring Boot 공식 문서 링크
  • https://docs.spring.io/spring-boot/docs/current/reference/html/application-properties.html#application-properties.server.server.tomcat.threads.min-spare
• Hikari 공식 링크
  • https://docs.spring.io/spring-boot/docs/current/reference/htmlsingle/#application-properties.data.spring.datasource.hikari
  • https://github.com/brettwooldridge/HikariCP

위 링크의 블로그에서 Thread와 Connection 관계, 스레드풀 작동방식, Spring Boot 공식 문서에서의 Default min-spare Thread의 수(10개), max Thread의수 (200개), Hikari의 Default maximumPoolSize(10개)를 확인하고 나니 오류의 원인을 깨달았다. 상황을 정리하면 아래와 같다.

• CPU에 우리 스프링 프로젝트의 Thread들이 올라가서 작업을 하게 되고, 그러다 한 Thread내의 별도 Transaction에서 추가적인 SQL문 실행이 필요해지면서Thread가 Connection을 더 필요로 하는 상황이 생겼다. 우리 스프링 부트 프로젝트에서 Thread가 Connection이 더 필요한 이유는 다음과 같다.
• 우리 스프링 부트 프로젝트에서 트랜잭션 로그를 확인해보니 Service의 메소드가 사용될 때 Service의 트랜잭션이 시작하고, Service의 메소드에서 Repository를 사용할 때 Repository의 트랜잭션이 시작했다. 김영한님의 자바 ORM 표준 JPA 프로그래밍 따르면 스프링 컨테이너는 트랜잭션 범위의 영속성 컨텍스트 전략을 사용한다고 한다. 즉, 우리는 요청을 처리하는 한 개의 Thread에서 Service의 트랜잭션과 Repository의 트랜잭션 때문에 2개의 영속성 컨텍스트가 생겼고 2개의 영속성 컨텍스트를 위한 엔티티 매니저도 2개가 생겼으므로, Connection이 2개가 필요한 상황인 것이다.
• 그러나 남은 Connection이 없는 상황이 발생해서 Thread는 작업을 끝내지도 못했고, Thread가 데드락에 걸렸다.
• 이후로 오는 요청에 대한 작업이 유휴 Thread가 없어 NIO Connector가 계속 Thread를 생성했다.
• 하지만, 남은 Connection이 없어서 Thread Starvation 상황으로 이어졌다. Thread가 추가로 생성되어야 해결되는게 아니라 Connection의 수를 늘려야 해결되는 상황이었다. 그래서 요청 작업이 발생하면 남은 Thread가 없고 NIO connector가 요청 작업을 위한 Thread를 계속 생성하는 상황이 반복하게 되었다.
• 종합해보면, 기존 Thread가 작업을 못 끝내고 계속 CPU를 사용하고, 새로운 Thread들이 최대 개수까지 생성하게 되면서 스프링 부트 프로젝트의 CPU 사용량이 극단적으로 99.9%까지 올라가게 된 것이다.
• 또한 Thread들이 Connection을 할당받지 못했으므로 스프링 부트 프로젝트는 아래에 첨부한 Thread Starvation 로그를 계속 출력하고, EC2서버는 CPU 99.9% 사용량으로 인해 인스턴스 상태 검사를 통과하지 못하고 죽어버린 것이다.

해결 방법으로는 HikarilCP에서 제공하는 최적의 Maximum Pool Size를 구하는 공식을 사용했다.

• https://github.com/brettwooldridge/HikariCP/wiki/About-Pool-Sizing

pool size = Tn x (Cm - 1) + 1

우리 스프링 프로젝트의 Thread수는 10개이다. 한 Thread가 작업을 하면서 필요로 하는 Connection의 수는 2개이다. 위 공식에 대입하면 우리 프로젝트의 최적 pool size는 10*(2-1)+1로 11개이다. 11개 이상의 Connection을 제공하면 오류가 해결될 것이다.

spring.datasource.hikari.maximum-pool-size=20

위의 코드를 application.properties에 추가해서 Connection의 개수를 20개로 늘렸다.

[HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=5m30s164ms615µs200ns)

---

2022-10-30 추가 작성

Connection이 부족하게 된 원인을 잘못 파악했다. 아래의 링크에 원인을 다시 파악하고 정정했다. 아래의 링크를 확인하면 된다.

• https://velog.io/@mbsik6082/Spring-Data-JPA-Transaction-Propagation-EntityManager-PersistContext%EC%97%90-%EA%B4%80%ED%95%9C-%EA%B3%A0%EC%B0%B0