mysql 커넥션 풀 오류 해결 과정

예전에 node.js express로 백엔드 개발을 진행한 적이 있었는데 그 당시 개발 중 발생했던 문제 상황에 대해서 기록을 남겨보려고 한다.

 

문제 개요

 

API 요청을 react native 앱에서 호출하여 사용하던 중이었는데 잘 동작하다가 어느 순간 버튼을 누르면 API 요청이 먹통이 되고 앱 자체가 무한 로딩에 걸린 것처럼 아무 기능이 되지 않는 문제가 발생했다.

 

이 문제는 뒤로 미루기엔 일단 아무 기능이 동작하지 않는 것이기 때문에 사용자 경험에 큰 영향을 미칠 뿐 아니라 서버에 심각한 오류를 가져올 수도 있었기에 다른 기능 개발보다도 우선적으로 해결할 필요가 있었다.

 

https://github.com/expressjs/morgan/issues/121

서버 로그를 확인해 보니 'GET / --ms--' 로그만 계속해서 찍히고 있었으며 다른 API는 요청과 응답에 대한 로그가 나오지 않는 것으로 보아 씹히고 있다는 사실을 확인할 수 있었다.

 

문제 분석

문제 자체는 요청을 보내다가 어느 순간부터 API가 먹통이 된다는 것이었으므로 그 “어느 순간”이 언제인지 알아내기 위해 postman을 통해 천천히 api를 계속해서 요청하면서 그 수를 카운팅해 보았다.

 

그랬더니 정확히 11번째부터 먹통이 되는 것을 확인할 수 있었다...! 다시 서버를 껐다 켠 다음 시도해도 정확히 11번째부터 먹통이 되는 것이었다.

 

이 말은 즉슨, 무엇인가 이 서버 안에 설정된 값에 의해(내가 설정한 게 아니더라도) 10번의 요청이후 API 요청을 받지 못하게 되었다는 것인데 어디서 문제가 생긴지를 모르니 코드를 계속해서 들여다 보았지만 원인을 찾지 못했었다.

 

이 때는 심지어 ChatGPT도 없을 때라 어디 물어볼 곳도 없이 구글 검색에만 의지해야 하는데 뭐가 문제인지도 모르니 뭐라고 검색해야 할 지도 몰라 한참 애를 먹었었다.

 

그런데 하나 더 확인할 수 있었던 사실은 앞서 말했듯 API 요청을 보냈을 때 서버에 로그가 찍히지 않다가 시간이 흐른 뒤에 'GET / --ms--' 라는 로그가 남아있다는 사실이었는데 뭔가 이것과 관련되어 찾다보면 해결방법이 나오지 않을까 하여 관련된 내용을 찾아보기 시작했고 한 글을 보게 된다.

 

https://stackoverflow.com/questions/29077355/what-does-get-bla-ms-mean-in-nodejs-console

위 스택오버플로우 글에 따르면 GET / --ms--는 개발 환경에서 흔히 볼 수 있는 형식으로 클라이언트가 서버에 요청을 보냈지만, 서버가 응답을 보내지 않은 상태에서 Node.js가 너무 오랫동안 아무 일도 일어나지 않았기 때문에 TCP 연결을 강제로 끊어버렸다는 것을 의미한다.

 

즉, 서버가 요청에 대한 응답을 줘야 하는데 주지 않고 너무 오랜 시간이 흘러 연결을 끊어버리면서 찍히는 로그였던 것이다.

 

그래서 timeout이 될만한 것이 무엇이 있을까 생각해 보다가 비즈니스 로직 자체에 막 몇 분씩 그렇게 오래 걸릴만한 부분이 없다고 생각했기 때문에 mysql 연결에 대해 의심을 해보았고 mysql과 관련된 내용을 찾아보았다.

 

MySQL 문서 중

node.js에서는 MySQL 데이터베이스와의 연결을 효율적으로 관리하기 위해 'mysql' 모듈이나 'mysql2' 모듈을 사용할 수 있다. 이 두 모듈 모두 데이터베이스 연결을 위한 연결 풀(connection pool)을 지원한다.

 

