mysql aborted clients 문제 해결

db를 mysql 을 쓰고 있는데,

갑자기 이슈로 client abort 되는게 너무 많다고 전달 받았다. 

원인을 찾고 이슈를 수정하기 까지의 과정을 정리해본다. 

 

aborted clients 는 클라이언트가 제대로 연결을 닫지 않고 죽어서 중단된 연결 수를 의미한다. 

해당 오류 관련해서 mysql 공식문서를 찾아봤더니 아래와 같이 가이드 되고 있었다.

• Aborted_clients 에러가 발생하면 확인 하면 좋을것들
  1. error log를 봐라
  2. general query log를 봐라
  3. The Aborted_***xxx*** and Connection_errors_***xxx***가 있을테니 상태를 확인해라

mysql 에서 저 로그를 찍는게 설정을 바꿔야 해서 mysql 에서 설정 바꾸다가 

잘 쓰고 있던 도커 컨테이너 하나가 날아갔다... 

db 데이터도 컨테이너 안에 세팅 해놔서 싹 다 날리고 다시 시작했다. 

다시 설정해서 log 를 찍을 수 있게 수정하고 로그를 확인했는데,

어플리케이션 단 구체적으로 어디에서 에러가 발생 했는지는 안알려준다. 

 

 

참고로 aborted clients 를 검색 하다가 보면 비슷한 Aborted_connects 라는것도 있는데

이 값은 클라이언트가 연결조차 할 수 없는 경우를 나타낸다 (ex> 잘못된 password)

      - 연결 실패 : 연결 과정중에서 fail 되는 경우 (Aborted_connects)
      - 연결 취소 : 연결이 된 상태에서 강제로 close 된 경우 (Aborted_clients)

 

클라이언트가 연결에 성공했지만 나중에 연결이 잘못되거나 종료되면 서버는 abortbed_clients 상태 변수를 증가시키고

연결 중단 메시지를 오류 로그에 기록하게 된다.

Aborted_clients가 발생하게 되는 대표적인 원인은 3가지가 있다. 

1. 클라이언트 프로그램에서 종료 하기전에 mysql_close() 을 호출하지 않는 경우
2. 클라이언트에서 서버에 어떤 request도 요청하지 않고 [wait_timeout] or [interactive_timeout] 보다 더 sleeping 하는 경우
3. 데이터 전송 도중 프로그램이 갑자기 종료 되었을때

 

---

원인 찾기

 

실제로 db에서 값들을 확인해 보니 다음과 같이 기록 되고 있었다.

 

A 서비스

• wait_timeout :600
• Aborted_clients - 3165607

B 서비스

• wait_timeout : 180
• Aborted_clients : 169551
  
  

C 서비스 - 처음부터 내가 만든 프로젝트 

• wait_timeout : 28800
• Aborted_clients : 827

 

A, B, C 에서 사용 중인 mysql 은 5.7 버전이다.

 

C 서비스는 정상적으로 동작되고 있는데

A 나 B 는 숫자가 비정상으로 높은것으로 보아 문제가 있는것으로 판단되었다.

 

A하고 B는 노드에서 제공해주는 서비스 였고, pool 의 사용 부터 의심스러운 상황이어서 관련 동작을 확인 했다.

 

db 커넥션을 종료하기 위한 두가지 방법이 있다. 

1. end() : 종료하기 전에 COM_QUIT 패킷을 mysql server에 보낸다.
2. destroy() : 즉시 종료 한다. 종료 콜백이 없다.

하지만 커넥션을 하나씩 관리하는 것보다 connection pool 으로 사용하는것이 더 효과적이다.

 

커넥션 풀을 사용하는 플로우는 다음과 같다.

pool.getConnection() -> connection.query() -> connection.release()

커넥션을 커넥션 풀에서 반환하기 위해서는 connection.release()

