거래소 API 의 스레드 풀과 커넥션 풀 조합을 JMeter 로 비교하면서 공정한 비교를 위해 부수 기능을 전부 껐다. 그런데 결과에 지정하지 않은 INSERT 사용량이 섞여 있었다.
Table of contents
Open Table of contents
증상 — 껐다고 생각한 것
features.cache=false 로 캐시를 비우고 features.async-notify=false 로 동적으로 붙는 알림도 제외했다. 그 두 가지면 전부 꺼졌다고 봤다.
결과를 보니 쓰지 않기로 한 표에 INSERT 가 들어가고 있었다. 껐다고 생각한 것과 실제로 꺼진 것이 달랐다는 뜻이다.
첫 가설을 문서로 기각
처음에는 Hibernate 가 부하에 따라 2차 캐시로 자동 전환하는 기능이 있는 것으로 봤다. 말은 됐지만 근거는 없었다.
Hibernate 5.4 공식 문서와 대조하니 그런 전환은 없었고, 기본값 ENABLE_SELECTIVE 에서는 @Cacheable 을 붙인 엔티티만 캐시된다. 조건도 대상도 서술과 안 맞아서 가설을 기각하고 데이터를 다시 봤다.
원인 — 설정에 비례한 패턴
다시 보니 패턴이 둘이었는데 하나는 모든 조합에 항상 있는 /actuator/health 보조 호출이었다. 상시 존재하므로 그것은 경로상 늘 거치는 것이었다.
다른 하나가 단서였는데 예상 밖 INSERT 가 스레드 수를 올릴수록 커졌다. 경로 문제라면 설정과 무관해야 하므로 설정이 높을 때 무언가가 더 일어난다는 뜻이었다.
설정에 따라 더 일어나는 것이 무엇인지 찾다가 전역 감사 규칙 audit-rules.yml 에 닿았다. 잔고를 바꾸는 요청마다 audit_logs 에 한 줄을 남긴다는 항목이 있었고 그것을 AuditAspect 가 AOP 로 수행하고 있었다. features.cache 와 features.async-notify 어느 것도 이 규칙 파일은 빼지 않았다. 규칙이 살아 있으니 요청마다 감사 행이 들어갔고 스레드가 많을수록 처리 요청이 늘어 비례가 나타난 것이었다.
판단 기준 — 측정의 한계를 명시
영향을 세어 보니 INSERT 가 몇 배로 뛰고 응답 시간도 배가 됐다. 조합별 성능을 재려던 측정에 감사 규칙 수행 여부가 섞였으므로 두 변수가 교락된 상태였다.
두 가지 길이 있었다. 조합별 결과를 그대로 결론으로 적는 것과, 감사 규칙이 섞여 순수 비교가 아니라고 적고 audit.enabled=false 같은 별도 제외 수단을 먼저 만드는 것이다. 뒤쪽을 골랐다. 이유는 지금 수치로 풀 크기를 정하면 감사가 빠진 배치 경로에서는 그 수치가 틀려서다. 대신 측정을 한 번 더 도는 것을 감수했다.
자동 실행에서도 같은 일이 난다
야간 배치에서도 같은 규칙이 돌아 조용히 INSERT 가 늘어난다는 것을 함께 남겼다. 끄는 옵션이 있는 것과 없는 것을 구분하지 않으면 그 차이가 결과에 그대로 들어온다.
정리
- 기능 플래그를 꺼도
audit-rules.yml같은 전역 규칙은 그대로 로드될 수 있다 - 규칙이 부가 동작을 부르면
INSERT와 응답 시간이 몇 배로 뛴다 - 첫 가설은 공식 문서와 대조해 기각한다
- 상시 존재하는 패턴과 설정에 비례하는 패턴은 원인이 다르다
- 비례하는 패턴이 무엇이 더 일어나는지를 가리킨다
- 제외 옵션이 무엇을 제외하는지 확인한다
- 남는 것이 있으면 순수 비교가 아니라고 명시하고 제외 수단부터 만든다
- 자동 실행에서는 같은 일이 조용히 비용을 늘린다