Rust 서버 성능 개선을 위해 병목부터 측정해봤습니다

이번에는 각 API들이 얼마만큼의 시간을 소비하고, 어디서 가장 많은 시간을 소비하는지 측정하기 위하여 개인 프로젝트에 해당 시스템을 도입했습니다.

 

이에 대한 내용에 대해 적어볼까 합니다.

왜

서버 성능 향상을 위해, 어느 시점에 가장 많은 시간을 소요하는지, 이에 대한 해결책을 찾아보고자 해당 시스템을 도입하게 되었습니다.

 

현재 서버는 서버 -> nexon open api / DB -> 서버 -> 클라이언트 구조를 기본적으로 가지고 있습니다.

 

여기서 어느 시점에 가장 오래걸리는지 확인하기 위하여 다음과 같이 구간을 나누었습니다.

• Nexon open api
• DB
• Logic
• Rest api
• Cache

어떻게?

현재 사용중인 tracing-subscriber을 활용하였습니다.

 

가장 먼저 해당 로직은 release모드가 아닌 debug모드에서만 작동해야 하므로, 다음과 같은 로직을 추가했습니다.

pub fn is_enabled() -> bool {
    cfg!(debug_assertions)
}

현재 로직이 처리하기 전 시간과, run을 통해 처리한 후의 시간을 비교해서 log_summary를 보여지도록 코드를 작성했습니다.

pub async fn middleware(request: Request, next: Next) -> Response {
    // 디버그 모드인지 확인
    if !is_enabled() {
        return next.run(request).await;
    }

    let method = request.method().to_string();
    let uri = request
        .uri()
        .path_and_query()
        .map(|pq| pq.as_str().to_owned())
        .unwrap_or_else(|| request.uri().path().to_owned());

    // 현재부터 로직이 처리되고 난 후의 시간 비교
    scope(async move {
        let started = Instant::now();
        let response = next.run(request).await;
        log_summary(&method, &uri, started.elapsed());
        response
    })
    .await
}

이후, Router 최상단에 해당 미들웨어를 추가했습니다.

.layer(middleware::from_fn(request_timing_middleware))

log_summary는 다음과 같이 작성되어 있습니다.

 

각 요청별로 시간을 측정해야 하기 때문에, RefCell로 지정해서 사용하였습니다.

tokio::task_local! {
    static REQUEST_TIMING: RefCell<RequestTiming>;
}

#[derive(Default, Clone, Debug)]
struct RequestTiming {
    nexon_ms: u64,
    nexon_cache_hits: u32,
    nexon_cache_misses: u32,
    db_ms: u64,
    external_ms: u64,
}

fn fmt_ms(ms: u64) -> String {
    format!("{:>5}ms", ms)
}

fn fmt_route(uri: &str) -> String {
    let chars: Vec<char> = uri.chars().collect();
    if chars.len() <= ROUTE_WIDTH {
        return format!("{uri:<ROUTE_WIDTH$}");
    }
    let truncated: String = chars.iter().take(ROUTE_WIDTH - 1).collect();
    format!("{:<width$}", format!("{truncated}…"), width = ROUTE_WIDTH)
}

fn log_summary(method: &str, uri: &str, total: Duration) {
    let Some(timing) = REQUEST_TIMING.try_with(|cell| cell.borrow().clone()).ok() else {
        return;
    };

    // 전체 시간
    let total_ms = total.as_millis() as u64;
    let accounted = timing
        .nexon_ms
        .saturating_add(timing.db_ms)
        .saturating_add(timing.external_ms);
    let rest_ms = total_ms.saturating_sub(accounted);

    println!(
        "  {:<METHOD_WIDTH$}  {}  {}  {}  {}  {}  {}  h{}/m{}",
        method,
        fmt_route(uri),
        fmt_ms(total_ms),
        fmt_ms(timing.nexon_ms),
        fmt_ms(timing.db_ms),
        fmt_ms(timing.external_ms),
        fmt_ms(rest_ms),
        timing.nexon_cache_hits,
        timing.nexon_cache_misses,
    );
}

각 함수를 다음과 같은 방식으로 묶어서 사용하였습니다.

함수	용도
timed_nexon(cache_hit, f)	Nexon HTTP 호출
record_nexon(duration, cache_hit)	캐시 hit 시
timed_db(f)	DB 쿼리
timed_external(f)	Nexon 외 외부 HTTP

결과

해당 로직을 적용하고 debug모드로 구동시, 다음과 같이 로그가 작성됩니다.

  METHOD  ROUTE                                                 TOTAL    NEXON       DB      EXT     REST  CACHE
  ────────────────────────────────────────────────────────────────────────────────────────
  GET     /api/notices/cash-shop                                170ms    169ms      0ms      0ms      1ms  h0/m1

각각의 의미는 다음과 같습니다.

컬럼	의미
TOTAL	미들웨어 진입 ~ 응답 반환까지 전체 시간
NEXON	Nexon API 호출 + 캐시 lookup 시간 합
DB	DB 쿼리 시간 합
EXT	Nexon 외 외부 HTTP
REST	TOTAL - (NEXON + DB + EXT) — JSON 파싱, Axum 처리 등 미계측 구간
CACHE	h{hit}/m{miss} — Nexon 캐시 hit/miss 횟수

이로 인하여 얻은 효과

내 서버에서 시간이 오래 걸린다면, 해당 시스템을 추가하고 얻는 효과가 있을거라고 생각했습니다.

 

그러나, 실질적으로 확인해본 결과, 1명의 캐릭터 정보를 클라이언트에서 모두 불러오는데 1초가량의 시간이 걸렸고, 그 중 90%의 시간이 Nexon open api에서 정보를 불러와 사용하는데 걸렸습니다.

 

이미 캐시도 처리되어 있어, 실직적인 성능 향상 방법은 없습니다.

 

Rust로 웹 백엔드를 구성하시는 분들에게는 도움이 되었으면 하여 해당 방식에 대하여 포스팅하게 되었습니다.