why apisix is so long,in prometheus

[kellyseeme]

Description

in apisix access log request_time upstream_connect_time upstream_header_time upstream_response_time 7.166 0 5.751 7.165 5.432 0 5.417 5.432 5.702 0 5.66 5.702 5.427 0 5.384 5.426 12.79 0 0.384 0.384

i cant find 13 seconds request time in access log,how this happen?
in pormetheus,this request time(13s) != apisix rt time(13s) + upstream rt time(6s),why?

Environment

• APISIX version (run apisix version):
• Operating system (run uname -a):
• OpenResty / Nginx version (run openresty -V or nginx -V):
• etcd version, if relevant (run curl http://127.0.0.1:9090/v1/server_info):
• APISIX Dashboard version, if relevant:
• Plugin runner version, for issues related to plugin runners:
• LuaRocks version, for installation issues (run luarocks --version):

[Baoyuantop]

What you're observing isn't APISIX slowing down or timing anomalies, but rather a misunderstanding of different label values within the same latency metric family in Prometheus. The latency histogram exposed by APISIX uses the first label to distinguish three phases:

1. type=request
   Overall duration: From the request entering APISIX (receiving the client's first byte) to the completion of response transmission. Corresponds to Nginx's $request_time.
2. type=upstream
   Upstream interaction time only: From initiating the connection/request to the upstream to reading the entire upstream response (or the last upstream response if retries occurred).
3. type=apisix
   APISIX processing time = request − upstream. Includes routing matching, plugin chain execution, waits, filtering, LB/retry control, and other stages beyond upstream interaction. This is not a separate, additional “fourth time period,” but rather the residual time after subtracting upstream time from the total time.

Therefore, do not add the three values together. The formula is: request ≈ upstream + apisix. If the upstream is not actually accessed (e.g., local direct return, authentication failure, rate limiting, early interception), only request = apisix will be observed, and upstream will be missing or 0.

[kellyseeme]

@Baoyuantop thanks for reply.
this is we access log

1 the prometheus metris is 请求RT is type=request,apisix RT is type=apisix,后端RT is type=upstream,in the prometheus , request time(13s) = apisix rt time(13s) + upstream rt time(6s),there in the accesslog we cant find
2 in access log,we find there request time is 12.79s,the upstream_response_time is 0.384s,then apisix cost 12s,this is a slow client? proxy_request_buffering on;proxy_buffer off. if a big file is upload,then the file in disk ,this time is apisix time?
3 upstream_header_time == upstream_response_time,this is a small reponse, but the header_time is equal upstream_response_time is strange

[bzp2010]

The starting of request timing is when Nginx completes the TCP handshake with the client and begins accepting packets, not when it actually enters APISIX to execute logic. Nginx will only begin executing APISIX logic after receiving the complete request headers.

https://nginx.org/en/docs/http/ngx_http_core_module.html#var_request_time

$request_time
request processing time in seconds with a milliseconds resolution (1.3.9, 1.2.6); time elapsed since the first bytes were read from the client

The current algorithm's calculation isn't entirely rigorous. APISIX's processing time is simply assumed to be the total request time (obtained from Nginx variables) minus the upstream processing time. This scenario only holds when downstream (client-side) processing time is negligible.

Therefore, if the client has a slow internet connection, these data transfer times will be included in the APISIX timing.

---

APISIX's latency should ideally be measured by the APISIX itself rather than calculated through simple subtraction using the aforementioned algorithm, as this approach yields more accurate results. However, the legacy code was implemented that way. If you're interested in this, feel free to submit a pull request for it.

[kellyseeme]

thanks