어쩌다 DB Index를 잡았는가?
Datadog 으로 모니터링을 하고 있는 어느 날
예상치도 못하게 로그인 관련 된 서비스들이 매우 느리다는 것을 알게되었다.
뭔가 기대했던 시간은 p50 기준으로 1,000ms 미만으로 나와야 하는데 해당하는 부분들이 초과하는 경우도 있었고
또 외부 소셜 인증의 경우에도 다른 외부 API 와 통신을 한다해도 기대밖의 성능이었다.
그렇게 Datadog 을 통해서 확인을 해보니 서비스 로직에서는 큰 문제는 없었는데 query를 통해서 조회를 할 때 너무 느리게 돌아가는 query 두개가 있었다.
하나는 프로젝트에서 사용하는 라이브러리 중 django-allauth 라는 라이브러리를 소셜 인증을 위해서 사용하는데 버전을 최근에 업데이트 하면서 생긴 것이었고 auth_user 에 username 을 upper 로 해서 조회를 하는 형태였다.
select username from auth_user where upper(username) = ?;
또 하나는 회원 관련해서 email의 대소문자에 대해서 정책이 없다가 생겨서 대소문자를 일괄 lowercase 로 변경해서 동일한 이메일이 있는 경우 회원가입 혹은 로그인시 해당하는 조회문을 타도록 변경을 했다.
select email from auth_user where lower(email) = ?;
이렇게 하다보니 이 부분에서 느려지는 케이스가 발견이 되었다.
1,195,056개(auth_user)의 row와 aws rds(db.t3.micro 기준) 실행계획을 보면 아래와 같은데 로 해서 아래와 같이 나왔다.
1. upper(username)
Gather (cost=1000.00..26955.60 rows=5975 width=77) (actual time=1029.396..1053.934 rows=0 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Seq Scan on auth_user (cost=0.00..25358.10 rows=2490 width=77) (actual time=1022.923..1023.124 rows=0 loops=3)
" Filter: (upper((username)::text) = 'testcase'::text)"
Rows Removed by Filter: 398353
Planning Time: 0.098 ms
Execution Time: 1053.982 ms
2. lower(email)
Gather (cost=1000.00..26955.60 rows=5975 width=77) (actual time=973.819..977.112 rows=0 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Seq Scan on auth_user (cost=0.00..25358.10 rows=2490 width=77) (actual time=962.838..962.840 rows=0 loops=3)
" Filter: (lower((email)::text) = 'test@email.com'::text)"
Rows Removed by Filter: 398353
Planning Time: 0.096 ms
Execution Time: 977.167 ms
그래서 해당하는 케이스를 index를 잡았다.
create index auth_user_idx_username_upper on auth_user ((upper(username));
create index auth_user_idx_email_lower on auth_user ((lower(email));
그리고 결과는
1. upper(username)
Bitmap Heap Scan on auth_user (cost=114.73..16303.61 rows=5975 width=77) (actual time=2.277..2.278 rows=0 loops=1)
" Recheck Cond: (upper((username)::text) = 'testcase'::text)"
-> Bitmap Index Scan on auth_user_username_upper_idx (cost=0.00..113.24 rows=5975 width=0) (actual time=2.275..2.275 rows=0 loops=1)
" Index Cond: (upper((username)::text) = 'testcase'::text)"
Planning Time: 1.133 ms
Execution Time: 2.327 ms
2. lower(email)
Bitmap Heap Scan on auth_user (cost=114.73..16303.61 rows=5975 width=77) (actual time=2.395..2.396 rows=0 loops=1)
" Recheck Cond: (lower((email)::text) = 'test@email.com'::text)"
-> Bitmap Index Scan on auth_user_email_lower_idx (cost=0.00..113.24 rows=5975 width=0) (actual time=2.393..2.394 rows=0 loops=1)
" Index Cond: (lower((email)::text) = 'test@email.com'::text)"
Planning Time: 0.110 ms
Execution Time: 2.428 ms
실행시간으로만 놓고보면 1/500 으로 시간이 줄었다. 코스트도 기존에는 최소 기준으로 약 10배에서 최대 기준 2배로 줄었다는 것을 볼 수 있다.
실제 운영 DB에서는 성능이 더 뛰어나서 저 정도의 실행 속도는 아니었지만 일단 느렸다.
그리고 적용이후에는 확실히 원하는 만큼의 퍼포먼스가 나왔다.
처음에는 그냥 너무 느리기도 하고 case가 복잡하지 않으니 그냥 index 를 만들어야지라는 생각이였다.
그래서 실행계획도 안보고 할 생각이였다.
그런데 최근 slow query 를 잡는다고 실행계획을 계속 보고 있으니 얼마나 개선이 되어지는 지 궁금했고
한번 전/후 를 비교해보자라고 했는데 솔직히 이정도로 개선이 되어질거라고 생각을 못했고 그리고 index의 소중함을 다시 알게되는 계기가 되었다.
그래서 현재 검색 기능에 gin 으로 trgm 으로 index 를 잡아놓은 것이 있는데 이거는 얼마만큼의 이점이 생기는지도 궁금하기는하다.
3줄 요약
1. auth_user 에서 upper(username), lower(email) 관련 where 절 explain 실행시간이 1000ms 가 나왔다.
2. auth_user 에 index 로 upper(username), lower(email) 을 생성했다.
3. auth_user 에서 upper(username), lower(email) 관련 where 절 explain 실행시간이 2ms 가 나왔다.