명품몰 상품 이미지 등록이 느려져서 처리 시간이 배로 늘었다. top 으로 서버 자원을 보니 CPU 에 여유가 많았다.
Table of contents
Open Table of contents
증상 — 자원이 남는데 느린 경우
CPU 가 놀고 있으면 코어를 늘려도 소용이 없다. 원인이 자원이 아니라 다른 데 있다는 뜻이다.
가능성은 iostat 으로 보는 입출력 대기와 직렬 처리와 잠금 경합과 오브젝트 스토리지 응답 대기 몇 갈래였다. 자원 지표만 보면 어느 쪽인지 안 갈리므로 ImageRegisterService 를 열어야 했다.
원인 — 순차 처리가 쌓은 왕복 시간
코드는 thumb_100 부터 detail_1200 까지 다섯 종류의 변환본을 하나씩 만들고 putObject() 로 하나씩 올리고 있었다. 한 건당 스토리지 왕복이 원본 다운로드와 업로드를 합쳐 여섯 번이었다.
각 왕복이 수백 밀리초면 합이 초 단위가 되고 그동안 CPU 는 놀고 있다. 두 가지 방법이 있었다. 변환본 종류를 셋으로 줄이는 것과, Java 8 공식 문서의 CompletableFuture.allOf() 로 다섯을 동시에 나가게 하는 것이다. 뒤쪽을 골랐다. 이유는 화면마다 쓰는 크기가 달라 종류를 줄이면 프런트도 함께 바꿔야 해서다. 대신 ExecutorService 스레드 풀 크기를 관리해야 하는 것을 감수했다. 바꾸니 전체 시간이 가장 느린 하나에 수렴했다.
주의 — 주석이 있어도 재 본다
바꾸기 전에 왜 순차였는지 보니 변환 버퍼가 동시에 힙에 쌓이는 것을 막는다는 주석이 있었다. 의도가 적혀 있으니 그대로 바꾸기 전에 멈췄다.
실제 변환 결과의 크기를 재 보니 킬로바이트 수준이라 다섯을 합쳐도 -Xmx 에 부담이 아니었다. 주석의 이유가 지금도 유효한지는 재 봐야 알 수 있고 멈추게 한 것만으로 그 주석은 값을 했으며 재 본 뒤에 주석도 갱신했다.
같은 구조가 있던 세 곳
같은 패턴을 grep -rn putObject 로 찾아보니 업로드 경로와 상품 복제 경로에도 있었다. 공통 함수를 안 쓰고 각자 비슷하게 짜여 있었다.
세 곳에 다 적용했는데 한 곳만 고치면 나머지는 그대로 느리다. 그러면 나중에 어디는 빠르고 어디는 느리다는 문의가 따로 온다.
검증 — 가설을 배제한 대조
조사 중에 Logstash 로그 파일이 커진 것을 보고 디스크 쓰기 부하를 의심했다. 확인 방법은 로그가 훨씬 적은 서버를 찾아 처리 시간을 비교하는 것이었다.
두 서버의 처리 시간에 차이가 없어서 로그는 원인이 아니었다. 가설을 세우면 그 조건만 다른 대상을 찾아 비교하는 것으로 빠르게 배제된다.
정리
- CPU 에 여유가 있는데 느리면 자원이 원인이 아니다
- 순서와 대기와 경합 중 어느 쪽인지는 코드를 봐야 갈린다
- 순차 처리는
putObject()왕복 횟수만큼 시간이 쌓인다 CompletableFuture.allOf()로 바꾸면 전체가 가장 느린 하나에 수렴한다- 주석에 이유가 있으면 존중하되 지금도 유효한지 잰다
- 근거가 안 맞으면 바꾸고 주석도 갱신한다
- 같은 구조가 여러 곳에 있으면 함께 고친다
- 가설은 그 조건만 다른 대상과 비교하면 빠르게 배제된다