[#2] 쿼리 문제 최적화

개요

[#1](인프라 개선하기 작업)을 통해 이제 정상적으로 테스트는 가능했지만 전반적으로 개선의 필요성이 있다는 것을 절실히 느꼈습니다. 'Postman으로 응답 오면 잘 만들어졌군!' 하던 스스로가 너무 부끄러웠지만 이제 시작이니 차근차근 해결해 나가 보자는 생각을 갖고 가장 쉽게 고칠 수 있는 부분부터 접근해 나가려는 계획을 세우고 시작했습니다.

 

로그인 API 테스트 핀포인트 StackTrace

가장 먼저 눈에 띄는 것은 바로 '쿼리의 수행 시간'이었습니다. Database라는 것을 학습하면서 인덱스를 통해 빠른 속도를 통해 데이터를 갖고 올 수 있고 왜 빠른지에 대해서 알고 있었지만 '정말 빨라?'라는 의문과 '나는 실행 계획(EXPLAIN)을 통해 쿼리를 개선할 수 있을까?'라는 의구심으로써 Primary Key와 Foreign Key를 제외하고 제약 조건과 인덱스를 생성하지 않았습니다.

Query 조회

각각의 API마다 실제로 어떤 쿼리가 나가는지 다시 한번 확인하고자 로깅된 쿼리를 기록했습니다. JPA를 사용하여 컬럼들의 이름들이 변환돼서 나타나는 것을 확인할 수 있었습니다.

User-SignIn

query time	lock time	rows sent	rows examined	db	sql text
0.067244	0.000003	1	10003	yousinsa	select userentity0.id as id15, userentity0.created_at as created25, userentity0.updated_at as updated35, userentity0.user_email as userema45, userentity0\.user\_name as user\nam55, userentity0.user_password as userpas65, userentity0.userrole as userro75 from users userentity0 where userentity0.user_email='4651@yousinsa.com'

Product-List

query time	lock time	rows sent	rows examined	db	sql text
0.193988	0.000001	3	90010	yousinsa	select options0_.product_id as product_400, options0.id as id100, options0.id as id101, options0.product_id as product_401, options0.product_count as product_201, options0.product_size as product_301 from productoptions options0 where options0.product_id=1
0.086256	0.000001	1	30004	yousinsa	select count(productent0.id) as col00 from products productent0 where productent0.category='TOP'

Purchase-Order

query time	lock time	rows sent	rows examined	sql text
0.053621	0.009842	0	0	insert into purchase_order_items (created_at, updated_at, product_option_id, purchase_order_id, purchase_order_amount) values ('2022-08-15 17:24:41.702432', '2022-08-15 17:24:41.702432', 90010, 188401, 7)
0.052619	0.000003	1	10003	select userentity0.id as id15, userentity0.created_at as created25, userentity0.updated_at as updated35, userentity0.user_email as userema45, userentity0.user_name as usernam55, userentity0.user_password as userpas65, userentity0.userrole as userrol75 from users userentity0 where userentity0.user_email='1940@yousinsa.com'
0.041697	0.005292	0	0	update product_options set product_id=30004, product_count=999915252, product_size='free' where id=90010
0.020577	0	0	0	commit
0.011458	0	0	0	rollback

Query 실행 계획

앞서 기록했던 쿼리의 실행계획을 확인했습니다. 확인해보면 Index를 적절하게 사용하지 않았기 때문에 type에서 ALL이 보이고 Full Scan을 수행한 것을 확인할 수 있었습니다.

 

User-SignIn

EXPLAIN select userentity0_.id as id1_5_, userentity0_.created_at as created_2_5_, userentity0_.updated_at as updated_3_5_, userentity0_.user_email as user_ema4_5_, userentity0_.user_name as user_nam5_5_, userentity0_.user_password as user_pas6_5_, userentity0_.user_role as user_rol7_5_ from users userentity0_ where userentity0_.user_email='9397@yousinsa.com'

id	select type	type	possible keys	key	key len	ref	rows	filtered	Extra
1	SIMPLE	ALL	NULL	NULL	NULL	NULL	9549	10	Using where

로그인 시 User의 Email을 통해 해당 User가 회원 가입된 User인지 조회하는데 Full Table Scan을 수행한 것을 확인할 수 있습니다. User의 Email의 경우 회원가입 시 중복 체크도 진행하므로 Unique 제약조건이 적합하다 판단하여 적용했습니다.

Product-List

EXPLAIN select options0_.product_id as product_4_0_0_, options0_.id as id1_0_0_, options0_.id as id1_0_1_, options0_.product_id as product_4_0_1_, options0_.product_count as product_2_0_1_, options0_.product_size as product_3_0_1_ from product_options options0_ where options0_.product_id=19
EXPLAIN select count(productent0_.id) as col_0_0_ from products productent0_ where productent0_.category='TOP';

 

id	select type	type	possible keys	key	key len	ref	rows	filtered	Extra
1	SIMPLE	ALL	NULL	NULL	NULL	NULL	90208	10	Using where
1	SIMPLE	ALL	NULL	NULL	NULL	NULL	30098	33.33	Using where

Product를 조회하고 해당 상품의 Option들을 조회하게 되는데 이 때 사용하는 Join Key에 인덱스가 걸려있지 않은 것을 확인할 수 있습니다. 그리고 Product와 Product Option은 1:N 관계이므로 N + 1 문제가 발생하여 해당 API에서 응답 속도가 느릴 수도 있다고 생각했습니다. 마지막으로 Paging 시 필요한 전체 개수 Count 시 Category에 Index가 걸려있지 않아 마찬가지로 Full Table Scan을 수행하는 것도 확인할 수 있었습니다. 

Purchase-Order

EXPLAIN select userentity0_.id as id1_5_, userentity0_.created_at as created_2_5_, userentity0_.updated_at as updated_3_5_, userentity0_.user_email as user_ema4_5_, userentity0_.user_name as user_nam5_5_, userentity0_.user_password as user_pas6_5_, userentity0_.user_role as user_rol7_5_ from users userentity0_ where userentity0_.user_email='9397@yousinsa.com'
EXPLAIN update product_options set product_id=30004, product_count=999915252, product_size='free' where id=90010

 

id	select type	type	possible keys	key	key len	ref	rows	filtered	Extra
1	SIMPLE	ALL	NULL	NULL	NULL	NULL	9549	10	Using where
1	UPDATE	range	PRIMARY	PRIMARY	8	CONST	1	100	Using where

UPDATE 쿼리의 경우 이미 Primary Key를 기준으로 WHERE 문이 실행되기 때문에 Index를 사용하는 실행 계획을 볼 수 있습니다.

 

Index 적용 후 실행계획

실행계획을 통해 전체적으로 쿼리 실행 성능 향상 포인트들이 보였습니다.

id	select type	type	possible keys	key	key len	ref	rows	filtered	Extra
1	SIMPLE	const	users_user_email_uindex	users_user_email_uindex	1023	const	1	100	NULL

 

id	select type	type	possible keys	key	key len	ref	rows	filtered	Extra
1	SIMPLE	ref	product_options_product_id_index	product_options_product_id_index	9	const	3	100	NULL
1	SIMPLE	ref	products_category_index	products_category_index	2	const	10002	100	Using index

API에 따라 분리하는 것이 아니라 한 번에 살펴 보겠습니다.

 

User의 Email을 통해 조회하는 쿼리의 경우 Email을 Unique 제약 조건으로 주었기 때문에 Index가 생성되었습니다. `id` 의 경우 Join, SubQuery가 포함되어 있다면 실행 계획이 더 있었겠지만 단순한 SELECT 문이었기 때문에 1번만 존재하는 것을 확인할 수 있습니다. select_type에는 SIMPLE이 표시되며 PRIMARY, UNION, DEPENDENT UNION, SUBQUERY가 아닙니다.

---

`type` 컬럼은 각 테이블의 레코드를 어떤 방식으로 읽었는지 나타냅니다. 이전에 봤던 ALL의 경우 Full Table Scan을 수행하던 쿼리가 Index를 사용하여 const, ref type으로 나오는 것을 확인할 수 있습니다. const의 경우 반드시 1건을 반환하는 쿼리의 처리 방식을 의미하여 유니크 인덱스 스캔이라고 표현하기도 합니다. 당연히 Unique 제약조건을 사용했기 때문에 const를 사용했을 것이라고 예상할 수 있습니다. ref의 경우 반환되는 레코드가 반드시 1건이라는 보장이 없어도 되며 조인의 순서나 인덱스의 종류와 관계없이 동등 조건으로 검색시 사용됩니다.

 

---

 

`rows` 컬럼은 쿼리를 처리하기 위해 얼마나 많은 레코드를 읽고 검사해야하는지를 의미합니다. Index를 적용하고 나서 `rows` 컬럼의 값이 줄어든 것을 확인할  수 있었습니다.

 

---

 

`filtered` 컬럼은 필터링되어 버려지는 레코드의 비율이 아니라 필터링되고 남은 레코드의 비율을 의미합니다. 이전과는 다르게 100% 비율로 남아있는 것으로 보아 효율성이 증가되었다고 볼 수 있었습니다.

 

---

 

`Extra` 컬럼에서는 주로 내부적인 처리 알고리즘에 대해 중요한 정보들을 알려줍니다. Using index라고 표시되어 있는 것을 확인할 수 있었습니다. Using index라 함은 커버링 인덱스를 사용했다는 의미입니다. 커버링 인덱스는 데이터 파일을 추가적으로 읽지 않고 인덱스 만을 통해 처리하는 것을 의미합니다. 따라서 Index를 더 효율적으로 사용한다고 판단할 수 있었습니다.

구매 주문의 경우 Insert, Update에서 병목이 생기므로 Index로 인해 성능 향상이 이루어지지 않을 것이라고 판단했었습니다.

하지만 인덱스도 영향을 줄 수 있다는 것을 후에 알게 되었습니다.😅

---

쿼리 튜닝 테스트

쿼리 튜닝을 진행하고 다시 nGrinder를 통해 실험을 진행했습니다. nGrinder의 TPS만 비교하더라도 이전에 비해 80%의 성능 향상이 이루어진 것을 확인할 수 있었습니다.

<쿼리 튜닝 전 vs 쿼리 튜닝 후>

Pinpoint의 결과를 확인해보면 실패하는 요청 없이 잘 처리하는 것을 볼 수 있습니다.

Pinpoint Inspector도 보면 메모리가 부족하지 않지만 CPU Usage가 100%에 가깝게 사용되는 것을 볼 수 있습니다.

이전에 비해 TPS 성능이 개선되긴 했지만 아직 목표한 성능에는 다다르지 못했습니다.

특히 지연이 긴 Request-Response 과정에 대한 StackTrace를 확인해보면 HikariCP에서 Connection을 갖고 오는 시간이 대부분을 차지하는 것을 확인할 수 있습니다.

비록 쿼리 튜닝만을 통해서 목표한 성능을 달성하지는 못했지만 성능을 높일 수 있는 2개의 실마리를 발견했습니다.

고민을 위한 여지

• CPU Usage가 100%에 가까우면 문제가 발생할까?
• 왜 Connection을 갖고 오는 부분에서 병목이 생기는 것일까?
• 더 많은 단서들을 얻기 위해서는 어떤 Tool이 필요할까?

해당 프로젝트는 네이버 클라우드의 지원을 받아 진행했습니다.