문제 발생

운영 중인 서버가 장애를 일으켰다. 로그를 우선 따와서 파악해보았다.

아래와 같은 로그를 볼 수 있었다.

Dec 20 03:02:44 ip-10-0-6-10 
	web: {
    	"context":"ExceptionsHandler",
        "level":"error",
        "message":"\nInvalid `prisma.tenant.findUnique()` invocation:\n\n\nTimed out fetching a new connection from the connection pool. More info: http://pris.ly/d/connection-pool (Current connection pool timeout: 10, connection limit: 5)",
        "stack":[
        	"Error: \nInvalid `prisma.tenant.findUnique()` invocation:\n\n\nTimed out fetching a new connection from the connection pool. More info: http://pris.ly/d/connection-pool (Current connection pool timeout: 10, connection limit: 5)\n    
            	at Zr.handleRequestError (/var/app/current/node_modules/@prisma/client/runtime/library.js:171:6414)\n    
                at Zr.handleAndLogRequestError (/var/app/current/node_modules/@prisma/client/runtime/library.js:171:5948)\n    
                at Zr.request (/var/app/current/node_modules/@prisma/client/runtime/library.js:171:5786)\n    
                at PrismaService._request (/var/app/current/node_modules/@prisma/client/runtime/library.js:174:10455)\n   
                at TenantService.findTenantByNameOrThrow (/var/app/current/src/tenant/tenant.service.ts:27:20)\n    
                at MiddlewareHost.use (/var/app/current/src/global-middleware.ts:15:20)\n    
                at /var/app/current/node_modules/@nestjs/core/router/router-proxy.js:9:17"
        ]}

이 로그는 데이터베이스와의 커넥션 풀이 가득 차서, 새로운 커넥션을 fetching 하는데 timeout 이 발생했다는 것이다.
그리고 현재 데이터베이스 커넥션 풀의 설정은 timout: 10초, connection limit: 5개라고 나타낸다.

이 로그만 보고 나는 처음에 다음과 같이 설정했다.

데이터베이스 커넥션 풀 조건을 수정해야겠다! timeout 을 늘려야 하나? connnection limit 을 늘려야 하나?

하지만 이는 잘못된 사고의 흐름이었다.
우리는 원인을 파악해서 수정해야한다. 단순히 지금 발생하는 현상을 뒤덮고 가는 사람들이 아니다.

물론 나는 처음에 데이터베이스 커넥션 풀 설정 자체가 원인이라고 생각했기 때문에 이를 수정해야 한다고 생각했던 것이다.
우리가 생각해야 할 것은 무엇이 데이터베이스 커넥션을 놓치 않고 있는지, 무엇이 타임아웃을 발생시키는지를 봐야한다. 그게 조금 더 근본적인 원인을 수정하는 방향에 가깝다.

원인 파악

그럼 우리는 이 문제의 원인을 어디서 찾을 수 있었을까?
어떤 쿼리가 문제를 발생하고 있는지 어떻게 찾았을까?
AWS의 RDS의 성능개선도우미를 활용하여 문제를 발견하였다.

우선 당시 RDS 의 권장사항 탭에 들어가니, RDS가 이미 여러번 소리치고 있었다. 나 죽어 ~

요롷게 자세히 알려주고 있다. 아 데이터베이스에 지금 과부하가 걸렸구나. 원인도 알려준다.
View Top SQL in Performance Insights 탭에 들어가면 성능개선도우미탭으로 이동되는데, 여기서 문제가 되는 쿼리를 확인할 수 있다.

요놈 자식이 문제였다. SELECT 조건문이 문제였고, 우리는 인덱싱을 통해 해결했다.

인덱싱

데이터베이스에 대해 생각해보자.
데이터베이스는 데이터를 관리하는 곳이다.
데이터는 계속해서 쌓일 것이다. 데이터가 계속해서 쌓이면 성능면에서 문제가 발생할 것임을 우리는 알고 있다. 데이터베이스를 한 번이라도 공부했다면.
나도 분명 알고 있었다.
하지만 이 현상과 그 생각이 연결이 되지 않았던 것이다.
데이터가 지속해서 쌓이면 어떤 성능에서 문제를 일으킬까? 바로 조회 부분이다.

수많은 데이터가 쌓인 상태에서 특정 조건에 해당하는 데이터들을 가져오려면, 무조건 전범위 탐색이 이루어진다.
찾고자 하는 데이터가 어디에 있는지 데이터베이스는 모른다. 그러니까 처음부터 모든 데이터를 조회할 수 밖에 없다.
그래서 우리는 그걸 쉽게 하도록 도와주는 목차를 설정해야한다. 그것이 데이터베이스 입장에서는 인덱스인 것이다.

이 문제는 이처럼 단순히 해당 테이블에 인덱스를 추가하는 것으로 수정이 되었다.
물론 테스트 데이터베이스에 우선 적용해서 쿼리 실행을 분석하고 (postgresql 의 explain analyze) 인덱스 추가 전과 후의 결과를 비교하였다.

후기

정확한 데이터나 지표를 보지 않고서 문제를 해결하고자 한다면 실수를 범하거나, 이상한 부분을 고치느라 삽질을 하거나, 당장은 수정한 것처럼 보여도 추후에 문제가 재발할 수 있다.

나는 로그를 바탕으로, 데이터베이스 커넥션에 문제가 있구나! 하고 데이터베이스의 커넥션을 원인이라고 판별했다.
엄청 아주 잘못된 방향은 아니었겠지만, 조금 더 깊게 파고들어갈 필요가 있었다.
무엇이 데이터베이스 커넥션을 잡고 있지? 어떤 쿼리가 문제일까? 트랜잭션 처리하는데 오류가 있을까? 조회 쿼리에 인덱스가 안 걸려있나? 등의 생각으로 넓어질 수 있었다면 좋았을 것이다.

물론 그런 경험이 없었으니까, 내가 생각을 넓힐 리소스 조차 없었다고 변명할 수 있겠다.
이번 경험을 토대로 내 생각의 범위가 넓어지기를 바랄 뿐이다.

만약 데이터베이스 커넥션 설정만 수정해 임시조치를 해두었다면, 분명 지금까지도 주기적으로 문제를 일으켰을 것이다.
또 언제까지고 커넥션 풀 설정을 늘릴 수 없기에 분명 장벽에 막히는 시점이 왔을 것이다.