[바미] 인덱스가 불러 일으킨 커다란 해프닝

시작

안녕하세요. 때는 저 저번주에 있었던 일입니다. 

 

기존에 온프라미스 환경에서 서비스중인 프로젝트의 버전을 구 버전에서 신 버전으로 업데이트 해야하는 일이 있었습니다. 

당연히 신버전은 DB 테이블도 달랐기 때문에 항상 최신 DB를 유지하고 있는 개발서버의 DB스키마를 덤프떠서 작업하려 했습니다.

에러 발생...

코드 최신화 후 덤프 띄운 DB도 적용시킨 뒤에 프로젝트를 재시작 시켰는데...

기존에 5분마다 돌고 있던 로직부분에서 Lock wait timeout exceeded; try restarting transaction 에러 문제가 발생하게 되었습니다.

 

처음에는 '또 DB 커넥션 풀에서 문제가 발생했구나'라고 생각했습니다. 왜냐하면 이전에도 비슷한 형태로 발생한 일이 있었는데 그 때는 커넥션 풀에서 발생했던 문제였었기 때문이죠.

 

범인은 커넥션 풀?

그래서 처음에 봤던 것은 커넥션 풀을 검사하게 되었습니다.

   const poolState = {
            total: sequelize.connectionManager.pool.size || 0,
            available: sequelize.connectionManager.pool.available || 0,
            using: sequelize.connectionManager.pool.borrowed || 0,
            pending: sequelize.connectionManager.pool.pending || 0,
        };
        logger.info("Connection Pool State:", poolState);

이런 형태로 커넥션 풀을 출력 할 준비를 하고

info: Connection Pool State: { total: 5, available: 3, using: 2, pending: 0 }

이런 형태의 출력 값을 보면서 커넥션 풀을 제대로 쓰고 해제하고 있는지, 또 허용시킨 커넥션 풀보다 더 많은 커넥션 풀을 일으키는 게 아닌건지 확인하게 되었죠..

 

하지만 커넥션 풀에서는 별다른 문제가 보이지 않았습니다. 정상적으로 연결하고, 해제하고 있었기 때문이죠.

 

이 과정에서 커넥션 풀의 max, min, acquire값을 아래와 같이 조정하면서 모니터링 했지만 별 다른 소득은 없었습니다.

 pool: {
        max: 10, // 최대 커넥션 수
        min: 0,  // 최소 커넥션 수
        acquire: 30000, // 커넥션 획득 대기 시간 (밀리초)
        idle: 10000, // 커넥션이 유휴 상태로 유지되는 최대 시간 (밀리초)
    }

---

그럼 새롭게 추가된 로직이 범인인가?

업데이트된 버젼에서 기존 로직이 시작되기 전에 추가된 함수들이 있습니다. 

try {
	if (조건) {
 	
         ... 중략
         await aService.function();
         await bService.function();
       
         await Afunction();
        ...	중략
  	
	} else {
    	// 조건에 맞지 않은 경우 처리
	}
} catch (err) {
    // 에러 처리
} finally {
	// 실행완료 상태
	this.run = false;
}

 

5분 마다 돌아가는 함수 내부의 모습이 대략 이런 형태로 이루어져 있고, aService.function()과 bService.function()은 새롭게 추가 되었던 함수이고,Afunction()이 문제가 발생했던 함수입니다.

 

이전에 커넥션 풀 모니터링할 때 aService.function() 함수에서 특히 커넥션 풀이 빈번하게 발생하다 보니 혹시 이 부분 때문에서 문제가 발생한 게 아닌가 싶었습니다.

 

실제로 DB에서 SHOW PROCESSLIST;를 확인했을 때, Afunction()에서 실행하는 쿼리가 무한정 대기 상태에 놓여 있었기 때문에 aService.function()  함수에서 커넥션 풀이 정상적으로 반환되지 않아, 최대치에 도달한 상태에서 Afunction()이 커넥션 풀을 확보하려고 대기하면서 문제가 발생한 것으로 의심하게 되었습니다.

 

그래서  aService.function()를 주석처리 후 시도를 했지만 여전히 문제가 발생하여 이 전에 먼저 실행했었던 함수 때문에 발생한 문제가 아닌 것을 확인하였습니다.

---

그럼 실행한 쿼리는 정상적인가?

커넥션 풀도 아니고,  함수도 아니라고 판단되었을 때 갑자기 하나의 생각이 스쳐 지나갑니다.

 

이 함수가 실행하려는 쿼리는 문제가 없는건가?

그래서 쿼리를 log로 출력한 뒤 쿼리를 실행해보았습니다. 

 

하지만 정상 실행되는 걸 보고 제 머리속은 혼돈 그 자체 였습니다.

 

쿼리도 정상적으로 동작해.. 커넥션 풀 조정해도 안 돼..  함수 없애도 안 돼.. 뭐가 문제인 지 제 머릿속은 너무 복잡해지기 시작했습니다.

---

도대체 범인은 누구인가?

시퀄라이즈 처리 부분인가?

그러다 한 분이 저에게 의견을 제시합니다. 시퀄라이즈 쿼리를 처리하는 부분에서 문제가 발생한 게 아니냐?

 

이 말이 무슨말이냐? 시퀄라이즈 쿼리를 처리하는 로직은 아래와 같습니다.

  result = await sequelize.query(

            cmd,
            {
                replacements: params,
                type: Sequelize.QueryTypes.SELECT
            }
        );
        return result;

여기 보이는 type에서 SELECT로 되어있는데 이 부분에서 처리하는 쿼리는 SELECT도 있지만 INSERT, DELETE 형태의 쿼리도 있어 type에 맞지 않는 부분을 처리했을 때 어떤 일이 일어나는 건지 의견을 내며, 그렇게 지옥의 시퀄라이즈 코드 까보기가 시작되었습니다.  

 