Connection Pool

connection pool은 여러 개의 데이터베이스 연결을 미리 생성해 두고, 필요할 때마다 새로 만드는 것이 아니라 만들어놓았던 연결을 재사용하는 방식을 위해 만들어진 개념이다.

 

이를 통해 각 요청마다 새로 연결을 생성해야 하는 오버헤드를 줄일 수 있고, 동시에 데이터베이스 연결 수를 직접 관리할 수 있게 된다. 이는 곧 데이터베이스 서버에 대한 부담을 줄일 수 있으며, 동시에 애플리케이션의 성능을 최적화하는 것으로 이어진다.

 

이러한 상황에서 중요한 것은 MySQL 모듈에서 기본적으로 connection pool을 관리하는 기능을 제공한다는 것이며, 해당 풀의 크기를 설정할 수 있는데 기본값(default)으로 정해진 풀의 크기가 10개라고 한다.(!!!)

 

이 10이라는 숫자를 보자마자 11번째 API 요청때부터 API가 먹통이 되는 것이 이것과 관련이 있을 것이라는 확신을 가질 수 있었다.

 

그런데 connection pool이 10개가 최대라고 해도 사용한 연결은 다시 재사용이 되어야 하는 건데 왜 11번째부터 API가 작동하지 않았던 것일까?

 

waitForConnections

mysql2 모듈에서 connection pool을 설정하는 예시 코드는 다음과 같다.

const mysql = require('mysql2');

const pool = mysql.createPool({
  host: 'localhost',
  user: 'root',
  database: 'test',
  waitForConnections: true,
  connectionLimit: 10,  // 기본 제한
  queueLimit: 0
});

 

위 코드에서 connectionLimit이 바로 풀에서 동시에 활성화될 수 있는 최대 연결 수를 정의하는 옵션이다.

 

그런데 waitForConnection이라는 옵션이 눈에 띈다.

 

waitForConnections 옵션은 true로 설정되어 있는 경우, 요청 자체가 연결이 사용 가능해질 때까지 대기하게 된다. 이 값 역시 true로 기본 설정되어 있다.

 

queue와 연결 대기

node.js 이벤트 큐와 비슷한 방식

waitForConnections 옵션이 활성화되어 있으면, 연결 풀이 최대 용량에 도달했을 때 추가 요청은 큐에 대기하게 된다. 이 대기 요청들은 기존 연결이 해제되면 순차적으로 처리되도록 되어있다.

 

waitForConnections: true,  // 대기 옵션 활성화
queueLimit: 0  // 대기열 제한 없음

 

위 코드에서 queueLimit이 0으로 설정되어 있는 경우, 대기열에 무한정으로 요청이 쌓일 수 있다. 하지만, 이 값을 양수로 설정하면 설정한 크기 이상의 대기열을 허용하지 않게 된다. 예를 들어, queueLimit: 50으로 설정하면, 대기열에는 최대 50개의 요청만 들어갈 수 있으며, 이보다 많은 요청이 발생하면 에러가 발생하게 된다.

 

그렇다면 해당 값이 0으로 설정되어 있는 경우에는 아무런 오류가 뜨지 않고 계속 해서 queue에 요청이 쌓이는 상황이 발생할 수 있다.

 

문제의 원인

커넥션 풀은 데이터베이스 요청을 한 번 처리하고 나면 다른 요청이 또 왔을 때 해당 커넥션을 사용할 수 있는 상태가 되어야 하는데 API의 요청이 끝났는데도 11번째 요청에 먹통이 된다는 것은 모든 커넥션에 대해 연결을 해제하는 부분이 제대로 동작하지 않았다는 것을 알 수 있었다.

 

MySQL에서 이 연결을 한 번 사용하고 해제하는 코드는 아래와 같다.

 

위 코드가 반드시 들어가야 connection이 해제가 된다.

 

원래 코드에서는 데이터베이스 트랜잭션을 위해 try catch문을 통해 데이터베이스 작업에 대한 코드를 감싸주었었는데 catch문에서는 release를 잘 해주었지만 작업이 성공하고 나서는 release를 해주지 않아 API가 응답을 마쳐도 연결 상태를 계속 유지하고 있어 10번의 요청에 성공하면 10개의 connection pool이 연결된 상태를 유지하고 있는 상황이 만들어졌던 것이다.

 

