VPN을 통한 psql 시간 측정: 네트워크 대기를 쿼리 작업과 분리하기

보고서는 데이터베이스 호스트에서 약 일 초, VPN을 통해서는 사 초에 끝나며, psql이 출력하는 숫자는 데이터베이스를 곧바로 가리킨다. 그 숫자는 클라이언트 쪽 스톱워치이지 서버의 측정값이 아니다. 문장이 나가는 길, 응답을 기다리는 시간, 행이 돌아오는 길을 모두 포함한다. 이 셋을 분리하는 것만이 어느 쪽을 조정할지 아는 방법이다.

psql 타이머가 실제로 재는 것

\timing on 클라이언트가 문장을 소켓에 쓰기 직전에 스톱워치를 시작하고 그 결과의 마지막 행을 읽었을 때 멈춘다. 서버 자체의 실행은 그 창 안 어딘가에 있고, 패킷이 터널에서 보내는 매 밀리초도 마찬가지다. 출력 어디에도 둘을 분리하지 않는다. EXPLAIN도 숫자를 출력하지만 그것은 서버가 만들고 클라이언트의 대기를 제외한다. 두 숫자, 두 가지 질문이다.

세션 하나를 시작하고 시간 측정을 켜 둔 채 관심 있는 문장을 그 안에서 실행한다. 세션을 재사용하면 연결 비용이 첫 측정에서 빠진다.

psql "host=db.internal port=5432 dbname=appdb user=app" \
  -c "\timing on" \
  -c "select count(*) from orders where created_at > now() - interval '1 day';"

숫자에는 결과 전송이 여전히 포함되며, 여기서는 그것이 원하는 바다. 새 호출이 더할 연결과 인증 교환은 더 이상 포함되지 않는다.

문장 하나를 세 경로에서 비교하라

같은 문장을 Unix 소켓, LAN 주소, VPN 호스트 이름으로 실행하고 셋을 비교한다. 마지막만 느리다면 쿼리가 변수가 아니다.

각 호출은 먼저 연결하고 그다음에야 문장을 재므로 연결 비용은 숫자 밖에 남고 전송은 안에 남는다. WHERE 절, 행 수, 클라이언트 머신을 동일하게 유지하라. 그렇지 않으면 경로가 아니라 작업량을 비교하는 셈이다.

psql -h /var/run/postgresql -U app -d appdb -c "\timing on" -c "select count(*) from orders;"
psql -h 10.40.0.12 -U app -d appdb -c "\timing on" -c "select count(*) from orders;"
psql -h db.vpn.internal -U app -d appdb -c "\timing on" -c "select count(*) from orders;"

LAN에서는 차이가 보통 무시할 만큼 작다. VPN을 통해서는 흔히 그렇지 않다. 세 결과를 정렬하면 어느 대기를 공격할지 알 수 있다.

로컬 소켓이 느리면 서버 작업이나 계획이다. LAN 결과가 느리면 쿼리나 그것이 옮기는 양이다. VPN 결과만 느리면 경로의 지연, MTU, 가용 대역폭이며 어떤 인덱스 변경도 그것을 고치지 않는다.

서버 자체의 실행 시간을 꺼내라

서버는 얼마나 많은 시간을 썼는지 보고할 수 있고, 클라이언트 숫자와 맞세워야 하는 값이 바로 그것이다. EXPLAIN에 ANALYZE를 붙이면 문장을 실행하고 계획 안에 계획 시간과 실행 시간을 출력하며, BUFFERS는 따뜻한 실행과 차가운 실행의 차이를 흔히 설명하는 캐시 동작을 더한다. 쓸 생각이 없다면 쓰기 문장에 겨누지 마라. 읽기 전용 복제본이 시작하기에 가장 안전한 곳이며, psql 참조 타이머의 클라이언트 측 범위를 문서화한다.

애플리케이션이 이미 실행하는 문장의 경우, pg_stat_statements는 아무것도 다시 실행하지 않고 서버 측 실행을 집계한다. 행은 정규화된 쿼리별이므로 한 항목이 여러 호출 지점을 덮을 수 있다.

select calls, round(mean_exec_time::numeric, 2) as mean_ms, rows
from pg_stat_statements
order by mean_exec_time desc
limit 5;

열 이름은 릴리스에 따라 다르다. PostgreSQL 13 이후는 mean_exec_time을 노출하고 오래된 버전은 mean_time이라 부르므로, 그 쿼리가 오류를 내면 \d pg_stat_statements 명령으로 확인하라. 이 값들은 계획을 제외하고 클라이언트까지의 왕복도 제외한다. 바로 그 제외가 이 값들을 비교에 유용하게 만든다.

밀리초만이 아니라 왕복 횟수를 세라

작은 의존 문장 이백 개로 만든 보고서는 경로가 더하는 지연을 이백 배로 만든다. 백만 행을 반환하는 문장 하나는 그 지연을 한 번 치르고 나서 오랫동안 대역폭을 치른다. 둘 다 클라이언트 타이머에서는 똑같아 보이고, 서로 반대되는 수정이 필요하다.

문장 수를 추정하지 말고 측정하라. 총계를 읽고 보고서를 한 번 실행한 뒤 다시 읽어 빼라.

select sum(calls) as calls from pg_stat_statements;
-- run the report here
select sum(calls) as calls from pg_stat_statements;

델타가 크고 각 문장이 서버에서 싸다면 배치가 값을 하는 수정이다. 의존 쿼리를 합치거나 집합 기반 문장 하나를 쓰거나 커서에서 루프를 돌려라. 대화형 psql에서는, \set FETCH_COUNT 1000 큰 결과가 묶음으로 도착하게 하고 전송과 클라이언트 메모리의 동작을 바꾼다. 서버 작업을 줄이지는 않으므로 느린 쿼리를 구하지는 못한다.

터널의 재전송과 MTU 정지를 확인하라

작은 문장은 빠른데 큰 결과가 중간에 멈춘다면 쿼리는 보통 괜찮고 경로가 아니다. MTU가 하위 링크보다 낮은 터널에 차단된 ICMP가 겹치면 정확히 그 패턴이 나온다. 첫 패킷은 도착하고 큰 패킷은 사라지며, 전송은 다시 시도할 때까지 매달린다. 클라이언트 측 재전송 카운터가 그것을 보여 준다.

일부러 느린 전송이 도는 동안 소켓과 커널 카운터를 지켜보라. 재전송 합계는 누적이므로 표본 하나를 읽는 대신 전후로 기록하라.

ss -tin dst 10.40.0.12
netstat -s | grep -iE "retransmit|segments retransmitted"
ping -M do -s 1400 -c 3 10.40.0.12

전송 중에 늘어나는 재전송과, 1400바이트에서 성공하고 1472에서 실패하는 ping은 데이터베이스 문제가 아니라 MTU 문제를 가리킨다. 터널 인터페이스의 MTU를 낮추거나 게이트웨이에서 MSS를 조이는 것이 보통의 수정이며, 같은 세 명령이 나중에 그것을 확인해 준다. 전송이 여전히 느린데 재전송이 평평하다면 손실이 아니라 터널에 허용된 대역폭을 보라.

짧은 순서가 다음 느린 보고서를 덮는다. 문장 하나를 로컬, LAN, VPN에서 비교하고, 서버 실행을 EXPLAIN이나 pg_stat_statements에서 읽고, 한 번 실행하기 전후로 호출을 세고, 큰 결과가 움직이는 동안 재전송을 지켜본다. 각 단계는 경로의 한쪽을 배제한다. 어느 것도 어느 구성 요소를 다시 시작할지 추측하라고 요구하지 않는다.