확인해보니 SELECT 일 땐 map으로 return 해주지만 SELECT가 아닐 때는 각 형태에 맞게 return하도록 되어 있더군요.

그럼에도 각 쿼리의 type에 맞게 처리되도록 변경해보라 해서 반신반의 하며 변경해보았지만 역시 이 부분도 아니였습니다.

 

다른 서버와 비교해보자..

이것도 저것도 시도해보았지만 여전히 풀리지 않아 마이그레이션 하려는 환경과 동일한 환경이 타 서버에 구축이 되어있어서 이 부분들을 확인해보았습니다.

 

Afunction()에서 처리하는 데이터의 형태는 시간, 날짜 별로 처리하는 함수입니다. 그러니까 5분, 15분, 1시간 단위, 하루,  달, 등등 별로 데이터를 집계처리 해주는 함수인데  이 중에서 1시간치의 데이터를 저장하는 테이블에서 락이 걸려 이를 두 곳에서 같이 진행해보았습니다. 참고로 데이터를 저장할 때 INSERT INTO ... ON DUPLICATE KEY UPDATE 문을 사용합니다.

 

A 서버는 바로 INSERT 되었는데 문제가 발생한 B서버는 실행하는데 허용된 innodb_lock_wait_timeout이 초과되는 것을 확인하게 되었습니다.

---

찾았다 요 놈!

이제 한 줄기 빛이 보이기 시작했습니다. 문제는 저 테이블에서 데이터를 추가할 때 발생했던 문제였었습니다.

 

그래서 인덱스가 제대로 설정되어 있지 않나 싶어서 해당 테이블과 해당 테이블을 Join하고 있는 테이블의 인덱스를 확인하였습니다.

SHOW INDEX FROM <table>

A 서버는 인덱스의 CARDINALITY가 정상적으로 표시되는 반면 B 서버는 조인되는 테이블 인덱스의 CARDINALITY가 0으로 뜨는 것을 확인하였습니다.

 

이는 B서버의 옵티마이저가 인덱스 통계가 오래되었거나, 데이터 변경 후 갱신되지 않아 조인하는 테이블에 행이 없다고 잘못 판단 할 수 있어 잘못된 실행 계획을 가지고 쿼리를 실행하여 발생된 원인 일 수 있겠다고 생각이 들었습니다.

 

그래서 INSERT 구문에 EXPLAIN을 추가하여 실행 계획을 살펴보게 되었는데  결과는 아래와 같습니다.

 

A 서버

id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	PRIMARY		ALL					1598	Using where
2	DERIVED	S	range	PRIMARY,idx_<table>_idx	PRIMARY	8		1598	Using where; Using temporary
2	DERIVED	P	eq_ref	PRIMARY	PRIMARY	4	idx	1	Using where

 

B 서버

id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	PRIMARY		ALL					386	Using where
2	DERIVED	P	ALL	PRIMARY				1	Using where; Using temporary
2	DERIVED	S	ref	PRIMARY,idx_<table>_idx	idx_<table>_idx	4	idx	386	Using index condition

 

A 서버에서 테이블 S에서는 range 검색이 수행되고 있어 약 1,598건의 데이터를 효율적으로 처리하고 있었고, 테이블 P는 eq_ref 방식으로 PRIMARY KEY를 적절하게 활용하여 정확히 1건만 매칭하는 형태로 최적화가 잘 되고 있는 것을 볼 수 있고,

 

B서버의 경우 실행 계획이 최적화되지 않은 상태로 볼 수 있는데 먼저, 테이블 P는 ALL(풀 테이블 스캔) 방식으로 처리되면서 인덱스를 활용하지 못하는 문제가 발생하고 있었습니다.

이로 인해 불필요한 데이터 검색이 많아지고, 쿼리 실행 시간이 증가하게 되었죠.

 

또한, 테이블 S는 ref 방식으로 약 386건을 처리하고 있으며, 상대적으로 더 많은 데이터를 읽고 있는 상태였습니다.

특히, P.ptIdx = S.ptIdx 조건이 B 서버에서는 eq_ref 방식으로 최적화되지 않아, A 서버보다 실행 성능이 떨어지는 원인이 되었죠.

 

결과적으로 B 서버에서는 테이블 P의 인덱스가 적절히 활용되지 않음으로 인해 실행 계획이 비효율적이며, 이에 대한 인덱스 튜닝 또는 실행 계획 최적화 필요한 상태가 된 것이죠.

---

어떻게 해결하였는가?

이를 위해 ANALYZE TABLE을 활용하여 테이블의 인덱스와 통계를 갱신시켰습니다.

ANALYZE 테이블명;

이런식으로 사용 할 수 있습니다. 

 

이후 아래와 같이 쿼리 실행 계획이 변경되었고

id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	PRIMARY		ALL					1598	Using where
2	DERIVED	S	range	PRIMARY,idx_<table>_idx	PRIMARY	8		1598	Using where; Using temporary
2	DERIVED	P	eq_ref	PRIMARY	PRIMARY	4	idx	1	Using where

정상적으로 처리되는 것을 지금까지 확인한 상태입니다.

 

마치며..

제가 이 오류를 해결하기 위해 1주일을 야근하며 힘들게 찾았는데 원인은 단, 그깟 인덱스 때문이였습니다.

그 인덱스, 인덱스, 인덱스 때문에 수 많은 삽질과 시간을 들인게 조금 허무하네요.

 

그래도 새로운 경험을 얻었으니 그걸로 만족하려 합니다.