성능 테스트 (4) - 시나리오 3

테스트 시나리오 3 - 공간 쿼리 테스트

목적: PostGIS 공간 검색 성능 측정
참고

• 느린 쿼리 기준은 500ms 이상
• 데이터 볼륨
  • Location: 425,094개
  • Guide: 50,000개
  • 평균 Media/Guide: 3개
• 조회 인덱스 추가한 상태
• 테스트 내용*
• ST_DWithin 반경 검색 (고정위치에서 50%, 랜덤 위치 잡아서 30%, 그리고 가이드 등록되어 있는 공간 20%)
• 여러 반경 크기 테스트 (5km, 10km, 20km, 50km)

테스트 결과

{
  "metrics": {
    "avg_duration_ms": 1393,
    "p95_duration_ms": 6361,
    "success_rate": 0.7122988819198255,
    "slow_queries_count": 1490,
    "slow_queries_percentage": "20.32%",
    "requests_per_second": "24.40"

20퍼센트의 쿼리가 여전이 500ms 목표치를 통과하지 못하고 있는것을 확인할 수 있습니다.

성능 이슈 이유와 개선
1.과도한 로깅
아래 코드를 보면 수많은 로그를 요약해서 찍지도 않고, 로그 레벨도 info로 분류해둔 부분을 확인할 수 있습니다.
(현재 DB Connection이 여전히 10개로 되어있습니다)

log.info("[findNearbyOptimized] 반환된 Location 수: {}", locations.size());
        locations.forEach(loc ->
                log.info("Location ID = {}, 이름 = {}, 좌표 = {}",
                        loc.getId(),
                        loc.getLocationName(),
                        loc.getCoordinate())
        );    

150VUser 기준 150 * 평균 100개의 location의 로그를 전부 출력합니다. 단순 계산으로도 15000번의 로그를 출력하게 됩니다.
이러한 수많은 로그 출력은 cpu를 점유하고 I/O 블로킹을 유발합니다.

단순히 해당 로그를 주석 처리하고 다시 테스트 해본 결과

{
  "metrics": {
    "avg_duration_ms": 152,
    "p95_duration_ms": 701,
    "success_rate": 0.9715066354410616,
    "slow_queries_count": 62,
    "slow_queries_percentage": "0.48%",
    "requests_per_second": "42.56"
  },

훨신 나아진 결과를 확인할 수 있습니다.

• 응답 속도 1393ms -> 152ms로 9.16배 개선
• 500ms 내 응답하지 못하는 비율도 20.32% -> 0.48%로 감소
• RPS도 24.4 -> 42.56으로 1.74배 개선

배운점
CPU가 실제 작업으로 바쁜지, Sleep/Wake 오버헤드로 바쁜지 구분해야 합니다.

• hikaricp.connections.pending > 0 지속 → 풀 부족으로 인한 오버헤드
• 쿼리 실행 시간 자체가 긴 경우 → 쿼리 최적화 필요

로깅할 때 다 찍지 말고, 요약(개수 혹은 샘플 몇개만) 로깅하고 상세 로깅은 DEBUG 레벨로 내리기 그리고 로그 레벨 구분해서 넣기

• 개발: 상세한 디버그 로그
• 운영: 최소한의 로그
• 긴급 상황: DEBUG로 즉시 전환 가능

리소스 메트릭 확인
그러나 아래 메트릭 그래프를 확인해보면
HTTP Response Time이 점진적으로 증가하며 시스템이 점점 포화상태가되는것을 확인할 수 있습니다.
또한 cpu 사용량이 피크일 때 80% 가까이 올라가며 서버 리소스에 여유가 없어지고, DB Connection Pool 사용량도 피크일 때 100%를 찍어 병목이 발생하는 사실을 확인할 수 있었습니다.

리소스 사용량 해결

위의 결과를 봤을 때 이미 cpu 사용량이 높아, DB Connection Pool의 크기를 늘리면 안된다고 생각했습니다.
이미 cpu가 처리하고 있는 일이 많은데, 여기서 Connection Pool을 늘려서 더 많은 동시 작업을 시키게 되면 CPU 부하가 더욱 늘어나고, Context Swithcing 비용도 함께 상승하기에 시스템 과부화가 올것이라 생각하였습니다.

그러나 딱히 이유를 찾기가 어려워 이것 저것 시도중 DB Connection수를 원래 목표한 15로 변경 했을 때 크게 성능이 개선되었습니다.

{
  "metrics": {
    "avg_duration_ms": 10,
    "p95_duration_ms": 27,
    "success_rate": 1,
    "slow_queries_count": 0,
    "slow_queries_percentage": "0.00%",
    "requests_per_second": "46.27"
  },

피크 상황에서 cpu 사용량이 79% -> 33% db connection pool 사용량 100% -> 20% 로 둘 다 안정된 모습을 확인할 수 있었습니다.
또한 성능도 개선되었습니다.

• 평균 응답시간 : 152ms -> 10ms 로 15배 개선
• 쿼리 목표 시간 내 성공률 : 100% 달성
• RPS : 42.56 -> 46.27로 9% 증가

이를 봤을 때 실제로 cpu를 사용하는 작업이 실제 로직 연산 보다는 connection pool이 부족해서 쓰레드들이 10개의 커넥션을 두고 대기 및 경쟁을 위해 cpu 리소스를 사용하게 되며 오버헤드가 발생했다는 것을 알 수 있습니다. 그러나 pool size를 15로 늘리니 쓰레드들이 대기를 거의 하지 않고 요청이 처리되어 Lock을 차지하기 위한 경쟁이 줄어들어 효율적인 처리가 가능해졌습니다.
이러한 개선과정을 통해 목표한 성능을 얻을 수 있었습니다.

참고

cpu스레드를 코어수보다 많이 설정할 수 있는 이유
단순하게 생각해보면 cpu가 8코어라고 하면, db connection pool size도 8로 하면 최적의 성능을 제공할것이고, 더욱 커지면 context switching 비용이 발생하여 손해일것입니다.
그러나 디스크는 요청한 데이터를 즉시 읽을 수 있는 것이 아닌, 디스크의 모터 구동 암이 플래터 위치를 찾고, 플래터의 데이터를 얻기 위한 회전 시간, 데이터 전송 시간 또한 추가적으로 필요합니다. 이러한 작업이 필요하여 스레드가 block되고, 이 시간동안 다른 스레드의 작업을 처리할 수 있기에 cpu 스레드를 코어수보다 많이 설정할 수 있습니다.

• SSD같은 경우에는 위의 HDD와 같은 물리적 지연이 없는 대신, 찾고자 하는 주소 변환하고 NAND 플래시 셀에서 전자적으로 데이터를 읽어오게 됩니다. HDD보다 약 100배 빠르지만, RAM보다 약1000배 느립니다.
• RAM이나 CPU 캐시 같은 경우에는 SSD보다도 훨씬 빠르게 처리가능합니다. (캐싱 사용하는 이유)

db connection pool usage의 메트릭이 0이 중간에 찍히는 이유
사용량 계산 방식이 현재

Usage = active / maximum-pool-size × 100%  

이렇게 되어있는데, active는 측정 순간 쿼리 실행 중인 커넥션 수 를 의미합니다.
현재 테스트 스크립트에 VUser의 think time같은 요청 간 빈 시간이 존재하여 이렇게 되었다 생각합니다.

Spin-wait
Spin-wait는 HikariCP에 적용되어 있는 방식으로 멀티스레드에서 Lock을 획득하기위해, 대기하는 스레드를 Sleep 상태로 만들지 않고 루프를 돌며 cpu 리소스를 사용하며 기다리는 기술입니다.

스레드가 Sleep 상태로 전환되지 않아 Sleep/Wake 오버헤드가 없고, 짧은 대기 시간 내 Lock을 획득하면 우수한 성능을 보여줍니다.
그러나 대기 시간이 길다면 쓰레드가 대기하며 cpu리소스를 소모하게 됩니다.