DB Connection 정리

문제 발견

주말마다 운영중인 서버의 응답이 느려지다 결국 먹통이 되는 문제가 있었다.

서버를 재시작하면 다시 정상적으로 동작했다.

 

원인 파악

메모리, CPU, DB의 상태를 살펴봤지만 모두 잘 동작하는 것 같았다. 로그를 분석해봐도 원인을 쉽게 찾을 수 없었다.

당장 해당 이슈를 해결할 수 없을 것 같아 이 문제를 뒤로하고 몇일이 흘렀는데 어느날 평일에 같은 문제가 발생하였다. 그래서 우선 서버를 재시작하고 원인을 찾기 위해 RDS의 모니터링 항목을 살펴보던 중에 DatabaseConnections의 그래프에서 특이점을 발견했다.

위 그래프에서와 같이 서버를 재시작한 시점의 커넥션 수가 갑자기 뚝 떨어져 있는 것이었다. 게다가 특정 시간마다 커넥션의 개수가 상승해서 다시 줄어들지 않는 것이 이상했다.

 

그래서 우선 SELECT * FROM pg_stat_activity 를 통해 실제 DB의 현재 활성화된 세션을 확인했다.

보이는 것과 같이 현재보다 한참 이른 시간에 발생한 여러 개의 동일한 쿼리를 확인할 수 있다.

 

다음으로 해당 시점의 로그를 확인하여 문제가 되는 쿼리를 실행하는 코드를 찾아갔다.

const query1 = 'SELECT * FROM example1';
await pool.query(query1);
for (let i = 0; i < 4; i++) {
    const client = await pool.connect();
    const query2 = 'SELECT * FROM example2';
    await pool.query(query2);
    if (i === 1) {
        try {
            await client.query('BEGIN');
            // ... 로직
            await client.query('COMMIT');
        } catch (err) {
            await client.query('ROLLBACK');
        } finally {
            client.release();
        }
    }
}

문제를 설명하기 위해 단순하게 작성한 예시 코드다.

 

이 코드의 문제점으로는

const client = await pool.connect();

클라이언트를 획득하여 사용을 완료하면

client.release();

항상 풀로 반환해서 다른 클라이언트에서도 사용할 수 있도록 해줘야 한다.

하지만 지금은 <i === 1>의 조건에서만 반환해주고 있다.

 

이로 인해 사용 가능한 커넥션 수가 감소하여 서버 응답이 느려지다가 결국 설정된 커넥션 개수 한도를 초과하여 새로운 요청은 쿼리를 실행할 수 있는 커넥션이 없어서 무한히 대기하는 문제가 발생하게 된 것이다.

그런데 유독 주말마다 해당 문제가 발생한 이유는, 평일에는 주로 배포를 진행하면서 서버를 재시작하기 때문에 연결된 커넥션 개수가 줄어들게 되었기 때문이다.

 

원인 분석

 

이렇게 원인을 발견하고 문제를 해결할 수 있게 되었지만 한가지 의문이 들었다.

이 사진은 실제로 예제 코드를 실행후 SELECT * FROM pg_stat_activity 를 통해 확인할 수 있는 현재 실행중인 쿼리인데 SELECT * FROM example1 쿼리는 pool.query()를 사용했는데 커넥션이 유지되고 있었다는게 이상했다.

PG의 공식문서를 확인하면 pool.query()는 내부적으로 클라이언트(커넥션)를 획득 및 해제를 하고 있기 때문에 코드상에서 직접 해제할 필요가 없다.
https://node-postgres.com/apis/pool#poolquery

 

그래서 내부적으로 어떻게 동작하는지가 궁금해 각 쿼리마다 사용하는 커넥션을 알 수 있도록 로그를 남겼고 답을 얻을 수 있었다.

위 그림에서 원은 하나의 client를 의미하고 안의 알파벳을 통해 사용한 client를 알 수 있다.

아래쪽의 client는 순서대로 release를 하지 않은 것이고, 현재 커넥션의 상태에서 보이는 실행쿼리와 매칭된다.

(a는 SELECT * FROM example1, 나머지도 차례대로 일치)

pool 큐는 client가 들어오고 나온 순서를 기록해두었다.

 

정리하자면, pool.query()를 통해 사용이 끝난 client가 release 되어 큐에 들어가게 되고 다음으로 해당 client를 사용하는 곳에서 client를 사용 후 해제하지 않아서 해당 커넥션에서 마지막으로 실행한 쿼리인 SELECT * FROM example1  이 보이는 것이다.

const query1 = 'SELECT * FROM example1';
await pool.query(query1); // 쿼리 실행 후 커넥션 반납
// 반납된 커넥션 큐에 추가됨
for (let i = 0; i < 4; i++) {
    const client = await pool.connect(); // 큐에 들어있는 위에서 반납한 커넥션 사용
    // 커넥션 반납하지 않음
	...

코드 흐름은 이와 같다.