Legacy라는 서비스의 모든 Pod들이 동시에 143 Error로 모두 계속 죽고 다시 살고, 또 죽고 다시 사는 문제가 발생했다.
모든 Pod들이 죽었기 때문에 서비스가 중지되었다.
아래 캡처는 K9S를 이용해 Pod에 대한 Description을 캡처한 것이다.
원인
Hikari Connection Pool
Pod에서 143 에러 코드가 무엇인지 찾아봤다. 143 에러코드는 Application에서 SIGTERM(종료 신호)를 Pod에 보냄으로써 바로 Pod를 종료시키는 것이 아니라, Graceful Shutdown으로 Pod를 종료시킨 것임을 알았다. GracefulShutDown이란 Pod가 종료 시그널을 받았을 때 처리 중인 Request가 있다면 모두 처리하고 Pod를 종료시키는 것을 의미한다. Graceful Shutdown에 관한 자세한 내용은 아래 블로그 글을 참조하길 바란다.
Kubernetes 를 위한 Spring Boot 개발 (feat. 무중단 배포/운영)
현재 Kubernetes, Istio를 사용하여 Java, Vue, Python Go 등으로 개발된 서비스를 개발/운영하고 있다. 우선 여기에서는 (Part 1) Spring Boot 설정 및 개발에 관련된 내용을 정리하고 Part 2에서는 kubernetes 에서
velog.io
POD의 로그를 살펴봤다.
로그 마지막에서 아래와 깉이 HikariDataSource에서 SpringBoot와 Pod를 종료시킨 것을 확인할 수 있었다.
297073 2022-04-27 00:37:30,807 [SpringApplicationShutdownHook] INFO
com.zaxxer.hikari.HikariDataSource - tx_hikari_cp - Shutdown initiated...
297098 2022-04-27 00:37:30,832 [SpringApplicationShutdownHook] INFO
com.zaxxer.hikari.HikariDataSource - tx_hikari_cp - Shutdown completed.
Stream closed EOF for legacy/legacy-api-68d6b69c78-4pclv (legacy-api)
참고로, Spring Application shutdown hook의 정의는 아래와 같다.
Spring Boot shutdown hook
Each SpringApplication will register a shutdown hook with the JVM to ensure that the ApplicationContext is closed gracefully on exit.
tx_hikari_cp는 application.properties에서 hikari의 data connection pool name인 것을 확인할 수 있었다.
좀 더 로그의 윗부분을 살펴보니, JDBC Connection을 얻을 수 없었다라는 에러를 발견했다.
294677 2022-04-27 00:37:28,411 [http-nio-8080-exec-186] ERROR
c.t.api.aspect.ControllerAspect - com.tradlinx.api.controller.UserRestController - getSession
org.springframework.transaction.CannotCreateTransactionException:
Could not open JPA EntityManager for transaction;
nested exception is org.hibernate.exception.GenericJDBCException: Unable to acquire JDBC Connection
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:467)
즉, 요청에 비해 JDBC Connection Pool의 Connection이 부족하여 컨테이너에 서비스 종료 시그널(SIGTERM)을 보낸 것으로 추측됐다.
노드의 CPU 사용량
요청이 많아진 것인지 확인하기 위해 Node의 CPU를 확인했다.
Azure의 K8S Service를 사용하고 있으므로, K8S 서비스의 Insights로 CPU 사용량을 확인했다.
문제가 일어난 시간CPU 사용량이 높아졌음을 확인했다.
Pod가 있는 Node의 CPU 사용량을 봤다. 노드의 CPU 사용량이 CPU 제한을 넘었다.
보면 Api-Schedule이라는 서비스의 CPU가 엄청 높음을 확인했다.
해결책
Hikari Pool Connection 문제가 난 원인을 부족한 CPU 때문이라고 생각했다.
그래서 우선, CPU 사용량이 많은 Api-Schedule을 다른 Node로 분산시켜주었다.
Legacy 서비스의 모든 Pod들도 하나의 노드에 들어있었는데, 이를 다른 노드에 분산 시켜주었다.
aks-nodepool01-22676046-vmss0000 노드에 2개의 api-schedule Pod가 있었는데, 이를 한 개로 줄여주었다.
aks-nodepool01-22676046-vmss0004 노드에 api-schedule Pod를 1개를 생성하고, legacy도 1개 생성하였다.
옮긴 후 노드의 CPU 사용량이 CPU 제한을 넘지 않았고, 모든 서비스들이 다시 잘 돌아가는 것을 확인할 수 있었다.
참고
https://techblog.woowahan.com/2664/
HikariCP Dead lock에서 벗어나기 (이론편) | 우아한형제들 기술블로그
{{item.name}} 안녕하세요! 공통시스템개발팀에서 메세지 플랫폼 개발을 하고 있는 이재훈입니다. 메세지 플랫폼 운영 장애를 바탕으로 HikariCP에서 Dead lock이 발생할 수 있는 case와 Dead lock을 회피할
techblog.woowahan.com
https://techblog.woowahan.com/2663/
HikariCP Dead lock에서 벗어나기 (실전편) | 우아한형제들 기술블로그
{{item.name}} 1부 HikariCP Dead lock에서 벗어나기 (이론편)은 잘 보셨나요? 2부 HikariCP Dead lock에서 벗어나기 (실전편)에서는 실제 장애 사례를 기반으로 장애 원인을 설명하고 해결 사례를 공유하고자
techblog.woowahan.com
[Spring] HikariCP Dead lock 벗어나기
※ Hikari, Connections pool, dead lock에 대한 설명이 포함되어 있지 않습니다 결론부터 말하자면 저의 경우엔 개발자의 실수였습니다. 체감상 2주 동안 걸쳐서 발견됐던 에러인데 막상 찾고보니 허무하
imksh.com
https://do-study.tistory.com/97
HikariCP와 커넥션 누수(Connection Leak) 관련 트러블슈팅
문제 발생 운영중인 서비스에서 사용하는 DB에서 특정 테이블들을 분리하여 별도 DB로 구축하는 일이 생겼습니다. 때문에 이를 위해 Multi Datasource를 적용하였습니다. 기존 서비스는 Tomcat connection
do-study.tistory.com
https://hyuntaeknote.tistory.com/12
내가 만든 서비스는 얼마나 많은 사용자가 이용할 수 있을까? - 3편(DB Connection Pool)
개요 지난 시간 현재 AGORA 서비스의 단일 피드 조회 기능에 대한 성능 테스트를 진행해보았습니다. 이번 시간에는 데이터베이스의 Connection Pool의 크기를 조절해보면서 발생하는 성능 변화에 대
hyuntaeknote.tistory.com
'트러블슈팅' 카테고리의 다른 글
| BooleanExpression의 NullPointException에러 (0) | 2022.05.04 |
|---|---|
| Mac에서 올린 파일이 Window에서 다운 받을 때, 파일명의 자음 모음이 분리되는 현상 (0) | 2022.05.02 |
| 필드명으로 인해 Spring Request DTO 에 null 값이 들어가는 이유 (0) | 2022.04.15 |
| AWS EC2 인스턴스 제거 후 비용 청구 문제 (원인: 탄력적 IP) (0) | 2022.04.03 |
| Github에 SSH 키 등록 (0) | 2022.03.27 |
