dial9는 Tokio 런타임의 개별 이벤트를 저렴한 비용으로 기록해 애플리케이션 스팬·로그 및 Linux 커널 이벤트와 함께 전체 타임라인을 분석할 수 있게 해주는 런타임 텔레메트리 도구입니다.
이 글은 Russell Cohen의 게스트 포스트입니다. Russell이 dial9을 보여줬을 때, 나는 Tokio 커뮤니티가 반드시 봐야 한다고 확신했습니다. 그래서 이 글을 써 달라고 부탁했고 TokioConf에서 데모도 해 달라고 초대했습니다. — Carl
대부분의 새로운 것들과 마찬가지로, dial9도 어떤 문제를 해결하는 과정에서 만들게 되었습니다. 누군가 도움을 요청해 왔습니다. 그들은 서비스에 새로운 Rust 컴포넌트를 통합하고 있었는데, 성능 문제가 프로덕션에서만 재현되었습니다. 그 서비스는 동시에 수천 개의 다른 호스트에 연결하고 있었고, 이런 규모는 다른 환경에서는 재현이 불가능했습니다. 시스템은 CPU 사용률 90%까지는 잘 동작했지만, 그 이상부터는 성능이 급격히 떨어졌습니다. CPU 여유가 아직 남아 있었기 때문에 이 현상은 의외였습니다.
그들은 이미 Tokio 런타임 메트릭을 갖고 있었지만, 데이터가 말이 되지 않았습니다. 워커는 유휴 상태처럼 보이는데 큐는 가득 차 있었습니다. 우리는 무엇이 원인일지에 대한 가설은 있었지만, 실제로 무슨 일이 벌어졌는지에 대한 타임라인이 없어서 더 나아갈 근거가 부족했습니다.
런타임 이벤트의 전체 순서를 볼 수 있는 방법이 필요했고, 또한 프로덕션 호스트에서 돌릴 수 있을 만큼 저렴해야 했습니다. 그래서 dial9를 만들었습니다. 실행해 보니 원인은 분명했습니다. 애플리케이션에 10ms+ 커널 스케줄링 지연이 자주 발생하고 있었습니다. 5–10ms 범위의 지연 시간 프로파일을 유지하려고 한다면, 이는 치명적인 문제입니다.
dial9는 Tokio를 위한 런타임 텔레메트리 도구입니다. “현재 실행 중인 태스크 수는?” 또는 “p99 poll duration은?” 같은 집계 메트릭을 넘어, dial9는 개별 poll, park, wake 같은 런타임 이벤트를 카운터 묶음이 아니라 로그로서 캡처합니다. Tokio 런타임 이벤트, 여러분 애플리케이션의 스팬과 로그, 그리고 Linux 커널 이벤트를 결합해, 애플리케이션이 Tokio와 어떻게 상호작용하는지, 그리고 Tokio가 운영체제와 어떻게 상호작용하는지에 대한 전체 그림을 제공합니다.
dial9는 crates.io에 있으며, 지금 바로 사용해 볼 수 있습니다.
TokioConf에 참가합니다! 부스에서 저희를 찾아주시고 dial9 라이트닝 토크도 놓치지 마세요!
대규모로 Tokio를 운영할 때 팀들이 흔히 부딪히는 문제는, 때때로 집계 메트릭만으로도 추론할 수 있습니다. 하지만 그런 증거는 잘해야 정황증거에 불과한 경우가 많고, 내부 동작과 컴포넌트 간 상호작용에 대한 깊은 이해에 의존합니다. 운영체제와 연관 지어 전체 이벤트 타임라인을 보는 것은 차원이 다른 디버깅입니다. 몇 가지 예를 들어 보겠습니다.
커널 스케줄링 지연은 OS에서 “실행 가능 상태”와 “실제로 실행 중” 사이의 간격입니다. 스레드는 실행할 준비가 되었지만, 커널이 즉시 스케줄하지 않는 것입니다. dial9는 워커 park/unpark 시 커널 메타데이터를 읽기 때문에, 커널이 워커 실행을 실제로 언제 시작했는지와 시작했어야 하는 시점이 언제인지 정확히 볼 수 있습니다. 호스트가 바쁠수록 커널 스케줄링 지연을 겪을 가능성이 커집니다.
위에서 언급한 AWS 서비스의 경우, 10ms+ 스케줄링 지연이 자주 발생하는 것을 볼 수 있었습니다. 이 스크린샷(프로덕션의 실제 데이터)에서는 런타임이 워커 47을 깨우려 하지만, 커널이 실제로 스케줄링하기까지 18ms가 걸립니다. 이 동안 모든 트래픽은 단일 워커가 처리하고 있습니다.
또 다른 프로덕션 서비스에서는, 팀이 시작 시점에 끔찍한 p99 지연 시간을 보고 있었습니다. dial9는 많은 수의 동시 연결을 열 때, 태스크들이 fd_table 리사이즈 과정에서 디스케줄되는 것을 보여 주었습니다. fd_table은 열린 파일 디스크립터를 추적하며, 이를 리사이즈하려면 새 연결을 열려는 모든 워커를 막는 락이 필요합니다. 이 락의 경합 때문에 100ms+ poll이 발생했고, 애플리케이션 전체가 지연되었습니다. 이런 종류의 문제는 집계 메트릭만으로는 찾아내기 거의 불가능합니다.
dial9는 태스크의 전체 수명과 각 개별 poll을 볼 수 있기 때문에, 특정 태스크가 Tokio 워커들 사이를 어떻게 이동하는지 관찰할 수 있습니다.
Tokio의 I/O 드라이버가 동작하는 방식 때문에, 태스크가 소켓을 기다린 뒤 다음에 그것을 집어드는 워커는 사실상 무작위입니다. 이를 알고 있었음에도, 실제로 얼마나 두드러지는지 보고 놀랐습니다. 스틸링과 I/O wakeup 때문에 태스크는 모든 워커 사이를 자주 튕기듯 이동합니다. 이는 데이터 집약적인 애플리케이션이 캐시 라인 바운싱을 피하기 위해 코어당 런타임(runtime-per-core) 아키텍처에서 이득을 볼 수 있는 이유를 보여 줍니다.
이 트레이스에서는 하나의 개별 태스크(노란색으로 강조)가 2ms 동안 5개의 서로 다른 워커 사이를 이동하는 모습을 볼 수 있습니다.
backtrace::trace의 전역 락마지막 예시는 dial9 _내부_의 문제인데, dial9 로 발견한 것입니다.
나는 dial9에 태스크 덤프를 추가하는 작업을 시작했습니다. future가 Poll::Pending이 될 때마다, dial9가 백트레이스를 캡처해 정확히 어디서 yield했는지 알 수 있게 하려는 것이었습니다. 하지만 이를 활성화하자 오버헤드가 5%에서 50%로 증가했습니다. 그리고 워커 수를 늘릴수록 더 나빠졌습니다.
원인은 트레이스를 dial9에 로드하자마자 분명해졌습니다. 이 글을 쓰는 시점에서 backtrace::trace는 전역 락을 잡습니다. 백트레이스를 캡처하려는 모든 워커가 단 하나의 뮤텍스에서 경합하고 있었습니다. 나는 프레임 포인터 언와인딩은 협조 없이도 할 수 있다고 생각했는데, 기술적으로는 가능하지만 라이브러리가 미묘한 이유로 이를 위해 전역 락을 획득합니다.
dial9는 (뮤텍스 같은) 리소스를 기다리느라 커널이 스레드를 디스케줄하는 이벤트를 추적하고, 바로 그 순간의 스택 트레이스를 캡처합니다. 그래서 트레이스를 보면 명확했습니다. 모든 poll이 끝나기 전에 디스케줄되었고, 이 락 하나를 획득하려고 기다리고 있었습니다.
우리는 여전히 태스크 덤프를 작업 중입니다! 하지만 먼저 Tokio에 프레임 포인터 언와인딩(frame-pointer unwinding)과 백트레이스를 위한 지연 심볼라이징(lazy symbolizing)을 반영해야 합니다.
지금 바로 dial9를 사용할 수 있습니다! 이미 여러 팀이 프로덕션에서 실행하고 있습니다(하지만 당연히 어떤 새로운 소프트웨어든 그렇듯, 주의해서 사용하세요).
의존성을 추가하세요: cargo add dial9-tokio-telemetry:
[dependencies]
dial9-tokio-telemetry = "0.1"
TracedRuntime으로 런타임을 감싸세요:
use dial9_tokio_telemetry::telemetry::{RotatingWriter, TracedRuntime};
fn main() -> std::io::Result<()> {
let writer = RotatingWriter::new(
"/tmp/my_traces/trace.bin",
20 * 1024 * 1024, // rotate after 20 MiB
100 * 1024 * 1024, // keep at most 100 MiB on disk
)?;
let mut builder = tokio::runtime::Builder::new_multi_thread();
builder.worker_threads(4).enable_all();
let (runtime, _guard) = TracedRuntime::build_and_start(builder, writer)?;
runtime.block_on(async {
// your async code here
});
Ok(())
}
이게 전부입니다. 트레이스는 /tmp/my_traces/에 생성됩니다. 트레이스 뷰어에서 열고 .bin 파일을 그냥 드래그해 넣으면 됩니다. 어떻게 생겼는지 보려면 로드할 수 있는 데모 트레이스도 있습니다. dial9는 트레이스를 S3로 직접 쓰는 것도 지원합니다.
오버헤드는 보통 5% 미만입니다. RotatingWriter가 디스크 사용량을 제한하므로, 프로덕션에서 계속 실행해 둘 수 있습니다.
피드백을 기다립니다. GitHub에 이슈를 등록해 주세요.
마지막으로, dial9를 가능하게 해 준 모든 분들께 큰 감사를 전합니다. 특히 Jess Izen, Mark Rousskov, 그리고 AWS의 모든 초기 도입자 여러분께 감사드립니다.
TokioConf에서 만나요!