diff --git a/common/request_timing.go b/common/request_timing.go new file mode 100644 index 000000000000..c114e1d7ee04 --- /dev/null +++ b/common/request_timing.go @@ -0,0 +1,170 @@ +package common + +import ( + "sync" + "time" + + "github.com/gin-gonic/gin" +) + +const requestTimingContextKey = "request_timing_session" + +type RequestTiming struct { + TotalMs int64 `json:"total_ms"` + GatewayMs *int64 `json:"gateway_ms,omitempty"` + UpstreamFirstDataMs *int64 `json:"upstream_first_data_ms,omitempty"` + FirstDataToClientMs *int64 `json:"first_data_to_client_ms,omitempty"` + ClientStreamMs *int64 `json:"client_stream_ms,omitempty"` + UpstreamResponseMs *int64 `json:"upstream_response_ms,omitempty"` + ResponseWriteMs *int64 `json:"response_write_ms,omitempty"` + UpstreamErrorMs *int64 `json:"upstream_error_ms,omitempty"` + FinalizeMs *int64 `json:"finalize_ms,omitempty"` +} + +type RequestTimingSession struct { + mu sync.Mutex + start time.Time + firstUpstreamAttempt time.Time + firstUpstreamData time.Time + upstreamComplete time.Time + firstClientWrite time.Time + lastClientWrite time.Time + stream bool +} + +func NewRequestTimingSession(start time.Time) *RequestTimingSession { + return &RequestTimingSession{start: start} +} + +func SetRequestTimingSession(c *gin.Context, session *RequestTimingSession) { + if c == nil || session == nil { + return + } + c.Set(requestTimingContextKey, session) +} + +func GetRequestTimingSession(c *gin.Context) *RequestTimingSession { + if c == nil { + return nil + } + value, exists := c.Get(requestTimingContextKey) + if !exists { + return nil + } + session, _ := value.(*RequestTimingSession) + return session +} + +func (s *RequestTimingSession) MarkUpstreamAttempt(at time.Time, stream bool) bool { + if s == nil { + return false + } + s.mu.Lock() + defer s.mu.Unlock() + resetFirstData := false + if s.firstUpstreamAttempt.IsZero() { + s.firstUpstreamAttempt = at + } else if s.firstClientWrite.IsZero() { + s.firstUpstreamData = time.Time{} + resetFirstData = true + } + s.upstreamComplete = time.Time{} + s.stream = stream + return resetFirstData +} + +func (s *RequestTimingSession) SetStream(stream bool) { + if s == nil { + return + } + s.mu.Lock() + s.stream = stream + s.mu.Unlock() +} + +func (s *RequestTimingSession) MarkFirstUpstreamData(at time.Time) { + if s == nil { + return + } + s.mu.Lock() + defer s.mu.Unlock() + s.stream = true + if s.firstUpstreamData.IsZero() { + s.firstUpstreamData = at + } +} + +func (s *RequestTimingSession) MarkClientWrite(startedAt time.Time, completedAt time.Time) { + if s == nil { + return + } + s.mu.Lock() + defer s.mu.Unlock() + if s.stream && s.firstUpstreamData.IsZero() { + return + } + if !s.stream && s.upstreamComplete.IsZero() { + s.upstreamComplete = startedAt + } + if s.firstClientWrite.IsZero() { + s.firstClientWrite = startedAt + } + s.lastClientWrite = completedAt +} + +func (s *RequestTimingSession) Snapshot(at time.Time, failed bool) *RequestTiming { + if s == nil { + return nil + } + s.mu.Lock() + start := s.start + firstUpstreamAttempt := s.firstUpstreamAttempt + firstUpstreamData := s.firstUpstreamData + upstreamComplete := s.upstreamComplete + firstClientWrite := s.firstClientWrite + lastClientWrite := s.lastClientWrite + stream := s.stream + s.mu.Unlock() + if start.IsZero() || at.Before(start) { + return nil + } + + timing := &RequestTiming{TotalMs: at.Sub(start).Milliseconds()} + if firstUpstreamAttempt.IsZero() { + if failed { + timing.GatewayMs = millisecondsBetween(start, at) + } + return timing + } + + timing.GatewayMs = millisecondsBetween(start, firstUpstreamAttempt) + if failed && upstreamComplete.IsZero() && firstUpstreamData.IsZero() { + timing.UpstreamErrorMs = millisecondsBetween(firstUpstreamAttempt, at) + return timing + } + + if stream { + timing.UpstreamFirstDataMs = millisecondsBetween(firstUpstreamAttempt, firstUpstreamData) + timing.FirstDataToClientMs = millisecondsBetween(firstUpstreamData, firstClientWrite) + timing.ClientStreamMs = millisecondsBetween(firstClientWrite, lastClientWrite) + timing.FinalizeMs = millisecondsBetween(lastClientWrite, at) + return timing + } + + timing.UpstreamResponseMs = millisecondsBetween(firstUpstreamAttempt, upstreamComplete) + timing.ResponseWriteMs = millisecondsBetween(upstreamComplete, lastClientWrite) + if lastClientWrite.IsZero() { + timing.FinalizeMs = millisecondsBetween(upstreamComplete, at) + } else { + timing.FinalizeMs = millisecondsBetween(lastClientWrite, at) + } + return timing +} + +func millisecondsBetween(start time.Time, end time.Time) *int64 { + if start.IsZero() || end.IsZero() || end.Before(start) { + return nil + } + value := end.Sub(start).Milliseconds() + return &value +} diff --git a/common/request_timing_test.go b/common/request_timing_test.go new file mode 100644 index 000000000000..921d93008073 --- /dev/null +++ b/common/request_timing_test.go @@ -0,0 +1,160 @@ +package common + +import ( + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func assertMilliseconds(t *testing.T, expected int64, actual *int64) { + t.Helper() + require.NotNil(t, actual) + assert.Equal(t, expected, *actual) +} + +func TestRequestTimingSnapshotForStreamingRequest(t *testing.T) { + start := time.Unix(100, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), true) + session.MarkClientWrite(start.Add(15*time.Millisecond), start.Add(16*time.Millisecond)) + session.MarkFirstUpstreamData(start.Add(30 * time.Millisecond)) + session.MarkClientWrite(start.Add(35*time.Millisecond), start.Add(36*time.Millisecond)) + session.MarkClientWrite(start.Add(60*time.Millisecond), start.Add(61*time.Millisecond)) + + timing := session.Snapshot(start.Add(70*time.Millisecond), false) + + require.NotNil(t, timing) + assert.Equal(t, int64(70), timing.TotalMs) + assertMilliseconds(t, 10, timing.GatewayMs) + assertMilliseconds(t, 20, timing.UpstreamFirstDataMs) + assertMilliseconds(t, 5, timing.FirstDataToClientMs) + assertMilliseconds(t, 26, timing.ClientStreamMs) + assertMilliseconds(t, 9, timing.FinalizeMs) + assert.Nil(t, timing.UpstreamResponseMs) + assert.Nil(t, timing.ResponseWriteMs) +} + +func TestRequestTimingSnapshotForNonStreamingRequest(t *testing.T) { + start := time.Unix(200, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), false) + session.MarkClientWrite(start.Add(40*time.Millisecond), start.Add(45*time.Millisecond)) + session.MarkClientWrite(start.Add(46*time.Millisecond), start.Add(47*time.Millisecond)) + + timing := session.Snapshot(start.Add(50*time.Millisecond), false) + + require.NotNil(t, timing) + assert.Equal(t, int64(50), timing.TotalMs) + assertMilliseconds(t, 10, timing.GatewayMs) + assertMilliseconds(t, 30, timing.UpstreamResponseMs) + assertMilliseconds(t, 7, timing.ResponseWriteMs) + assertMilliseconds(t, 3, timing.FinalizeMs) + assert.Nil(t, timing.UpstreamFirstDataMs) + assert.Nil(t, timing.FirstDataToClientMs) + assert.Nil(t, timing.ClientStreamMs) +} + +func TestRequestTimingSnapshotForUpstreamErrorBeforeClientWrite(t *testing.T) { + start := time.Unix(250, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), false) + + timing := session.Snapshot(start.Add(45*time.Millisecond), true) + + require.NotNil(t, timing) + assertMilliseconds(t, 10, timing.GatewayMs) + assertMilliseconds(t, 35, timing.UpstreamErrorMs) + assert.Nil(t, timing.UpstreamResponseMs) + assert.Nil(t, timing.FinalizeMs) +} + +func TestRequestTimingSnapshotForUpstreamFailure(t *testing.T) { + start := time.Unix(300, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), false) + + timing := session.Snapshot(start.Add(45*time.Millisecond), true) + + require.NotNil(t, timing) + assert.Equal(t, int64(45), timing.TotalMs) + assertMilliseconds(t, 10, timing.GatewayMs) + assertMilliseconds(t, 35, timing.UpstreamErrorMs) + assert.Nil(t, timing.UpstreamResponseMs) + assert.Nil(t, timing.FinalizeMs) +} + +func TestRequestTimingSnapshotForGatewayFailure(t *testing.T) { + start := time.Unix(400, 0) + session := NewRequestTimingSession(start) + + timing := session.Snapshot(start.Add(20*time.Millisecond), true) + + require.NotNil(t, timing) + assert.Equal(t, int64(20), timing.TotalMs) + assertMilliseconds(t, 20, timing.GatewayMs) + assert.Nil(t, timing.UpstreamErrorMs) +} + +func TestRequestTimingSnapshotIncludesRetriesInUpstreamPhase(t *testing.T) { + start := time.Unix(500, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), true) + session.MarkFirstUpstreamData(start.Add(20 * time.Millisecond)) + session.MarkUpstreamAttempt(start.Add(30*time.Millisecond), true) + session.MarkFirstUpstreamData(start.Add(50 * time.Millisecond)) + session.MarkClientWrite(start.Add(55*time.Millisecond), start.Add(56*time.Millisecond)) + + timing := session.Snapshot(start.Add(60*time.Millisecond), false) + + require.NotNil(t, timing) + assertMilliseconds(t, 10, timing.GatewayMs) + assertMilliseconds(t, 40, timing.UpstreamFirstDataMs) +} + +func TestRequestTimingFirstDataPromotesResponseToStreaming(t *testing.T) { + start := time.Unix(550, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), false) + session.MarkFirstUpstreamData(start.Add(30 * time.Millisecond)) + session.MarkClientWrite(start.Add(35*time.Millisecond), start.Add(36*time.Millisecond)) + + timing := session.Snapshot(start.Add(40*time.Millisecond), false) + + require.NotNil(t, timing) + assertMilliseconds(t, 20, timing.UpstreamFirstDataMs) + assert.Nil(t, timing.UpstreamResponseMs) +} + +func TestRequestTimingStreamPromotionIgnoresWritesBeforeFirstData(t *testing.T) { + start := time.Unix(575, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), false) + session.SetStream(true) + session.MarkClientWrite(start.Add(15*time.Millisecond), start.Add(16*time.Millisecond)) + session.MarkFirstUpstreamData(start.Add(30 * time.Millisecond)) + session.MarkClientWrite(start.Add(35*time.Millisecond), start.Add(36*time.Millisecond)) + + timing := session.Snapshot(start.Add(40*time.Millisecond), false) + + require.NotNil(t, timing) + assertMilliseconds(t, 5, timing.FirstDataToClientMs) + assert.Nil(t, timing.UpstreamResponseMs) +} + +func TestRequestTimingSnapshotPreservesZeroMillisecondPhases(t *testing.T) { + start := time.Unix(600, 0) + session := NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start, false) + session.MarkClientWrite(start, start) + + timing := session.Snapshot(start, false) + + require.NotNil(t, timing) + assert.Equal(t, int64(0), timing.TotalMs) + assertMilliseconds(t, 0, timing.GatewayMs) + assertMilliseconds(t, 0, timing.UpstreamResponseMs) + assertMilliseconds(t, 0, timing.ResponseWriteMs) + assertMilliseconds(t, 0, timing.FinalizeMs) +} diff --git a/middleware/request_timing.go b/middleware/request_timing.go new file mode 100644 index 000000000000..a143f546be06 --- /dev/null +++ b/middleware/request_timing.go @@ -0,0 +1,74 @@ +package middleware + +import ( + "net/http" + "strings" + "time" + + "github.com/QuantumNous/new-api/common" + + "github.com/gin-gonic/gin" +) + +type requestTimingResponseWriter struct { + gin.ResponseWriter + session *common.RequestTimingSession +} + +func (w *requestTimingResponseWriter) Write(data []byte) (int, error) { + startedAt := time.Now() + written, err := w.ResponseWriter.Write(data) + if written > 0 { + w.session.MarkClientWrite(startedAt, time.Now()) + } + return written, err +} + +func (w *requestTimingResponseWriter) WriteString(data string) (int, error) { + startedAt := time.Now() + written, err := w.ResponseWriter.WriteString(data) + if written > 0 { + w.session.MarkClientWrite(startedAt, time.Now()) + } + return written, err +} + +func RequestTiming() gin.HandlerFunc { + return func(c *gin.Context) { + if !shouldRecordRequestTiming(c.Request.Method, c.Request.URL.Path) { + c.Next() + return + } + + session := common.NewRequestTimingSession(time.Now()) + common.SetRequestTimingSession(c, session) + c.Writer = &requestTimingResponseWriter{ + ResponseWriter: c.Writer, + session: session, + } + c.Next() + } +} + +func shouldRecordRequestTiming(method string, path string) bool { + if method != http.MethodPost { + return false + } + switch path { + case "/v1/chat/completions", "/v1/completions", "/v1/responses", "/v1/messages": + return true + } + + const prefix = "/v1beta/models/" + if !strings.HasPrefix(path, prefix) { + return false + } + modelAction := strings.TrimPrefix(path, prefix) + for _, action := range []string{":generateContent", ":streamGenerateContent"} { + if strings.HasSuffix(modelAction, action) { + model := strings.TrimSuffix(modelAction, action) + return model != "" && !strings.Contains(model, "/") + } + } + return false +} diff --git a/middleware/request_timing_test.go b/middleware/request_timing_test.go new file mode 100644 index 000000000000..fa15fcb29587 --- /dev/null +++ b/middleware/request_timing_test.go @@ -0,0 +1,87 @@ +package middleware + +import ( + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/QuantumNous/new-api/common" + + "github.com/gin-gonic/gin" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestShouldRecordRequestTiming(t *testing.T) { + tests := []struct { + name string + method string + path string + expected bool + }{ + {name: "chat completions", method: http.MethodPost, path: "/v1/chat/completions", expected: true}, + {name: "legacy completions", method: http.MethodPost, path: "/v1/completions", expected: true}, + {name: "responses", method: http.MethodPost, path: "/v1/responses", expected: true}, + {name: "claude messages", method: http.MethodPost, path: "/v1/messages", expected: true}, + {name: "gemini generate", method: http.MethodPost, path: "/v1beta/models/gemini-2.5-pro:generateContent", expected: true}, + {name: "gemini stream generate", method: http.MethodPost, path: "/v1beta/models/gemini-2.5-pro:streamGenerateContent", expected: true}, + {name: "get chat", method: http.MethodGet, path: "/v1/chat/completions", expected: false}, + {name: "responses compact", method: http.MethodPost, path: "/v1/responses/compact", expected: false}, + {name: "realtime", method: http.MethodPost, path: "/v1/realtime", expected: false}, + {name: "embedding", method: http.MethodPost, path: "/v1/embeddings", expected: false}, + {name: "playground", method: http.MethodPost, path: "/pg/chat/completions", expected: false}, + {name: "gemini embedding", method: http.MethodPost, path: "/v1beta/models/text-embedding:embedContent", expected: false}, + {name: "gemini missing model", method: http.MethodPost, path: "/v1beta/models/:generateContent", expected: false}, + {name: "gemini extra suffix", method: http.MethodPost, path: "/v1beta/models/gemini:generateContent/extra", expected: false}, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + assert.Equal(t, test.expected, shouldRecordRequestTiming(test.method, test.path)) + }) + } +} + +func TestRequestTimingMiddlewareIgnoresKeepaliveWrites(t *testing.T) { + gin.SetMode(gin.TestMode) + engine := gin.New() + engine.Use(RequestTiming()) + var session *common.RequestTimingSession + engine.POST("/v1/chat/completions", func(c *gin.Context) { + session = common.GetRequestTimingSession(c) + require.NotNil(t, session) + session.MarkUpstreamAttempt(time.Now(), true) + _, err := c.Writer.Write([]byte(": PING\n\n")) + require.NoError(t, err) + session.MarkFirstUpstreamData(time.Now()) + _, err = c.Writer.WriteString("data: result\n\n") + require.NoError(t, err) + }) + + request := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) + response := httptest.NewRecorder() + engine.ServeHTTP(response, request) + + require.NotNil(t, session) + timing := session.Snapshot(time.Now(), false) + require.NotNil(t, timing) + require.NotNil(t, timing.FirstDataToClientMs) +} + +func TestRequestTimingMiddlewareSkipsOtherRoutes(t *testing.T) { + gin.SetMode(gin.TestMode) + engine := gin.New() + engine.Use(RequestTiming()) + var session *common.RequestTimingSession + engine.POST("/v1/embeddings", func(c *gin.Context) { + session = common.GetRequestTimingSession(c) + c.Status(http.StatusNoContent) + }) + + request := httptest.NewRequest(http.MethodPost, "/v1/embeddings", nil) + response := httptest.NewRecorder() + engine.ServeHTTP(response, request) + + assert.Nil(t, session) +} diff --git a/model/log.go b/model/log.go index 1d2b38fc7c1c..fca87bcf8e09 100644 --- a/model/log.go +++ b/model/log.go @@ -285,6 +285,7 @@ func RecordErrorLog(c *gin.Context, userId int, channelId int, modelName string, username := c.GetString("username") requestId := c.GetString(common.RequestIdKey) upstreamRequestId := c.GetString(common.UpstreamRequestIdKey) + other = attachRequestTiming(c, other, true) otherStr := common.MapToJsonStr(other) // 判断是否需要记录 IP needRecordIp := false @@ -349,6 +350,7 @@ func RecordConsumeLog(c *gin.Context, userId int, params RecordConsumeLogParams) requestId := c.GetString(common.RequestIdKey) upstreamRequestId := c.GetString(common.UpstreamRequestIdKey) createdAt := common.GetTimestamp() + params.Other = attachRequestTiming(c, params.Other, false) otherStr := common.MapToJsonStr(params.Other) // 判断是否需要记录 IP needRecordIp := false @@ -403,6 +405,22 @@ func RecordConsumeLog(c *gin.Context, userId int, params RecordConsumeLogParams) } } +func attachRequestTiming(c *gin.Context, other map[string]interface{}, failed bool) map[string]interface{} { + session := common.GetRequestTimingSession(c) + if session == nil { + return other + } + snapshot := session.Snapshot(time.Now(), failed) + if snapshot == nil { + return other + } + if other == nil { + other = make(map[string]interface{}) + } + other["request_timing"] = snapshot + return other +} + type RecordTaskBillingLogParams struct { UserId int LogType int diff --git a/model/log_format_test.go b/model/log_format_test.go index f580dda637af..9a25b60279a0 100644 --- a/model/log_format_test.go +++ b/model/log_format_test.go @@ -33,3 +33,27 @@ func TestFormatUserLogsStripsQuotaSaturation(t *testing.T) { // Non-admin billing fields remain visible. require.Contains(t, parsed, "model_price") } + +func TestFormatUserLogsKeepsRequestTiming(t *testing.T) { + other := common.MapToJsonStr(map[string]interface{}{ + "request_timing": map[string]interface{}{ + "total_ms": 42, + "gateway_ms": 4, + "upstream_first_data_ms": 30, + }, + "admin_info": map[string]interface{}{ + "channel_id": 9, + }, + }) + logs := []*Log{{Other: other}} + + formatUserLogs(logs, 0) + + parsed, err := common.StrToMap(logs[0].Other) + require.NoError(t, err) + require.Contains(t, parsed, "request_timing") + require.NotContains(t, parsed, "admin_info") + timing, ok := parsed["request_timing"].(map[string]interface{}) + require.True(t, ok) + require.Equal(t, float64(42), timing["total_ms"]) +} diff --git a/model/log_request_timing_test.go b/model/log_request_timing_test.go new file mode 100644 index 000000000000..87769b0819d0 --- /dev/null +++ b/model/log_request_timing_test.go @@ -0,0 +1,76 @@ +package model + +import ( + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/QuantumNous/new-api/common" + + "github.com/gin-gonic/gin" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func newLogTimingContext(t *testing.T, requestID string, stream bool) *gin.Context { + t.Helper() + gin.SetMode(gin.TestMode) + c, _ := gin.CreateTestContext(httptest.NewRecorder()) + c.Request = httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) + c.Set(common.RequestIdKey, requestID) + start := time.Now().Add(-50 * time.Millisecond) + session := common.NewRequestTimingSession(start) + session.MarkUpstreamAttempt(start.Add(10*time.Millisecond), stream) + if stream { + session.MarkFirstUpstreamData(start.Add(25 * time.Millisecond)) + session.MarkClientWrite(start.Add(30*time.Millisecond), start.Add(31*time.Millisecond)) + session.MarkClientWrite(start.Add(40*time.Millisecond), start.Add(41*time.Millisecond)) + } else { + session.MarkClientWrite(start.Add(25*time.Millisecond), start.Add(30*time.Millisecond)) + } + common.SetRequestTimingSession(c, session) + return c +} + +func requireStoredRequestTiming(t *testing.T, requestID string) map[string]interface{} { + t.Helper() + var log Log + require.NoError(t, LOG_DB.Where("request_id = ?", requestID).First(&log).Error) + other, err := common.StrToMap(log.Other) + require.NoError(t, err) + timing, ok := other["request_timing"].(map[string]interface{}) + require.True(t, ok) + assert.Contains(t, timing, "total_ms") + assert.Contains(t, timing, "gateway_ms") + for _, key := range []string{"channel_id", "channel_name", "channel_type", "api_key", "ip", "request_content"} { + assert.NotContains(t, timing, key) + } + return timing +} + +func TestRecordConsumeLogIncludesRequestTiming(t *testing.T) { + requestID := "timing-consume-log" + c := newLogTimingContext(t, requestID, false) + + RecordConsumeLog(c, 1001, RecordConsumeLogParams{ + ModelName: "test-model", + UseTimeSeconds: 1, + Other: map[string]interface{}{"frt": 25}, + }) + + timing := requireStoredRequestTiming(t, requestID) + assert.Contains(t, timing, "upstream_response_ms") + assert.Contains(t, timing, "response_write_ms") +} + +func TestRecordErrorLogIncludesAvailableRequestTiming(t *testing.T) { + requestID := "timing-error-log" + c := newLogTimingContext(t, requestID, true) + + RecordErrorLog(c, 1002, 8, "test-model", "test-token", "upstream interrupted", 7, 1, true, "default", nil) + + timing := requireStoredRequestTiming(t, requestID) + assert.Contains(t, timing, "upstream_first_data_ms") + assert.Contains(t, timing, "client_stream_ms") +} diff --git a/relay/channel/cloudflare/relay_cloudflare.go b/relay/channel/cloudflare/relay_cloudflare.go index c98208787100..dea6106c6197 100644 --- a/relay/channel/cloudflare/relay_cloudflare.go +++ b/relay/channel/cloudflare/relay_cloudflare.go @@ -6,7 +6,6 @@ import ( "io" "net/http" "strings" - "time" "github.com/QuantumNous/new-api/logger" relaycommon "github.com/QuantumNous/new-api/relay/common" @@ -62,14 +61,17 @@ func cfStreamHandler(c *gin.Context, info *relaycommon.RelayInfo, resp *http.Res } response.Id = id response.Model = info.UpstreamModelName - err = helper.ObjectData(c, response) if isFirst { - isFirst = false - info.FirstResponseTime = time.Now() + info.MarkFirstUpstreamData() } + err = helper.ObjectData(c, response) if err != nil { logger.LogError(c, "error_rendering_stream_response: "+err.Error()) } + if isFirst { + isFirst = false + info.SetFirstResponseTime() + } } if err := scanner.Err(); err != nil { diff --git a/relay/channel/cohere/relay-cohere.go b/relay/channel/cohere/relay-cohere.go index 30a3038c1363..bb9b7e69d22b 100644 --- a/relay/channel/cohere/relay-cohere.go +++ b/relay/channel/cohere/relay-cohere.go @@ -5,7 +5,6 @@ import ( "io" "net/http" "strings" - "time" "github.com/QuantumNous/new-api/common" relaycommon "github.com/QuantumNous/new-api/relay/common" @@ -117,7 +116,7 @@ func cohereStreamHandler(c *gin.Context, info *relaycommon.RelayInfo, resp *http case data := <-dataChan: if isFirst { isFirst = false - info.FirstResponseTime = time.Now() + info.SetFirstResponseTime() } data = strings.TrimSuffix(data, "\r") var cohereResp CohereResponse diff --git a/relay/chat_completions_via_responses.go b/relay/chat_completions_via_responses.go index b8a6fc875872..04f1c89018db 100644 --- a/relay/chat_completions_via_responses.go +++ b/relay/chat_completions_via_responses.go @@ -137,6 +137,7 @@ func chatCompletionsViaResponses(c *gin.Context, info *relaycommon.RelayInfo, ad var requestBody io.Reader = body var httpResp *http.Response + info.MarkUpstreamAttempt() resp, err := adaptor.DoRequest(c, info, requestBody) if err != nil { return nil, types.NewOpenAIError(err, types.ErrorCodeDoRequestFailed, http.StatusInternalServerError) diff --git a/relay/claude_handler.go b/relay/claude_handler.go index ff7854469d7f..50bd0d070ff8 100644 --- a/relay/claude_handler.go +++ b/relay/claude_handler.go @@ -202,6 +202,7 @@ func ClaudeHelper(c *gin.Context, info *relaycommon.RelayInfo) (newAPIError *typ statusCodeMappingStr := c.GetString("status_code_mapping") var httpResp *http.Response + info.MarkUpstreamAttempt() resp, err := adaptor.DoRequest(c, info, requestBody) if err != nil { return types.NewOpenAIError(err, types.ErrorCodeDoRequestFailed, http.StatusInternalServerError) @@ -209,7 +210,7 @@ func ClaudeHelper(c *gin.Context, info *relaycommon.RelayInfo) (newAPIError *typ if resp != nil { httpResp = resp.(*http.Response) - info.IsStream = info.IsStream || strings.HasPrefix(httpResp.Header.Get("Content-Type"), "text/event-stream") + info.SetStream(info.IsStream || strings.HasPrefix(httpResp.Header.Get("Content-Type"), "text/event-stream")) if httpResp.StatusCode != http.StatusOK { newAPIError = service.RelayErrorHandler(c.Request.Context(), httpResp, false) // reset status code 重置状态码 diff --git a/relay/common/relay_info.go b/relay/common/relay_info.go index b0bb19bdca3b..3184d3542dd8 100644 --- a/relay/common/relay_info.go +++ b/relay/common/relay_info.go @@ -90,6 +90,7 @@ type RelayInfo struct { TokenUnlimited bool StartTime time.Time FirstResponseTime time.Time + RequestTiming *common.RequestTimingSession isFirstResponse bool //SendLastReasoningResponse bool IsStream bool @@ -527,6 +528,7 @@ func genBaseRelayInfo(c *gin.Context, request dto.Request) *RelayInfo { StartTime: startTime, FirstResponseTime: startTime.Add(-time.Second), + RequestTiming: common.GetRequestTimingSession(c), ThinkingContentInfo: ThinkingContentInfo{ IsFirstThinkingContent: true, SendLastThinkingContent: false, @@ -841,11 +843,37 @@ func (info *RelayInfo) ConvOptions() *convmeta.Options { func (info *RelayInfo) SetFirstResponseTime() { if info.isFirstResponse { - info.FirstResponseTime = time.Now() + now := time.Now() + info.FirstResponseTime = now + info.RequestTiming.MarkFirstUpstreamData(now) info.isFirstResponse = false } } +func (info *RelayInfo) MarkFirstUpstreamData() { + if info == nil { + return + } + info.RequestTiming.MarkFirstUpstreamData(time.Now()) +} + +func (info *RelayInfo) MarkUpstreamAttempt() { + if info == nil { + return + } + if info.RequestTiming.MarkUpstreamAttempt(time.Now(), info.IsStream) { + info.isFirstResponse = true + } +} + +func (info *RelayInfo) SetStream(stream bool) { + if info == nil { + return + } + info.IsStream = stream + info.RequestTiming.SetStream(stream) +} + func (info *RelayInfo) HasSendResponse() bool { return info.FirstResponseTime.After(info.StartTime) } diff --git a/relay/common/relay_info_test.go b/relay/common/relay_info_test.go index 42a0f8567bfe..97f2d1e82bcb 100644 --- a/relay/common/relay_info_test.go +++ b/relay/common/relay_info_test.go @@ -4,7 +4,9 @@ import ( "encoding/json" "net/http/httptest" "testing" + "time" + rootcommon "github.com/QuantumNous/new-api/common" "github.com/QuantumNous/new-api/relaykit/dto" "github.com/QuantumNous/new-api/relaykit/relayconvert/convmeta" "github.com/QuantumNous/new-api/relaykit/types" @@ -13,6 +15,74 @@ import ( "github.com/stretchr/testify/require" ) +func TestSetFirstResponseTimeMarksRequestTiming(t *testing.T) { + start := time.Now().Add(-20 * time.Millisecond) + timing := rootcommon.NewRequestTimingSession(start) + timing.MarkUpstreamAttempt(start.Add(5*time.Millisecond), true) + info := &RelayInfo{ + StartTime: start, + isFirstResponse: true, + RequestTiming: timing, + } + + info.SetFirstResponseTime() + info.SetFirstResponseTime() + + snapshot := timing.Snapshot(time.Now(), false) + require.NotNil(t, snapshot) + require.NotNil(t, snapshot.UpstreamFirstDataMs) + assert.True(t, info.HasSendResponse()) +} + +func TestMarkFirstUpstreamDataDoesNotChangeLegacyFirstResponseTime(t *testing.T) { + start := time.Now().Add(-time.Second) + timing := rootcommon.NewRequestTimingSession(start) + timing.MarkUpstreamAttempt(start.Add(10*time.Millisecond), true) + original := start.Add(-time.Second) + info := &RelayInfo{ + StartTime: start, + FirstResponseTime: original, + RequestTiming: timing, + isFirstResponse: true, + } + + info.MarkFirstUpstreamData() + + snapshot := timing.Snapshot(time.Now(), false) + require.NotNil(t, snapshot) + require.NotNil(t, snapshot.UpstreamFirstDataMs) + assert.Equal(t, original, info.FirstResponseTime) + assert.False(t, info.HasSendResponse()) +} + +func TestMarkUpstreamAttemptMarksRequestTiming(t *testing.T) { + start := time.Now().Add(-time.Second) + timing := rootcommon.NewRequestTimingSession(start) + info := &RelayInfo{IsStream: true, RequestTiming: timing} + + info.MarkUpstreamAttempt() + timingSnapshot := timing.Snapshot(time.Now(), true) + + require.NotNil(t, timingSnapshot) + require.NotNil(t, timingSnapshot.GatewayMs) + require.NotNil(t, timingSnapshot.UpstreamErrorMs) +} + +func TestMarkUpstreamAttemptResetsFirstResponseAfterRetry(t *testing.T) { + start := time.Now().Add(-time.Second) + timing := rootcommon.NewRequestTimingSession(start) + info := &RelayInfo{IsStream: true, RequestTiming: timing, isFirstResponse: true} + + info.MarkUpstreamAttempt() + info.SetFirstResponseTime() + info.MarkUpstreamAttempt() + info.SetFirstResponseTime() + timingSnapshot := timing.Snapshot(time.Now(), false) + + require.NotNil(t, timingSnapshot) + require.NotNil(t, timingSnapshot.UpstreamFirstDataMs) +} + func TestRelayInfoGetFinalRequestRelayFormatPrefersExplicitFinal(t *testing.T) { info := &RelayInfo{ RelayFormat: types.RelayFormatOpenAI, diff --git a/relay/compatible_handler.go b/relay/compatible_handler.go index 8edb3362b6e0..2db170d2a344 100644 --- a/relay/compatible_handler.go +++ b/relay/compatible_handler.go @@ -185,6 +185,7 @@ func TextHelper(c *gin.Context, info *relaycommon.RelayInfo) (newAPIError *types } var httpResp *http.Response + info.MarkUpstreamAttempt() resp, err := adaptor.DoRequest(c, info, requestBody) if err != nil { return types.NewOpenAIError(err, types.ErrorCodeDoRequestFailed, http.StatusInternalServerError) @@ -194,7 +195,7 @@ func TextHelper(c *gin.Context, info *relaycommon.RelayInfo) (newAPIError *types if resp != nil { httpResp = resp.(*http.Response) - info.IsStream = info.IsStream || strings.HasPrefix(httpResp.Header.Get("Content-Type"), "text/event-stream") + info.SetStream(info.IsStream || strings.HasPrefix(httpResp.Header.Get("Content-Type"), "text/event-stream")) if httpResp.StatusCode != http.StatusOK { newApiErr := service.RelayErrorHandler(c.Request.Context(), httpResp, false) // reset status code 重置状态码 diff --git a/relay/gemini_handler.go b/relay/gemini_handler.go index 57010d87c380..694a885f21b1 100644 --- a/relay/gemini_handler.go +++ b/relay/gemini_handler.go @@ -173,6 +173,7 @@ func GeminiHelper(c *gin.Context, info *relaycommon.RelayInfo) (newAPIError *typ requestBody = body } + info.MarkUpstreamAttempt() resp, err := adaptor.DoRequest(c, info, requestBody) if err != nil { logger.LogError(c, "Do gemini request failed: "+err.Error()) @@ -184,7 +185,7 @@ func GeminiHelper(c *gin.Context, info *relaycommon.RelayInfo) (newAPIError *typ var httpResp *http.Response if resp != nil { httpResp = resp.(*http.Response) - info.IsStream = info.IsStream || strings.HasPrefix(httpResp.Header.Get("Content-Type"), "text/event-stream") + info.SetStream(info.IsStream || strings.HasPrefix(httpResp.Header.Get("Content-Type"), "text/event-stream")) if httpResp.StatusCode != http.StatusOK { newAPIError = service.RelayErrorHandler(c.Request.Context(), httpResp, false) // reset status code 重置状态码 diff --git a/relay/responses_handler.go b/relay/responses_handler.go index f8b4dec2be7b..31b8b632a1d5 100644 --- a/relay/responses_handler.go +++ b/relay/responses_handler.go @@ -119,6 +119,7 @@ func ResponsesHelper(c *gin.Context, info *relaycommon.RelayInfo) (newAPIError * } var httpResp *http.Response + info.MarkUpstreamAttempt() resp, err := adaptor.DoRequest(c, info, requestBody) if err != nil { return types.NewOpenAIError(err, types.ErrorCodeDoRequestFailed, http.StatusInternalServerError) diff --git a/router/relay-router.go b/router/relay-router.go index e08ecb14bc17..a4b9495f6876 100644 --- a/router/relay-router.go +++ b/router/relay-router.go @@ -11,6 +11,7 @@ import ( ) func SetRelayRouter(router *gin.Engine) { + router.Use(middleware.RequestTiming()) router.Use(middleware.CORS()) router.Use(middleware.DecompressRequestMiddleware()) router.Use(middleware.BodyStorageCleanup()) // 清理请求体存储 diff --git a/web/src/features/usage-logs/components/__tests__/request-timing-display.test.tsx b/web/src/features/usage-logs/components/__tests__/request-timing-display.test.tsx new file mode 100644 index 000000000000..d22724c0076b --- /dev/null +++ b/web/src/features/usage-logs/components/__tests__/request-timing-display.test.tsx @@ -0,0 +1,198 @@ +import assert from 'node:assert/strict' +import { after, describe, test } from 'node:test' + +import { Window } from 'happy-dom' +import type React from 'react' + +import type { UsageLog } from '../../data/schema' + +const domWindow = new Window() +const domGlobals = [ + 'window', + 'document', + 'navigator', + 'HTMLElement', + 'SVGElement', + 'Node', + 'Element', + 'Event', + 'CustomEvent', + 'FocusEvent', + 'PointerEvent', + 'MutationObserver', + 'requestAnimationFrame', + 'cancelAnimationFrame', + 'getComputedStyle', +] as const + +for (const key of domGlobals) { + Object.defineProperty(globalThis, key, { + configurable: true, + value: domWindow[key], + }) +} + +const { act } = await import('react') +const { createRoot } = await import('react-dom/client') +const { createInstance } = await import('i18next') +const { I18nextProvider, initReactI18next } = await import('react-i18next') +const { RequestTimingBreakdown } = await import('../request-timing-breakdown') +const { TimingMetricsCell } = await import('../timing-metrics-cell') +const { DetailsDialog } = await import('../dialogs/details-dialog') +const { buildTimingPresentation } = await import('../../lib/request-timing') + +const i18n = createInstance() +await i18n.use(initReactI18next).init({ + lng: 'en', + resources: { + en: { + translation: { + 'Timing breakdown': 'Timing breakdown', + 'Gateway processing': 'Gateway processing', + 'Upstream first data': 'Upstream first data', + 'First data to client': 'First data to client', + 'Client streaming': 'Client streaming', + Finalization: 'Finalization', + 'First token': 'First token', + Duration: 'Duration', + 'N/A': 'N/A', + }, + }, + }, +}) + +const reactTestGlobals = globalThis as typeof globalThis & { + IS_REACT_ACT_ENVIRONMENT?: boolean +} +reactTestGlobals.IS_REACT_ACT_ENVIRONMENT = true + +type RenderedComponent = { + container: HTMLDivElement + root: ReturnType +} + +async function renderComponent( + element: React.ReactNode +): Promise { + const container = document.createElement('div') + document.body.append(container) + const root = createRoot(container) + await act(async () => { + root.render({element}) + }) + return { container, root } +} + +async function unmountComponent(rendered: RenderedComponent) { + await act(async () => rendered.root.unmount()) + rendered.container.remove() +} + +describe('request timing display', () => { + after(() => domWindow.close()) + + test('renders the available stream phases including zero milliseconds', async () => { + const presentation = buildTimingPresentation(9, undefined, { + total_ms: 1500, + gateway_ms: 100, + upstream_first_data_ms: 400, + first_data_to_client_ms: 0, + client_stream_ms: 900, + finalize_ms: 100, + }) + const rendered = await renderComponent( + + ) + + const text = rendered.container.textContent ?? '' + assert.equal(text.includes('Gateway processing'), true) + assert.equal(text.includes('Upstream first data'), true) + assert.equal(text.includes('First data to client'), true) + assert.equal(text.includes('0.0s'), true) + + await unmountComponent(rendered) + }) + + test('retains timing values in the breakdown trigger accessible name', async () => { + const rendered = await renderComponent( + + ) + + const text = rendered.container.textContent ?? '' + assert.equal(text.includes('0.5s'), true) + assert.equal(text.includes('1.5s'), true) + const trigger = rendered.container.querySelector('button') + assert.ok(trigger) + const accessibleName = trigger.getAttribute('aria-label') ?? '' + assert.equal(accessibleName.includes('First token'), true) + assert.equal(accessibleName.includes('0.5s'), true) + assert.equal(accessibleName.includes('Duration'), true) + assert.equal(accessibleName.includes('1.5s'), true) + assert.equal(accessibleName.includes('Timing breakdown'), true) + + await unmountComponent(rendered) + }) + + test('shows the same phase breakdown in log details for a non-admin viewer', async () => { + const log: UsageLog = { + id: 1, + user_id: 10, + created_at: 1, + type: 2, + content: '', + username: 'user', + token_name: 'token', + model_name: 'model', + quota: 0, + prompt_tokens: 1, + completion_tokens: 2, + use_time: 9, + is_stream: true, + channel: 0, + channel_name: '', + token_id: 1, + group: 'default', + ip: '', + request_id: 'request-id', + upstream_request_id: '', + other: JSON.stringify({ + request_timing: { + total_ms: 1500, + gateway_ms: 100, + upstream_first_data_ms: 400, + first_data_to_client_ms: 0, + client_stream_ms: 900, + finalize_ms: 100, + }, + }), + } + const rendered = await renderComponent( + undefined} + /> + ) + + const text = document.body.textContent ?? '' + assert.equal(text.includes('Gateway processing'), true) + assert.equal(text.includes('Client streaming'), true) + assert.equal(text.includes('0.5s'), true) + + await unmountComponent(rendered) + }) +}) diff --git a/web/src/features/usage-logs/components/columns/common-logs-columns.tsx b/web/src/features/usage-logs/components/columns/common-logs-columns.tsx index e7b29441e2f3..d9d47af4c8a9 100644 --- a/web/src/features/usage-logs/components/columns/common-logs-columns.tsx +++ b/web/src/features/usage-logs/components/columns/common-logs-columns.tsx @@ -717,6 +717,7 @@ export function useCommonLogsColumns(isAdmin: boolean): ColumnDef[] { useTimeSec={useTime} completionTokens={log.completion_tokens} frtMs={other?.frt} + requestTiming={other?.request_timing} isStream={log.is_stream} /> ) diff --git a/web/src/features/usage-logs/components/dialogs/details-dialog.tsx b/web/src/features/usage-logs/components/dialogs/details-dialog.tsx index f30e35a86555..e32f6316b140 100644 --- a/web/src/features/usage-logs/components/dialogs/details-dialog.tsx +++ b/web/src/features/usage-logs/components/dialogs/details-dialog.tsx @@ -77,12 +77,14 @@ import { getReasoningEffortVariant, renderAuditContent, } from '../../lib/format' +import { buildTimingPresentation } from '../../lib/request-timing' import { getLogTypeConfig, isPerCallBilling, isTimingLogType, } from '../../lib/utils' import { USAGE_BILLING_PATH, type LogOtherData } from '../../types' +import { RequestTimingBreakdown } from '../request-timing-breakdown' // Maps a channel-update changed-field token (as recorded by the backend audit) // to its i18n label key for display in the audit details. @@ -482,6 +484,11 @@ export function DetailsDialog(props: DetailsDialogProps) { const { copiedText, copyToClipboard } = useCopyToClipboard({ notify: false }) const details = props.log.content ?? '' const other = parseLogOther(props.log.other) + const timing = buildTimingPresentation( + props.log.use_time, + other?.frt, + other?.request_timing + ) const typeConfig = getLogTypeConfig(props.log.type) const isViolation = isViolationFeeLog(other) @@ -701,41 +708,50 @@ export function DetailsDialog(props: DetailsDialogProps) { /> )} - {showTiming && props.log.use_time > 0 && ( - - {formatUseTime(props.log.use_time)} - {props.log.is_stream && - other?.frt != null && - other.frt > 0 && ( - 0 || other?.request_timing != null) && ( + + + {formatUseTime(timing.totalSeconds)} + {props.log.is_stream && + timing.firstTokenSeconds != null && ( + + {' '} + ({t('First token')}:{' '} + {formatUseTime(timing.firstTokenSeconds)}) + )} - > - {' '} - (FRT: {formatUseTime(other.frt / 1000)}) - - )} - - } - /> - )} + + + + } + /> + )} {/* Request conversion (admin only, not for refund) */} diff --git a/web/src/features/usage-logs/components/request-timing-breakdown.tsx b/web/src/features/usage-logs/components/request-timing-breakdown.tsx new file mode 100644 index 000000000000..41958f788c00 --- /dev/null +++ b/web/src/features/usage-logs/components/request-timing-breakdown.tsx @@ -0,0 +1,49 @@ +import { useTranslation } from 'react-i18next' + +import { formatUseTime } from '@/lib/format' +import { cn } from '@/lib/utils' + +import type { + RequestTimingPhase, + RequestTimingPhaseKey, +} from '../lib/request-timing' + +const phaseLabelKeys: Record = { + gateway_ms: 'Gateway processing', + upstream_first_data_ms: 'Upstream first data', + first_data_to_client_ms: 'First data to client', + client_stream_ms: 'Client streaming', + upstream_response_ms: 'Upstream response', + response_write_ms: 'Response write', + upstream_error_ms: 'Upstream error', + finalize_ms: 'Finalization', +} + +interface RequestTimingBreakdownProps { + phases: RequestTimingPhase[] + className?: string +} + +export function RequestTimingBreakdown(props: RequestTimingBreakdownProps) { + const { t } = useTranslation() + if (props.phases.length === 0) return null + + return ( +
+ {props.phases.map((phase) => ( +
+ {t(phaseLabelKeys[phase.key])} + + {formatUseTime(phase.milliseconds / 1000)} + +
+ ))} +
+ ) +} diff --git a/web/src/features/usage-logs/components/timing-metrics-cell.tsx b/web/src/features/usage-logs/components/timing-metrics-cell.tsx index 74a17c137963..b1e90ae19779 100644 --- a/web/src/features/usage-logs/components/timing-metrics-cell.tsx +++ b/web/src/features/usage-logs/components/timing-metrics-cell.tsx @@ -34,7 +34,9 @@ import { formatUseTime } from '@/lib/format' import { cn } from '@/lib/utils' import { getFirstResponseTimeColor, getResponseTimeColor } from '../lib/format' +import { buildTimingPresentation } from '../lib/request-timing' import type { LogOtherData } from '../types' +import { RequestTimingBreakdown } from './request-timing-breakdown' /** * Softened fills for the full-height timing bar. The bar sits directly beside @@ -54,6 +56,7 @@ interface TimingMetricsCellProps { useTimeSec: number completionTokens: number frtMs?: number + requestTiming?: LogOtherData['request_timing'] isStream: boolean className?: string /** @@ -69,19 +72,30 @@ export function TimingMetricsCell(props: TimingMetricsCellProps) { const { t } = useTranslation() const indicator = props.indicator ?? 'bar' const showFirstToken = props.isStream - const firstTokenSeconds = - props.frtMs != null && props.frtMs > 0 ? props.frtMs / 1000 : null + const timing = buildTimingPresentation( + props.useTimeSec, + props.frtMs, + props.requestTiming + ) + const firstTokenSeconds = timing.firstTokenSeconds const firstTokenVariant: StatusVariant = firstTokenSeconds == null ? 'neutral' : getFirstResponseTimeColor(firstTokenSeconds) const totalTimeVariant = getResponseTimeColor( - props.useTimeSec, + timing.totalSeconds, props.completionTokens ) const firstTokenLabel = firstTokenSeconds == null ? t('N/A') : formatUseTime(firstTokenSeconds) - const totalTimeLabel = formatUseTime(props.useTimeSec) + const totalTimeLabel = formatUseTime(timing.totalSeconds) + const timingBreakdownLabel = [ + showFirstToken ? `${t('First token')} ${firstTokenLabel}` : null, + `${t('Duration')} ${totalTimeLabel}`, + t('Timing breakdown'), + ] + .filter(Boolean) + .join(', ') const labels = (
@@ -122,30 +136,49 @@ export function TimingMetricsCell(props: TimingMetricsCellProps) {
) + let content if (indicator === 'dot') { - return ( + content = (
{labels}
) + } else { + content = ( +
+ + {showFirstToken && ( + <> + + + + )} + + {labels} +
+ ) } + if (timing.phases.length === 0) return content + return ( -
- - {showFirstToken && ( - <> - - - - )} - - {labels} -
+ + + + {content} + + + + + + ) } diff --git a/web/src/features/usage-logs/components/usage-logs-mobile-card.tsx b/web/src/features/usage-logs/components/usage-logs-mobile-card.tsx index 9e4261a3c013..b448708f4516 100644 --- a/web/src/features/usage-logs/components/usage-logs-mobile-card.tsx +++ b/web/src/features/usage-logs/components/usage-logs-mobile-card.tsx @@ -294,6 +294,7 @@ function MobileStreamTimingField({ log }: { log: UsageLog }) { useTimeSec={useTime} completionTokens={log.completion_tokens} frtMs={other?.frt} + requestTiming={other?.request_timing} isStream={log.is_stream} indicator='dot' className='min-w-0 flex-1' diff --git a/web/src/features/usage-logs/lib/__tests__/request-timing.test.ts b/web/src/features/usage-logs/lib/__tests__/request-timing.test.ts new file mode 100644 index 000000000000..727db1eced47 --- /dev/null +++ b/web/src/features/usage-logs/lib/__tests__/request-timing.test.ts @@ -0,0 +1,83 @@ +import assert from 'node:assert/strict' +import { describe, test } from 'node:test' + +import { buildTimingPresentation } from '../request-timing' + +describe('request timing presentation', () => { + test('uses end-to-end stream timing and preserves zero millisecond phases', () => { + const presentation = buildTimingPresentation(9, 3200, { + total_ms: 1500, + gateway_ms: 100, + upstream_first_data_ms: 400, + first_data_to_client_ms: 0, + client_stream_ms: 900, + finalize_ms: 100, + }) + + assert.equal(presentation.totalSeconds, 1.5) + assert.equal(presentation.firstTokenSeconds, 0.5) + assert.deepEqual( + presentation.phases.map((phase) => [phase.key, phase.milliseconds]), + [ + ['gateway_ms', 100], + ['upstream_first_data_ms', 400], + ['first_data_to_client_ms', 0], + ['client_stream_ms', 900], + ['finalize_ms', 100], + ] + ) + }) + + test('builds the non-stream response phase list', () => { + const presentation = buildTimingPresentation(4, undefined, { + total_ms: 800, + gateway_ms: 50, + upstream_response_ms: 600, + response_write_ms: 25, + finalize_ms: 125, + }) + + assert.equal(presentation.totalSeconds, 0.8) + assert.equal(presentation.firstTokenSeconds, null) + assert.deepEqual( + presentation.phases.map((phase) => phase.key), + ['gateway_ms', 'upstream_response_ms', 'response_write_ms', 'finalize_ms'] + ) + }) + + test('shows the available upstream failure phase', () => { + const presentation = buildTimingPresentation(2, undefined, { + total_ms: 320, + gateway_ms: 20, + upstream_error_ms: 300, + }) + + assert.deepEqual( + presentation.phases.map((phase) => phase.key), + ['gateway_ms', 'upstream_error_ms'] + ) + }) + + test('falls back to legacy duration and first response time', () => { + const presentation = buildTimingPresentation(3, 250, undefined) + + assert.equal(presentation.totalSeconds, 3) + assert.equal(presentation.firstTokenSeconds, 0.25) + assert.deepEqual(presentation.phases, []) + }) + + test('ignores invalid request timing values', () => { + const presentation = buildTimingPresentation(3, 250, { + total_ms: -1, + gateway_ms: Number.NaN, + upstream_first_data_ms: 100, + }) + + assert.equal(presentation.totalSeconds, 3) + assert.equal(presentation.firstTokenSeconds, 0.25) + assert.deepEqual( + presentation.phases.map((phase) => phase.key), + ['upstream_first_data_ms'] + ) + }) +}) diff --git a/web/src/features/usage-logs/lib/request-timing.ts b/web/src/features/usage-logs/lib/request-timing.ts new file mode 100644 index 000000000000..3d9ce5000e12 --- /dev/null +++ b/web/src/features/usage-logs/lib/request-timing.ts @@ -0,0 +1,60 @@ +import type { RequestTimingData } from '../types' + +const phaseKeys = [ + 'gateway_ms', + 'upstream_first_data_ms', + 'upstream_response_ms', + 'upstream_error_ms', + 'first_data_to_client_ms', + 'response_write_ms', + 'client_stream_ms', + 'finalize_ms', +] as const + +export type RequestTimingPhaseKey = (typeof phaseKeys)[number] + +export interface RequestTimingPhase { + key: RequestTimingPhaseKey + milliseconds: number +} + +export interface TimingPresentation { + totalSeconds: number + firstTokenSeconds: number | null + phases: RequestTimingPhase[] +} + +function isDuration(value: unknown): value is number { + return typeof value === 'number' && Number.isFinite(value) && value >= 0 +} + +export function buildTimingPresentation( + useTimeSec: number, + frtMs: number | undefined, + requestTiming: RequestTimingData | undefined +): TimingPresentation { + const totalSeconds = isDuration(requestTiming?.total_ms) + ? requestTiming.total_ms / 1000 + : useTimeSec + + let firstTokenSeconds: number | null = null + if ( + isDuration(requestTiming?.gateway_ms) && + isDuration(requestTiming?.upstream_first_data_ms) + ) { + firstTokenSeconds = + (requestTiming.gateway_ms + requestTiming.upstream_first_data_ms) / 1000 + } else if (isDuration(frtMs) && frtMs > 0) { + firstTokenSeconds = frtMs / 1000 + } + + const phases: RequestTimingPhase[] = [] + for (const key of phaseKeys) { + const milliseconds = requestTiming?.[key] + if (isDuration(milliseconds)) { + phases.push({ key, milliseconds }) + } + } + + return { totalSeconds, firstTokenSeconds, phases } +} diff --git a/web/src/features/usage-logs/types.ts b/web/src/features/usage-logs/types.ts index 3e3789b9cbf3..2a3346b774d4 100644 --- a/web/src/features/usage-logs/types.ts +++ b/web/src/features/usage-logs/types.ts @@ -113,6 +113,18 @@ export interface ToolSurchargeItem { price: number } +export interface RequestTimingData { + total_ms?: number + gateway_ms?: number + upstream_first_data_ms?: number + first_data_to_client_ms?: number + client_stream_ms?: number + upstream_response_ms?: number + response_write_ms?: number + upstream_error_ms?: number + finalize_ms?: number +} + export interface LogOtherData { admin_info?: { is_multi_key?: boolean @@ -188,6 +200,7 @@ export interface LogOtherData { audio_ratio?: number audio_completion_ratio?: number frt?: number + request_timing?: RequestTimingData // Tiered (expression-based) billing fields, set by backend when // billing_mode === 'tiered_expr'. expr_b64 is the base64-encoded billing // expression; the matched tier and request-rule traces come from the actual diff --git a/web/src/i18n/locales/en.json b/web/src/i18n/locales/en.json index cbac6b6119d7..23a586c8fe2f 100644 --- a/web/src/i18n/locales/en.json +++ b/web/src/i18n/locales/en.json @@ -4654,6 +4654,15 @@ "Timeline": "Timeline", "times": "times", "Timing": "Timing", + "Timing breakdown": "Timing breakdown", + "Gateway processing": "Gateway processing", + "Upstream first data": "Upstream first data", + "First data to client": "First data to client", + "Client streaming": "Client streaming", + "Upstream response": "Upstream response", + "Response write": "Response write", + "Upstream error": "Upstream error", + "Finalization": "Finalization", "Tip": "Tip", "to access this resource.": "to access this resource.", "To Anthropic Messages": "To Anthropic Messages", diff --git a/web/src/i18n/locales/fr.json b/web/src/i18n/locales/fr.json index fefe91d5cee3..a6b34ce48363 100644 --- a/web/src/i18n/locales/fr.json +++ b/web/src/i18n/locales/fr.json @@ -4654,6 +4654,15 @@ "Timeline": "Chronologie", "times": "Fois", "Timing": "Durée", + "Timing breakdown": "Détail des temps", + "Gateway processing": "Traitement par la passerelle", + "Upstream first data": "Premières données en amont", + "First data to client": "Premières données vers le client", + "Client streaming": "Diffusion vers le client", + "Upstream response": "Réponse en amont", + "Response write": "Écriture de la réponse", + "Upstream error": "Erreur en amont", + "Finalization": "Finalisation", "Tip": "Astuce", "to access this resource.": "pour accéder à cette ressource.", "To Anthropic Messages": "Vers Anthropic Messages", diff --git a/web/src/i18n/locales/ja.json b/web/src/i18n/locales/ja.json index d1b56e3e77bb..a61f5e0b20a9 100644 --- a/web/src/i18n/locales/ja.json +++ b/web/src/i18n/locales/ja.json @@ -4654,6 +4654,15 @@ "Timeline": "タイムライン", "times": "回", "Timing": "所要時間", + "Timing breakdown": "所要時間の内訳", + "Gateway processing": "ゲートウェイ処理", + "Upstream first data": "アップストリームの最初のデータ", + "First data to client": "最初のデータをクライアントへ送信", + "Client streaming": "クライアントへのストリーミング", + "Upstream response": "アップストリーム応答", + "Response write": "応答の書き込み", + "Upstream error": "アップストリームエラー", + "Finalization": "終了処理", "Tip": "ヒント", "to access this resource.": "このリソースにアクセスするには。", "To Anthropic Messages": "Anthropic Messages へ", diff --git a/web/src/i18n/locales/ru.json b/web/src/i18n/locales/ru.json index 895627bb1d29..3a35c3a5cfce 100644 --- a/web/src/i18n/locales/ru.json +++ b/web/src/i18n/locales/ru.json @@ -4654,6 +4654,15 @@ "Timeline": "Хронология", "times": "раз", "Timing": "Время", + "Timing breakdown": "Разбивка времени", + "Gateway processing": "Обработка шлюзом", + "Upstream first data": "Первые данные от источника", + "First data to client": "Первые данные клиенту", + "Client streaming": "Потоковая передача клиенту", + "Upstream response": "Ответ источника", + "Response write": "Запись ответа", + "Upstream error": "Ошибка источника", + "Finalization": "Завершение", "Tip": "Совет", "to access this resource.": "для доступа к этому ресурсу.", "To Anthropic Messages": "В Anthropic Messages", diff --git a/web/src/i18n/locales/vi.json b/web/src/i18n/locales/vi.json index 73b1b6c7c59a..b4721642d337 100644 --- a/web/src/i18n/locales/vi.json +++ b/web/src/i18n/locales/vi.json @@ -4654,6 +4654,15 @@ "Timeline": "Dòng thời gian", "times": "lần", "Timing": "Thời gian", + "Timing breakdown": "Chi tiết thời gian", + "Gateway processing": "Xử lý tại cổng", + "Upstream first data": "Dữ liệu đầu tiên từ thượng nguồn", + "First data to client": "Dữ liệu đầu tiên tới máy khách", + "Client streaming": "Truyền luồng tới máy khách", + "Upstream response": "Phản hồi thượng nguồn", + "Response write": "Ghi phản hồi", + "Upstream error": "Lỗi thượng nguồn", + "Finalization": "Hoàn tất", "Tip": "Mẹo", "to access this resource.": "để truy cập tài nguyên này.", "To Anthropic Messages": "Sang Anthropic Messages", diff --git a/web/src/i18n/locales/zh-TW.json b/web/src/i18n/locales/zh-TW.json index a0fb9d1f3a31..07a391aa880c 100644 --- a/web/src/i18n/locales/zh-TW.json +++ b/web/src/i18n/locales/zh-TW.json @@ -4654,6 +4654,15 @@ "Timeline": "時間線", "times": "次", "Timing": "耗時", + "Timing breakdown": "耗時明細", + "Gateway processing": "閘道處理", + "Upstream first data": "上游首筆資料", + "First data to client": "首筆資料寫回用戶端", + "Client streaming": "用戶端串流傳輸", + "Upstream response": "上游回應", + "Response write": "回應寫回", + "Upstream error": "上游錯誤", + "Finalization": "收尾處理", "Tip": "提示", "to access this resource.": "存取此資源。", "To Anthropic Messages": "轉 Anthropic Messages", diff --git a/web/src/i18n/locales/zh.json b/web/src/i18n/locales/zh.json index 9366feb653d3..394abc7753c2 100644 --- a/web/src/i18n/locales/zh.json +++ b/web/src/i18n/locales/zh.json @@ -4654,6 +4654,15 @@ "Timeline": "时间线", "times": "次", "Timing": "耗时", + "Timing breakdown": "耗时明细", + "Gateway processing": "网关处理", + "Upstream first data": "上游首个数据", + "First data to client": "首个数据写回客户端", + "Client streaming": "客户端流式传输", + "Upstream response": "上游响应", + "Response write": "响应写回", + "Upstream error": "上游错误", + "Finalization": "收尾处理", "Tip": "提示", "to access this resource.": "访问此资源。", "To Anthropic Messages": "转 Anthropic Messages",