线上问题:nginx日志打印时间问题

有一个发送短信的功能,用户有7000人,要每人发送3条短信,结果用户描述,点击了一次,发送了2次短信,也就是没人发送了6条短信,据此排查问题。

查看kibana的nginx日志
这里写图片描述

这里写图片描述

从上面的日志分析,用户应该是点击了多次,因为发送时间没有规律可寻,应该不是程序触发的动作,也就是有可能前端没有控制好,点击发送短信的按钮。

但是有一个小插曲,到短信供应商的平台,查看短信发送情况,发现时间对不上,从nginx日志看,打印日志的时间,短信平台已经提前发送短信了。

这里写图片描述

走到这里,怀疑是nginx的log时间不对,查看nginx的配置的日志格式

log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" '
                      '"$http_host" "$upstream_response_time" "$request_time" "$request_body"';

    access_log  /home/logs/nginx/access.log  main;
    error_log  /home/logs/nginx/error.log;

time_local 就是我们在kibana上的时间
官方文档只是这样解释

$time_local
local time in the Common Log Format

现在的疑问是:他是请求的时间还是nginx处理完成打印日志的时间。找到一个英文解释,我们验证一下

The $local_time variable contains the time when the log entry is written.

when the HTTP request header is read, nginx does a lookup of the associated virtual server configuration. If the virtual server is found, the request goes through six phases:

server rewrite phase
location phase
location rewrite phase (which can bring the request back to the previous phase)
access control phase
try_files phase
log phase
Since the log phase is the last one, $local_time variable is much more colse to the end of the request than it's start.

查看我们自己tomcat请求发送短信的日志,在日志所在位置输入liunx命令:

cat -n  catalina.2017-11-06.out  | grep "发送短信操作开始" -B 2

这里写图片描述

可以看出:
20:57:27发送第一次请求,短信平台最早收到请求是20:58:00,后台把整个短信发完总处理时间为560.417秒,kibana中的时间为21:06:47,恰恰是20:57:27+560.417≈21:06:47

21:08:49发送第二次请求,短信平台最早收到请求是21:18:10,后台把整个短信发送处理时间为561.225秒,kibana中的时间为21:18:10,恰恰是21:57:27+561.225≈21:18:10

21:20:11发送第三次请求,短信平台没有收到请求,后台处理完成时间为40.743秒,kibana中的时间为21:20:51,恰恰是21:20:11+40.743≈21:20:51

经验证:time_local 是日志产生的时间

nginx日志中的其他两个时间的解释 :
1、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 。
指的就是从接受用户请求的第一个字节到发送完响应数据的时间,即包括接收请求数据时间、程序响应时间、输出
响应数据时间。

2、upstream_response_time
官网描述:keeps times of responses obtained from upstream servers; times are kept in seconds with a milliseconds resolution. Several response times are separated by commas and colons like addresses in the $upstream_addr variable

是指从Nginx向后端(php-cgi)建立连接开始到接受完数据然后关闭连接为止的时间。

从上面的描述可以看出, requesttime upstream_response_time值大,特别是使用POST方式传递参数时,因为Nginx会把request body缓存住,接受完毕后才会把数据一起发给后端。所以如果用户网络较差,或者传递数据较大时, requesttime upstream_response_time大很多。

从上面的例子看,这个短信处理时间太长了,做的不合理,需要用优化。

  • 0
    点赞
  • 1
    收藏
    觉得还不错? 一键收藏
  • 打赏
    打赏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包

打赏作者

MonkeyKing.sun

对你有帮助的话,可以打赏

¥1 ¥2 ¥4 ¥6 ¥10 ¥20
扫码支付:¥1
获取中
扫码支付

您的余额不足,请更换扫码支付或充值

打赏作者

实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值