클라이언트가 잰 시간과 서버가 잰 시간

한 줄 요약

나가는 호출은 양쪽에서 잰다. 클라이언트 스팬과 서버 스팬의 차이가 곧 "서버 밖에서 쓴 시간" 이고, 그 시간을 스팬 경계 안에 넣지 않으면 사용자가 겪는 느림이 트레이스에 없다.

왜 이게 필요했나

장애 회의에서 가장 흔한 교착이 이것이다. 하류 팀은 "우리 p99 는 20밀리초" 라고 하고, 상류 팀은 "우리가 재면 300밀리초" 라고 한다. 둘 다 자기 대시보드를 보고 있고 둘 다 맞다. 다른 구간을 재고 있을 뿐이다.

서버가 재는 것은 요청 핸들러가 열려 있던 시간이다. 그 앞에는 연결을 얻고, 요청을 직렬화하고, 바이트를 보내고, 상대의 스레드 풀에서 차례를 기다리는 시간이 있다. 뒤에는 응답을 받아 역직렬화하는 시간이 있다. 클라이언트에서만 보이는 이 구간이 사용자가 실제로 기다린 시간의 대부분일 때가 많다.

더 나쁜 것은 커넥션 풀 대기다. 풀이 비어 있으면 호출을 보내기도 전에 기다리는데, 많은 계측이 풀에서 연결을 얻은 뒤에 스팬을 시작한다. 그러면 그 기다림은 어느 스팬에도 들어 있지 않다. 트레이스에는 30밀리초짜리 호출만 줄지어 있는데 루트 스팬은 2초다. 사람은 "빈 구간" 을 보며 원인을 찾지 못한다.

어떻게 동작하나

OpenTelemetry 는 나가는 호출에 SpanKind.CLIENT 를, 받는 쪽에 SpanKind.SERVER 를 쓴다. 이 둘은 한 트레이스 안에서 부모-자식으로 이어지고, 같은 논리적 작업을 서로 다른 관점에서 잰 한 쌍이다. 두 스팬의 시간 차이를 빼 보는 것이 이 실습의 출발점이다.

경계를 어디에 둘 것인가가 설계의 핵심이다. 규칙은 하나로 적을 수 있다 — 호출자가 응답을 기다리기 시작한 순간부터 응답을 손에 쥔 순간까지가 CLIENT 스팬이다. 연결을 얻으려고 기다린 시간도, 재시도 사이에 쉰 시간도 그 안에 있어야 사용자가 겪은 시간과 같아진다. 재시도는 시도마다 자식 스팬을 하나씩 두고 바깥 스팬이 전체를 덮는 모양이 읽기 좋다.

끊긴 호출은 짝이 어긋난다. 클라이언트가 120밀리초에 포기해도 서버는 400밀리초를 끝까지 일한다. 그러면 같은 트레이스에 120밀리초짜리 CLIENT 스팬과 400밀리초짜리 SERVER 스팬이 함께 남는다. 이 모양을 알아보지 못하면 "서버 스팬이 부모보다 길다" 를 계측 버그로 오해한다. 실제로는 자원이 새고 있다는 신호다 — 아무도 읽지 않을 응답을 서버가 계속 만들고 있다.

취소는 오류와 다르게 남겨야 한다. 사용자가 탭을 닫아 연결이 끊긴 것은 서비스의 실패가 아니다. 상태를 ERROR 로 올리면 오류율이 사용자의 행동에 따라 출렁이고, 그 지표로 건 경보는 새벽에 사람을 깨운다. [OpenTelemetry 의 스팬 상태 규약](https://opentelemetry.io/docs/specs/otel/trace/api/#set-status)은 상태를 Unset·Ok·Error 셋으로 두고, 오류로 올릴지는 계측하는 쪽이 정하게 한다. 취소는 상태를 그대로 두고 속성과 이벤트로 남기는 편이 다루기 쉽다.

속성 설계는 카디널리티 문제다. 나가는 호출의 대상을 적을 때 주소를 그대로 넣으면 주문 아이디와 파드 접미사가 값에 섞여 들어간다. [Semantic Conventions 의 RPC 규약](https://opentelemetry.io/docs/specs/semconv/rpc/rpc-spans/)이 rpc.service·rpc.method 를 따로 두는 이유가 이것이다 — 어느 서비스의 어느 연산인지는 값의 종류가 적고, 그래야 집계가 된다. 아이디는 속성 값이 아니라 필요할 때 이벤트나 로그로 내려간다.

덤프를 놓고 임계 경로나 반복 호출을 계산하는 법은 이 패스의 다른 실습이 다루고, 나가는 헤더에 무엇을 실을지는 자격 코스의 문맥 경계 실습이 다룬다. 여기서 하는 일은 그 둘 사이다 — 그런 계산이 성립하도록 나가는 쪽에 스팬을 어디서부터 어디까지 긋고 무엇을 붙일 것인가.

마지막으로, 한 요청이 같은 대상을 여러 번 부르는 일은 클라이언트 스팬이 있어야 보인다. 서버 쪽만 계측하면 하류에 스팬 여섯 개가 흩어져 있을 뿐, 그것이 한 요청에서 나갔다는 사실이 상류 트레이스에 드러나지 않는다. 대상과 연산을 저카디널리티 속성으로 붙여 두면 같은 짝이 몇 번 나갔는지 세는 일이 질의 한 줄이 된다.

현장에서 만나는 모습

결제 지연 조사에서 이런 트레이스를 본 적이 있다. 루트가 1.8초인데 자식 스팬을 다 더해도 0.4초였다. 나머지 1.4초는 어느 스팬에도 없었다. 원인은 커넥션 풀 크기가 2였고 한 요청이 하류를 여덟 번 부르고 있었던 것이다. 계측이 연결을 얻은 뒤에 스팬을 시작했기 때문에 대기 시간이 통째로 사라져 있었다. 스팬 시작을 풀 획득 앞으로 옮기는 세 줄짜리 변경으로 그 1.4초가 화면에 나타났고, 그제야 논의가 "왜 느린가" 에서 "풀을 늘릴 것인가 호출을 줄일 것인가" 로 넘어갔다.

다른 서비스에서는 반대로 타임아웃이 문제를 감추고 있었다. 클라이언트 타임아웃이 200밀리초라 대시보드의 p99 가 언제나 200밀리초에 붙어 있었다. 서버 쪽 스팬을 함께 보니 같은 트레이스에 1.2초짜리 SERVER 스팬이 남아 있었다. 클라이언트는 포기했고 서버는 계속 일하고 있었으며, 그 일감이 쌓여 뒤이은 요청을 더 느리게 만들고 있었다. 짝이 어긋난 스팬 쌍을 세는 질의 하나가 이 고리를 끊는 근거가 됐다.

다음 실습에서 할 것

같은 호출을 클라이언트와 서버 양쪽에서 재어 차이를 구하고, 그 차이를 대기열 시간과 나머지로 쪼갠다. 커넥션 풀 대기를 스팬 밖에 둔 경우와 안에 넣은 경우를 나란히 만들어 같은 일이 얼마나 다르게 보이는지 확인한다. 타임아웃으로 끊긴 호출의 짝을 두 덤프에서 찾아 맞추고, 취소된 호출을 오류와 다르게 남기는 규칙을 정한다. 그다음 대상 식별 속성을 저카디널리티로 설계해 값의 가짓수를 직접 세고, 한 요청이 같은 대상을 여섯 번 부르는 것을 클라이언트 스팬만으로 드러낸다. 마지막으로 그 규칙을 파일로 적고 두 번째 클라이언트에 그대로 적용한다.