feat(observability): add fine-grained OTel spans for the plugin pipeline and model selector - #165
feat(observability): add fine-grained OTel spans for the plugin pipeline and model selector#165gyliu513 wants to merge 4 commits into
Conversation
|
/cc @nirrozenbaum |
| defer stageSpan.End() | ||
|
|
||
| for _, reqPlugin := range reqPlugins { | ||
| name := reqPlugin.TypedName() |
There was a problem hiding this comment.
nit: maybe better to name this typedName?
it reads a bit strange name.Type and name.Name.
| name := reqPlugin.TypedName() | |
| typedName := reqPlugin.TypedName() |
There was a problem hiding this comment.
Done, renamed to typedName here and in the response/filter/scorer/picker loops for consistency. Thanks.
| pluginCtx, span := tracer.Start(ctx, "plugin."+name.Type, | ||
| trace.WithSpanKind(trace.SpanKindInternal), | ||
| trace.WithAttributes( | ||
| attribute.String("llm_d.plugin.extension_point", requestPluginExtensionPoint), | ||
| attribute.String("llm_d.plugin.type", name.Type), | ||
| attribute.String("llm_d.plugin.name", name.Name), | ||
| )) |
There was a problem hiding this comment.
I'm not a tracing expert so forgive me if the question is obvious..
why do we specify type twice?
once in plugin.name.Type and another one in attribute?
There was a problem hiding this comment.
Good question, it's intentional.
The span name (plugin.type)is the human-readable label shown in trace UIs; it's meant to be low-cardinality and isn't reliably queryable across tracing backends.
The llm_d.plugin.type attribute is the structured, indexable dimension you filter and aggregate on (e.g. "p99 latency grouped by plugin type"). Per OTel conventions, the span name is for display and attributes carry the queryable data, so keeping both is by design.
| defer stageSpan.End() | ||
|
|
||
| for _, respPlugin := range respPlugins { | ||
| name := respPlugin.TypedName() |
|
|
||
| tracer := tracing.Tracer(modelSelectorTracerScope) | ||
| for _, filter := range p.filters { | ||
| name := filter.TypedName() |
| if result != nil && result.TargetModel != nil { | ||
| span.SetAttributes(attribute.String("llm_d.picker.selected_model", result.TargetModel.GetName())) | ||
| } |
There was a problem hiding this comment.
Picker is guaranteed to select a target model. we can remove the conditional.
| if result != nil && result.TargetModel != nil { | |
| span.SetAttributes(attribute.String("llm_d.picker.selected_model", result.TargetModel.GetName())) | |
| } | |
| span.SetAttributes(attribute.String("llm_d.picker.selected_model", result.TargetModel.GetName())) |
| span.RecordError(err) | ||
| span.SetStatus(codes.Error, err.Error()) | ||
| } else if result != nil && result.TargetModel != nil { | ||
| span.SetAttributes(attribute.String("llm_d.model_selector.selected_model", result.TargetModel.GetName())) |
There was a problem hiding this comment.
this would fit better before the log line Model selection completed. without the conditionals.
nirrozenbaum
left a comment
There was a problem hiding this comment.
@gyliu513 thanks, overall looks good.
left few minor comments.
| defer stageSpan.End() | ||
|
|
||
| for _, reqPlugin := range reqPlugins { | ||
| name := reqPlugin.TypedName() |
There was a problem hiding this comment.
Done, renamed to typedName here and in the response/filter/scorer/picker loops for consistency. Thanks.
| pluginCtx, span := tracer.Start(ctx, "plugin."+name.Type, | ||
| trace.WithSpanKind(trace.SpanKindInternal), | ||
| trace.WithAttributes( | ||
| attribute.String("llm_d.plugin.extension_point", requestPluginExtensionPoint), | ||
| attribute.String("llm_d.plugin.type", name.Type), | ||
| attribute.String("llm_d.plugin.name", name.Name), | ||
| )) |
There was a problem hiding this comment.
Good question, it's intentional.
The span name (plugin.type)is the human-readable label shown in trace UIs; it's meant to be low-cardinality and isn't reliably queryable across tracing backends.
The llm_d.plugin.type attribute is the structured, indexable dimension you filter and aggregate on (e.g. "p99 latency grouped by plugin type"). Per OTel conventions, the span name is for display and attributes carry the queryable data, so keeping both is by design.
| defer stageSpan.End() | ||
|
|
||
| for _, respPlugin := range respPlugins { | ||
| name := respPlugin.TypedName() |
|
|
||
| tracer := tracing.Tracer(modelSelectorTracerScope) | ||
| for _, filter := range p.filters { | ||
| name := filter.TypedName() |
| span.RecordError(err) | ||
| span.SetStatus(codes.Error, err.Error()) | ||
| } else if result != nil && result.TargetModel != nil { | ||
| span.SetAttributes(attribute.String("llm_d.model_selector.selected_model", result.TargetModel.GetName())) |
| if result != nil && result.TargetModel != nil { | ||
| span.SetAttributes(attribute.String("llm_d.picker.selected_model", result.TargetModel.GetName())) | ||
| } |
b367c50 to
ea46ec9
Compare
| span.End() | ||
| } | ||
|
|
||
| return nil |
There was a problem hiding this comment.
Seems that we may want to add more test coverage for these changes:
We need a test that does this:
- Set up a
tracetest.SpanRecorder(as done intelemetry_test.go). - Run
runRequestPluginswith one or more fake plugins. - Assert that a
request_pluginsstage span is created with childplugin.*spans. - Assert that a failing plugin produces a span with
codes.Errorstatus.
If I'm not mistaken, I don't believe we have that currently which would leave an opportunity for regressions.
There was a problem hiding this comment.
I'll add a runRequestPlugins test using a tracetest.SpanRecorder (mirroring telemetry_test.go) with fake plugins that asserts the request_plugins stage span, nested plugin.* child spans, and a codes.Error status when a plugin fails.
There was a problem hiding this comment.
Should we now use the new tracing.Tracer helper?
There was a problem hiding this comment.
Yes, I'll fix it. It was merged after I created this PR.
There was a problem hiding this comment.
A new constant for this was added above but we're not using it here yet.
There was a problem hiding this comment.
Yes, I'll fix it. It was merged after I created this PR.
| before := time.Now() | ||
| result := p.picker.Pick(ctx, cycleState, scoredModels) | ||
| metrics.RecordPluginProcessingLatency(pickerExtensionPoint, p.picker.TypedName().Type, p.picker.TypedName().Name, time.Since(before)) | ||
| result := p.picker.Pick(spanCtx, cycleState, scoredModels) |
There was a problem hiding this comment.
It appears that this call may be able to return a nil value for TargetModel?
If it does we will panic on GetName() below.
There was a problem hiding this comment.
Hi @shaneutt , @nirrozenbaum post a comment here and I agree that the Picker is guaranteed to select a target model, do we still need the guard?
| debugLogger.Info("Completed running picker plugin", "plugin", typedName, "result", result) | ||
| } | ||
|
|
||
| return result |
There was a problem hiding this comment.
I think we're in a situation with this one, as before, where test coverage needs expansion.
There was a problem hiding this comment.
Yes, will add a test case
| return nil, err | ||
| } | ||
|
|
||
| span.SetAttributes(attribute.String("llm_d.model_selector.selected_model", result.TargetModel.GetName())) |
There was a problem hiding this comment.
Similar to above: no nil guards
There was a problem hiding this comment.
This one is already safe — lines 91-94 guard immediately
|
|
||
| // instrumentationName is the default OTel instrumentation scope used when no | ||
| // explicit scope is supplied to Tracer. | ||
| const instrumentationName = "llm-d-inference-payload-processor" |
There was a problem hiding this comment.
I recommend shortning the name. How about:
| const instrumentationName = "llm-d-inference-payload-processor" | |
| const instrumentationName = "llm-d-ipp" |
| const instrumentationName = "llm-d-inference-payload-processor" | ||
|
|
||
| // Tracer returns a tracer for the given instrumentation scope, defaulting to | ||
| // "llm-d-inference-payload-processor". The build version and commit SHA are |
There was a problem hiding this comment.
| // "llm-d-inference-payload-processor". The build version and commit SHA are | |
| // "llm-d-ipp". The build version and commit SHA are |
|
|
||
| // handlersTracerScope is the OTel instrumentation scope for spans emitted by | ||
| // the request/response handlers, following the package-path naming convention. | ||
| handlersTracerScope = "llm-d-inference-payload-processor/pkg/handlers" |
There was a problem hiding this comment.
@shmuelk with your above comment, do we need to update here as well to
| handlersTracerScope = "llm-d-inference-payload-processor/pkg/handlers" | |
| handlersTracerScope = "llm-d-ipp/pkg/handlers" |
| // modelSelectorTracerScope is the OTel instrumentation scope for spans | ||
| // emitted by the model-selector pipeline, following the package-path | ||
| // naming convention. | ||
| modelSelectorTracerScope = "llm-d-inference-payload-processor/pkg/modelselector" |
There was a problem hiding this comment.
@shmuelk ditto here, how about
| modelSelectorTracerScope = "llm-d-inference-payload-processor/pkg/modelselector" | |
| modelSelectorTracerScope = "llm-d-ipp/pkg/modelselector" |
bacd262 to
5b3594e
Compare
|
@shmuelk @shaneutt @nirrozenbaum can you help review? |
|
This PR is marked as stale after 21d of inactivity. After an additional 14d of inactivity (7d to become rotten, then 7d more), it will be closed. To prevent this PR from being closed, add a comment or remove the |
5b3594e to
cc6fe05
Compare
|
@shmuelk @shaneutt @nirrozenbaum can you help review? I think all comments are addressed. |
56cbcd0 to
293942a
Compare
|
A similar PR is being discussed in the ll-d-router repo.Some, including myself think this very low level tracing is too much. All of my requested changes have been made. From my perspective this PR can be merged if the functionality is desired and not deemed to be too much. |
|
@shmuelk I was talking with @elevran at llm-d/llm-d-router#1834, but I think we should be good to merge this. |
293942a to
2e6cff8
Compare
|
@shmuelk @nirrozenbaum can we get this merged? I can do some performance test later |
|
@shmuelk llm-d/llm-d-router#1834 has been merged, can you help merge this as well? I want to have this in next release, thanks! |
|
This PR is marked as stale after 21d of inactivity. After an additional 14d of inactivity (7d to become rotten, then 7d more), it will be closed. To prevent this PR from being closed, add a comment or remove the |
…ine and model selector Signed-off-by: Guangya Liu <gyliu513@gmail.com>
Signed-off-by: Guangya Liu <gyliu513@gmail.com>
Signed-off-by: Guangya Liu <gyliu513@gmail.com>
2e6cff8 to
b603127
Compare
|
Hey @nirrozenbaum , I think this can be merged, can you help check? |
nirrozenbaum
left a comment
There was a problem hiding this comment.
@gyliu513 thank you for the PR.
left some comments/questions
| logger.Error(err, "Failed to execute request plugin", "plugin", reqPlugin.TypedName()) | ||
| span.RecordError(err) | ||
| span.SetStatus(codes.Error, err.Error()) | ||
| span.End() |
There was a problem hiding this comment.
nit: can we have
defer span.End()
only once after we create it in L177 instead of having writing it twice?
There was a problem hiding this comment.
Good catch on the duplication, but a plain defer span.End() right after tracer.Start() here wouldn't do what we want, since the span is created inside the for loop body of this function (not a per-iteration helper), the defer would only fire when runRequestPlugins returns, not per plugin, so all the per-plugin spans would stay open until the loop finishes and get bogus end-times. llm-d-router's runScorer (scheduler_profile.go:288-289) hits the same shape and solves it by extracting the per-plugin span+call into its own function so the defer scopes correctly per call. I can refactor runRequestPlugins/runResponsePlugins the same way if you'd like, happy to do that as a follow-up in this PR.
There was a problem hiding this comment.
yeah extracting to a helper function would make it nicer :)
| logger.Error(err, "Failed to execute response plugin", "plugin", respPlugin.TypedName()) | ||
| span.RecordError(err) | ||
| span.SetStatus(codes.Error, err.Error()) | ||
| span.End() |
| verboseLogger.Info("Running filter plugin", "plugin", filter.TypedName()) | ||
| verboseLogger.Info("Running filter plugin", "plugin", typedName) | ||
| } | ||
| spanCtx, span := tracer.Start(ctx, "plugin."+typedName.Type, |
There was a problem hiding this comment.
what happens if there are multiple plugins from the same type?
isn't it better to have `plugin. +typedName.String()' to include both type and name here?
There was a problem hiding this comment.
This mirrors the convention llm-d-router uses for its scorer spans (scheduler_profile.go:288), span name carries just the Type for low cardinality, and both llm_d.plugin.type/llm_d.plugin.name are separate attributes for the actual instance. If two plugin instances share a Type, their spans will look identical by name in the waterfall, but the attributes (visible on hover in Jaeger/Tempo/etc.) disambiguate them. Keeping it consistent with llm-d-router's existing pattern rather than introducing a different naming scheme here, but open to revisiting org-wide if you feel disambiguation-by-name is worth the cardinality cost.
There was a problem hiding this comment.
I'm not a tracing expert, but I think it might be worth considering revisiting this point.
looking on a waterfall of spans, it should be clear what each refers to without having to drill down.
e.g., if we see multiple spans like this there's no way to understand without drilling down:
https://github.com/llm-d/llm-d-router/blob/db17418ade6cd5a15c6bbb04c9d0f0089c37034f/pkg/epp/framework/plugins/scheduling/scorer/endpointattribute/endpointattribute.go#L32
| verboseLogger.Info("Running scorer plugin", "plugin", scorer.TypedName()) | ||
| verboseLogger.Info("Running scorer plugin", "plugin", typedName) | ||
| } | ||
| spanCtx, span := tracer.Start(ctx, "plugin."+typedName.Type, |
| trace.WithAttributes( | ||
| attribute.String("llm_d.plugin.extension_point", scorerExtensionPoint), | ||
| attribute.String("llm_d.plugin.type", typedName.Type), | ||
| attribute.String("llm_d.plugin.name", typedName.Name), | ||
| attribute.Int("llm_d.scorer.candidate_count", len(models)), | ||
| attribute.Float64("llm_d.scorer.weight", scorer.Weight()), |
There was a problem hiding this comment.
I think this should come after the Score function and include the score as well.
ideally one would like to see in the traces the scorer typed name, the score and and the weight.
score is missing cause it's too early.
There was a problem hiding this comment.
Agreed, this is worth fixing. llm-d-router (scheduler_profile.go:297-316) and llm-d-kv-cache (traced_scorer.go:60-82) both do this: span.SetAttributes(...) right after Score() returns, recording aggregate score.max/score.avg (not per-model, to keep cardinality bounded). I'll follow the same pattern here — add llm_d.scorer.score.max/llm_d.scorer.score.avg computed from scores right before span.End().
There was a problem hiding this comment.
apologize for picking to this point.
I'm not sure max/avg gives us information that's really helpful in terms of observability.
I was thinking on a more detailed option, something like creating a new span scores and then have a entry with two attributes - target and score (and I would recommend doing the same in llm-d-router).
that could allow us to drill into a specific request and understand what was the score for each of the models/endpoints, the span one level up can specify the selected target.
in case max-picker is used, then obviously it's the target with max score, but in case a different picker is used, it's not obvious which would get selected.
Signed-off-by: Guangya Liu <gyliu513@gmail.com>
What type of PR is this?
/kind feature
What this PR does / why we need it:
Adds fine-grained OpenTelemetry spans for IPP's request/response plugin pipeline and the model-selector pipeline (filters → scorers → picker), so a single sampled request shows which plugins ran, in what order, and how long each took, instead of one opaque
gateway.requestspan.Until now the entire request lifecycle produced exactly one span.
Which issue(s) this PR fixes:
Fixes #163
Release note (write
NONEif no user-facing change):