이러한 경우에는 try-catch 문 각각에 release를 호출할 필요 없이 finally 블럭을 사용하여 해당 부분에서 conneciton.release를 해주면 try 혹은 catch 이후에는  finally 코드가 반드시 실행되기 때문에 몇 줄의 코드만으로 연결 해제를 쉽게 해줄 수 있다.

 

정리

정리하자면 Node.js에서(뿐만 아니라 다른 프레임워크에서도) MySQL 모듈을 사용하여 데이터베이스와 연결을 관리할 때, 연결 풀을 사용하는 것은 일반적인 패턴인데, 연결 해제를 제대로 처리하지 않는 경우, 연결 풀이 가득 차서 새로운 요청이 처리되지 못하고 응답 시간이 길어지는 문제가 발생할 수 있게 된다.

 

데이터베이스에 연결이 된 상태에서 각 요청이 끝난 후 연결을 해제(connection.release())해 주지 않는 상황을 가정해보면, 연결 풀에 있는 연결이 점점 고갈되다가, 결국 모든 연결이 사용 중인 상태가 되어 추가적인 요청을 처리할 수 없는 상태에 돌입하게 된다.

 

이러한 문제가 발생하면, 정확히 그 순간부터 MySQL 쿼리를 동작하려는데 사용가능한 connection이 없어 connection이 주어지기를 기다리게 되고, Express app에서는 해당 API 요청을 처리하는 데 지연이 발생하게 되어, 특히 express 서버의 응답 대기 시간이 길어지게 되면서 API가 사실상 먹통이 되는 상황이 초래되는 것이다.

 

내 상황에서는 연결 풀의 크기를 지정해주지 않았기 때문에 크기가 10으로 설정되었는데, 처음 10개의 요청은 정상적으로 처리되지만, 요청이 끝난 후 연결을 해제하지 않으면 연결 풀이 가득 차게 되었다. 이 시점에서 11번째 요청이 들어오면 새로운 연결을 할 수 없게 되어, 그 이후에 들어온 요청들은 연결 풀에서 연결에 해제되기만을 무한정 대기하게 된다.

 

이 대기 상태가 계속되면, 결국 응답 시간이 길어지게 되면서 timeout이 결국 발생해 로그에는 요청이 처리되지 않고 대기 중이거나 타임아웃으로 인해 응답을 받지 못한 상태를 의미하는 GET / --ms--가 찍히게 되었던 것이다.

 

 

추가적으로 mysql 모듈을 뜯어보면 위와 같이 정의된 세 개의 상수가 있는데 각각 네트워크 연결 시도에 대한 시간을 제어하는 데 사용되는 상수이다.

 

• CHECK_INTERVAL_MS (200ms):
  • 이 상수는 next 함수에서 연결 시도가 실패했을 때, 다음 연결 시도를 하기 전에 대기하는 시간 간격을 밀리초 단위로 나타낸다.
  • 즉, 서버에 연결할 수 없을 때, 200ms 후에 다시 연결을 시도하게 된다.
• CHECK_TIMEOUT (1200000ms, 120초)
  • 이 상수는 전체 연결 시도가 제한된 시간 내에 성공하지 못할 경우, 프로그램이 실패로 종료되도록 하는 타임아웃 시간을 설정한다.
  • 2분 동안 연결에 성공하지 못하면 process.exit(1)로 프로그램이 종료되도록 설계되어 있다.
• TCP_TIMEOUT (1000ms, 1초)
  • 이 상수는 각 개별 연결 시도에 대해 응답을 기다리는 최대 시간을 설정한다.
  • 서버에 연결 시도 후 1초 이내에 응답을 받지 못하면, 해당 연결 시도를 실패로 간주하고 소켓을 닫고 callback(false)를 호출하여 실패로 처리한다.

