luvjoey1996

晚上用systemtap尝试追踪nginx时间缓存的更新,发现有可能时nginx对时间做了缓存,导致读写不一致.计算upstream_response_time是用到src/core/ngx_times.c 中定义的ngx_current_msec,而计算request_time 是使用的是ngx_cached_time,当ngx_current_msec更新到最新值,但是ngx_cached_time未更新时,就可能导致 ngx_current_time 与 upstream->start_time 的差值大于 ngx_cached_time->sec - request->start_sec * 1000 + ngx_cached_time->msec - request->start_msec的值. 我在追踪过程里面记录到了一次ngx_cached_time与ngx_current_time在计算upstream_response_time,request_time时,差值为11ms的情况,所以最后upstream_response_time>request_time也的确是有可能的.如果追求时间精确可以尝试设置time_resolution, 可以提供毫秒级的精确度.
我把动态追踪的脚本放在github上了,有兴趣可以验证一下.

阿辉 <luvjo...@gmail.com> 于2020年3月24日周二 下午6:13写道：
实践了一下，发现这个现象出现的频率比较高。看了源码发现nginx计算 request_time 的时候用的是 (ngx_cached_time.sec - req->start_sec) * 1000 + ngx_cached_time.msec -  req->start_msec , 但是计算upstream_response_time的时候是用的ngx_current_msec - upstream->start_time ; 推测是这里的问题吧。更新时间的时候，ngx_current_msec和ngx_cached_time都是在 ngx_update_time函数里面更新的，单进程环境感觉时间缓存不一致的可能性比较小吧。晚上还需要验证一下。

在 2020年3月24日星期二 UTC+8上午8:50:53，田晓勇写道：
感谢回复，我做了上述调整 还是会出现这种问题
image.png

阿辉 <luvjo...@gmail.com> 于2020年3月23日周一 下午5:20写道：
或者基于目前的配置，生成一个随机数，同时打印出来，确定一下是同一个请求。

在 2020年3月23日星期一 UTC+8下午5:16:33，阿辉写道：
是单进程还是多进程啊，如果是多进程的话，你也不能确定连续的两行就是同一个请求来的吧。可以考虑放在request_time和upstream_response_time一行输出，同时只开一个worker试试。

在 2020年3月20日星期五 UTC+8下午12:09:49，田晓勇写道：
最近在做OpenResty指标监控方面的东西，我在log阶段打印下这两个值，但是今天惊讶的发现竟然有$upstream_response_time 大于 $request_time的情况，按照Nginx官方对于这两个变量的解释，应该是$request_time包含$upstream_time才会；$request_time应该包含 接收请求数据时间、程序响应时间、输出
响应数据时间， 是nginx 收到请求开始到将响应数据包发送到本地网卡的时间  ；而$upstream_response_time包含了 上游服务器接收响应所花费的时间  
。我猜测$request_time会不会不包含写入日志的时间，而$upstream_response_time包含了处理日志的时间，导致有一定概率的误差呢？

image.png
--
tel: 18336032131
address: 上海

Attachment: abc.png
Description: PNG image

luvjoey1996

https://github.com/luvjoey1996/time-puzzle

阿辉 <luvjo...@gmail.com> 于2020年3月24日周二 下午11:41写道：
晚上用systemtap尝试追踪nginx时间缓存的更新,发现有可能时nginx对时间做了缓存,导致读写不一致.计算upstream_response_time是用到src/core/ngx_times.c 中定义的ngx_current_msec,而计算request_time 是使用的是ngx_cached_time,当ngx_current_msec更新到最新值,但是ngx_cached_time未更新时,就可能导致 ngx_current_time 与 upstream->start_time 的差值大于 ngx_cached_time->sec - request->start_sec * 1000 + ngx_cached_time->msec - request->start_msec的值. 我在追踪过程里面记录到了一次ngx_cached_time与ngx_current_time在计算upstream_response_time,request_time时,差值为11ms的情况,所以最后upstream_response_time>request_time也的确是有可能的.如果追求时间精确可以尝试设置time_resolution, 可以提供毫秒级的精确度.
我把动态追踪的脚本放在github上了,有兴趣可以验证一下.

阿辉 <luvjo...@gmail.com> 于2020年3月24日周二 下午6:13写道：
实践了一下，发现这个现象出现的频率比较高。看了源码发现nginx计算 request_time 的时候用的是 (ngx_cached_time.sec - req->start_sec) * 1000 + ngx_cached_time.msec -  req->start_msec , 但是计算upstream_response_time的时候是用的ngx_current_msec - upstream->start_time ; 推测是这里的问题吧。更新时间的时候，ngx_current_msec和ngx_cached_time都是在 ngx_update_time函数里面更新的，单进程环境感觉时间缓存不一致的可能性比较小吧。晚上还需要验证一下。

在 2020年3月24日星期二 UTC+8上午8:50:53，田晓勇写道：
感谢回复，我做了上述调整 还是会出现这种问题
image.png

阿辉 <luvjo...@gmail.com> 于2020年3月23日周一 下午5:20写道：
或者基于目前的配置，生成一个随机数，同时打印出来，确定一下是同一个请求。

在 2020年3月23日星期一 UTC+8下午5:16:33，阿辉写道：
是单进程还是多进程啊，如果是多进程的话，你也不能确定连续的两行就是同一个请求来的吧。可以考虑放在request_time和upstream_response_time一行输出，同时只开一个worker试试。

在 2020年3月20日星期五 UTC+8下午12:09:49，田晓勇写道：
最近在做OpenResty指标监控方面的东西，我在log阶段打印下这两个值，但是今天惊讶的发现竟然有$upstream_response_time 大于 $request_time的情况，按照Nginx官方对于这两个变量的解释，应该是$request_time包含$upstream_time才会；$request_time应该包含 接收请求数据时间、程序响应时间、输出
响应数据时间， 是nginx 收到请求开始到将响应数据包发送到本地网卡的时间  ；而$upstream_response_time包含了 上游服务器接收响应所花费的时间  
。我猜测$request_time会不会不包含写入日志的时间，而$upstream_response_time包含了处理日志的时间，导致有一定概率的误差呢？

image.png
--
tel: 18336032131
address: 上海

tanjinhua

这个例子好，总的来说就是两个使用的是不同的变量缓存，stackoverflow 上面也有相关介绍：https://stackoverflow.com/questions/53978695/how-can-request-time-be-less-than-upstream-response-time-in-nginx