DB가 왜그럴까?

Ericamoyed·2022년 12월 26일

개발한장

목록 보기

21/22

상황

갑자기 밤에 DB 연결이 이상하다고 오류로그가 떨어지는 일이 발생했다. 막 timeout이 나는거 같다. 근데 30분정도 있으니 자동 해소됐다.
db중 한대를 살펴보니 오류 상황일 때 read/write가 급격히 감소했다가 자동 해소되니 read/write 지표가 아예 0으로 전락했다. 무슨일이 일어난걸까.

DB 설정

    validationQuery: select 7
    minEvictableIdleTimeMillis: 1800000
    timeBetweenEvictionRunsMillis: 60000
    testOnBorrow: false
    testWhileIdle: true
    testOnReturn: false

각각 요소 설명

validationQuery : 커넥션 풀에서 커넥션을 가져올때 해당 커넥션의 유효성 검증에 사용할 SQL Query (반드시 하나 이상의 row 가 반환될 SELECT 구분이어야 함.)
minEvictableIdleTimeMillis : evictor thread 작업시 설정된 시간만큼 사용되지 않은 커넥션을 제거한다. 그리고, testWhileIdle 옵션이 true일 경우 설정된 시간을 초과하지 않은 커넥션에 대해서 validationQuery를 수행해서 유효하지 않은 커넥션을 제거한다.
timeBetweenEvictionRunsMillis : 설정된 시간 간격마다 놀고 있는 커넥션을 풀에서 제거하는 evictor thread 가 실행된다. minIdle 로 커넥션을 유지한다.
testOnBorrow : 커넥션 풀에서 커넥션을 가져올때 해당 커넥션의 유효성 검사를 할것인지 여부. (기본값 : true, 반드시 validationQuery 가 설정되어 있어야 함.)
testWhileIdle : Evictor 스레드가 실행될 때 (timeBetweenEvictionRunMillis > 0) 커넥션 풀 안에 있는 유휴 상태의 커넥션을 대상으로 테스트 실행(기본값 : false, 반드시 validationQuery 가 설정되어 있어야 함.)
testOnReturn : testOnBorrow 와 비슷함. 다만 유효성 검사 시점이 커넥션을 풀에 반환할때 이다.

왜저렇게 돼있음?

아마 d2 가이드에 따라 정석으로 설정한것 같다..
https://d2.naver.com/helloworld/5102792

그러면 어떻게 동작함?

60초(...) 마다 배치성으로 idle애들 데려다가 validation 체크하고 validation 통과 안하면 없애고 새로 커넥션 맺음.
60초마다 1800초(30분)나 놀고 있는 커넥션들은 아예 풀에서 제거해버림.
- 우리야 바쁜 서비스니까 요 조건에 해당돼서 풀에서 제거되는 애들은 없을듯 ?
커넥션풀에서 실 사용하느라 꺼낼 때나, 쓰고 커넥션 풀에 넣어놓을 때 따로 검사는 하지 않음.
우리 DB 연결할 때 socketTimeout, connectTimeout이 각각 60000으로 설정돼있음.
connectTimeout
- TCP/IP 연결이 established 될 때까지의 timeout. 소켓이 비로소 연결될 때까지의 timeout이다.
socketTimeout
- 소켓을 통해서 데이터를 받을 때의 timeout. statementTimeout보다 길게 설정하며 statement별로 statementTimeout이 적용 -> 설정이 없다면 socketTimeout까지 기다린다. 반대로 socketTimeout 설정이 없어서 무제한인 상황에 statementTimeout만 적용돼있다면 statementTimeout은 정상동작하지 않고 OS단 sockettimeout이 감행되는 시점이 감지된다. (하단 참고 중 넷마블 엔지니어링 게시물 참고)

에러 분석

4/5는 socketTimeout
- socketTimeout은 60초라 아래와 같이 오류가 남았다.

