하나씩 빼서 가른 원인

응답이 느린데 거치는 계층이 다섯이라 어디가 느린지 알 수 없었다. 각 구간의 로그가 서로 다른 곳에 있어서 모으는 것부터 일이었다.

Open Table of contents

배경 — 다섯 단계를 거치는 요청

CloudFront 와 ALB 와 nginx 와 Laravel 과 MySQL 을 지나는 경로였다. curl -w '%{time_total}' 로 전체 시간만 알고 있고 구간별 분해가 없었다.

두 가지 방법이 있었는데 다섯 계층의 로그를 모아 구간을 재는 것과 경로에서 하나씩 빼면서 재는 것이다. 뒤쪽을 골랐다. 이유는 각 계층의 로그 형식이 달라 정렬부터 해야 해서다. 대신 각 계층 안에서 걸린 시간은 끝내 모르는 것을 감수했다.

CloudFront 를 건너뛰고 ALB 를 직접 부르고 다음에는 ALB 를 건너뛰고 nginx 를 직접 불렀다. 마지막으로 서버 안에서 curl localhost 로 자기 자신을 불렀다.

세 단계를 건너뛰어도 시간이 거의 안 줄어서 문제는 애플리케이션 안에 있었다. 바깥 계층은 설정 없이 주소만 바꾸면 빠지므로 안쪽보다 훨씬 싸게 뺄 수 있다.

애플리케이션 안에서 조회와 변환과 직렬화 구간에 microtime(true) 을 찍으니 변환이 대부분을 쓰고 있었다. Resource 안에서 행마다 별도 조회를 하는 N+1 형태였다.

MySQL 은 경로에서 뺄 수 없으므로 collect() 로 만든 고정된 가짜 자료로 바꿔서 돌렸다. 그래도 시간이 그대로여서 데이터베이스가 아니라는 것이 확정됐고 뺄 수 없는 것은 흉내 내서 뺀 효과를 만들 수 있었다.

CloudFront 를 뺐을 때 Content-Encoding 이 달라져 있었다. 이번 비교에서는 영향이 작았지만 알아 두고 기록했다.

한 계층을 빼면 그 계층이 하던 다른 일도 함께 빠지므로 조건이 하나만 달라지지 않을 수 있다. 그러면 비교 자체가 성립하지 않으므로 뺀 뒤에 무엇이 달라졌는지를 함께 봐야 했다.

처음에는 가끔만 느려서 빼도 차이가 안 났다. 목록 조회에서 per_page 가 일정 수를 넘을 때만 느리다는 조건을 먼저 찾았다.

인자를 고정하고 나서야 매번 비슷한 값이 나와 비교가 됐다. 재현이 안 되는 상태에서 빼면 무엇 때문에 달라졌는지 알 수 없으므로 조건 고정이 순서상 먼저였다.