해야 했는데 ``release = mysql_close()` 잘 호출되는것을 확인했다.

 

그렇지만 어떤 문제 때문에 지속적으로 Aborted_clients 숫자가 올라가는것을 확인 했다.

db console 에서 아래 명령어를 치면 현재 db에서 aborted_client 된 갯수가 나오는데

어떤 api가 문제가 있다면 호출 할때 마다 aborted_client 카운트가 늘어날 것이라고 판단했다.

상태를 확인 하는 명령어

SHOW GLOBAL STATUS;

 

문제 추측 1 - wait_timeout 설정이나 pool 관련 문제일것이다.

공식 문서에서 나온 [클라이언트에서 서버에 어떤 request도 요청하지 않고 wait_timeout or interactive_timeout 보다 더 sleeping 하는 경우] 문제가 발생하기 때문에 wait_timeout 관련 설정이나 pool 을 반환 할 때 문제가 생기는것이 아닐까 했다. 

wait_timeout을 검증 하기 위해서 connection 스레드의 상태를 확인 해야 했다. 

connection 의 상태는 아래와 같은 방법으로 확인한다.

1. api 호출한다.
2. 명령어로 스레드 리스트를 가져온다

SHOW processlist ;

 

api 를 호출 하고 정상적으로 connection이 맺어졌다면 processlist에 process 가 나온다.

여기서 time 은 db에 설정된 wait_timeout 이 지나면 자동으로 aborted client에 value 가 증가하게 된다.

 

wait_timeout을 찾다보면 또 connect_timeout 이 같이 나오게 되는데, 

connect_timeout 하고 wait_timeout 은 서로 비슷해보이면서 확실하게 다르다.

---

connect_timeout

이 설정은 mysqld 와 mysql client 가 연결(connection)을 맺기 위해서
mysqld 가 연결 패킷을 기다리는 최대 시간입니다.

즉 TCP 연결을 맺는 과정(3-way handshake)에서, connect_timeout 동안에도
연결 패킷이 들어오지 않으면 연결이 실패(취소가 아님)되고,
bad handshake 로 응답합니다.

wait_timeout

 

mysqld 와 mysql client 가 연결을 맺은 후, 다음 쿼리까지 기다리는
최대 시간을 의미합니다

 

---

저 옵션을 보다보니깐 어플리케이션에서는 connection pool을 사용하는데 db 설정에 있는 wait_timeout 사용하는것이 이상했다.

1. connection pool은 connection 을 맺고 끊는게 비용이 많이 들어서
   pool에 넣고 쓰는건데 wait_timeout을 쓰면 pool을 쓰는 의미가 없는것 아닐까
2. 이상적인 connection pool 의 동작 방식은 어플리케이션이 올라갈때 지정된 숫자로
   connection을 맺고 종료 할때까지 끊지 않는거 같은데…

위 가정이라면 pool 의 동작과 wait_timeout 의 관계가 상충되어 말이 안된다라고 생각지만

initialSize, maxIdle, minIdle 로 추가 설정을 할 수 있어서 개발자의 선택에 맡기는 느낌이다. 

 

connection 을 맺기 위한 config

"acquireTimeout": 10000, // 연결을 획득하는 데에 대한 타임아웃 시간 : 10초
"waitForConnections": true, //모든 연결이 사용 중일 때
// 새 연결을 기다릴지 여부. true 면 대기 
"connectionLimit": 5, //풀 내 최대 연결 개수
"queueLimit": 0,//연결 획득을 위해 대기하는 큐의 최대 길이. 0이면 제한없음
"queueTimeout": 0, // 큐 대기 시간에 대한 타임아웃
"testOnBorrow": true,
"testOnBorrowInterval": 20000,
"initialSize": 0,//초기에 풀 내에 생성되는 연결의 개수
"maxIdle": 5, //풀 내 유지되는 최대 유휴 연결의 개수
"minIdle": 0, 
"maxReuseCount": 0, // 연결이 재사용되는 최대 횟수
"timeBetweenEvictionRunsMillis": 0,
"numTestsPerEvictionRun": 3,
"minEvictableIdleTimeMillis": 1800000

 

내가 생각 했을때 이상적인 동작 방식은(서비스가 계속 제공된다는 가정)

풀에 커넥션들이 끊기지 않고 어플리케이션이 구동될때 적당한 initialSize 만큼 설정되있다. 

어플리케이션에서 connection은 minIdle 만큼 유지되고 있다가

서비스에 트레픽이 많아지면 maxIdle 만큼 생성된다.

새벽이나 트레픽이 적은 시간에는 wait_timeout 시간이 지나 maxIdle -> minIdle 만큼 유지된다.

커넥션 풀에서 커넥션을 쓰고 나면 processlist 나온 time 은 0으로 초기화 된다.

이게 아닐까 싶다. 

 

해결방법 1 : initialSize 와 minIdle 의 사이즈를 조절해 보자

→ node mysql 2.18.1 버전을 쓰고 있었다

→ mysql.createPool이라는걸로 pool을 만드는데 해당값 설정을 지원하지 않았다.

mysql 모듈

GitHub - mysqljs/mysql: A pure node.js JavaScript Client implementing the MySQL protocol.

GitHub - mysqljs/mysql: A pure node.js JavaScript Client implementing the MySQL protocol.

문제가 되는 db 에서 wait_timeout 이 60초로 짧게 잡혀있어서 커넥션 풀에서.
다른 커넥션들을 쓰기 전에 60초가 넘어가서 사용이 안되는것으로 판단하고 해당 wait_timeout 시간을 늘려봤다.

늘렸더니 쓰레드들이 계속 늘어나기만 하고 줄지 않았고 다시 롤백을 시켰다.

기존에 이런 장애가 발생 해서 wait_timeout 을 줄여 놓은것으로 보였다.

근본적인 원인을 해결하면 wait_timeout 과 상관없이 잘 동작할걸로 보였다.

 

문제 추측 2 - api를 호출할때 문제가 생길것이다.

소스에서 문제가 되는 경우 - 대충 아래 처럼 구성되어 있었는데 

self.ProxyShardControl.getProxyClusterNode()
    .then(self.db.connection.getReadConnection)
    .then(context => {
      context.shard = self.getShard(db_info.name);
      return Promise.resolve(context);
    })
		.then(self.db.connection.releaseConnection)
    .then(context => {
      return Promise.resolve(data);
    })
    .catch(self.db.errorHandler)
    .catch(self.emptyCatch)

1. .then(self.db.connection.getReadConnection) 커넥션을 받아온다.
2. self.ProxyShardControl.getShard(db_info.name, data.project_key); 위로 함수 호출을 할때 db_info.name 이 없다면…?
3. .catch(self.db.errorHandler) 가 호출 된다.

function errorHandler(err) {
	if (err && err.context) {
		return connectionWrapper.rollbackTransaction(err.context).then(() => {
			return Promise.reject(err.error);
		});
	} else {
		return Promise.reject(err);
	}
}

rollbackTransaction: function (context) {
		return new Promise(function (resolved, rejected) {
			context.connection.rollback();
			context.connection.release();
			return resolved(context);
		});
	},

4. err에 context 가 없어서 rollbackTransaction 을 타지 않는다.

5. release 도 되지 않는다.

→ 이 부분은 sql 을 만드는 부분과 커넥션을 맺고 release 하는 부분을 나눈다.

그러면 context가 없어서 에러가 발생했던 부분을 방지 할 수 있다.

 

문제 추측 3 - 특정 api 를 호출 할때 마다 10개 씩 늘어남.

async getMergedExecutionCount

require('async') - 3.2.4

async.queue(async (task, callback) => {
...

}, constants.MAX_QUEUE_CONCURRENCY);

queue.push(queryValues);

await queue.drain();

동기로 돌아가는 부분을 비동기적으로 실행시키기 위해 추가된 부분이 문제가 생겼다.

해당 부분을 동기적으로 바꿨을때는 문제 발생 안했다.

 

pool 에 관련된 문제 인것 같아서 확인을 했는데,

어플리케이션에서는 2가지 방법으로 pool 을 썼는데 

첫번째 방법는 (require("mysql")) 에 있는 poolCluster 

두번째는 require("mysql-pool-booster")(require("mysql")) mysql.createPoolCluster(clusterConfig)

왜 2가지 방법을 썻을까..? 

그 이유는...?!!! 

아무리 봐도 이유 없어보인다... 그냥 레거시인걸로.... 

 

위에서 테스트 했던게 잘못되었다.

mysql 모듈 에서 보는게 아니라 mysql-pool-booster에서 봤어야 했다!!!!!!!! 

 

더 정확히 pool 의 상태를 알기 위해 찾다가 pool 의 상태를 알려주는게 있길래

적용을 시켜 봤다.

 

Monitoring the status of a pool

If you want to know about the status of the pool, use the getStatus method. The result of method consists of 4 values(all, use, idle, queue).

var status = pool.getStatus();
console.log('All connected connections : %d', status.all);
console.log('Connections being used : %d', status.use);
console.log('Idle connections : %d', status.idle);
console.log('Queued requests : %d', status.queue);

 

mysql-pool-booster 에서 모니터링을 할려면 Pool 에 대한 status 값을 가져 와야 되는데

어떤건 찍히고 어떤건 안찍히는 현상(pool.getStatus() == undefine)이 발견되었다.

 

확인해보니

잘 나오는 pool 은 그냥 원본 pool 을 가져오는 거고

잘 안나오는 건 poolCluster 를 통해서 pool 을 가져온게 다른점이었다. 

왜 다른가 봤더니 pool 을 직접 만든것과 poolCluster 를 통해서 얻는 pool의 상태가 서로 달랐다.

• pool 을 직접 만든 구현체

• poolCluster에서 가져온 pool

query를 날릴수 있는 함수는 둘 다 있는데 poolCluster (정확히 말하자면 PoolNamespace)에서는

status 값을 가져 올수 없어서 알 수 없었다.

그래서 poolCluster 사용하던것을 제거 하고 pool로 바꿔서 테스트를 진행 했다.

이게 왜 서로 다른건지 자바스크립트 엔진 관점에서 이해하기 힘들면 당신도 아래 글을 읽어야 한다!!!! 

자바스크립트 event loop와 scope chain 이해

 

pool 동작 방식 확인 해보기

 

async 모듈에서 설정한 concurrency 갯수 = 50

어플리케이션에서 설정한 connectionLimit 갯수 = 5

실제 요청하는 갯수 = 30

maxIdle = 10

 

정상적인 상황

All connected connections : 5
Connections being used : 5
Idle connections : 0
Queued requests : 26

• 기본으로 db 커넥트 하는 개수 1개
• concurrency 는 50이지만 요청하는 총 개수는 30개
• connected connections 은 설정한 connetionLimit 와 같음.
• 사용중인 connection 은 5개, connection 을 갖지못해서 대기하는 큐 26개

All connected connections : 5
Connections being used : 5
Idle connections : 0
Queued requests : 25

• Connections 에서 처리가 하나가 되고 queue에서 기다리고 있던 request 가 하나 빠지고 connection으로 들어감
• connection은 그대로 request는 하나 줄어듬

All connected connections : 5
Connections being used : 5
Idle connections : 0
Queued requests : 0

All connected connections : 5
Connections being used : 4
Idle connections : 1
Queued requests : 0

• queue 에서 기다리고 있던게 다 빠지게 되면 connection은 더이상 쓰이지 않기 때문에 pool 에 반환 하기 때문에 Connections being used 가 5→4로 줄어 들게됨.
• 남은 Connection 은 pool 에 유후 상태로 반환하게 되서 Idle connections 개수가 올라감

All connected connections : 5
Connections being used : 0
Idle connections : 5
Queued requests : 0

• 쿼리가 다 실행이 된다면 used 되는 connection 은 다 실행이 되어서 pool에 Idle 상태로 들어감

 

문제가 되는 상황

async.concurrency = 50

connectionLimit = 10 → 20

동시에 요청하는 개수 = 30

maxIdle = 10

All connected connections : 20
Connections being used : 20
Idle connections : 0
Queued requests : 11

All connected connections : 20
Connections being used : 10
Idle connections : 10
Queued requests : 0

• 위와 같은 동작으로 Queued requests 가 11개 있고 connected connections 은 설정한 connetionLimit 와 같아서 20으로 되어있음.
• queued request가 다 빠지게 되고 connection 은 20개에서 사용되고 다 처리되서 idle 상태로 10개가 넘어감.

All connected connections : 20
Connections being used : 9
Idle connections : 10
Queued requests : 0

• Connections being used 가 줄었으니 Idle connections 이 증가해야하는 상황
• 하지만 증가되지 않음!
• 이유는! maxIdle 설정값이 10으로 세팅되어 있기 때문

그래서 위에서 aborted client가 10 증가된건 (20 - 50 : client 10 증가 )

connections 의 갯수(20개)가 maxIdle(10개) 보다 더 커서 10(20-10)이 증가 되었다.

정리 하자면 중요하니깐 3번 읽자 

1. 동시에 30개가 요청이 와서 최대로 맺을수 있는 20개의 connection이 연결 되고 queue에는 나머지 connection이 쌓인다.
2. queue에 있는게 빠지면서 queue에 있는게 다 처리된다.
3. Connections being used 에서 처리 되면서 한개씩 빠지면서 처리한 connection 은 Pool 로 들어간다(idle connection 증가)
4. idle connection 이 max idle 까지 도달하게 되면, 사용된 커넥션은 pool 로 들어가는게 아니라 aborted client로 되어서 해당 value 가 증가 되게 된다.

결론 : connectionLimit =< max Idle 으로 설정해야 된다!!!