Span의 Start/End Time을 임의로 지정할 수 있는 기능 추가

[libc-furiosa]

Motivation

• 기존 구현에서는 Span의 StartTime과 EndTime이 span의 life cycle에 의해서만 지정되도록 제한되어 있음
  • on_new_span(): 호출 시점의 SystemTime::now()로 start_time 정해짐
  • on_close() : 호출 시점의 SystemTime::now()로 end_time 정해짐
• 일반적인 함수 콜로 정의되는 span이 아닌, NPU Execution, Instruction의 경우 Span의 start ~ end를 계산에 의해 산출된 값으로 지정할 필요가 있어 SystemTime::now()가 아닌 임의의 값을 다룰 수 있어야 함

Solution

• 사전에 정의한 특수한 키(npu.start, npu.end)에 정해진 형식(nanos, u128)을 입력하는 경우 start_time, end_time으로 지정한 값이 사용되도록 기능을 추가함

Example

// start, end: Duration (since UNIX_EPOCH)

let span = info_span!("NPU Instruction", name,
        "npu.start" = start.as_nanos(), "npu.end" = end.as_nanos(),
        cat, base, pe_idx, exec_idx, inst_idx);
drop(span);

///

let span = info_span!("NPU Task", name = "Execution",
        "npu.start" = start.as_nanos(), "npu.end" = field::Empty,
        cat, base, pe_idx, exec_idx);
// ...
span.record("npu.end", end.as_nanos());
drop(span);

[ileixe]

저도 구체적인 아이디어가 있는건 아닌데 혹시 이 부분이 조금 더 general하게 넣을수 있는 API 포인트가 있을까요? 예를 들어 지금은 npu.start 라는 특정 string이 field에 들어가는 형태인데 다른 제 3의 방법이 있을까 해서요 (아마 없을거 같긴한데.. 😇 업스트림에 넣는게 계속 조금 아쉬워서 질문드립니다.)

[libc-furiosa]

아예 시간 정보를 attribute로 받지 않고, span에 대한 function call로 builder의 time을 update하는 방법을 찾았습니다. SpanExt trait을 만들고 Span에 대해 구현을 아래와 같이 하면 되는 것 같습니다.

// impl OpenTelemetrySpanExt for tracing::Span
    fn set_start_time(&self, start: SystemTime) {
        self.with_subscriber(|(id, subscriber)| {
            if let Some(get_context) = subscriber.downcast_ref::<WithContext>() {
                get_context.with_context(subscriber, id, |otel_data, _tracer| {
                    otel_data.builder.start_time = Some(start);
                })
            }
        });
    }
// ...
let span = info_span!("something", ...);
span.set_start_time(start_time);

다만 유일하게 문제가 되는 부분이 아래의 on_close() 부분인데요.
span을 drop하면 사실상 항상 호출되는 on_close에서 end_time을 now로 덮어버려서 set_end_time이 의미가 없게 되어버립니다.
이 부분만 회피할 수 있다면 tracing-opentelemetry를 수정하지 않아도 될 것 같습니다. 다만 해결할 수 있는 뾰족한 방법이 보이지 않네요.

[ileixe]

realtime clock을 쓰는 부분은 monotonic clock이랑 conflict가 없는지 확인해봐야 될 거 같아요. 저희는 지금 monotonic clock을 쓰고 있거든요.

[libc-furiosa]

그렇지 않아도 이 부분을 npu-tools에서 리뷰를 요청드리려 했었습니다.
Opentelemetry Span에서는 SystemTime을 기준으로 하다보니 Instant를 그대로 사용할 수는 없었는데요.
instrument의 경우 일반적인 방식으로 on_new_span과 on_close 시점의 SystemTime::now()가 적용되고,
NPU profiling의 경우 profiler.sync() 시 SystemTime::now() (기존의 Instant::now()를 대체)가 불리고 이를 기준으로 상대 시간으로 계산하고 있습니다.

기존 방식과 결과 자체는 다르지 않아 보이는데 검토는 필요할 것 같습니다. 이 내용은 npu-tools 쪽에 올릴 PR에서 자세히 다루면 좋을 것 같습니다.