Why Tengine’s access_log Shows Fast Times While Users See Delays – Uncover the Hidden Timing Secrets

Introduction

Tengine, a web server project originated by Taobao and built on Nginx, adds many advanced features for high‑traffic sites. This article discusses common timing and caching issues in Tengine, explains why logs may seem misleading, and analyzes the problem from both client and server perspectives.

Tengine access_log Timing

Tengine writes an entry to access_log only after it considers the request finished . For normal requests, this occurs after the last byte is sent to the protocol stack. For abnormal requests, it happens when Tengine detects a timeout or abnormal disconnection.

Understanding "Last Byte Sent"

"Last byte sent" means the final chunk of data has been placed into the protocol stack buffer and send() returned successfully; Tengine does not wait for the client to actually receive the data.

Server‑Side vs. Client‑Side E2E Time

The request_time_msec field in access_log measures the time from the first byte read from the client to the moment the last byte is written to the protocol stack. The client‑side end‑to‑end time additionally includes connection establishment, TLS handshake, transmission of the first request byte, and the time the server‑side buffer data takes to reach the client.

request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client.

What request_time_msec Actually Includes

Connection establishment time is not counted.

For HTTPS, the handshake time is not counted.

The period after the last byte is placed in the protocol stack buffer is not counted.

Connection teardown time is not counted.

Upload vs. Download Latency Differences

For upload requests, the server‑side and client‑side latency differ by roughly one RTT for the handshake and another RTT for the final header, totaling about 2.5 RTT (or 1 RTT on a persistent connection). For download requests, the difference depends on how quickly the server’s buffer can drain; large buffers or poor client network conditions can increase the gap.

Minimum Single‑Connection Download Speed

Tengine configures various timeouts (e.g., send_timeout, recv_timeout, keepalive_timeout) that effectively impose a minimum download speed. If the socket remains unwritable for longer than send_timeout, the connection is closed. For example, with a 512 KB buffer and a 30 s timeout, at least 170 KB must be sent within 30 s, i.e., a minimum of ~5.7 KB/s.

Measuring the Minimum Speed

Use wget --limit-rate to perform a binary search for the lowest sustainable rate. Example script:

low_rate=0k
up_rate=100k
deviation=5k
while up_rate - low_rate < deviation:
    mid_rate=(low_rate+up_rate)/2
    wget url --limit-rate ${mid_rate}
    if succ; then
        up_rate=${mid_rate}
    else
        low_rate=${mid_rate}
    fi
print low_rate, up_rate

Testing with OSS shows that rates below 5 KB/s cause frequent failures, 5‑10 KB/s cause intermittent issues, and above 10 KB/s are generally stable.

Special Status Codes in access_log

Tengine uses 400, 408, and 499 to indicate request termination scenarios that are only visible on the server side:

400 : Client aborted before sending the full request body.

408 : Client timed out while sending request data.

499 : Client closed the connection before the upstream response was received (common in proxy scenarios).

These codes are not returned to the client unless propagated by an upstream service.

Reproducing the Codes

Use nc or curl to abort connections at appropriate stages (e.g., Ctrl‑C before request body completion for 400, delay after headers for 408, or abort before upstream reply for 499).

Conclusion

Understanding Tengine’s access_log timing fields and special status codes greatly speeds up troubleshooting. Recognizing the difference between server‑side and client‑side E2E times, as well as the impact of buffer sizes and timeout settings, helps diagnose performance anomalies and configure buffers appropriately for high‑load environments.