4시 정도에 슬랙 채널에 글이 올라왔다.
"백엔드 서버가 또 다운된거 같아요 ㅠㅠ 이거 큰일이네요 어떡하지요...
어제도 오늘도 4시쯤 다운이 됐는데 무슨 이유일까요... 방금까진 잘 되던거 같은데 ㅠㅠ
방문자 수가 갑자기 늘어난것도 아니고 뭔가 다른 이유가 있는거 같아요"
putty로 인스턴스에 접속하려 했지만 역시나 접속되지 않았다.
어제도 서버가 터져서 인스턴스를 ☆종료(삭제)☆하고 인스턴스를 새로 만들어서 배포를 했다.
이때까지만 해도 종료가 인스턴스 삭제가 아닌 인스턴스 off로 생각했고
그로 인해서 인스턴스가 삭제되서 많이 당황했다.
아무튼 오늘은 인스턴스를 삭제하지 않고 인스턴스를 재구동해서 접속했다.
원인을 파악하기 위해서 nohup.out(로그 파일)을 살펴보았다.
로그 파일에는 많은 sql 쿼리문들이 있었고
2021-01-31 07:13:55.627 WARN 30747 --- [or-http-epoll-1] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@1066d1f0 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value.
2021-01-31 07:13:48.441 WARN 30747 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m13s50ms252µs185ns).
2021-01-31 07:14:55.986 WARN 30747 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=1m49s539ms302µs551ns).
2021-01-31 07:14:59.900 WARN 30747 --- [or-http-epoll-1] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 0, SQLState: 08003
2021-01-31 07:15:05.201 ERROR 30747 --- [or-http-epoll-1] o.h.engine.jdbc.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 491632ms.
2021-01-31 07:15:07.606 ERROR 30747 --- [or-http-epoll-1] o.h.engine.jdbc.spi.SqlExceptionHelper : No operations allowed after connection closed.
2021-01-31 07:17:26.154 WARN 30747 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Thread starvation or clock leap detected (housekeeper delta=51s20ms282µs452ns).로그 파일에서 Thread starvation or clock leap detected 메시지가 출력됐고
마지막에 이런 오류 메시지와 함께 백그라운드에서 실행되던 서버는 더이상 구동되지 않았다.
문제 해결을 위해 긴급히 회의를 열었다.
근본적으로 이것 때문에 서버가 터졌다! 라는 것은 발견하지 못했다.
다만 이러이러한 이유때문에 서버가 터진 것은 아닐까? 라는 추측은 해보았다.
아무튼 지금 당장 조치를 취해야 할 부분은 hikari connection pool을 10개에서 20개로 늘리는 것이다.
10명 이상의 접속자가 동시에 요청을 보내면 connection pool이 감당할 수 없게 되어 더 이상 DB가 동작하지 않는다고 예상했다.
connection pool을 무작정 늘리기보다는 서버가 터질 때마다 10개씩 늘려서 경과를 지켜볼 것이다.
지금 당장은 connection pool을 100개씩 늘리면 접속자가 많아도 괜찮지않을까? 라는 생각을 하고있는데 trade off에 대해서도 알아봐야겠다.
또한 mysql의 slow query 로그를 만들고 다른 로그도 daily rotate 설정(아직 무슨 말인지 모름)을 해야한다.
여기까지가 프로젝트에 대한 조치이고
추가적으로 jmap 명령어로 heap 메모리를 dump하고
jstack 명령어로 thread 관련 dump를 해서 비교 분석 후
memory leak이 발생하는 부분이 있는지, 불필요하게 thread가 남아있는지 확인을 해봐야 한다.
이를 eclipse mat, jprofile 프로그램?을 이용해서 thread busy한 부분이 있는지 확인해봐야 한다.
aws에 대해서 잘 알지도 못하는 나에게는 처음 서버가 터졌을 때 어떤 문제가 있는지, 어디서 문제를 찾아야하는지 알 수 없었다. 그래서 재부팅도 해보고 ☆종료☆ 버튼도 눌러보고 시도는 해보았다. 결국 인스턴스를 다시 생성해서 처음부터 jar 파일을 재배포해서 급하게 막았지만 다시 문제가 발생했을 때 어떻게 대처해야 할 지 알 수 없었다.
그런데 오늘 떡하니 똑같은 문제가 발생했다. 이번에는 백엔드 선배님들을 포함해서 여러 명의 사람들과 회의를 열었다.
여러 예측을 해보고 파일을들 하나씩 파해쳐보고 어떻게 해야 할 지 가이드 라인을 잡아갔다.
오늘만해도 처음 들어보는 용어도 정말 많이 나왔고 이것을 하나씩 풀어나가야 할 지 막막하다. 하지만 이런 경험이 레벨업에 있어서 직빵이기 때문에 기대가 되기도 한다.
유어슈가 없었더라면 이런 문제가 있을지에 대해서도 알지 못했을 것이다.
동아리 분들께 너무 감사하다.
추가 사항(2021-06-24)
디버깅을 미루고 있다가 다른 프로젝트를 진행하면서 똑같은 오류 메시지가 발생했다.
이 프로젝트를 포함한 많은 프로젝트들이 도커 위에서 돌아가고 있었다.
그러다보니 속도가 매우매우 느렸다.
구동중이지만 사용하지 않는 도커 컨테이너를 여러 개 중지시켰고
그 뒤로 위의 오류 메시지는 발생하지 않았다.
만약 이 오류 메시지가 발생한다면 서버 사양을 높여보자.
