[26.09.23] 챌린지 API의 DB 호출 지연 분석을 위한 쿼리 실행과 대기 시간 구분하기

상황

어제 낙서장의 API trace에서 테이블 조회 두 번이 312.9ms와 149.56ms였습니다. 이 쿼리의 평소 p50은 1.5ms입니다. 운영 메트릭에서도 DB 호출 p95가 50ms를 넘는 분이 정각이나 정각 1분 뒤에 5번 반복됐고, 처음에는 DB가 정각에 잠시 응답하지 못한다는 가설을 세웠습니다.

어제는 이 가설을 기준으로 slow log와 performance_schema에서 slow query의 실행 정보를 뽑는 방법을 비교했습니다. 오늘은 그 전에 312.9ms가 실제로 DB 내부 쿼리 실행 시간인지 확인했습니다.

원인

9월 16일 ~ 23일 운영 메트릭에서 DB 호출 p95가 50ms를 넘은 분을 인스턴스(ECS 태스크)별로 나눴습니다.

• 두 인스턴스는 같은 RDS master와 replica를 사용합니다.
• 6번 모두 한 인스턴스만 50ms를 넘었고, 다른 인스턴스는 1 ~ 21ms였습니다.

매시 정각과 정각 1분 뒤에는 DB를 거의 쓰지 않는 요청의 p99도 16 ~ 23ms 늘었습니다.

상황의 trace에서도 요청의 첫 호출인 Redis SET이 12ms로, 평소 1ms 미만보다 11ms 이상 늘었습니다.

DB 호출 한 번이 거치는 과정을 단계별로 나누고, 단계마다 시간을 늘릴 수 있는 후보가 위 관측과 맞는지 확인했습니다.

• 두 인스턴스가 함께 쓰는 RDS 서버나 DB 잠금이 원인이면, 같은 분에 두 인스턴스의 DB 호출 p95가 함께 50ms를 넘어야 합니다.
• 커넥션 풀이나 실행계획처럼 DB 호출에만 있는 단계가 원인이면, DB를 쓰지 않는 요청의 p99는 늘지 않아야 합니다.
• 원인은 정각이나 정각 1분 뒤에 일어나야 합니다.

남은 후보는 CFS 스로틀, steal, 네트워크 경로 지연, Fluent Bit 로그 파이프입니다. 여기부터는 추정입니다. 스레드는 CPU를 할당받아야 응답을 읽고 span을 끝낼 수 있습니다. 그래서 CFS 스로틀이나 steal로 스레드가 CPU를 기다리면, 애플리케이션이 측정한 DB 호출 시간은 기다린 시간만큼 늘고 MySQL이 측정한 시간은 동일합니다.

• CFS 스로틀: 인스턴스가 CFS 주기(기본 100ms)의 CPU 쿼터를 이미 다 썼으면, 실행 가능한 스레드도 주기가 끝날 때까지 실행되지 않습니다. 평균 CPU 사용률이 2%여도 한 주기 안에 쿼터를 모두 쓰면 그 주기의 남은 시간 동안 스로틀됩니다.
• steal: 하이퍼바이저가 인스턴스의 vCPU에 CPU를 할당하지 않으면 인스턴스 안의 모든 스레드가 실행되지 않습니다.

해결

JVM 정지로 애플리케이션과 MySQL 측정값의 차이 구분하기

스레드가 CPU를 할당받지 못하면 애플리케이션이 측정한 쿼리 시간만 늘어나는지 로컬에서 확인했습니다. CPU를 할당받지 못하는 상황은 kill -STOP으로 JVM을 정지시켜 만들었습니다. JVM이 정지하면 JVM의 모든 스레드가 실행되지 않습니다. SQL에 traceId를 함께 전달해 애플리케이션과 MySQL의 기록을 연결하고, 같은 쿼리의 실행 시간을 비교했습니다.

로컬 쿼리는 약 1ms라 JVM만 정지시키면 정지 시점에 실행 중인 쿼리가 없었습니다. 그래서 다른 세션이 쿼리 대상 테이블을 잠가 쿼리가 MySQL에서 대기하게 하고, 그동안 JVM을 정지시켰습니다.

• DB 잠금: 테이블을 2초 동안 잠급니다. JVM은 정지하지 않습니다. DB 내부 쿼리 실행 시간만 늘어나는 조건입니다.
• DB 잠금 + JVM 정지: 테이블을 1초 동안 잠그고, 쿼리가 대기하는 동안 JVM을 1.5초 정지합니다. 잠금이 풀려 MySQL이 응답을 보낸 뒤에도 JVM은 정지 상태입니다.

