作者 | 俞青
来源 | 阿里技术公众号
假如日志欺骗了你，不要悲伤，看下这篇文章吧。
一 前言
在日常排查问题或者同用户连调的时候，是否经常会遇到，在access_log里看到用户请求很快，但用户却反馈很慢？
在日志中看到用户的请求都成功了，用户却反馈说有大量请求失败等一系列自己看到的和用户描述不一致的问题，有时候会怀疑用户搞错了，等用户贴出截图的时候又怀疑自己搞错了，如果有遇到这类问题，这篇文章或许对你有帮助。
二 Tengine打access_log 时机
在接着往下介绍之前，先看下Tengine打access_log的时机，清楚了这个后，再接着往下看会清晰很多。
Tengine的access_log是在Tengine“认为”这个请求结束后才打的，对于正常请求，Tengine会在请求最后一个字节发出后认为请求结束；对于异常请求，当Tengine判断连接超时或者异常断开，无法再发送和接收数据的时候。通常情况下可以认为Tengine在请求结束后随即会打出日志。
三 如何理解Tengine的"请求最后一个字节发出"
Tengine认为请求最后一个字节发出后，该请求就结束了，其实最后一个字节发出可以理解为最后一串数据发出，这里是“发出”而不是用户收到，指的是将最后一串数据填到协议栈中，只要send 成功返回，Tengine就认为结束了，至于数据是否被客户端收到那就是协议栈和网络上的事情了，Tengine不会去关心。
四 为什么服务端看到的延时同客户端不一致
4.1 服务端request_time_msec的含义
要搞清楚这个问题，首先我们要明确Tengine access_log中的“request_time_msec” 字段到底表达了什么含义。
我们先看下官方文档是怎么说的：
$request_time
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.
这个字段表示的是从请求的第一个字节开始到请求最后一个字节发出后所经历的时间。
这里其实包含如下几点信息：
- 建连的时间是不会被算进去的。
- 如果是HTTPS请求，建连及HTTPS握手的时间都不会被算进去。
- 最后一个字节发出后Tengine认为请求结束，数据仅仅是填在协议栈中，从协议栈Buffer中的数据发送给用户的这段时间是不被算进去的。
- 连接挥手的过程是不会被算进去。
注：从长连接的角度去看，上述1、2、4的时间不被算进去还是好理解的。
4.2 客户端看到的E2E时间
4.1节中分析的request_time_msec从服务器端看到的请求E2E时间，而用户看到的时间，假设用户用curl去测试：
time curl https://bucket.oss-cn-hangzhou.aliyuncs.com/object那么上面4.1节提到的几点不会算到服务器端时间的计算逻辑里的，除了4都会被客户端计算进去。
针对延时不一致，下面我们从HTTP的上传下载，具体分析一下这个延时区别，是否差，差多少。
4.3 上传类请求延时差异
针对于上传来说，服务器端和客户端看到的延时差异不大，相差一个握手/和最后返回的Header发送回去的时间。
握手到服务器端收到请求首字节2rtt，请求完成后返回的HEADER数据一般不会很大可以塞在1个cwnd内发完，需要一个0.5个rtt，一共是2.5个rtt。如果是长连接，忽略三次握手的话，那么看到的差异为1个rtt。
因此针对上传类请求，客户端和服务器端看到的延时差距为2.5个RT，如果是长连接(非连接上首个请求）的话差异为1个rtt。
4.4 下载类请求延时差异
关于下载请求的延时差异会稍微复杂一些。上传的情况下，服务器只会有HTTP状态码和一些HTTP Header，通常一个rtt就可以发完。而下载，通常服务器会有较多的数据发送给客户端，Tengine把最后一串数据填在协议栈的Buffer里，如果在Buffer中的数据能在一个rtt内发完，那么同上传类请求一致，否则就会比上传类请求的差异大。至于协议栈Buffer中最后一串数据花多长时间能发送到客户端，这个就不太好估计了，取决于当时的网络状况及当时的拥塞窗口大小，需要具体情况具体分析。
在网络情况不错并且服务器端Buffer配置较小情况下，通常差距不大，但是如果客户端网络差，而服务器端Buffer配置较大的情况下，差距会比较大。比如此时客户端网络比较差，只达到100KB/s, 而服务器端协议栈Buffer配置的较大，为1M，Tengine最后一串数据把1M Buffer填满后Tengine认为请求已经结束了，而实际上客户端在10s之后才完整的收到请求应答数据，才认为结束。大家可以用wget测试一下，分别观察下服务器端和客户端看到的请求时间：
wget your-bucket.oss-cn-hangzhou.aliyuncs.com/tmp/1m-file --limit-rate=10k --debug注：wget这个限速是在应用层面做的，测试看到的时间差异除了服务端Buffer的原因，还有客户端Buffer的原因，数据到达客户端协议栈，而应用因限速而迟迟不读。
4.5 总结
服务器端看到的E2E时间“request_time_msec” 时间是Tengine收到请求的首字节开始，到最后一个字节写到协议栈的时间。
客户端看到的E2E时间相比服务器多了：客户端建联及HTTPS 握手时间、请求首字节发送到服务器的时间、外加Tengine认为请求结束后协议栈将Buffer中的数据递送到客户端的时间。
因此当客户抱怨延时高而服务器端看到却很快的时候，可能客户说的也对，你看到的也对，这时候就需要根据上述分析，判断具体是哪里导致客户端和服务器端看到延时差距，进而快速定位问题。
服务器端慢是真的慢，但是服务器端看到快，可不一定真的快。
五 服务器端看到的请求成功和客户端看到的请求成功
接下来分析的都是小概率事件，正常情况下通常不会遇到，主要针对出问题时的分析。
服务器端看到的成功，是服务器端正确处理这个请求，并把数据发送到协议栈后，服务器就会认为请求已经成功。
客户端看到请求成功，是收到服务器端返回的状态码及完整的body后才认为请求成功。
5.1 access_log看到的“200 OK”
access_log里的状态码，只要请求的header已经发出去，那么状态码就确定了，access_log里面打出来的状态码也是确定的。
如果是上传类请求，access_log里打印出状态码为200，那么请求一定是成功了（但是客户端不一定能感知到这个成功）。
如果是下载类请求，access_log里打印出来的状态码是200，那么请求不一定成功，可能body并未发完请求就异常结束了。
5.2 写到协议栈里的数据不一定能发送出去
Tengine把数据写到协议栈的Buffer中后，从Tengine的角度来说，可以认为数据已经发往客户端了，但从实际角度来看，数据写到协议栈仅仅是写到协议栈，至于写到协议栈的数据是否能否真正被发送出去，是不一定的。在协议栈数据还没发出去之前可能网络中断了，或者连接被reset 了，都会可能发生。这是造成客户端和服务器端看到有差异的一个主要原因。
有的同学会问，TCP不是可靠的传输协议嘛，怎么会发不过去？建议看下这篇文章，就明白TCP的可靠性具体指的是什么了。文章地址：
https://blog.csdn.net/dog250/article/details/82177299
六 单连接最低下载速度
6.1 为什么会有最低下载速度限制
针对系统性能指标，通常我们会描述一个单连接峰值吞吐的数值，但是实际上一个还有一个最低速度的限制。那么这个最低速度是怎么来的呢？
一个正常C/S架构的系统，通常会有很多Buffer，会设置很多超时时间，针对Tengine会有send_timeout，recv_timeout，keepalive_timeout等各种超时限制。这就会造成系统会有一个最小下载速度的限制。
像上面描述的各类超时时间，其实是会随着各类网络事件触发设置及更新。在Linux环境下，套接字可写就是其中一个事件，如果套接字长时间不可写，超过Tengine配置的send_timeout，那么就会触发超时，引发Tengine主动断开连接，甚至reset连接。Linux TCP 套接字在该套接字上的剩余Buffer空间大于总Buffer 1/3 才会被epoll 等“反应堆”返回可写，也就是说，如果Buffer被填满后，在timeout时间内，Buffer中的数据1/3 还没被发出去的话，就会触发定时器超时，导致请求异常中断。假设Buffer配置的是512k，send_timeout配置的是30s。那么必须在30s内发送出去170k才行，也就是最低要达到5.69KB/s的速度才行。
6.2 如何获取系统最低下载速度
正常情况下，我们可以通过分析系统中各个Buffer 的大小及超时时间计算出一个理论的最低下载速度，但是一个复杂的系统，很难理清楚或者找到各个位置的Buffer 大小及超时时间。因此我们可以利用wget的 --limit-rate 功能进行二分测试，直到找到最低下载速度的零界点，注意下载的时候文件不要选择太小，选择太小了会测试不出来，当然也不要太大，太大了会造成测试时间过长，设置为系统最大Buffer的2倍左右即可。
二分测试过程：
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
print low_rate, up_rate如下是测试OSS最低下载速度：
- 单连接持续5k以内：速度必然出问题(一般持续30s+出问题）。
- 单连接持续5 ~10k以内：速度随机出问题，看系统状况（比较具有偶然性）。
- 单连接持续10k+：基本不出问题。
根据上述6.1节中的理论和6.2节中的测试方法，我们甚至可以测试出来服务器端设置的sndbuf有多大。
6.3 如何解决
在正常情况下，这个最低下载速度并不会造成什么问题，因为大家都想方设法让速度更快，但是有些计算密集型的场景，可能会遇到这个问题。比如说之前遇到一个OSS客户，从OSS一个文件中读10k数据，处理30s，然后再读10k数据，再处理30s，处理一段时间后发现服务器端数据没发完就莫名其妙关闭连接了。其实就是遇到“最低下载速度问题”了。
针对上述情况，客户端不要在一个请求上一条连接反反复复缓慢读数据，如果文件不大，可以考虑一次性全读出来，放内存或者本地再慢慢处理。如果文件太大，可以使用RangeGet，需要多少数据就从服务器端RangeGet读多少。
注：针对上传类请求，通常来说没有速度下限要求。
6.4 为什么复现不出来
有同学使用wget/curl的limit_rate功能把连接速度限制到很低，但是复现不出来最低下载速度的问题，这是因为测试的文件太小了，测试的文件大小需要比客户端的rcvbuf + 服务端的sndbuf还要大才能测试出来，否则数据堆在两端的协议栈里，是触发不到应用的超时时间限制的。
七 access_log中的400、408及499
7.1 产生原因
400是很普通的错误码，但是在Tengine里也有不是普通“400”的时候，在这里我们只介绍非普通400的情况。
408及499在Tengine中是不会作为错误码返回给用户的（除非upstream返回了），只是Tengine利用了这两个状态码标识请求的一种完成状态。这两种错误码都是和时间相关，但是是不同场景下产生，都是在服务端才能看到的状态，客户端是感知不到的。
- 400，如果用户请求数据还未发完之前，客户端主动断开或者连接异常断开（如被reset 掉），在Tengine的access_log 中计为400。
- 499，客户端关闭请求，在proxy 场景下确切的说是客户端先于proxy upstream 返回前断开，Tengine在做proxy 的情况下（fastcgi_pass/proxy_pass 等），同一请求链路上，客户端与Tengine的连接先于Tengine后端返回前断开，此时在Tengine的access_log中计为499的日志。
- 408，客户端请求超时，确切说客户端发送数据超时，客户端向服务器发送请求数据时中间因某种原因中断了一会，引起服务器端读数据超时，此时在Tengine的access_log中会记为408。注意，发送header和发送body可能会有不同的超时时间。
7.2 如何复现
400请求数据发完之前提前断开连接，nc建立连接后输入完成Host头部后Ctrl + c断掉，或者发送PUT请求在body没有发送完成之前Ctrl + c掉。
408客户端发送超时，nc建立连接后输入完成Host 头部后等待连接超时，或者在Body 发送完成之前等待连接超时。
499客户端在服务器返回之前提前关闭连接 直接Curl，在服务器返回之前Ctrl + c掉, Tengine在等待upstream返回，此时客户端连接已经断开。可能你的手速没服务端处理的快，可以找一些服务器处理相对耗时的请求来复现，比如OSS的大图片处理。
注：用public-read-write权限的bucket进行测试。
7.3 是否异常
一般正常情况下，400、408、499这三个状态码出现的会比较少，日志中偶尔零星出现一些也不是什么大问题，如果大量出现，那就可能出问题了。
假如日志中大量出现400，如果请求的request_time_msec很小，优先排查是否是客户端问题，如果这个时间很大，请检查服务器压力是否过大，是否有hang住情况。如果服务器端hang 住，请求在发送的时候数据堆在Tengine里，服务器端长时间不读，造成客户端超时断开连接，此时Tengine会产生大量因客户端发送超时而提前断连造成的400。
如果日志中大量出现499，如果请求的request_time_msec很小（ms级别），需要排查是否是客户端问题，如果这个时间很大，需要从两个方向排查：
- 检查用户请求，是否后端处理确实需要很长时间，而客户端设置的超时时间又很短，此时需要客户端调整超时时间，否则客户端的重试可能会导致雪崩（如果没有限流的话）。
- 检查服务器是否压力过大，是否有hang住的情况，如果后端持续不返回客户端提前断开的话就会造成大量499。
这三个状态码出现，多多少少都是有些异常的，通常情况下，我们需要快速判断是服务器端的异常还是客户端的异常，从而快速定位问题。
当然上述描述的情况也不是绝对的，有时候需要特殊场景特殊分析。
八 总结
学会分析access_log在日常调查问题中会方便很多，理解access_log中一些特殊状态码的含义及出现的场景，会让调查问题事半功倍。同时对C/S系统上Buffer的理解也可以加快调查问题的速度，同时指导设置Buffer的大小，解决系统在大压力下出现的一些性能及其他一些奇怪问题。
