This is an automated email from the ASF dual-hosted git repository.
AlinsRan pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/apisix.git
The following commit(s) were added to refs/heads/master by this push:
new f9f4a70f4 fix(ai-proxy): report error-path latency vars in
milliseconds (#13711)
f9f4a70f4 is described below
commit f9f4a70f470c092bbc00358aa010f74a1c1fc498
Author: AlinsRan <[email protected]>
AuthorDate: Wed Jul 22 11:53:43 2026 +0800
fix(ai-proxy): report error-path latency vars in milliseconds (#13711)
---
apisix/plugins/ai-proxy/base.lua | 21 ++++
apisix/plugins/prometheus/exporter.lua | 5 +-
docs/en/latest/plugins/ai-proxy-multi.md | 4 +-
docs/en/latest/plugins/ai-proxy.md | 5 +-
docs/zh/latest/plugins/ai-proxy-multi.md | 4 +-
docs/zh/latest/plugins/ai-proxy.md | 4 +-
t/plugin/ai-proxy-latency-vars.t | 203 +++++++++++++++++++++++++++++++
t/plugin/prometheus-ai-proxy.t | 76 ++++++++++++
8 files changed, 313 insertions(+), 9 deletions(-)
diff --git a/apisix/plugins/ai-proxy/base.lua b/apisix/plugins/ai-proxy/base.lua
index 97c980dc5..f16ffd34a 100644
--- a/apisix/plugins/ai-proxy/base.lua
+++ b/apisix/plugins/ai-proxy/base.lua
@@ -23,6 +23,7 @@ local pcall = pcall
local pairs = pairs
local type = type
local table = table
+local math_floor = math.floor
local exporter = require("apisix.plugins.prometheus.exporter")
local protocols = require("apisix.plugins.ai-protocols")
local transport_http = require("apisix.plugins.ai-transport.http")
@@ -70,6 +71,23 @@ local function read_upstream_error_body(res)
return body
end
+
+-- Fill the AI latency vars in MILLISECONDS on the early-exit paths, using the
+-- same clock as the success path (ctx.llm_request_start_time, reset at the
+-- start of every attempt). Without this the log phase falls back to nginx
+-- $upstream_response_time, which is in seconds, so a 429/5xx would report a
+-- value 1000x off from a 200 for the same upstream latency.
+local function set_error_latency_vars(ctx, upstream_responded)
+ local elapsed_ms = math_floor((ngx_now() - ctx.llm_request_start_time) *
1000)
+ ctx.var.apisix_upstream_response_time = elapsed_ms
+ if upstream_responded then
+ -- the error response is the only payload the upstream produced, so the
+ -- time until we knew it answered is this request's time to first token
+ ctx.var.llm_time_to_first_token = elapsed_ms
+ end
+end
+
+
function _M.set_logging(ctx, summaries, payloads)
if summaries then
ctx.llm_summary = {
@@ -297,6 +315,7 @@ function _M.before_proxy(conf, ctx, on_error)
})
end
end
+ set_error_latency_vars(ctx, false)
return transport_http.handle_error(transport_err)
end
@@ -338,6 +357,7 @@ function _M.before_proxy(conf, ctx, on_error)
if res._httpc then
res._httpc:close()
end
+ set_error_latency_vars(ctx, true)
return res.status, error_body
end
@@ -352,6 +372,7 @@ function _M.before_proxy(conf, ctx, on_error)
if res._httpc then
res._httpc:close()
end
+ set_error_latency_vars(ctx, true)
return 500
end
diff --git a/apisix/plugins/prometheus/exporter.lua
b/apisix/plugins/prometheus/exporter.lua
index ca71a1972..4b6ead0b7 100644
--- a/apisix/plugins/prometheus/exporter.lua
+++ b/apisix/plugins/prometheus/exporter.lua
@@ -604,7 +604,10 @@ function _M.http_log(conf, ctx)
if vars.request_type == "ai_stream" or vars.request_type == "ai_chat" then
local llm_time_to_first_token = vars.llm_time_to_first_token
- if llm_time_to_first_token ~= "0" then
+ -- error responses (429/5xx) also carry a real millisecond value in
+ -- llm_time_to_first_token, so filter them out here: llm_latency has no
+ -- status label and must keep measuring served responses only.
+ if llm_time_to_first_token ~= "0" and (tonumber(vars.status) or 0) <
400 then
-- type="total": full response latency. For non-streaming this
equals
-- llm_time_to_first_token; for streaming, that var holds only the
-- TTFT, so use apisix_upstream_response_time (refreshed on every
diff --git a/docs/en/latest/plugins/ai-proxy-multi.md
b/docs/en/latest/plugins/ai-proxy-multi.md
index a91b0f43b..88a1274ef 100644
--- a/docs/en/latest/plugins/ai-proxy-multi.md
+++ b/docs/en/latest/plugins/ai-proxy-multi.md
@@ -2600,9 +2600,9 @@ For verification, the behaviours should be consistent
with the verification in [
The following example demonstrates how you can log LLM request related
information in the gateway's access log to improve analytics and audit. The
following variables are available:
* `request_llm_model`: LLM model name specified in the request.
-* `apisix_upstream_response_time`: Time taken for APISIX to send the request
to the upstream service and receive the full response.
+* `apisix_upstream_response_time`: Time taken for APISIX to send the request
to the upstream service and receive the full response, in milliseconds. Error
responses from the LLM service (such as 429 or 5xx) are also recorded in
milliseconds.
* `request_type`: Type of request, where the value could be
`traditional_http`, `ai_chat`, or `ai_stream`.
-* `llm_time_to_first_token`: Duration from request sending to the first token
received from the LLM service, in milliseconds.
+* `llm_time_to_first_token`: Duration from request sending to the first token
received from the LLM service, in milliseconds. For an error response from the
LLM service, this is the duration until the error response was received. It
stays `0` when the LLM service could not be reached at all.
* `llm_model`: LLM model.
* `llm_prompt_tokens`: Number of tokens in the prompt.
* `llm_completion_tokens`: Number of chat completion tokens in the response.
diff --git a/docs/en/latest/plugins/ai-proxy.md
b/docs/en/latest/plugins/ai-proxy.md
index 17992d03f..b93702ed0 100644
--- a/docs/en/latest/plugins/ai-proxy.md
+++ b/docs/en/latest/plugins/ai-proxy.md
@@ -2077,8 +2077,9 @@ In the Kafka topic, you should also see a log entry
corresponding to the request
The following example demonstrates how you can log LLM request related
information in the gateway's access log to improve analytics and audit. The
following variables are available:
* `request_llm_model`: LLM model name specified in the request.
+* `apisix_upstream_response_time`: Time taken for APISIX to send the request
to the upstream service and receive the full response, in milliseconds. Error
responses from the LLM service (such as 429 or 5xx) are also recorded in
milliseconds.
* `request_type`: Type of request, where the value could be
`traditional_http`, `ai_chat`, or `ai_stream`.
-* `llm_time_to_first_token`: Duration from request sending to the first token
received from the LLM service, in milliseconds.
+* `llm_time_to_first_token`: Duration from request sending to the first token
received from the LLM service, in milliseconds. For an error response from the
LLM service, this is the duration until the error response was received. It
stays `0` when the LLM service could not be reached at all.
* `llm_model`: LLM model.
* `llm_prompt_tokens`: Number of tokens in the prompt.
* `llm_completion_tokens`: Number of chat completion tokens in the response.
@@ -2111,7 +2112,7 @@ Update the access log format in your configuration file
to include additional LL
```yaml title="conf/config.yaml"
nginx_config:
http:
- access_log_format: "$remote_addr - $remote_user [$time_local] $http_host
\"$request_line\" $status $body_bytes_sent $request_time \"$http_referer\"
\"$http_user_agent\" $upstream_addr $upstream_status $upstream_response_time
\"$upstream_scheme://$upstream_host$upstream_uri\" \"$apisix_request_id\"
\"$request_type\" \"$llm_time_to_first_token\" \"$llm_model\"
\"$request_llm_model\" \"$llm_prompt_tokens\" \"$llm_completion_tokens\""
+ access_log_format: "$remote_addr - $remote_user [$time_local] $http_host
\"$request_line\" $status $body_bytes_sent $request_time \"$http_referer\"
\"$http_user_agent\" $upstream_addr $upstream_status
$apisix_upstream_response_time
\"$upstream_scheme://$upstream_host$upstream_uri\" \"$apisix_request_id\"
\"$request_type\" \"$llm_time_to_first_token\" \"$llm_model\"
\"$request_llm_model\" \"$llm_prompt_tokens\" \"$llm_completion_tokens\""
```
Reload APISIX for configuration changes to take effect.
diff --git a/docs/zh/latest/plugins/ai-proxy-multi.md
b/docs/zh/latest/plugins/ai-proxy-multi.md
index 8f3ea99dc..2e18dd9b9 100644
--- a/docs/zh/latest/plugins/ai-proxy-multi.md
+++ b/docs/zh/latest/plugins/ai-proxy-multi.md
@@ -2710,9 +2710,9 @@ curl "http://127.0.0.1:9080/anything"; -X POST \
以下示例演示了如何在网关的访问日志中记录 LLM 请求相关信息，以改进分析和审计。以下变量可用：
* `request_llm_model`：请求中指定的 LLM 模型名称。
-* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间
+* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间（毫秒）。LLM
服务返回的错误响应（如 429 或 5xx）同样以毫秒记录。
* `request_type`：请求类型，值可能是 `traditional_http`、`ai_chat` 或 `ai_stream`。
-* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。
+* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。当 LLM
服务返回错误响应时，该值为收到错误响应为止的持续时间；当完全无法连接到 LLM 服务时，该值保持为 `0`。
* `llm_model`：LLM 模型。
* `llm_prompt_tokens`：提示中的令牌数量。
* `llm_completion_tokens`：响应中的聊天完成令牌数量。
diff --git a/docs/zh/latest/plugins/ai-proxy.md
b/docs/zh/latest/plugins/ai-proxy.md
index aa5d0cce9..62a1b4eae 100644
--- a/docs/zh/latest/plugins/ai-proxy.md
+++ b/docs/zh/latest/plugins/ai-proxy.md
@@ -2076,9 +2076,9 @@ curl "http://127.0.0.1:9080/anything"; -X POST \
以下示例演示了如何在网关的访问日志中记录 LLM 请求相关信息，以改进分析和审计。以下变量可用：
* `request_llm_model`：请求中指定的 LLM 模型名称。
-* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间
+* `apisix_upstream_response_time`：APISIX 向上游服务发送请求并接收完整响应所花费的时间（毫秒）。LLM
服务返回的错误响应（如 429 或 5xx）同样以毫秒记录。
* `request_type`：请求类型，值可能是 `traditional_http`、`ai_chat` 或 `ai_stream`。
-* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。
+* `llm_time_to_first_token`：从发送请求到从 LLM 服务接收第一个令牌的持续时间（毫秒）。当 LLM
服务返回错误响应时，该值为收到错误响应为止的持续时间；当完全无法连接到 LLM 服务时，该值保持为 `0`。
* `llm_model`：LLM 模型。
* `llm_prompt_tokens`：提示中的令牌数量。
* `llm_completion_tokens`：响应中的聊天完成令牌数量。
diff --git a/t/plugin/ai-proxy-latency-vars.t b/t/plugin/ai-proxy-latency-vars.t
new file mode 100644
index 000000000..1c4dc965e
--- /dev/null
+++ b/t/plugin/ai-proxy-latency-vars.t
@@ -0,0 +1,203 @@
+#
+# Licensed to the Apache Software Foundation (ASF) under one or more
+# contributor license agreements. See the NOTICE file distributed with
+# this work for additional information regarding copyright ownership.
+# The ASF licenses this file to You under the Apache License, Version 2.0
+# (the "License"); you may not use this file except in compliance with
+# the License. You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+
+use t::APISIX 'no_plan';
+
+log_level("info");
+repeat_each(1);
+no_long_string();
+no_root_location();
+
+
+add_block_preprocessor(sub {
+ my ($block) = @_;
+
+ if (!defined $block->request) {
+ $block->set_value("request", "GET /t");
+ }
+
+ my $http_config = $block->http_config // <<_EOC_;
+ server {
+ server_name openai;
+ listen 18724;
+
+ default_type 'application/json';
+
+ location /v1/chat/completions {
+ content_by_lua_block {
+ ngx.sleep(0.2)
+ ngx.req.read_body()
+ local body = ngx.req.get_body_data() or ""
+ local status = ngx.req.get_headers()["x-test-status"]
+ if status == "500" or body:find("FAIL", 1, true) then
+ ngx.status = 500
+ ngx.say('{"error":"internal"}')
+ return
+ end
+ if status == "429" then
+ ngx.status = 429
+ ngx.say('{"error":"rate limited"}')
+ return
+ end
+
ngx.say('{"choices":[{"finish_reason":"stop","index":0,"message":{"content":"2","role":"assistant"}}],"model":"gpt-4","object":"chat.completion","usage":{"completion_tokens":5,"prompt_tokens":8,"total_tokens":13}}')
+ }
+ }
+ }
+_EOC_
+
+ $block->set_value("http_config", $http_config);
+});
+
+run_tests();
+
+__DATA__
+
+=== TEST 1: set up a route with ai-proxy and a log-phase printer of both vars
+--- config
+ location /t {
+ content_by_lua_block {
+ local t = require("lib.test_admin").test
+ local code, body = t('/apisix/admin/routes/1',
+ ngx.HTTP_PUT,
+ [[{
+ "uri": "/anything",
+ "plugins": {
+ "ai-proxy": {
+ "provider": "openai",
+ "auth": {"header": {"Authorization": "Bearer
token"}},
+ "options": {"model": "gpt-4"},
+ "override": {"endpoint": "http://localhost:18724"},
+ "ssl_verify": false
+ },
+ "serverless-post-function": {
+ "phase": "log",
+ "functions": ["return function(conf, ctx)
ngx.log(ngx.WARN, \"LATENCYVARS status=\", ngx.status, \" aurt=\",
tostring(ctx.var.apisix_upstream_response_time), \" ttft=\",
tostring(ctx.var.llm_time_to_first_token)) end"]
+ }
+ }
+ }]]
+ )
+ if code >= 300 then
+ ngx.status = code
+ end
+ ngx.say(body)
+ }
+ }
+--- response_body
+passed
+
+
+
+=== TEST 2: 200 response records both vars in milliseconds
+--- request
+POST /anything
+{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] }
+--- error_code: 200
+--- error_log eval
+qr/LATENCYVARS status=200 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/
+
+
+
+=== TEST 3: 500 early exit records both vars in milliseconds, not seconds
+--- request
+POST /anything
+{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] }
+--- more_headers
+x-test-status: 500
+--- error_code: 500
+--- error_log eval
+qr/LATENCYVARS status=500 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/
+
+
+
+=== TEST 4: 429 early exit records both vars in milliseconds
+--- request
+POST /anything
+{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] }
+--- more_headers
+x-test-status: 429
+--- error_code: 429
+--- error_log eval
+qr/LATENCYVARS status=429 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/
+
+
+
+=== TEST 5: the unit no longer flips between a 200 and a 500 in one lifecycle
+--- config
+ location /t {
+ content_by_lua_block {
+ local http = require "resty.http"
+ local uri = "http://127.0.0.1:"; .. ngx.var.server_port ..
"/anything"
+ local body_ok = [[{ "messages": [ { "role": "user", "content":
"ok"} ] }]]
+ local body_fail = [[{ "messages": [ { "role": "user", "content":
"FAIL"} ] }]]
+ local res1 = http.new():request_uri(uri, {method = "POST", body =
body_ok})
+ local res2 = http.new():request_uri(uri, {method = "POST", body =
body_fail})
+ ngx.sleep(0.5)
+ ngx.say(res1.status, " ", res2.status)
+ }
+ }
+--- request
+GET /t
+--- response_body
+200 500
+--- error_log eval
+[qr/LATENCYVARS status=200 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/,
+ qr/LATENCYVARS status=500 aurt=\d{3,4}(?![\.\d]) ttft=\d{3,4}(?![\.\d])/]
+
+
+
+=== TEST 6: set up a route pointing at a dead upstream
+--- config
+ location /t {
+ content_by_lua_block {
+ local t = require("lib.test_admin").test
+ local code, body = t('/apisix/admin/routes/1',
+ ngx.HTTP_PUT,
+ [[{
+ "uri": "/anything",
+ "plugins": {
+ "ai-proxy": {
+ "provider": "openai",
+ "auth": {"header": {"Authorization": "Bearer
token"}},
+ "options": {"model": "gpt-4"},
+ "override": {"endpoint": "http://localhost:18725"},
+ "ssl_verify": false
+ },
+ "serverless-post-function": {
+ "phase": "log",
+ "functions": ["return function(conf, ctx)
ngx.log(ngx.WARN, \"LATENCYVARS status=\", ngx.status, \" aurt=\",
tostring(ctx.var.apisix_upstream_response_time), \" ttft=\",
tostring(ctx.var.llm_time_to_first_token)) end"]
+ }
+ }
+ }]]
+ )
+ if code >= 300 then
+ ngx.status = code
+ end
+ ngx.say(body)
+ }
+ }
+--- response_body
+passed
+
+
+
+=== TEST 7: transport error records a millisecond value, ttft stays 0
+--- request
+POST /anything
+{ "messages": [ { "role": "user", "content": "What is 1+1?"} ] }
+--- error_code: 500
+--- error_log eval
+qr/LATENCYVARS status=500 aurt=\d+(?![\.\d]) ttft=0(?![\.\d])/
diff --git a/t/plugin/prometheus-ai-proxy.t b/t/plugin/prometheus-ai-proxy.t
index 0e58f1c2f..6e7002e21 100644
--- a/t/plugin/prometheus-ai-proxy.t
+++ b/t/plugin/prometheus-ai-proxy.t
@@ -503,3 +503,79 @@ GET /apisix/prometheus/metrics
qr/apisix_llm_prompt_tokens\{.*request_llm_model="",llm_model=""\}/
--- response_body_unlike eval
qr/apisix_llm_prompt_tokens\{.*request_llm_model="distinct-model-/
+
+
+
+=== TEST 27: create a route to check llm_latency excludes error responses
+--- config
+ location /t {
+ content_by_lua_block {
+ local data = {
+ {
+ url = "/apisix/admin/routes/5",
+ data = [[{
+ "plugins": {
+ "prometheus": {},
+ "ai-proxy-multi": {
+ "instances": [
+ {
+ "name": "openai-gpt4",
+ "provider": "openai",
+ "weight": 1,
+ "auth": {
+ "header": {
+ "Authorization": "Bearer token"
+ }
+ },
+ "options": {
+ "model": "gpt-4"
+ },
+ "override": {
+ "endpoint": "http://127.0.0.1:1980";
+ }
+ }
+ ]
+ }
+ },
+ "uri": "/chat-guard"
+ }]],
+ },
+ }
+ local t = require("lib.test_admin").test
+ for _, data in ipairs(data) do
+ local _, body = t(data.url, ngx.HTTP_PUT, data.data)
+ ngx.say(body)
+ end
+ }
+ }
+--- response_body
+passed
+
+
+
+=== TEST 28: a served response records one llm_latency observation
+--- request
+POST /chat-guard
+{"messages":[{"role":"user","content":"What is 1+1?"}], "model": "gpt-3"}
+--- more_headers
+X-AI-Fixture: prometheus/chat-basic.json
+--- error_code: 200
+
+
+
+=== TEST 29: a 429 error response goes through the same route
+--- request
+POST /chat-guard
+{"messages":[{"role":"user","content":"What is 1+1?"}], "model": "gpt-3"}
+--- more_headers
+X-AI-Fixture: prometheus/chat-basic.json
+X-AI-Fixture-Status: 429
+--- error_code: 429
+
+
+
+=== TEST 30: the error response is excluded, so the count stays 1 not 2
+--- request
+GET /apisix/prometheus/metrics
+--- response_body eval
+qr/apisix_llm_latency_count\{type="total",.*route_id="5",.*,node="openai-gpt4".*request_type="ai_chat",request_llm_model="gpt-3",llm_model="gpt-4"\}
1\n/
