diff --git a/core/providers/anthropic/anthropic.go b/core/providers/anthropic/anthropic.go index decc3b5e3d5..231cb090dff 100644 --- a/core/providers/anthropic/anthropic.go +++ b/core/providers/anthropic/anthropic.go @@ -997,8 +997,12 @@ func HandleAnthropicChatCompletionStreaming( continue } var event AnthropicStreamEvent - if err := sonic.Unmarshal([]byte(eventData), &event); err != nil { - logger.Warn("Failed to parse message_start event: %v", err) + // Per-event decode -> "response-parse" (Serialization) stream phase. + parseStart := time.Now() + umErr := sonic.Unmarshal([]byte(eventData), &event) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + logger.Warn("Failed to parse message_start event: %v", umErr) continue } if event.Type == AnthropicStreamEventTypeMessageStart && event.Message != nil && event.Message.ID != "" { @@ -1172,7 +1176,10 @@ func HandleAnthropicChatCompletionStreaming( } } + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() response, bifrostErr, isLastChunk := event.ToBifrostChatCompletionStream(ctx, structuredOutputToolName, streamState) + schemas.AddStreamConvert(ctx, time.Since(convStart)) if bifrostErr != nil { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) providerUtils.ProcessAndSendBifrostError(ctx, postHookRunner, bifrostErr, responseChan, logger, postHookSpanFinalizer) diff --git a/core/providers/bedrock/bedrock.go b/core/providers/bedrock/bedrock.go index 4a1d0f11d7a..0df58cc8d35 100644 --- a/core/providers/bedrock/bedrock.go +++ b/core/providers/bedrock/bedrock.go @@ -1204,13 +1204,16 @@ func (provider *BedrockProvider) TextCompletionStream(ctx *schemas.BifrostContex } } - // Parse the chunk payload + // Parse the chunk payload. Per-event decode -> "response-parse" (Serialization) stream phase. var chunkPayload struct { Bytes []byte `json:"bytes"` } - if err := sonic.Unmarshal(message.Payload, &chunkPayload); err != nil { - provider.logger.Debug("Failed to parse JSON from event buffer: %v, data: %s", err, string(message.Payload)) - providerUtils.ProcessAndSendError(ctx, postHookRunner, err, responseChan, provider.logger, postHookSpanFinalizer) + parseStart := time.Now() + umErr := sonic.Unmarshal(message.Payload, &chunkPayload) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + provider.logger.Debug("Failed to parse JSON from event buffer: %v, data: %s", umErr, string(message.Payload)) + providerUtils.ProcessAndSendError(ctx, postHookRunner, umErr, responseChan, provider.logger, postHookSpanFinalizer) return } @@ -1575,11 +1578,15 @@ func (provider *BedrockProvider) ChatCompletionStream(ctx *schemas.BifrostContex } } - // Converse API path: parse Bedrock Converse-specific stream events + // Converse API path: parse Bedrock Converse-specific stream events. + // Per-event decode -> "response-parse" (Serialization) stream phase. var streamEvent BedrockStreamEvent - if err := sonic.Unmarshal(message.Payload, &streamEvent); err != nil { - provider.logger.Debug("Failed to parse JSON from event buffer: %v, data: %s", err, string(message.Payload)) - providerUtils.ProcessAndSendError(ctx, postHookRunner, err, responseChan, provider.logger, postHookSpanFinalizer) + parseStart := time.Now() + umErr := sonic.Unmarshal(message.Payload, &streamEvent) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + provider.logger.Debug("Failed to parse JSON from event buffer: %v, data: %s", umErr, string(message.Payload)) + providerUtils.ProcessAndSendError(ctx, postHookRunner, umErr, responseChan, provider.logger, postHookSpanFinalizer) return } @@ -1696,7 +1703,10 @@ func (provider *BedrockProvider) ChatCompletionStream(ctx *schemas.BifrostContex } } + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() response, bifrostErr, _ := streamEvent.ToBifrostChatCompletionStream(streamState) + schemas.AddStreamConvert(ctx, time.Since(convStart)) if bifrostErr != nil { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) providerUtils.ProcessAndSendBifrostError(ctx, postHookRunner, bifrostErr, responseChan, provider.logger, postHookSpanFinalizer) @@ -1994,11 +2004,15 @@ func (provider *BedrockProvider) ResponsesStream(ctx *schemas.BifrostContext, po } } - // Converse API path: parse Bedrock Converse-specific stream events + // Converse API path: parse Bedrock Converse-specific stream events. + // Per-event decode -> "response-parse" (Serialization) stream phase. var streamEvent BedrockStreamEvent - if err := sonic.Unmarshal(message.Payload, &streamEvent); err != nil { - provider.logger.Debug("Failed to parse JSON from event buffer: %v, data: %s", err, string(message.Payload)) - providerUtils.ProcessAndSendError(ctx, postHookRunner, err, responseChan, provider.logger, postHookSpanFinalizer) + parseStart := time.Now() + umErr := sonic.Unmarshal(message.Payload, &streamEvent) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + provider.logger.Debug("Failed to parse JSON from event buffer: %v, data: %s", umErr, string(message.Payload)) + providerUtils.ProcessAndSendError(ctx, postHookRunner, umErr, responseChan, provider.logger, postHookSpanFinalizer) return } @@ -2062,7 +2076,10 @@ func (provider *BedrockProvider) ResponsesStream(ctx *schemas.BifrostContext, po } } + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() responses, bifrostErr, _ := streamEvent.ToBifrostResponsesStream(chunkIndex, streamState) + schemas.AddStreamConvert(ctx, time.Since(convStart)) if bifrostErr != nil { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) providerUtils.ProcessAndSendBifrostError(ctx, postHookRunner, bifrostErr, responseChan, provider.logger, postHookSpanFinalizer) diff --git a/core/providers/cohere/cohere.go b/core/providers/cohere/cohere.go index fdd472b95b9..8e21020a9b5 100644 --- a/core/providers/cohere/cohere.go +++ b/core/providers/cohere/cohere.go @@ -568,10 +568,13 @@ func (provider *CohereProvider) ChatCompletionStream(ctx *schemas.BifrostContext eventData := string(data) - // Parse the unified streaming event + // Parse the unified streaming event. Per-event decode -> "response-parse" (Serialization) stream phase. var event CohereStreamEvent - if err := sonic.Unmarshal(data, &event); err != nil { - provider.logger.Warn("Failed to parse stream event: %v", err) + parseStart := time.Now() + umErr := sonic.Unmarshal(data, &event) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + provider.logger.Warn("Failed to parse stream event: %v", umErr) continue } @@ -580,7 +583,10 @@ func (provider *CohereProvider) ChatCompletionStream(ctx *schemas.BifrostContext responseID = *event.ID } + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() response, bifrostErr, isLastChunk := event.ToBifrostChatCompletionStream() + schemas.AddStreamConvert(ctx, time.Since(convStart)) if bifrostErr != nil { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) providerUtils.ProcessAndSendBifrostError(ctx, postHookRunner, bifrostErr, responseChan, provider.logger, postHookSpanFinalizer) @@ -855,17 +861,23 @@ func (provider *CohereProvider) ResponsesStream(ctx *schemas.BifrostContext, pos eventData := string(data) - // Parse the unified streaming event + // Parse the unified streaming event. Per-event decode -> "response-parse" (Serialization) stream phase. var event CohereStreamEvent - if err := sonic.Unmarshal(data, &event); err != nil { - provider.logger.Warn("Failed to parse stream event: %v", err) + parseStart := time.Now() + umErr := sonic.Unmarshal(data, &event) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + provider.logger.Warn("Failed to parse stream event: %v", umErr) continue } // Note: response.created and response.in_progress are now emitted by ToBifrostResponsesStream // from the message_start event, so we don't need to call them manually here + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() responses, bifrostErr, isLastChunk := event.ToBifrostResponsesStream(chunkIndex, streamState) + schemas.AddStreamConvert(ctx, time.Since(convStart)) if bifrostErr != nil { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) providerUtils.ProcessAndSendBifrostError(ctx, postHookRunner, bifrostErr, responseChan, provider.logger, postHookSpanFinalizer) diff --git a/core/providers/gemini/gemini.go b/core/providers/gemini/gemini.go index dc859f1a7f7..d74565518be 100644 --- a/core/providers/gemini/gemini.go +++ b/core/providers/gemini/gemini.go @@ -559,8 +559,10 @@ func HandleGeminiChatCompletionStream( providerUtils.ProcessAndSendError(ctx, postHookRunner, readErr, responseChan, logger, postHookSpanFinalizer) return } - // Process chunk using shared function + // Process chunk using shared function. Per-event decode -> "response-parse" (Serialization) stream phase. + parseStart := time.Now() geminiResponse, err := processGeminiStreamChunk(eventData) + schemas.AddStreamParse(ctx, time.Since(parseStart)) if err != nil { if strings.Contains(err.Error(), "gemini api error") { // Handle API error @@ -581,8 +583,10 @@ func HandleGeminiChatCompletionStream( modelName = geminiResponse.ModelVersion } - // Convert to Bifrost stream response + // Convert to Bifrost stream response. Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() response, bifrostErr, isLastChunk := geminiResponse.ToBifrostChatCompletionStream(streamState) + schemas.AddStreamConvert(ctx, time.Since(convStart)) if bifrostErr != nil { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) providerUtils.ProcessAndSendBifrostError(ctx, postHookRunner, providerUtils.EnrichError(ctx, bifrostErr, jsonBody, nil, sendBackRawRequest, sendBackRawResponse, latency), responseChan, logger, postHookSpanFinalizer) @@ -1072,8 +1076,10 @@ func HandleGeminiResponsesStream( return } - // Process chunk using shared function + // Process chunk using shared function. Per-event decode -> "response-parse" (Serialization) stream phase. + parseStart := time.Now() geminiResponse, err := processGeminiStreamChunk(eventData) + schemas.AddStreamParse(ctx, time.Since(parseStart)) if err != nil { if strings.Contains(err.Error(), "gemini api error") { // Handle API error @@ -1095,8 +1101,10 @@ func HandleGeminiResponsesStream( } } - // Convert to Bifrost responses stream response + // Convert to Bifrost responses stream response. Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() responses, bifrostErr := geminiResponse.ToBifrostResponsesStream(sequenceNumber, streamState) + schemas.AddStreamConvert(ctx, time.Since(convStart)) if bifrostErr != nil { ctx.SetValue(schemas.BifrostContextKeyStreamEndIndicator, true) providerUtils.ProcessAndSendBifrostError(ctx, postHookRunner, providerUtils.EnrichError(ctx, bifrostErr, jsonBody, nil, sendBackRawRequest, sendBackRawResponse), responseChan, logger, postHookSpanFinalizer) diff --git a/core/providers/openai/openai.go b/core/providers/openai/openai.go index 528833bd120..9292a32c585 100644 --- a/core/providers/openai/openai.go +++ b/core/providers/openai/openai.go @@ -618,7 +618,10 @@ func HandleOpenAITextCompletionStreaming( jsonData := string(data) var response schemas.BifrostTextCompletionResponse if customResponseHandler != nil { + // Custom handler decodes the raw event itself -> time as "response-parse" stream phase. + parseStart := time.Now() rawRequest, rawResponse, handlerErr := customResponseHandler([]byte(jsonData), &response, nil, sendBackRawRequest, sendBackRawResponse) + schemas.AddStreamParse(ctx, time.Since(parseStart)) if handlerErr != nil { // TODO fix this if sendBackRawRequest { @@ -646,9 +649,14 @@ func HandleOpenAITextCompletionStreaming( } } - // Parse into bifrost response - if err := sonic.UnmarshalString(jsonData, &response); err != nil { - logger.Warn("Failed to parse stream response: %v", err) + // Parse into bifrost response. Timed as the "response-parse" stream phase + // (per-event JSON decode) so it lands in Serialization like unary/Anthropic, + // instead of folding into core/provider-internal. + parseStart := time.Now() + umErr := sonic.UnmarshalString(jsonData, &response) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + logger.Warn("Failed to parse stream response: %v", umErr) continue } } @@ -659,7 +667,11 @@ func HandleOpenAITextCompletionStreaming( } if postResponseConverter != nil { - if converted := postResponseConverter(&response); converted != nil { + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() + converted := postResponseConverter(&response) + schemas.AddStreamConvert(ctx, time.Since(convStart)) + if converted != nil { response = *converted } else { logger.Warn("postResponseConverter returned nil; leaving chunk unmodified") @@ -1263,7 +1275,10 @@ func HandleOpenAIChatCompletionStreaming( // Parse into bifrost response var response schemas.BifrostChatResponse if customResponseHandler != nil { + // Custom handler decodes the raw event itself -> time as "response-parse" stream phase. + parseStart := time.Now() rawRequest, rawResponse, handlerErr := customResponseHandler([]byte(jsonData), &response, nil, sendBackRawRequest, sendBackRawResponse) + schemas.AddStreamParse(ctx, time.Since(parseStart)) if handlerErr != nil { if sendBackRawRequest { handlerErr.ExtraFields.RawRequest = rawRequest @@ -1276,8 +1291,12 @@ func HandleOpenAIChatCompletionStreaming( return } } else { - if err := sonic.UnmarshalString(jsonData, &response); err != nil { - logger.Warn("Failed to parse stream response: %v", err) + // Per-event decode -> "response-parse" (Serialization) stream phase. + parseStart := time.Now() + umErr := sonic.UnmarshalString(jsonData, &response) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + logger.Warn("Failed to parse stream response: %v", umErr) continue } } @@ -1318,7 +1337,10 @@ func HandleOpenAIChatCompletionStreaming( } } + // Per-event mapping (chat->responses) -> "convertor" (Convertor) stream phase. + convStart := time.Now() spreadResponses := response.ToBifrostResponsesStreamResponse(responsesStreamState) + schemas.AddStreamConvert(ctx, time.Since(convStart)) for _, response := range spreadResponses { if response.Type == schemas.ResponsesStreamResponseTypeError { bifrostErr := &schemas.BifrostError{ @@ -1361,7 +1383,11 @@ func HandleOpenAIChatCompletionStreaming( } } else { if postResponseConverter != nil { - if converted := postResponseConverter(&response); converted != nil { + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() + converted := postResponseConverter(&response) + schemas.AddStreamConvert(ctx, time.Since(convStart)) + if converted != nil { response = *converted } else { logger.Warn("postResponseConverter returned nil; leaving chunk unmodified") @@ -1943,7 +1969,10 @@ func HandleOpenAIResponsesStreaming( // Parse into bifrost response var response schemas.BifrostResponsesStreamResponse if customResponseHandler != nil { + // Custom handler decodes the raw event itself -> time as "response-parse" stream phase. + parseStart := time.Now() rawRequest, rawResponse, bifrostErr := customResponseHandler([]byte(jsonData), &response, nil, sendBackRawRequest, sendBackRawResponse) + schemas.AddStreamParse(ctx, time.Since(parseStart)) if bifrostErr != nil { if sendBackRawRequest { bifrostErr.ExtraFields.RawRequest = rawRequest @@ -1959,13 +1988,21 @@ func HandleOpenAIResponsesStreaming( response.ExtraFields.RawResponse = jsonData } } else { - if err := sonic.UnmarshalString(jsonData, &response); err != nil { - logger.Warn("Failed to parse stream response: %v", err) + // Per-event decode -> "response-parse" (Serialization) stream phase. + parseStart := time.Now() + umErr := sonic.UnmarshalString(jsonData, &response) + schemas.AddStreamParse(ctx, time.Since(parseStart)) + if umErr != nil { + logger.Warn("Failed to parse stream response: %v", umErr) continue } if postResponseConverter != nil { - if converted := postResponseConverter(&response); converted != nil { + // Per-event mapping -> "convertor" (Convertor) stream phase. + convStart := time.Now() + converted := postResponseConverter(&response) + schemas.AddStreamConvert(ctx, time.Since(convStart)) + if converted != nil { response = *converted } else { logger.Warn("postResponseConverter returned nil; leaving chunk unmodified") diff --git a/core/providers/utils/sse.go b/core/providers/utils/sse.go index c3eca6ef7cc..4b0e96f243b 100644 --- a/core/providers/utils/sse.go +++ b/core/providers/utils/sse.go @@ -4,6 +4,7 @@ import ( "bufio" "bytes" "io" + "time" "github.com/bytedance/sonic" "github.com/maximhq/bifrost/core/schemas" @@ -66,7 +67,7 @@ func GetSSEDataReader(ctx *schemas.BifrostContext, reader io.Reader) SSEDataRead return factory.NewDataReader(reader) } } - return newDefaultSSEDataReader(reader) + return newDefaultSSEDataReader(ctx, reader) } // GetSSEEventReader returns an SSEEventReader for the given reader. @@ -96,18 +97,37 @@ type defaultSSEDataReader struct { scanner *bufio.Scanner pending []byte // line carried over from an aborted multi-line JSON accumulation sawDone bool // stream ended on "data: [DONE]" rather than a bare body EOF + // ctx carries the request context so the per-event copy out of the scanner buffer + // can be attributed to the "response-parse" stream phase centrally, for every + // provider that uses the shared reader — rather than each provider timing its own + // copy. Nil-safe: AddStreamParse no-ops when there is no accumulator. + ctx *schemas.BifrostContext } // SawDoneMarker implements SSEStreamTerminator. func (r *defaultSSEDataReader) SawDoneMarker() bool { return r.sawDone } -func newDefaultSSEDataReader(reader io.Reader) *defaultSSEDataReader { +func newDefaultSSEDataReader(ctx *schemas.BifrostContext, reader io.Reader) *defaultSSEDataReader { scanner := bufio.NewScanner(reader) scanner.Buffer(make([]byte, 0, sseInitialBufSize), sseMaxBufSize) - return &defaultSSEDataReader{scanner: scanner} + return &defaultSSEDataReader{scanner: scanner, ctx: ctx} } func (r *defaultSSEDataReader) ReadDataLine() ([]byte, error) { + // Attribute the SSE framing CPU (scanner buffer splitting, prefix parsing, and the + // per-event copy out of the scanner buffer) to the "response-parse" stream phase, for + // every provider using the shared reader. The socket-read WAIT interleaved inside the + // scanner is already accounted as upstream by the wrapping reader, so subtract the + // upstream delta accrued during this call to leave only the CPU — no double count. + // AddStreamParse guards non-positive (measurement skew). + if r.ctx != nil { + upBefore, _ := schemas.GetUpstreamLatency(r.ctx) + frameStart := time.Now() + defer func() { + upAfter, _ := schemas.GetUpstreamLatency(r.ctx) + schemas.AddStreamParse(r.ctx, time.Since(frameStart)-(upAfter-upBefore)) + }() + } for { line, ok := r.nextLine() if !ok { @@ -131,7 +151,9 @@ func (r *defaultSSEDataReader) ReadDataLine() ([]byte, error) { r.sawDone = true return nil, io.EOF } - // Copy to decouple from scanner's internal buffer + // Copy to decouple from scanner's internal buffer. This copy, the scanner + // split, and the prefix parsing are all attributed to "response-parse" by the + // deferred framing timer at the top of this method. return append([]byte(nil), data...), nil } diff --git a/core/providers/utils/sse_test.go b/core/providers/utils/sse_test.go index cbcda93bacc..cffcc66cc13 100644 --- a/core/providers/utils/sse_test.go +++ b/core/providers/utils/sse_test.go @@ -28,7 +28,7 @@ func TestSSEDataReader_DataLinesAndDone(t *testing.T) { "\n" + "data: {\"b\":2}\n" + "data: [DONE]\n" - payloads := drainSSEDataReader(t, newDefaultSSEDataReader(strings.NewReader(stream))) + payloads := drainSSEDataReader(t, newDefaultSSEDataReader(nil, strings.NewReader(stream))) if len(payloads) != 2 || payloads[0] != `{"a":1}` || payloads[1] != `{"b":2}` { t.Errorf("unexpected payloads: %#v", payloads) } @@ -38,7 +38,7 @@ func TestSSEDataReader_DataLinesAndDone(t *testing.T) { // reader must record which one it was — that flag is the only way a provider // loop can tell a finished stream from a dead upstream connection. func TestSSEDataReader_SawDoneMarkerOnDone(t *testing.T) { - reader := newDefaultSSEDataReader(strings.NewReader("data: {\"a\":1}\n\ndata: [DONE]\n\n")) + reader := newDefaultSSEDataReader(nil, strings.NewReader("data: {\"a\":1}\n\ndata: [DONE]\n\n")) drainSSEDataReader(t, reader) if !reader.SawDoneMarker() { t.Error("expected SawDoneMarker to be true after reading [DONE]") @@ -51,7 +51,7 @@ func TestSSEDataReader_SawDoneMarkerOnDone(t *testing.T) { // A stream that just stops (upstream connection died on a chunk boundary) ends // with the same io.EOF but no marker. func TestSSEDataReader_SawDoneMarkerAbsentOnBareEOF(t *testing.T) { - reader := newDefaultSSEDataReader(strings.NewReader("data: {\"a\":1}\n\n")) + reader := newDefaultSSEDataReader(nil, strings.NewReader("data: {\"a\":1}\n\n")) drainSSEDataReader(t, reader) if reader.SawDoneMarker() { t.Error("expected SawDoneMarker to be false when the body ended without [DONE]") @@ -64,7 +64,7 @@ func TestSSEDataReader_SawDoneMarkerAbsentOnBareEOF(t *testing.T) { // A reader with no bytes at all (upstream died before its first byte) must also // report no marker. func TestSSEDataReader_SawDoneMarkerAbsentOnEmptyStream(t *testing.T) { - reader := newDefaultSSEDataReader(strings.NewReader("")) + reader := newDefaultSSEDataReader(nil, strings.NewReader("")) drainSSEDataReader(t, reader) if SSEStreamEndedOnMarker(reader) { t.Error("expected SSEStreamEndedOnMarker to be false for an empty stream") @@ -87,7 +87,7 @@ func TestSSEStreamEndedOnMarker_UnknownReaderDefaultsTrue(t *testing.T) { func TestSSEDataReader_SingleLineRawJSONFallback(t *testing.T) { stream := `{"error": {"code": 429, "status": "RESOURCE_EXHAUSTED"}}` + "\n" - payloads := drainSSEDataReader(t, newDefaultSSEDataReader(strings.NewReader(stream))) + payloads := drainSSEDataReader(t, newDefaultSSEDataReader(nil, strings.NewReader(stream))) if len(payloads) != 1 || payloads[0] != `{"error": {"code": 429, "status": "RESOURCE_EXHAUSTED"}}` { t.Errorf("unexpected payloads: %#v", payloads) } @@ -104,7 +104,7 @@ func TestSSEDataReader_MultilineErrorReassembly(t *testing.T) { " \"status\": \"RESOURCE_EXHAUSTED\"\n" + " }\n" + "}\n" - payloads := drainSSEDataReader(t, newDefaultSSEDataReader(strings.NewReader(stream))) + payloads := drainSSEDataReader(t, newDefaultSSEDataReader(nil, strings.NewReader(stream))) if len(payloads) != 2 { t.Fatalf("expected 2 payloads, got %d: %#v", len(payloads), payloads) } @@ -122,7 +122,7 @@ func TestSSEDataReader_MultilineErrorReassembly(t *testing.T) { func TestSSEDataReader_AccumulationAbortedByDataLine(t *testing.T) { stream := "{\n" + "data: {\"b\":2}\n" - payloads := drainSSEDataReader(t, newDefaultSSEDataReader(strings.NewReader(stream))) + payloads := drainSSEDataReader(t, newDefaultSSEDataReader(nil, strings.NewReader(stream))) if len(payloads) != 2 || payloads[0] != "{" || payloads[1] != `{"b":2}` { t.Errorf("unexpected payloads: %#v", payloads) } @@ -133,7 +133,7 @@ func TestSSEDataReader_MultilineReassemblyWithLeadingWhitespace(t *testing.T) { stream := " {\n" + " \"error\": {\"code\": 429}\n" + " }\n" - payloads := drainSSEDataReader(t, newDefaultSSEDataReader(strings.NewReader(stream))) + payloads := drainSSEDataReader(t, newDefaultSSEDataReader(nil, strings.NewReader(stream))) want := " {\n \"error\": {\"code\": 429}\n }" if len(payloads) != 1 || payloads[0] != want { t.Errorf("unexpected payloads: %#v", payloads) @@ -145,7 +145,7 @@ func TestSSEDataReader_MultilineReassemblyWithLeadingWhitespace(t *testing.T) { func TestSSEDataReader_PartialObjectAtEOF(t *testing.T) { stream := "{\n" + " \"error\": {\n" - payloads := drainSSEDataReader(t, newDefaultSSEDataReader(strings.NewReader(stream))) + payloads := drainSSEDataReader(t, newDefaultSSEDataReader(nil, strings.NewReader(stream))) if len(payloads) != 1 || payloads[0] != "{\n \"error\": {" { t.Errorf("unexpected payloads: %#v", payloads) } diff --git a/plugins/logging/main.go b/plugins/logging/main.go index cdcc0fda16c..639544c8652 100644 --- a/plugins/logging/main.go +++ b/plugins/logging/main.go @@ -2068,7 +2068,7 @@ func (p *LoggerPlugin) Inject(_ context.Context, trace *schemas.Trace) error { } // Per-span self-time decomposition of overhead, attached to the same terminal // row that receives the overhead number below. - overheadBreakdown := computeOverheadBreakdown(trace, overheadMs, ovOK, upstreamMs, upOK) + overheadBreakdown, measuredOverheadMs, isStreaming := computeOverheadBreakdown(trace, overheadMs, ovOK, upstreamMs, upOK) p.logger.Debug("Inject: enqueuing %d log entries", len(pending.entries)) // Upstream/overhead are request-level: put them on one row per trace, not all. @@ -2099,20 +2099,41 @@ func (p *LoggerPlugin) Inject(_ context.Context, trace *schemas.Trace) error { entry.UpstreamLatency = nil entry.OverheadLatency = nil } - if upOK { - u := upstreamMs - entry.UpstreamLatency = &u - } - if ovOK { - o := overheadMs - entry.OverheadLatency = &o - } - // Latency = full-request wall-clock = upstream + overhead. Summing (not - // the raw span duration) keeps latency >= upstream when overhead clamps - // to zero, so the breakdown always adds up. - if upOK && ovOK { + if isStreaming && upOK && ovOK { + // Streaming: overhead is the measured Bifrost CPU (the breakdown buckets), + // not total-upstream. The remainder (total - upstream - measured) is the + // off-CPU relay/scheduler wait the request goroutine spends parked between + // provider chunks — not Bifrost work — so it is folded into upstream. This + // makes the overhead number reflect actual Bifrost cost while keeping + // latency = upstream + overhead and the breakdown buckets summing to overhead. total := upstreamMs + overheadMs + measured := measuredOverheadMs + if measured > overheadMs { + measured = overheadMs // measurement skew: never exceed total-upstream + } + if measured < 0 { + measured = 0 + } + up := total - measured + entry.UpstreamLatency = &up + entry.OverheadLatency = &measured entry.Latency = &total + } else { + if upOK { + u := upstreamMs + entry.UpstreamLatency = &u + } + if ovOK { + o := overheadMs + entry.OverheadLatency = &o + } + // Latency = full-request wall-clock = upstream + overhead. Summing (not + // the raw span duration) keeps latency >= upstream when overhead clamps + // to zero, so the breakdown always adds up. + if upOK && ovOK { + total := upstreamMs + overheadMs + entry.Latency = &total + } } if len(overheadBreakdown) > 0 { entry.OverheadBreakdownParsed = overheadBreakdown @@ -2220,9 +2241,14 @@ func overheadBucketName(s *schemas.Span) string { // derived from overheadMs (which already excludes upstream), not from the root // span's self-time, so it never picks up streaming socket reads. Buckets are // returned with microsecond values, measured spans first (chronological) then core. -func computeOverheadBreakdown(trace *schemas.Trace, overheadMs float64, overheadOK bool, upstreamMs float64, upstreamOK bool) []logstore.OverheadBucket { +// computeOverheadBreakdown returns the per-phase buckets, the measured Bifrost-CPU +// total in ms (the sum of those buckets), and whether this was a streaming request. +// For streams the caller uses measuredMs as the overhead (see Inject): total-upstream +// over-counts stream overhead because it includes off-CPU relay/scheduler wait between +// chunks, which is not Bifrost work. +func computeOverheadBreakdown(trace *schemas.Trace, overheadMs float64, overheadOK bool, upstreamMs float64, upstreamOK bool) ([]logstore.OverheadBucket, float64, bool) { if trace == nil || len(trace.Spans) == 0 { - return nil + return nil, 0, false } // Sum direct-children time per parent, over ALL spans (upstream ones too), so // excluded child spans are still removed from their parent's self-time. Only the @@ -2338,10 +2364,25 @@ func computeOverheadBreakdown(trace *schemas.Trace, overheadMs float64, overhead // an existing one — can never silently inflate "core"; it lands here instead, and its // size tells us a provider needs finer spans. Summed across attempts: retries create // one llm.call span each, and upstream latency likewise accumulates across them. - // Streaming is excluded implicitly: its llm.call span ends when the channel is handed - // off (before the stream drains), so its self-time is small and the difference falls - // below the threshold; stream phases are decomposed via the stream attributes above. - if upstreamOK { + // + // STREAMING IS EXCLUDED. For a streamed response the llm.call span is DEFERRED — it + // covers the entire stream (ended on the final chunk), not just setup — while upstream + // is only time-to-first-byte. So llm.call self - upstream would capture the whole + // per-chunk relay, which is instead decomposed by the stream phases above + // (response-parse / convertor / backpressure via the stream accumulator). Computing + // provider-internal there would double-count that work and mislabel it. Detect + // streaming by the presence of any stream-overhead attribute on the root span. + isStreaming := false + if trace.RootSpan != nil && trace.RootSpan.Attributes != nil { + a := trace.RootSpan.Attributes + for _, k := range []string{schemas.AttrBifrostStreamParseMs, schemas.AttrBifrostStreamConvertMs, schemas.AttrBifrostStreamBackpressureMs} { + if _, ok := a[k]; ok { + isStreaming = true + break + } + } + } + if upstreamOK && !isStreaming { var llmSelfNs int64 var firstLLM time.Time for _, s := range trace.Spans { @@ -2383,19 +2424,34 @@ func computeOverheadBreakdown(trace *schemas.Trace, overheadMs float64, overhead return buckets[out[i].Name].first.Before(buckets[out[j].Name].first) }) - // Attribute whatever overhead is left over to Bifrost core. Skip when the - // measured spans already exceed the total (upstream over-counting): a negative - // core is a diagnostic signal, not a bucket, and is surfaced in the UI footer. - if overheadOK { - coreUs := overheadMs*1000.0 - float64(measuredNs)/1000.0 - if coreUs > 0.5 { - out = append(out, logstore.OverheadBucket{Name: "core", Kind: "core", DurationUs: coreUs}) + measuredMs := float64(measuredNs) / float64(time.Millisecond) + + // Unary requests: whatever overhead is left over after every instrumented phase is + // the residual between phases — goroutine-scheduling latency (the request hops across + // the HTTP, core-pipeline and provider-worker goroutines) plus any not-yet-spanned + // transport edge. Now that the code phases are instrumented, this is small and + // dominated by scheduling, so it is surfaced as "scheduling" rather than an opaque + // "core". Skip when measured spans already exceed the total (upstream over-counting): + // a negative value is a diagnostic signal, not a bucket, surfaced in the UI footer. + // + // STREAMING IS EXCLUDED. For a stream, total-upstream is NOT Bifrost overhead: it + // includes the off-CPU relay/scheduler wait the request goroutine spends parked + // between provider chunks (confirmed ~2% CPU under load). All actual Bifrost CPU is + // already measured in the buckets above (parse/convert accumulators, aggregated + // per-chunk plugin timing, transport marshal/write). Emitting a residual bucket there + // would resurrect the misleading "scheduling = 95% of overhead" figure. Instead the + // caller takes measuredMs as the stream's overhead and folds the off-CPU remainder + // into upstream, so latency = upstream + overhead still holds. + if overheadOK && !isStreaming { + schedulingUs := overheadMs*1000.0 - float64(measuredNs)/1000.0 + if schedulingUs > 0.5 { + out = append(out, logstore.OverheadBucket{Name: "scheduling", Kind: "scheduling", DurationUs: schedulingUs}) } } if len(out) == 0 { - return nil + return nil, measuredMs, isStreaming } - return out + return out, measuredMs, isStreaming } // traceAttrFloatMs reads a millisecond span attribute, tolerating int/int64/float64. diff --git a/plugins/logging/overhead_breakdown_test.go b/plugins/logging/overhead_breakdown_test.go index 06799d0efa5..6d21c7a52a1 100644 --- a/plugins/logging/overhead_breakdown_test.go +++ b/plugins/logging/overhead_breakdown_test.go @@ -22,7 +22,8 @@ func span(base time.Time, id, parent, name string, kind schemas.SpanKind, startM func bucketMap(t *testing.T, trace *schemas.Trace, overheadMs float64, ovOK bool) map[string]float64 { t.Helper() out := map[string]float64{} - for _, b := range computeOverheadBreakdown(trace, overheadMs, ovOK, 0, false) { + buckets, _, _ := computeOverheadBreakdown(trace, overheadMs, ovOK, 0, false) + for _, b := range buckets { out[b.Name] = b.DurationUs } return out @@ -46,7 +47,7 @@ func TestComputeOverheadBreakdown_ChatPath(t *testing.T) { got := bucketMap(t, trace, 12, true) if len(got) != 3 { - t.Fatalf("expected 3 buckets (key.selection, plugin.governance, core), got %v", got) + t.Fatalf("expected 3 buckets (key.selection, plugin.governance, scheduling), got %v", got) } if got["key.selection"] != 2000 { t.Errorf("key.selection = %v us, want 2000", got["key.selection"]) @@ -55,9 +56,9 @@ func TestComputeOverheadBreakdown_ChatPath(t *testing.T) { if got["plugin.governance"] != 6000 { t.Errorf("plugin.governance = %v us, want 6000", got["plugin.governance"]) } - // 12ms overhead - 8ms measured = 4ms attributed to core - if got["core"] != 4000 { - t.Errorf("core = %v us, want 4000", got["core"]) + // 12ms overhead - 8ms measured = 4ms attributed to scheduling + if got["scheduling"] != 4000 { + t.Errorf("scheduling = %v us, want 4000", got["scheduling"]) } // llm.call (upstream) and the root http.request span are not overhead buckets if _, ok := got["chat gpt-4o"]; ok { @@ -97,8 +98,8 @@ func TestComputeOverheadBreakdown_NestedPhaseSpansCountedOnce(t *testing.T) { if sum := got["request-sign"] + got["credentials-fetch"]; sum != 20000 { t.Errorf("request-sign + credentials-fetch = %v us, want 20000 (no double-count)", sum) } - if _, ok := got["core"]; ok { - t.Errorf("core should be empty when spans account for all overhead, got %v", got["core"]) + if _, ok := got["scheduling"]; ok { + t.Errorf("scheduling should be empty when spans account for all overhead, got %v", got["scheduling"]) } } @@ -133,8 +134,8 @@ func TestComputeOverheadBreakdown_SiblingPluginsUnderPhaseCountedOnce(t *testing if sum != 40000 { t.Errorf("phase + plugins = %v us, want 40000 (== pipeline-post wall, no double-count)", sum) } - if _, ok := got["core"]; ok { - t.Errorf("core should be empty, got %v", got["core"]) + if _, ok := got["scheduling"]; ok { + t.Errorf("scheduling should be empty, got %v", got["scheduling"]) } } @@ -148,7 +149,7 @@ func TestComputeOverheadBreakdown_CoreOnly(t *testing.T) { }} got := bucketMap(t, trace, 3, true) - if len(got) != 1 || got["core"] != 3000 { + if len(got) != 1 || got["scheduling"] != 3000 { t.Errorf("expected a single core bucket of 3000 us, got %v", got) } } @@ -167,7 +168,7 @@ func TestComputeOverheadBreakdown_NoNegativeCore(t *testing.T) { if len(got) != 1 || got["plugin.governance"] != 10000 { t.Errorf("expected only plugin.governance=10000, got %v", got) } - if _, ok := got["core"]; ok { + if _, ok := got["scheduling"]; ok { t.Error("core bucket must not be emitted when it would be negative") } } @@ -214,7 +215,7 @@ func TestComputeOverheadBreakdown_SelfTimeExcludesChildren(t *testing.T) { if got["plugin.mcp"] != 10000 { t.Errorf("plugin.mcp = %v us, want 10000", got["plugin.mcp"]) } - if _, ok := got["core"]; ok { + if _, ok := got["scheduling"]; ok { t.Error("no core bucket without an overhead total") } } @@ -238,8 +239,8 @@ func TestComputeOverheadBreakdown_KeySelectionReparentedLLMCall(t *testing.T) { t.Errorf("key.selection = %v us, want 2000", got["key.selection"]) } // 5ms overhead - 2ms key.selection = 3ms core. - if got["core"] != 3000 { - t.Errorf("core = %v us, want 3000", got["core"]) + if got["scheduling"] != 3000 { + t.Errorf("core = %v us, want 3000", got["scheduling"]) } } @@ -253,16 +254,59 @@ func TestComputeOverheadBreakdown_NegligibleOverhead(t *testing.T) { span(base, "llm", "root", "chat gpt-4o", schemas.SpanKindLLMCall, 0, 100), }} - if got := computeOverheadBreakdown(trace, 0, false, 0, false); len(got) != 0 { + if got, _, _ := computeOverheadBreakdown(trace, 0, false, 0, false); len(got) != 0 { t.Errorf("expected no overhead buckets when overhead is negligible, got %v", got) } } func TestComputeOverheadBreakdown_Empty(t *testing.T) { - if computeOverheadBreakdown(nil, 0, false, 0, false) != nil { + if got, _, _ := computeOverheadBreakdown(nil, 0, false, 0, false); got != nil { t.Error("nil trace must yield nil") } - if computeOverheadBreakdown(&schemas.Trace{}, 5, true, 0, false) != nil { + if got, _, _ := computeOverheadBreakdown(&schemas.Trace{}, 5, true, 0, false); got != nil { t.Error("trace with no spans must yield nil") } } + +// Streaming: overhead is the measured Bifrost CPU (the buckets), never total-upstream. +// A stream stamps stream-phase attributes on the root span; the breakdown must fold those +// into buckets, emit NO "scheduling" residual (that leftover is off-CPU relay/scheduler +// wait between chunks, not Bifrost work), and return measuredMs = the bucket sum with +// isStreaming=true so Inject can use it as the overhead and fold the remainder into upstream. +func TestComputeOverheadBreakdown_StreamingNoSchedulingResidual(t *testing.T) { + base := time.Now() + root := span(base, "root", "", "/v1/responses", schemas.SpanKindHTTPRequest, 0, 100) + root.Attributes = map[string]any{ + schemas.AttrBifrostStreamParseMs: 1.0, // 1ms SSE framing+decode -> response-parse bucket + } + trace := &schemas.Trace{ + RootSpan: root, + Spans: []*schemas.Span{ + root, + span(base, "keysel", "root", "key.selection", schemas.SpanKindInternal, 1, 3), // 2ms + }, + } + + // total-upstream overhead is a huge 40ms (dominated by off-CPU relay wait), but the + // measured Bifrost CPU is only key.selection (2ms) + stream-parse (1ms) = 3ms. + buckets, measuredMs, isStreaming := computeOverheadBreakdown(trace, 40, true, 5, true) + if !isStreaming { + t.Fatal("expected isStreaming=true when a stream attr is present on the root span") + } + got := map[string]float64{} + for _, b := range buckets { + got[b.Name] = b.DurationUs + } + if _, ok := got["scheduling"]; ok { + t.Errorf("streaming must not emit a scheduling residual bucket, got %v", got) + } + if got["key.selection"] != 2000 { + t.Errorf("key.selection = %v us, want 2000", got["key.selection"]) + } + if got["response-parse"] != 1000 { + t.Errorf("response-parse (stream framing) = %v us, want 1000", got["response-parse"]) + } + if measuredMs < 2.99 || measuredMs > 3.01 { + t.Errorf("measuredMs = %v, want ~3 (2ms key.selection + 1ms stream-parse), not the 40ms total-upstream", measuredMs) + } +} diff --git a/transports/bifrost-http/handlers/inference.go b/transports/bifrost-http/handlers/inference.go index 5fa1a1d1123..af804f04e70 100644 --- a/transports/bifrost-http/handlers/inference.go +++ b/transports/bifrost-http/handlers/inference.go @@ -2000,6 +2000,11 @@ func (h *CompletionHandler) handleStreamingResponse(ctx *fasthttp.RequestCtx, bi // Producer goroutine: processes the stream channel, formats SSE events, sends to reader go func() { var transportLogs []schemas.PluginLogEntry + // Per-chunk transport-goroutine costs, stamped onto the root span at stream end so + // the overhead breakdown attributes the outbound relay (chunk marshal = transport + // CPU -> "convertor.stream-out"; client socket write -> "stream-client-write") + // instead of folding it into the residual bucket. Mirrors integrations/router.go. + var streamTransportCPUNs, streamClientWriteNs int64 completerRan := false // runCompleter invokes the transport post-hook completer at most once. // sendSSEOnError=true emits plugin errors as SSE "event: error" frames so the @@ -2064,6 +2069,10 @@ func (h *CompletionHandler) handleStreamingResponse(ctx *fasthttp.RequestCtx, bi // lib.StopSSEHeartbeat's doc for the full ordering rationale. lib.StopSSEHeartbeat(reader, heartbeatDone, heartbeatExited) schemas.ReleaseHTTPRequest(httpReq) + // Stamp the outbound relay costs onto the root span before the trace completes + // below (traceCompleter), so they reach the overhead breakdown. Runs on every + // exit path (normal end, client disconnect, interceptor error). + bifrostCtx.StampStreamTransport(time.Duration(streamTransportCPUNs), time.Duration(streamClientWriteNs)) // Fallback: on early-return paths (client disconnect, interceptor error) // we never reached the pre-[DONE] invocation, so run it now. Any error is // logged server-side only — the stream is already closing. @@ -2141,8 +2150,10 @@ func (h *CompletionHandler) handleStreamingResponse(ctx *fasthttp.RequestCtx, bi } } - // Convert response to JSON + // Convert response to JSON (transport-goroutine CPU). + cpuStart := time.Now() chunkJSON, err := sonic.Marshal(chunk) + streamTransportCPUNs += time.Since(cpuStart).Nanoseconds() if err != nil { logger.Warn("Failed to marshal streaming response: %v", err) continue @@ -2167,7 +2178,10 @@ func (h *CompletionHandler) handleStreamingResponse(ctx *fasthttp.RequestCtx, bi } } - if !reader.SendEvent(eventType, chunkJSON) { + writeStart := time.Now() + sent := reader.SendEvent(eventType, chunkJSON) + streamClientWriteNs += time.Since(writeStart).Nanoseconds() + if !sent { cancel() // Client disconnected, cancel upstream stream // Drain remaining chunks so the provider goroutine's defer // (HandleStreamCancellation -> PostLLMHook -> storeOrEnqueueEntry) finishes diff --git a/ui/app/workspace/logs/sheets/logDetailView.tsx b/ui/app/workspace/logs/sheets/logDetailView.tsx index 7f998a0b5d4..cc6151b5c8e 100644 --- a/ui/app/workspace/logs/sheets/logDetailView.tsx +++ b/ui/app/workspace/logs/sheets/logDetailView.tsx @@ -492,13 +492,14 @@ function formatMicros(us: number): string { return `${us.toFixed(us < 10 ? 1 : 0)} µs`; } -// Top-level overhead categories. The four JSON (un)marshalling phases fold into one -// "Serialization" category; the auth middleware spans (middleware.*) fold into -// "Middleware"; every plugin span folds into "Plugins"; the remaining named phase -// spans (queue-wait, convertor, key.selection) and the backend "core" remainder each -// get their own category; anything else lands in "Other". The stacked bar and legend -// show these categories, and "View details" drills into the member spans (individual -// (un)marshal phases, individual middlewares, individual plugins) inside grouped ones. +// Top-level overhead categories shown in the stacked bar + legend. Raw backend span +// names are grouped into a handful of user-facing categories: Serialization (JSON +// parse/encode), Conversion (API schema translation), Plugins, Middleware (auth/access), +// Key selection, Processing (internal request pipeline), Networking +// (client<->gateway<->provider handling), Client delivery (SSE egress to the client), and Scheduling (the +// residual goroutine-hop latency between phases). "View details" drills into the member +// spans inside each grouped category with their friendly labels. See OVERHEAD_LABELS / +// OVERHEAD_BUCKET_CATEGORY / overheadCategoryKey for the mapping. type OverheadCategory = { key: string; label: string; @@ -511,29 +512,95 @@ type OverheadCategory = { // per-phase labels below are used for the drill-down rows. const OVERHEAD_SERIALIZATION_PHASES = new Set(["request-unmarshal", "request-marshal", "response-parse", "response-marshal"]); +// Top-level categories shown in the stacked bar + legend. Each has a distinct colour. const OVERHEAD_CATEGORY_META: Record = { serialization: { label: "Serialization", colorClass: "bg-indigo-500/70" }, - middleware: { label: "Middleware", colorClass: "bg-cyan-500/70" }, - "middleware.apikeys": { label: "API", colorClass: "bg-cyan-500/70" }, - "middleware.scim": { label: "SCIM", colorClass: "bg-cyan-500/70" }, - "middleware.auth": { label: "Auth", colorClass: "bg-cyan-500/70" }, - "queue-wait": { label: "Queue wait", colorClass: "bg-orange-500/70" }, - "request-unmarshal": { label: "Request unmarshal", colorClass: "bg-sky-500/70" }, - convertor: { label: "Convertor", colorClass: "bg-fuchsia-500/70" }, - "attribute-population": { label: "Attribute population", colorClass: "bg-pink-500/70" }, - "request-marshal": { label: "Request marshal", colorClass: "bg-indigo-500/70" }, - "response-parse": { label: "Response unmarshal", colorClass: "bg-purple-500/70" }, - "response-marshal": { label: "Response marshal", colorClass: "bg-rose-500/70" }, - "key.selection": { label: "Key selection", colorClass: "bg-amber-500/70" }, - core: { label: "Core", colorClass: "bg-slate-500/70" }, - "convertor.stream-in": { label: "Stream inbound convert", colorClass: "bg-fuchsia-500/70" }, - "convertor.stream-out": { label: "Stream outbound convert", colorClass: "bg-fuchsia-500/70" }, - "stream-client-write": { label: "Stream client write", colorClass: "bg-red-500/70" }, - "stream-backpressure": { label: "Stream backpressure", colorClass: "bg-red-500/70" }, - transport: { label: "Transport", colorClass: "bg-teal-500/70" }, + conversion: { label: "Conversion", colorClass: "bg-fuchsia-500/70" }, plugins: { label: "Plugins", colorClass: "bg-blue-500/70" }, - other: { label: "Other", colorClass: "bg-emerald-500/70" }, + middleware: { label: "Middleware", colorClass: "bg-cyan-500/70" }, + routing: { label: "Key selection", colorClass: "bg-amber-500/70" }, + processing: { label: "Processing", colorClass: "bg-teal-500/70" }, + networking: { label: "Networking", colorClass: "bg-emerald-500/70" }, + streaming: { label: "Client delivery", colorClass: "bg-red-500/70" }, + scheduling: { label: "Scheduling", colorClass: "bg-slate-500/70" }, + other: { label: "Other", colorClass: "bg-muted-foreground/50" }, +}; + +// Friendly drill-down labels for each raw bucket name (the technical span names the +// backend emits). Members without an entry fall back to the name with any "plugin." +// prefix stripped. +const OVERHEAD_LABELS: Record = { + // Serialization (JSON parse / encode) + "request-unmarshal": "Request parse", + "request-marshal": "Request encode", + "response-parse": "Response parse", + "response-marshal": "Response encode", + // Conversion (API schema translation) + convertor: "Schema conversion", + "convertor.stream-in": "Stream convert (inbound)", + "convertor.stream-out": "Stream convert (outbound)", + // Middleware (auth / access control) + "middleware.apikeys": "API", + "middleware.scim": "SCIM", + "middleware.auth": "Auth", + // Routing + "key-pool": "Key pool", + "key.selection": "Key selection", + // Processing (internal request pipeline) + "handle-setup": "Request setup", + "pipeline-pre": "Pre-hooks", + "pipeline-post": "Post-hooks", + "worker-setup": "Worker setup", + "worker-handoff": "Worker handoff", + "queue-wait": "Queue wait", + "attribute-population": "Attribute population", + // Networking (client<->gateway<->provider handling) + "provider-internal": "Provider I/O", + "transport-context": "Request context building", + "transport-response-headers": "Response headers", + "response-finalize": "Response read", + "request-sign": "Request signing", + "credentials-fetch": "Credential fetch", + // Streaming relay + "stream-backpressure": "Client backpressure", + "stream-client-write": "Client write", + scheduling: "Scheduling", +}; + +// Category assignment for buckets that aren't matched by a prefix rule below. Every +// backend bucket name should be either matched by a prefix rule (serialization phases, +// middleware.*, convertor*, plugin.*) or listed here — otherwise it lands in "Other", +// which is the signal that a new bucket needs a home. +const OVERHEAD_BUCKET_CATEGORY: Record = { + "key-pool": "routing", + "key.selection": "routing", + "handle-setup": "processing", + "pipeline-pre": "processing", + "pipeline-post": "processing", + "worker-setup": "processing", + "worker-handoff": "processing", + "queue-wait": "processing", + "attribute-population": "processing", + "provider-internal": "networking", + "transport-context": "networking", + "transport-response-headers": "networking", + "response-finalize": "networking", + "request-sign": "networking", + "credentials-fetch": "networking", + "stream-backpressure": "streaming", + "stream-client-write": "streaming", + scheduling: "scheduling", +}; + +// Raw backend spans that split one user-facing step into internals a reader doesn't care +// about are folded into a single member. key-pool (the pool lookup) + key.selection (the +// actual pick) are both "choosing the API key", so they collapse into "Key selection". +const OVERHEAD_MEMBER_MERGE: Record = { + "key-pool": "key.selection", }; +function mergedBucketName(name: string): string { + return OVERHEAD_MEMBER_MERGE[name] ?? name; +} function overheadCategoryKey(b: OverheadBucket): string { if (OVERHEAD_SERIALIZATION_PHASES.has(b.name)) { @@ -542,24 +609,48 @@ function overheadCategoryKey(b: OverheadBucket): string { if (b.name.startsWith("middleware.")) { return "middleware"; } - // Streaming emits per-chunk convert phases (convertor.stream-in / .stream-out) that - // belong under the single Convertor category, shown as members in the drill-down. - if (b.name.startsWith("convertor.")) { - return "convertor"; + // The bare "convertor" phase and the per-chunk streaming variants (convertor.stream-in + // / .stream-out) all fold into the single Conversion category. + if (b.name === "convertor" || b.name.startsWith("convertor.")) { + return "conversion"; } - if (OVERHEAD_CATEGORY_META[b.name] && b.name !== "plugins" && b.name !== "other") { - return b.name; + const mapped = OVERHEAD_BUCKET_CATEGORY[b.name]; + if (mapped) { + return mapped; } return b.kind === "plugin" ? "plugins" : "other"; } -// overheadMemberLabel renders a drill-down member with its friendly phase label when -// there is one (serialization phases), else the span name with the redundant -// "plugin." prefix stripped (every plugin row already sits under the Plugins group). +// overheadMemberLabel renders a drill-down member with its friendly label when there is +// one, else the span name with the redundant "plugin." prefix stripped (every plugin row +// already sits under the Plugins group). +// Plugin display names where a plain title-case of the kebab id would read wrong +// (acronyms, multi-word tokens). Everything else is title-cased from its id. +const PLUGIN_LABEL_OVERRIDES: Record = { + otel: "OpenTelemetry", + datadog: "Datadog", + compat: "Compatibility", + "adaptive-loadbalancer": "Adaptive Load Balancer", + "model-catalog-resolver": "Model Catalog Resolver", +}; + +// pluginDisplayName turns a plugin's kebab-case id ("enterprise-governance") into a +// friendly label ("Enterprise Governance"), honouring PLUGIN_LABEL_OVERRIDES first. +function pluginDisplayName(id: string): string { + if (PLUGIN_LABEL_OVERRIDES[id]) return PLUGIN_LABEL_OVERRIDES[id]; + return id + .split("-") + .filter(Boolean) + .map((w) => w.charAt(0).toUpperCase() + w.slice(1)) + .join(" "); +} + function overheadMemberLabel(name: string): string { - const friendly = OVERHEAD_CATEGORY_META[name]?.label; + const friendly = OVERHEAD_LABELS[name]; if (friendly) return friendly; - return name.startsWith("plugin.") ? name.slice("plugin.".length) : name; + if (name.startsWith("plugin.")) return pluginDisplayName(name.slice("plugin.".length)); + if (name.startsWith("middleware.")) return name.slice("middleware.".length); + return name; } // buildOverheadCategories groups the raw buckets into the top-level categories, @@ -573,7 +664,17 @@ function buildOverheadCategories(buckets: OverheadBucket[]): OverheadCategory[] else grouped.set(key, [b]); } const cats: OverheadCategory[] = []; - for (const [key, members] of grouped) { + for (const [key, rawMembers] of grouped) { + // Fold raw span splits into their merged member (e.g. key-pool -> key.selection), + // summing durations, before sorting/rendering. + const byName = new Map(); + for (const m of rawMembers) { + const name = mergedBucketName(m.name); + const existing = byName.get(name); + if (existing) existing.duration_us += m.duration_us; + else byName.set(name, { ...m, name }); + } + const members = Array.from(byName.values()); members.sort((a, b) => b.duration_us - a.duration_us); cats.push({ key, @@ -588,10 +689,10 @@ function buildOverheadCategories(buckets: OverheadBucket[]): OverheadCategory[] // OverheadBreakdown renders Bifrost's overhead as a single horizontal stacked bar // split into the top-level categories, with a legend beneath. Plugin and internal -// spans are measured directly; the "core" bucket (from the backend) accounts for the -// rest of the overhead, so the segments sum to the full overhead number. "View -// details" expands the categories that hold more than one span (Plugins, Other) into -// their individual members so a specific plugin can be inspected. +// spans are measured directly; the "scheduling" bucket (from the backend) accounts for +// the residual goroutine-hop latency between phases, so the segments sum to the full +// overhead number. "View details" expands the categories that hold more than one span +// into their individual members so a specific phase or plugin can be inspected. function OverheadBreakdown({ buckets, overheadMs }: { buckets: OverheadBucket[]; overheadMs?: number }) { const [showDetails, setShowDetails] = useState(false); if (!buckets || buckets.length === 0) return null; @@ -601,7 +702,7 @@ function OverheadBreakdown({ buckets, overheadMs }: { buckets: OverheadBucket[]; const overheadUs = overheadMs != null && !isNaN(overheadMs) ? overheadMs * 1000 : undefined; // When measured spans already exceed the computed overhead, the backend omits a - // core bucket (it would be negative): a sign the upstream accumulator is + // scheduling bucket (it would be negative): a sign the upstream accumulator is // over-counting. Surface it rather than let the numbers look inconsistent. const overCounted = overheadUs != null && sumUs > overheadUs + 1;