使用awk统计tomcat中access.log日志里时延超过500毫秒的记录

　　之前在一个springboot项目中开启了access.log日志（参见spring boot打开tomcat的access日志），现在可以很方便的根据access日志统计时延。先看日志文件：

 

 

　　再看access.log里的8个字段：

%h %l %u %t "%r" %s %b %D

　　这几个字段都是啥意思？

• %h = 发起请求的客户端 IP 地址
• %l = 客户机的 RFC 1413 标识 ( 参考 ) ，只有实现了 RFC 1413 规范的客户端，才能提供此信息。
• %u = 访问用户的 ID
• %t = 收到请求的时间
• %r = 来自客户端的请求行
• %s = 服务器返回客户端的状态码
• %b = 返回给客户端的字节大小，但不包括响应头的大小
• %D = 接口请求时延

　　

　　从以上参数可以看出，如果要统计时延超过500毫秒的请求，就看最后一个字段就行了。使用awk统计时延超过500毫秒命令如下：

wulf@wulf00 MINGW64 /e/workspace/subtitle/logs (master)
$ awk '$NF >= 500 {print $0}' access_log*.log
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 668
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 768
127.0.0.1 - - [02/Dec/2020:06:51:52 +0800] "POST /liveStop HTTP/1.1" 200 43 819
127.0.0.1 - - [02/Dec/2020:06:51:53 +0800] "POST /liveStop HTTP/1.1" 200 43 1000
127.0.0.1 - - [02/Dec/2020:06:52:18 +0800] "POST /liveModify HTTP/1.1" 200 43 643
127.0.0.1 - - [02/Dec/2020:06:52:18 +0800] "POST /liveModify HTTP/1.1" 200 43 501
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 1668
127.0.0.1 - - [02/Dec/2020:06:51:47 +0800] "POST /liveSync HTTP/1.1" 200 43 888
127.0.0.1 - - [02/Dec/2020:06:51:53 +0800] "POST /liveStop HTTP/1.1" 200 43 710
127.0.0.1 - - [02/Dec/2020:06:52:18 +0800] "POST /liveModify HTTP/1.1" 200 43 666
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 608
127.0.0.1 - - [02/Dec/2020:06:51:47 +0800] "POST /liveSync HTTP/1.1" 200 43 558
127.0.0.1 - - [02/Dec/2020:06:52:18 +0800] "POST /liveModify HTTP/1.1" 200 43 556

　　有一点要注意，虽然我们在access日志文件里是8个字段，但实际上awk解析的时候是11个字段：

• awk '{print $1}' access_log.2020-12-02.log       # IP 地址  (%h)
• awk '{print $2}' access_log.2020-12-02.log       # RFC 1413 标识  (%l)
• awk '{print $3}' access_log.2020-12-02.log       # 用户 ID  (%u)
• awk '{print $4,$5}' access_log.2020-12-02.log     # 日期和时间  (%t)
• awk '{print $7}' access_log.2020-12-02.log      #  URI (%>s)
• awk '{print $9}' access_log.2020-12-02.log      # 状态码 (%>s)
• awk '{print $10}' access_log.2020-12-02.log     # 响应大小  (%b)
• awk '{print $11}' access_log.2020-12-02.log     # 时延大小  (%b)

　　我们注意到awk按字符串的空格来分割，比如我们要看接口名，那么http方法类型（其中的$6，即POST)就被干掉了：

$ awk '{print $7}' access_log*.log
/liveSync

 

　　再结合这条命令awk '$NF >= 500 {print $0}' access_log*.log说两点：一个是$NF，它指定最后一列，即$11，所以用NF或者11都行；另一个是$0，它代表所有的列。

　　如果我们想对延时做倒排序：

wulf@wulf00 MINGW64 /e/workspace/subtitle/logs (master)
$ awk '$NF >= 500 {print $NF}' access_log*.log | sort -nr
1668
1000
888
819
768
710
668
666
643
608
558
556
501

 

　　如果我们想统计延时超过500毫秒有多少条数据：

wulf@wulf00 MINGW64 /e/workspace/subtitle/logs (master)
$ awk '$NF >= 500 {print $NF}' access_log*.log | wc -l
13

 

　　如果我们想统计延时超过500毫秒而且在06时51分这个时间段里：

wulf@wulf00 MINGW64 /e/workspace/subtitle/logs (master)
$ awk '$NF >= 500 {print $4}' access_log*.log | grep '02/Dec/2020:06:51' | wc -l
9

 

 　　如果我们想看延时超过500毫秒而且在06时51分10秒到06时52分10秒这个区间内的：

 

wulf@wulf00 MINGW64 /e/workspace/subtitle/logs (master)
$ awk '$NF >= 500 && $4 >= "[02/Dec/2020:06:51:10" && $4 <= "[02/Dec/2020:06:52:10"' access_log*.log
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 668
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 768
127.0.0.1 - - [02/Dec/2020:06:51:52 +0800] "POST /liveStop HTTP/1.1" 200 43 819
127.0.0.1 - - [02/Dec/2020:06:51:53 +0800] "POST /liveStop HTTP/1.1" 200 43 1000
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 1668
127.0.0.1 - - [02/Dec/2020:06:51:47 +0800] "POST /liveSync HTTP/1.1" 200 43 888
127.0.0.1 - - [02/Dec/2020:06:51:53 +0800] "POST /liveStop HTTP/1.1" 200 43 710
127.0.0.1 - - [02/Dec/2020:06:51:19 +0800] "POST /liveSync HTTP/1.1" 200 43 608
127.0.0.1 - - [02/Dec/2020:06:51:47 +0800] "POST /liveSync HTTP/1.1" 200 43 558