errorCode:### Error querying database.  
Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 60,061 milliseconds ago.  
The last packet sent successfully to the server was 60,060 milliseconds ago.
.
.
.
Caused by: java.net.SocketTimeoutException: Read timed out
  at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_202]
  at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_202]

60초 기다렸는데 이후로 패킷 받은게 없단다.
1/5는 queryTimeout. 아래와 같은 로그가 남았다.

org.springframework.dao.QueryTimeoutException: 
### Error querying database.  Cause: com.mysql.jdbc.exceptions.MySQLTimeoutException: Statement cancelled due to timeout or client request

queryTimeout은 ~~우리 DB 설정에 명시적으로 돼있지가 않다. 찾아보니 jdbc 드라이버 설정을 승계하며 디폴트가 60초다~~
- 인줄 알았는데 5초로 설정돼있는듯 ㅎ;
https://docs.spring.io/spring-framework/docs/3.2.4.RELEASE_to_4.0.0.M3/Spring%20Framework%203.2.4.RELEASE/org/springframework/jdbc/core/JdbcTemplate.html
https://docs.oracle.com/cd/E19159-01/819-3681/abehq/index.html
아무리 생각해도 이해할 수 없다. 어떤 flow길래 어떤 케이스에는 queryTimeout, 어떤 케이스에는 socketTimeout인거지 ? 응답이 느리지만 가끔은 해주긴 해줬다는건가 ? socketTimeout은 아예 망한거고 queryTimeout은 그래도 소켓에서 응답이 오긴 했지만 5초 넘었기 때문에 queryTimeout으로 남은건지.. 도저히 모르겐.

원인분석

0003 ~ 0008 까지 균등하게 커넥션을 가지고 있는 상황.
3:04 커넥션 풀에서 할당받았는데 0004번이랑 연결된 애가 나왔다. 0004번 커넥션을 평소처럼 이용하고자 했다. 근데 응답이 바로 안오네 ? socketTimeout(60000) 까지 노력했지만 실패했고 커넥션 풀에서 없애버렸다.
노는 애들 데려다가 validation 돌렸다. validation 하려고 렸더니 0004번 다 실패해서 한번 싹 정리했다.
- 참, validationQueryTimeout은 별도로 설정안하면 무제한이다. 이 때 돈 애들은 queryTimeout은 안났을거다. 그대신 socketTimeout(60000)짜리가 무지하게 났겠지.
정리가 되고 났더니 오래 돌던 0004번들 커넥션이 반납됐다. 바로 다음 요청에 방금 반납된 커넥션을 줬더니 그 친구도 오류가 났고 커넥션 풀에서 없어졌다. 점점 0004번의 입지가 작아져간다.
0004번 커넥션이 계속 없어지니 커넥션풀의 커넥션이 적어졌고, 적어지다 못해 minIdle에까지 도달했다. 새로 커넥션을 맺을 수밖에 없다. 0004번도 커넥션을 주긴준다. 근데 동작을 안해서 할당만 되면 바로 커넥션 풀에서 제거당한다.
0004번을 오래 물고 있던 커넥션들이 30분이 지나니 전부 반납처리가 됐다. 반납되고 재사용되는순간 차근차근 처형한 결과 다른 DB 커넥션들이 그 자리를 채움으로써 0004번을 대체하게 되었다. 근데 커넥션풀에서 처형되었음에도 mysqld에서 커넥션 정리가 제대로 안됐는지 실질적인 커넥션은 줄어든 것으로 보이나 mysqld 스레드는 급증하여 10000개까지 치솟은 상태로 유지되었다. 심지어 mysql 본인도 max connection인줄 알고 있는 상황이 발생했다.
0004번에서 커넥션을 신규로 물고 -> 사용하려다가 실패해서 -> 바로 반납하는 과정이 계속 이어질만 했지만 본인이 max connection인줄 알며 아예 커넥션을 주지 않는 상황이 발생하자 이슈가 종료되었다.
0004번의 이상현상은 현재로서 정확하게 알 길이 없다.