그래서 아마 추측컨데, 2분 동안 기다리는 MySQL 설정보다 express(혹은 node.js 혹은 morgan 혹은 nginx)에서 설정된 timeout이 짧게 설정되어 해당 시간이 지났을 때 GET / --ms-- 와 같은 로그가 찍히지 않았을까 생각해본다.

 

Node.js HTTP 모듈에 설정된 timeout 값

https://nodejs.org/dist/latest-v6.x/docs/api/http.html#http_server_settimeout_msecs_callback

HTTP | Node.js v6.17.1 Documentation

Node.js 문서에 따르면 HTTP 서버에는 타임아웃과 관련되어 설정이 존재한다.

 

sever.headersTimeout

• 기본값: 40000(40초)
• HTTP 헤더 전체를 수신하는 데 허용되는 최대 시간(ms 단위)을 설정한다. 즉, 서버가 HTTP 요청의 헤더를 모두 수신할 때까지 기다리는 시간 제한을 지정한다.
• 만약 비활성 상태라면, [server.timeout]에 정의된 규칙이 적용된다. 하지만 이 비활성 상태 기반의 타임아웃은 헤더가 매우 천천히 전송되는 경우에도 연결을 유지할 수 있도록 허용한다(기본적으로 2분당 1바이트).
• 이를 방지하기 위해, 헤더 데이터가 도착할 때마다 연결이 설정된 이후 server.headersTimeout 밀리초가 넘지 않았는지 추가로 확인한다. 이 확인이 실패하면 'timeout' 이벤트가 서버 객체에서 발생하며, 기본적으로 소켓이 파괴된다.
• 이 설정은 서버가 클라이언트로부터 헤더를 수신하는 데 시간이 너무 오래 걸릴 경우, 연결을 종료시키는 역할을 한다. 이는 서버가 오래 걸리는 클라이언트를 기다리며 리소스를 낭비하지 않도록 할 수 있다.

 

server.timeout

• 기본값: 120000(2분)
• 소켓이 비활성 상태로 간주되기까지의 시간(ms단위)을 설정한다. 즉, 서버가 클라이언트로부터 아무런 데이터도 받지 못할 때까지 기다리는 시간이다. 값이 0으로 설정되면, 수신 연결에 대한 타임아웃 동작이 비활성화된다.
• 소켓 타임아웃 로직은 연결 시점에 설정되므로, 이 값을 변경해도 기존 연결에는 영향을 주지 않으며, 새로운 연결에만 적용된다.
• 이 설정은 서버가 데이터를 주고받지 않는 소켓 연결을 일정 시간 이후에 자동으로 종료시키는 역할을 한다. 이로 인해, 불필요한 연결이 서버에 부담을 주지 않도록 관리할 수 있다.

 

server.keepAliveTimeout

• 기본값: 5000(5초)
• 서버가 마지막 응답을 작성한 후, 추가적인 데이터가 수신되기까지 기다리는 시간(ms단위)을 설정한다. 이 시간 동안 추가적인 데이터가 수신되지 않으면 소켓이 파괴된다. 만약 서버가 새 데이터를 keep-alive 타임아웃이 발생하기 전에 수신하면, 기존의 비활성 타임아웃(즉, 'server.timeout')이 리셋된다. 값이 0으로 설정되면, 수신 연결에 대한 keep-alive 타입아웃 동작이 비활성화된다.
• 소켓 타입아웃 로직은 연결 시점에 설정되므로, 이 값을 변경해도 기존 연결에는 영향을 주지 않으며, 새로운 연결에만 적용된다.
• 이 설정은 HTTP Keep-Alive 연결에 적용되며, 마지막 응답 후 추가적인 요청을 대기하는 시간을 제어한다. 이로 인해, 오래된 연결이 서버에 부담을 주지 않도록 관리할 수 있다.

 

결국, MySQL 커넥션 풀 문제로 인해 Express 서버에서 응답이 지연되어 위와 같은 timeout에 걸리게 되었고, 일정 시간이 지나 자동으로 TCP 연결이 종료되면서, 이로 인해 클라이언트는 응답을 받지 못하고, 서버에서는 타임아웃 관련 로그를 남기게 된 것으로 마무리할 수 있을 것 같다.