갑자기 느려진 쿼리속도
Cabi 프로젝트를 하던 중에 프로젝트 설정에 문제가 조금 있기도 했고 Intellij의 루트 디렉토리를 변경하고자, 프로젝트를 삭제하고 다시 clone을 받아서 새로 환경을 세팅했다. 처음에는 빌드와 테스트, 부팅까지 정상적으로 동작하길래 전혀 문제가 없는 줄 알았다.
하지만 로컬에서 층 전체 사물함을 조회해오는 요청의 응답이 7~8초 정도로 굉장히 느린 것을 발견했다. 원래 20ms 내로 응답을 보내주던 코드인데 갑자기 느려지기도 했고, dev 서버와 main 서버에서는 여전히 빠르게 잘 가져오길래 이게 뭐지 싶었다.
원인 분석
일단 여러 쿼리들을 전부 돌면서 또 느려진 쿼리가 있는지 확인해지만, 해당 쿼리 외에 체감될만큼 확연히 느려진 쿼리는 없었다.
해당 쿼리는 QueryDSL을 사용하는데, 그래서 처음에는 queryDSL의 문제인 줄 알았다. 원인도 잘 모르겠고 되던게 안되니까 짜증나기도 하고 그래서, Database 연결이 문제가 있나 확인해보거나 Intellij를 업데이트 하거나 Projection.constructor을 적용해보는 등 다른 방법들을 적용해보며 원인 분석 없이 되도 않는 여러 방법들을 시도 했었다. 하지만 예상했듯이 모두 실패… 여전히 응답까지 7~8초 정도 걸린다.
자포자기하고 있다가, 혹시 싶어서 일단 출력 시간을 찍어봤다.
이처럼 쿼리 호출 직전에 출력 문구를 찍고,
이와 같이 설정을 추가해서 hibernate가 쿼리를 날릴 때 log를 남기도록 하여 시간을 비교해보려 했다.
repository called : 1702654032203
00:27:12.375 [http-nio-2424-exec-1] DEBUG org.hibernate.SQL -
select
distinct cabinet0_.`cabinet_id` as cabinet_1_2_0_,
lenthistor2_.`lent_history_id` as lent_his1_5_1_,
user3_.`user_id` as user_id1_6_2_,
cabinet0_.`cabinet_place_id` as cabinet11_2_0_,
cabinet0_.`col` as col2_2_0_,
cabinet0_.`row` as row3_2_0_,
cabinet0_.`lent_type` as lent_typ4_2_0_,
cabinet0_.`max_user` as max_user5_2_0_,
cabinet0_.`memo` as memo6_2_0_,
cabinet0_.`status` as status7_2_0_,
cabinet0_.`status_note` as status_n8_2_0_,
cabinet0_.`title` as title9_2_0_,
cabinet0_.`visible_num` as visible10_2_0_,
lenthistor2_.`cabinet_id` as cabinet_2_5_1_,
lenthistor2_.`ended_at` as ended_at3_5_1_,
lenthistor2_.`expired_at` as expired_4_5_1_,
lenthistor2_.`started_at` as started_5_5_1_,
lenthistor2_.`user_id` as user_id6_5_1_,
lenthistor2_.`version` as version7_5_1_,
user3_.`blackholed_at` as blackhol2_6_2_,
user3_.`deleted_at` as deleted_3_6_2_,
user3_.`email` as email4_6_2_,
user3_.`name` as name5_6_2_,
user3_.`role` as role6_6_2_
from
`cabinet` cabinet0_
inner join
`cabinet_place` cabinetpla1_
on (
cabinet0_.`cabinet_place_id`=cabinetpla1_.`cabinet_place_id`
)
inner join
`lent_history` lenthistor2_
on (
cabinet0_.`cabinet_id`=lenthistor2_.`cabinet_id`
)
inner join
`user` user3_
on (
lenthistor2_.`user_id`=user3_.`user_id`
)
where
cabinetpla1_.`building`=?
and cabinetpla1_.`floor`=?
and (
lenthistor2_.`ended_at` is null
)
00:27:12.381 [http-nio-2424-exec-1] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [새롬관]
00:27:12.381 [http-nio-2424-exec-1] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [INTEGER] - [2]
2023-12-16 00:27:20 INFO [http-nio-2424-exec-1] {userId=b169d4b71855} ActiveCabinetInfoEntities: cabinet = {], lentHistory = Cabinet(cabinetId=130, visibleNum=70, status=FULL, lentType=PRIVATE, maxUser=1, statusNote=, grid=org.ftclub.cabinet.cabinet.domain.Grid@57c2d5c5, title=, memo=null), user = LentHistory(lentHistoryId=19512, version=2, startedAt=2023-12-06T13:07:04, expiredAt=2024-02-06T23:59:59, endedAt=null, userId=5, cabinetId=130)
dto called : 1702654041010
2023-12-16 00:27:21 INFO [http-nio-2424-exec-1] {userId=b169d4b71855} ActiveCabinetInfoEntities: cabinet = {], lentHistory = Cabinet(cabinetId=126, visibleNum=66, status=FULL, lentType=PRIVATE, maxUser=1, statusNote=, grid=org.ftclub.cabinet.cabinet.domain.Grid@68ff7fd4, title=, memo=null), user = LentHistory(lentHistoryId=19193, version=2, startedAt=2023-11-24T13:42:33, expiredAt=2024-01-15T23:59:59, endedAt=null, userId=49, cabinetId=126)
dto called : 1702654041011
2023-12-16 00:27:21 INFO [http-nio-2424-exec-1] {userId=b169d4b71855} ActiveCabinetInfoEntities: cabinet = {], lentHistory = Cabinet(cabinetId=61, visibleNum=17, status=FULL, lentType=PRIVATE, maxUser=1, statusNote=, grid=org.ftclub.cabinet.cabinet.domain.Grid@6a50a946, title=, memo=null), user = LentHistory(lentHistoryId=19304, version=2, startedAt=2023-11-26T19:28:09, expiredAt=2024-01-17T23:59:59, endedAt=null, userId=43, cabinetId=61)
dto called : 1702654041011
2023-12-16 00:27:21 INFO [http-nio-2424-exec-1] {userId=b169d4b71855} ActiveCabinetInfoEntities: cabinet = {], lentHistory = Cabinet(cabinetId=133, visibleNum=73, status=FULL, lentType=PRIVATE, maxUser=1, statusNote=, grid=org.ftclub.cabinet.cabinet.domain.Grid@5567c7ec, title=, memo=null), user = LentHistory(lentHistoryId=19357, version=3, startedAt=2023-11-27T00:47:37, expiredAt=2024-02-18T23:59:59, endedAt=null, userId=62, cabinetId=133)
dto called : 1702654041011
2023-12-16 00:27:21 INFO [http-nio-2424-exec-1] {userId=b169d4b71855} ActiveCabinetInfoEntities: cabinet = {], lentHistory = Cabinet(cabinetId=110, visibleNum=50, status=FULL, lentType=SHARE, maxUser=4, statusNote=, grid=org.ftclub.cabinet.cabinet.domain.Grid@4713490, title=, memo=null), user = LentHistory(lentHistoryId=19449, version=1, startedAt=2023-11-29T13:52:06, expiredAt=2024-01-28T23:59, endedAt=null, userId=36, cabinetId=110)
dto called : 1702654041011
...
JavaScript
복사
위는 출력 로그를 상위 일부만 가져온건데, 아래의 dto called : ~~~ 내용은 ActiveCabinetInfoEntities 생성자에서 찍은 log와 출력이다. 보면 알 수 있듯, 쿼리 발생 이후 7~8초 이후에 생성자가 호출된다. 비즈니스 로직이나 동작 문제가 아니라 그냥 실제 쿼리 수행 속도가 느리다.
여기까지와서 생각을 해보니 내가 환경 세팅을 새로 한 이후, mariadb에서 직접 쿼리를 날려본 적이 없다는걸 깨달았다. 얼마전에 위의 저 쿼리가 왜 빨라진 건지 분석까지 했으면서, 인덱스를 확인해 볼 생각을 한 번을 안해보다니…
실행 계획을 확인해보니, 4개의 테이블 전부 풀 테이블 스캔이 사용된다.
인덱스를 찍어보니 하나도 없다.
사실 환경 세팅 직후에 데이터를 확인할 일이 있어서 Datagrip으로 데이터베이스를 확인한 적이 있다. 당시에는 다른 데이터는 거의 없고 admin만 하나 등록되어 있길래, 아무 생각 없이 dev DB에 있는 데이터를 긁어와서 로컬 DB에 복사해 붙여넣었다.
생각을 해보니, 테이블을 그런 방식으로 복사하여 생성할 게 아니라 DDL로 테이블이 잘 생성 되는지 확인부터 했어야 했다. 이걸 확인하지 않고 다른 데이터베이스에 테이블째로 복사해서 붙여넣었으니, 동작은 잘 하지만 인덱스가 하나도 없을 수 밖에…
해결
로컬 데이터베이스에서 테이블을 전부 Drop 후에 Cabi의 설정 DDL 파일을 통해 테이블 구조를 먼저 생성했다. 그 후 데이터를 복사하는 방식으로 데이터를 가져왔다.
인덱스가 잘 생겨있는 것을 확인할 수 있고,
응답 또한 다시 빠른 시간 내에 오는 것을 확인 할 수 있다.
결론
사실 이 문제로 이틀가량 골머리를 앓았는데, 해결하고 보니 진짜 별 것 아닌 문제로 그만큼이나 시간을 낭비하고 고생을 했다는게 너무 짜증나고 스스로가 한심했다. 심지어 최근에 쿼리 분석까지 해본 로직이여서 더 그런 것 같다.
당연히 정상 동작하지만 속도가 느려졌으면, 각 부분별로 어디서 느렸는지 확인하고 느려진 원인부터 찾을 생각을 했어야 했다. 미처 생각이 닿지 못했다고 변명할 수 있지만, 경험의 부족이라고 하기에도 아쉬운 트러블 슈팅이다.
오늘의 교훈1 : 문제가 발생하면 넘겨짚지 말고, 원인이 뭘까 제대로 고민하고 분석해보자
오늘의 교훈2 : 데이터베이스 테이블 복사 방식으로는 인덱스 복사가 이루어지지 않는다.