분산 추적

서비스가 하나였을 때는 느린 원인 찾기가 어렵지 않았습니다. 기록을 시간순으로 훑으면 어느 함수에서 오래 걸렸는지 나왔습니다. 여러 개로 나누면 그 방법이 통하지 않습니다. 각 서비스가 자기 기록만 남기고, 그 사이에 한 요청을 이어 줄 실이 없습니다.

페이지덱이 그 자리에 있었습니다. 문서 열기가 열 번에 한 번쯤 4초가 걸렸습니다. 태오가 네 개 서비스의 기록을 모두 열어 봤는데 각각은 정상이었습니다. 문서 서비스는 200밀리초, 권한 서비스는 80밀리초, 검색 서비스는 150밀리초였습니다. 합쳐도 4초가 안 되는데 남은 3.5초가 어디 있는지 알 방법이 없었습니다. 요청 하나만 따라가 보고 싶은데 각 서비스의 기록에서 어느 줄이 같은 요청인지 짚을 수 없었습니다.

분산 추적은 요청마다 고유한 표를 붙여 그 문제를 푸는 방법입니다. 표를 들고 다니게 하면 어느 기록이 같은 요청인지 이어지고, 구간마다 걸린 시간이 한 그림에 놓입니다. 태오가 붙인 뒤 찾은 원인은 네 서비스 가운데 어디도 아니었습니다. 권한 서비스를 세 번 호출하고 있었고 그중 두 번이 중복이었습니다.

요청 하나에 표를 붙이고, 그 요청이 거치는 구간마다 시작과 끝을 기록해 표로 묶습니다. 용어가 둘 있습니다. 요청 하나의 전체 여정을 트레이스라고 부르고, 그 안의 한 구간을 스팬이라고 부릅니다.

1. 표를 만듭니다. 요청이 처음 들어오는 자리에서 고유한 문자열을 만듭니다. 여러 서비스의 입구를 하나로 모아 주는 층인 API 게이트웨이가 있다면 대개 그 자리가 시작점입니다.
2. 표를 넘깁니다. 서비스가 다른 서비스를 호출할 때 그 표를 요청 머리에 실어 보냅니다. 중간에 한 서비스라도 표를 넘기지 않으면 그 뒤가 끊깁니다. 실무에서 추적이 반쪽만 보이는 이유가 거의 이것입니다.
3. 스팬을 남깁니다. 구간마다 시작 시각, 걸린 시간, 어느 서비스인지, 성공했는지를 기록합니다. 스팬은 부모와 자식 관계를 가져서, 문서 서비스 스팬 아래에 권한 조회 스팬이 자식으로 붙습니다. 이 관계가 있어야 호출 순서와 중첩이 보입니다.
4. 필요한 값을 태그로 붙입니다. 어느 사용자인지, 어느 문서인지, 어느 버전에서 돌았는지를 달아 둡니다. 나중에 느린 요청만 골라 보려면 기준이 여기 있어야 합니다.
5. 일부만 저장합니다. 모든 요청의 모든 구간을 남기면 기록량이 본 서비스보다 커집니다. 그래서 전체의 1에서 10퍼센트만 저장하고, 오류가 난 요청과 느린 요청은 비율과 상관없이 전부 저장하는 규칙을 함께 둡니다.

보는 화면은 가로 막대를 층층이 쌓은 그림입니다. 막대 길이가 걸린 시간이고 층이 호출 깊이입니다. 여기서 눈에 들어오는 것은 긴 막대 하나가 아니라 같은 막대가 세 번 반복되는 모양입니다.

가장 먼저 쓰이는 자리는 느린 원인을 찾는 일입니다. 평균은 멀쩡한데 열 번에 한 번 느린 경우가 특히 그렇습니다. 느린 요청만 골라 그림을 열면 어느 구간이 시간을 먹었는지 한눈에 나옵니다. 수치로 모아 시간축에 쌓는 메트릭은 평균이 올랐다는 사실까지만 알려 줍니다.

나머지 세 자리는 이렇습니다.

1. 장애 대응 — 서비스 다섯 개가 동시에 느려졌을 때 원인과 결과를 가려야 합니다. 조건을 넘으면 담당자에게 알리는 알림이 울린 직후 트레이스를 열면 호출 방향이 보여서 뒤쪽에서 막힌 서비스를 먼저 짚습니다. 문제가 터졌을 때 복구하고 재발을 막는 장애 대응의 첫 10분을 줄이는 자리입니다.
2. 의존 관계 확인 — 설계 문서의 호출 관계와 실제가 다른 경우가 많습니다. 트레이스를 모아 보면 실제 호출 그래프가 나오고, 아무도 기억하지 못하는 호출이 하나씩 발견됩니다.
3. 배포 전후 비교 — 같은 요청의 트레이스를 배포 전후로 놓으면 어느 구간이 늘었는지 나옵니다. 전체 응답 시간만 보면 20밀리초 차이가 묻히지만 구간별로 보면 한 구간이 두 배가 된 것이 드러납니다.

안 맞는 자리도 있습니다. 서비스가 하나뿐이면 이 장치는 과합니다. 붙이는 비용과 저장 비용이 드는데 이어 줄 구간이 없습니다. 기록을 잘 남기는 것으로 충분합니다.

"느린 요청 트레이스 하나 열어 봅시다. 어느 구간인지부터 봐야죠."

원인을 추측하지 말고 구간별 시간을 보자는 제안입니다.

"권한 서비스 스팬이 세 번 찍혔는데요. 두 번은 같은 호출입니다."

그림에서 중복 호출을 발견한 보고입니다.

"여기서 추적이 끊겼어요. 이 서비스가 표를 안 넘기고 있습니다."

전파가 빠진 구간을 짚는 지적입니다.

태오가 붙인 순서는 이랬습니다. 게이트웨이에서 표를 만들게 하고, 네 서비스가 표를 넘기도록 고치고, 샘플링을 5퍼센트로 두고 오류와 2초 초과는 전부 저장하게 했습니다. 나흘이 걸렸고 그중 이틀이 표를 넘기지 않던 검색 서비스 때문이었습니다.

문서 열기의 중복 호출을 걷어내자 느린 요청의 비율이 열 번에 한 번에서 100번에 한 번으로 줄었습니다. 그보다 값을 한 것은 그다음이었습니다. 다른 화면에서도 같은 종류의 중복 호출 두 건이 그림에서 그대로 보였습니다.

추적을 붙이면 기록이 필요 없어진다고 보는 경우가 가장 많습니다. 구간별 시간이 다 보이니 그렇게 느껴집니다. 하지만 트레이스는 어디서 오래 걸렸는지를 알려 주고 왜 그랬는지는 알려 주지 않습니다. 권한 조회가 3초 걸렸다는 사실 다음에 필요한 것은 어떤 값으로 조회했고 어떤 오류가 났는지인데, 그것은 기록에 있습니다. 스팬에 붙인 표를 기록에도 함께 남기면 그림에서 바로 그 요청의 기록으로 넘어갈 수 있습니다.

일부만 저장하면 문제를 놓친다고 보는 것도 흔합니다. 스무 번에 한 번만 본다는 뜻이니 불안합니다. 그런데 찾으려는 것은 특정 요청 하나가 아니라 반복되는 모양입니다. 같은 구간이 느린 요청이 하루에 2,000건 생긴다면 5퍼센트만 저장해도 100건이 남고, 100건이면 모양이 충분히 드러납니다. 놓치면 곤란한 것은 드물게 나는 오류인데, 그쪽은 전부 저장하는 규칙으로 따로 잡습니다.