• DB 잠금: DB 내부 쿼리 실행 시간이 두 측정값에 같이 기록됐습니다.
• DB 잠금 + JVM 정지: 응답 패킷이 도착한 뒤 JVM이 정지해 응답을 읽지 못한 975ms가 애플리케이션 측정값에만 기록됐습니다.

같은 쿼리의 두 측정값 차이가 10ms 이하이면 DB 내부 쿼리 실행 시간이고, 10ms를 넘으면 그 차이가 DB 외부 대기 시간입니다. 운영에서도 slow query 로그의 elapsed_ms와 RDS performance_schema의 TIMER_WAIT를 traceId로 연결하면 같은 방법으로 구분할 수 있습니다.

CFS 스로틀로 애플리케이션과 MySQL 측정값의 차이 구분하기

두 측정값의 차이만으로는 원인을 하나로 정할 수 없습니다. JVM 정지는 모든 스레드를 한 번에 멈추므로 CFS 스로틀과 조건이 다릅니다. 운영에 추가할 지표를 정하려고, CPU 한도를 건 컨테이너에서 CFS 스로틀을 재현했습니다. CPU 한도 없음은 CPU 사용량이 몰린 것만으로 차이가 생기는지 확인하는 조건입니다. 코드와 측정값은 실험 디렉터리에 있습니다.

• 쿼리: 인덱스 조회를 20ms 간격으로 60초 동안 보내고, 애플리케이션 측정값과 TIMER_WAIT를 traceId로 짝지었습니다. 조건마다 3회 반복했습니다.
• cgroup 지표: 컨테이너 cgroup의 cpu.stat nr_throttled와 cpu.pressure some total, /proc/stat의 steal을 1초마다 읽었습니다.

표의 값은 3회 측정값의 평균입니다. 쿼리 수와 1ms 이상의 시간은 정수로 반올림했습니다. 차이는 같은 쿼리의 애플리케이션 측정값에서 TIMER_WAIT를 뺀 값입니다.

• CFS 스로틀: 평균 CPU 사용률 13.9%에서 60초 동안 43번 스로틀됐습니다. 차이가 10ms를 넘은 쿼리는 기준 조건보다 20건 많았고, MySQL 측정값 p50은 0.49ms로 기준 조건보다 0.05ms 컸습니다. PSI는 기준 조건보다 2,638ms 늘었습니다.
• CPU 한도 없음: 평균 CPU 사용률이 30.2%로 가장 높았지만 스로틀은 0번이었고, 차이가 10ms를 넘은 쿼리는 기준 조건보다 1건 많았습니다.
• steal: 모든 조건에서 0이었습니다. Docker Desktop의 Linux VM은 steal을 기록하지 않아 재현하지 못했습니다.

CFS 스로틀은 nr_throttled와 PSI가 늘어난 경우로 구분됐습니다.

네트워크 지연으로 애플리케이션과 MySQL 측정값의 차이 구분하기

ENI나 VPC 경로에서 패킷 전달이 지연되어도, 지연된 시간만큼 두 측정값의 차이가 생깁니다. 같은 컨테이너(CPU 한도 1개)에서 프록시가 MySQL 응답을 30ms 늦춰 전달하도록 하고, 앞 절과 같은 방법으로 3회 측정했습니다.

차이 p50이 기준 조건보다 33ms 늘었고, 모든 쿼리에서 차이가 10ms를 넘었습니다. nr_throttled는 0, PSI는 기준 조건보다 13ms 작았습니다. 네트워크 지연은 nr_throttled가 0이고 PSI가 기준 조건 이하인 상태에서 차이만 늘어난 경우로 구분됐습니다.

결과

전날에는 slow query의 실행 정보를 뽑으려 했지만, DB에서 오래 실행된 slow query는 없었습니다. 같은 분에 다른 인스턴스는 DB 호출 p95가 1 ~ 21ms였고, 두 쿼리의 평소 p50은 1.5ms였습니다. 정각 지연은 DB 외부 대기 시간이었고, 로컬에서 CFS 스로틀로 CPU가 부족한 상황을 만들었을 때 같은 형태의 지연이 재현됐습니다.

애플리케이션과 MySQL 측정값의 차이, nr_throttled, steal 값으로 slow query의 원인을 구분하는 기준을 정리했습니다.