日志分析查看——grep,sed,sort,awk运用

概述

        我们日常应用中都离不开日志。可以说日志是我们在排查问题的一个重要依据。但是日志并不是写了就好了，当你想查看日志的时候，你会发现线上日志堆积的长度已经超越了你一行行浏览的耐性的极限了。于是，很有必要通过一些手段来高效地辅助你来快速的从日志中找到你要找的问题。本文通过一个从项目中衍生出来的例子从查找日志，筛选日志和统计日志3个方面层层递进来简述日志文件查看中一些有用的手段。（注：在linux环境下）

例子背景：

        后台跑一个定时任务，对指定时间段的订单数据表中的每一条记录进行以此任务处理。在日志中输出：

        1.订单id

        2.订单处理状态

        3.日志类别

准备工具：sort, tail, less, uniqu,grep,sed,awk

示例日志：demo.log

1. 2011-08-23 19:57:00,610 [] INFO  bo.CommodityCerOrderBO – =====>属性订正任务执行开始|每页读取100条数据  
2. 2011-08-23 19:57:05,012 [] INFO  bo.CommodityCerOrderBO – 当前正在处理页数:1  
3. 2011-08-23 19:57:30,688 [] INFO  bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:attr_ids不含0跳过  
4. 2011-08-23 19:57:30,709 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100104  
5. 2011-08-23 19:57:31,721 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100105  
6. 2011-08-23 19:57:32,727 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100107  
7. 2011-08-23 19:57:32,782 [] INFO  bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:attr_ids成功保存为0|100104|0|100105|100107  
8. 2011-08-23 19:57:32,782 [] INFO  bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:attr_ids不含0跳过  
9. 2011-08-23 19:57:32,805 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100104  
10. 2011-08-23 19:57:33,828 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100107  
11. 2011-08-23 19:57:33,838 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：46  
12. 2011-08-23 19:57:34,850 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100106  
13. 2011-08-23 19:57:35,860 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100105  
14. 2011-08-23 19:57:36,871 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3  
15. 2011-08-23 19:57:36,884 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3  
16. 2011-08-23 19:57:36,891 [] INFO  bo.CommodityCerOrderBO – order-fix.curr_id:10226,status:attr_ids成功保存为6|100104|0|0|100107|46|100106|100105|3|3  
17. 2011-08-23 19:57:36,891 [] INFO  bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:attr_ids不含0跳过  
18. 2011-08-23 19:57:36,928 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3  
19. 2011-08-23 19:57:36,942 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100104  
20. 2011-08-23 19:57:36,955 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100105  
21. 2011-08-23 19:57:36,969 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100107  
22. 2011-08-23 19:57:36,980 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：46  
23. 2011-08-23 19:57:36,992 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100106  
24. 2011-08-23 19:57:37,011 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10222,status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3  

0.一些最基础的日志查看命令

最简单的日志查看命令就是浏览日志文件了，一般会从有限浏览文件末尾的

1. tail -400f demo.log #监控最后400行日志文件的变化 等价与 tail -n 400 -f （-f参数是实时）  
2. less demo.log #查看日志文件，支持上下滚屏，查找功能  
3. uniq -c demo.log  #标记该行重复的数量，不重复值为1  

以上命令具体使用详见本机man手册

1.查找关键日志记录 grep

浏览了日志文件后你会发现，日志文件成千上万行，怎么能找到我要找的内容呢。这时候，就可已用grep来进行日志的关键行提取了。

grep 简单使用

规则：*grep [选项]…模式 [文件]…   * （模式是正则表达式）

例子1：

1. grep 'INFO' demo.log     #在文件demo.log中查找所有包行INFO的行  

输出：
2011-08-23 19:57:00,610 [] INFO  bo.CommodityCerOrderBO – =====>属性订正任务执行开始|每页读取100条数据
2011-08-23 19:57:05,012 [] INFO  bo.CommodityCerOrderBO – 当前正在处理页数:1
2011-08-23 19:57:30,688 [] INFO  bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:attr_ids不含0跳过
…(略)

例子2：

1. grep -o 'order-fix.curr_id:([0-9]+)' demo.log    #-o选项只提取order-fix.curr_id:xxx的内容（而不是一整行），并输出到屏幕上  

输出：

order-fix.curr_id:10117

order-fix.curr_id:10117

order-fix.curr_id:10117

order-fix.curr_id:10117

order-fix.curr_id:10117

order-fix.curr_id:10226

…(略)

例子3：

1. grep -c 'ERROR' demo.log   #输出文件demo.log中查找所有包行ERROR的行的数量  

输出：17

例子4：

1. grep -v 'ERROR' demo.log   #查找不含"ERROR"的行  

输出：（功能和grep 'INFO' demo.log 命令一样，输出略）

grep 用法小结（转自网络图片）：请点击直接查看大图

详细用法请man之

2.精简日志内容 sed

        从n多行的日志文件中提取到一定数量的行后，可能你还会觉得有些功能不够，比如你每行并不需要有哪个类抛出的描述，比如你不需要日志时间，或者要把时间格式换个形式展示等等，这时候你就可以通过sed的替换命令来进行对日志文件提取具体内容了。
如果把grep比作过滤器，那sed就是个修改器了。 

sed简单用法：

1. sed [-n][-e] '命令' 文件        #-n选项是默认不输出信息，除非使用了p命令或者是s命令的p标志符；-e是表明空格后面接的是一个命令  
2. sed [-n] -f 脚本 文件           #这个用法是把命令写在脚本里  

»'命令'的格式： [地址1[,地址2]][!] 指令 [参数]
» 地址的格式：用行号标识(1 表明匹配第一行)，或者用正则表达式匹配('^INFO'表明该地址匹配以INFO打头的行)   
» 指令的例子：p打印指令，s替换指令，d删除指令等等（以下表格摘自abs的sed小册子）：

[地址范围]/p
打印
打印[指定的地址范围]
[地址范围]/d
删除
删除[指定的地址范围]
s/pattern1/pattern2/
替换
将指定行中, 将第一个匹配到的pattern1, 替换为pattern2.
[地址范围]/s/pattern1/pattern2/
替换
在地址范围指定的每一行中, 将第一个匹配到的pattern1, 替换为pattern2.
[地址范围]/y/pattern1/pattern2/
transform
在地址范围指定的每一行中, 将pattern1中的每个匹配到pattern2的字符都使用pattern2的相应字符作替换. (等价于tr命令)
g
全局
在每个匹配的输入行中, 将每个模式匹配都作相应的操作. (译者注: 不只局限于第一个匹配)
小结：sed就是遍历对于输入文件的每一行，如果该行匹配地址1，地址2的范围之内，那么就对这一行执行命令。

例1：(摘自abs的sed小册子)

8d	删除输入的第8行.
/^$/d	删除所有空行.
1,/^$/d	从输入的开头一直删除到第1个空行(第一个空行也删除掉).
/Jones/p	只打印那些包含"Jones"的行(使用-n选项).
s/Windows/Linux/	在每个输入行中, 将第一个出现的"Windows"实例替换为"Linux".
s/BSOD/stability/g	在每个输入行中, 将所有"BSOD"都替换为"stability".
s/ *$//	删除掉每行结尾的所有空格.
s/00*/0/g	将所有连续出现的0都压缩成单个的0.
/GUI/d	删除掉所有包含"GUI"的行.
s/GUI//g	将所有"GUI"都删除掉, 并保持剩余部分的完整性.

看完基本用法，让我们结合demo.log来具体应用下：

例2：输出demo.log中的某个日期中的ERROR的行

来具体应用下：

1. sed -n '/^2011-08-23.*ERROR/p' demolog.log  

输出：

2011-08-23 19:57:30,709 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100104
2011-08-23 19:57:31,721 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100105
2011-08-23 19:57:32,727 [] ERROR bo.CommodityCerOrderBO – order-fix.curr_id:10117,status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100107

例3：提取demo.log中的日期，日志级别，订单id和状态。

1. sed -f demo.sed2 demo.log  

2. #n                                #这一行用法和命令中的-n一样意思，就是默认不输出  

3. #demo.sed2  

4.   

5. #下面的一行是替换指令，就是把19位长的日期和INFO/ERROR,id,和后面的一截提取出来，然后用@分割符把这4个字段重新按顺序组合  

6. s/^([-: 0-9]{19}).*(INFO|ERROR) .*order-fix.curr_id:([0-9]+),(.*$)/\1@\3@\2@\4/p   

输出：

2011-08-23 19:57:30@10117@INFO@status:attr_ids不含0跳过

2011-08-23 19:57:30@10117@ERROR@status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100104

2011-08-23 19:57:31@10117@ERROR@status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100105

2011-08-23 19:57:32@10117@ERROR@status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100107

2011-08-23 19:57:32@10117@INFO@status:attr_ids成功保存为0|100104|0|100105|100107

…略

sed详细用法可以参考《sed 与 awk》(第二版), 或者man之

或者点击下面这个参考链接链接地址

3.对记录进行排序 sort

        经过了日志文件的精炼后，我们可能不想对日志进行时间排序，这时候我们就可以用sort进行排序。

基本使用

---

1
2
1 sort [options] [file...]

2

---

对于demo.log，经过了上面的sed提取后，我希望先用id进行排序，然后再用日志级别倒序进行排序，最后才是日期排序

1. #排序功能 -t表示用@作为分割符，-k表示用分割出来的第几个域排序(不要漏掉后面的,2/,3/,1，详细意思看下面的参考链接，这里不做详述)  
2. sed -f test.sed demolog.log | sort -t@ -k2,2n -k3,3r -k1,1                  #n为按数字排序，r为倒序  

输出：

2011-08-23 19:57:30@10117@INFO@status:attr_ids不含0跳过
2011-08-23 19:57:32@10117@INFO@status:attr_ids成功保存为0|100104|0|100105|100107
2011-08-23 19:57:30@10117@ERROR@status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100104
2011-08-23 19:57:31@10117@ERROR@status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100105
2011-08-23 19:57:32@10117@ERROR@status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100107
2011-08-23 19:57:36@10222@INFO@status:attr_ids不含0跳过
2011-08-23 19:57:36@10222@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100104
2011-08-23 19:57:36@10222@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100105
2011-08-23 19:57:36@10222@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100106
2011-08-23 19:57:36@10222@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100107
2011-08-23 19:57:36@10222@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3
2011-08-23 19:57:36@10222@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：46
2011-08-23 19:57:37@10222@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3
2011-08-23 19:57:32@10226@INFO@status:attr_ids不含0跳过
2011-08-23 19:57:36@10226@INFO@status:attr_ids成功保存为6|100104|0|0|100107|46|100106|100105|3|3
2011-08-23 19:57:32@10226@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100104
2011-08-23 19:57:33@10226@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100107
2011-08-23 19:57:33@10226@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：46
2011-08-23 19:57:34@10226@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100106
2011-08-23 19:57:35@10226@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100105
2011-08-23 19:57:36@10226@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3
2011-08-23 19:57:36@10226@ERROR@status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：3

4.统计日志相关记录数 awk

现在日志已经比较清晰了，但是如果我想对不同日志进行统计怎么办，比如我要统计所有ERROR的日志记录书，或者要统计每个订单有多少个ERROR？这就需要我们的awk帮忙了。

awk简单使用：

1. awk [-v 变量名=变量值] [-Fre] [–] '模式 { 语句 }' 变量名=变量值 文件名  
2. awk [-v 变量名=变量值] [-Fre] -f 脚本文件 [–] 变量名=变量值 文件名  

和sed一样，awk也支持2中方式调用，一种是把awk脚本直接在命令行写入，第二种是把awk写在文件中在命令行中调用。

awk处理方式也与sed类似，对文件中的每一个输入行进行处理，每个处理首先判断是否是模式中匹配的行，是的话就具体执行相应的语句。

不同的是，awk侧重与对每一行的列进行处理，并且，awk脚本和c语言类似也拥有变量，条件判断，循环等复杂语句，所以这里只能简单介绍一下基本应用，详细的请查看后面给出的相关链接。

而且，awk在处理所有行前和处理完行后各有BEGIN和END语句做预处理和后置处理。

例子1：打印日志中的第2，3列

1. awk 'BEGIN{FS="@"} {print $2,$3}' demo.log_after_sort   #BEGIN中预处理的是，把@号作为行的列分割符,把分割后的行的第2，3列输出  

输出：（对于从sort得出的结果作为输入）

10117 INFO

10117 INFO

10117 ERROR

10117 ERROR

10117 ERROR

10222 INFO

…略

例子2. 统计日志中INFO，ERROR出现的总数,以及总记录数

1. #下面的例子是作为命令行输入的，利用单引号作为换行标记，这样就不用另外把脚本写进文件调用了  
2. awk '  
3. BEGIN {  
4.   FS="@"  
5. }  
6.   
7. {  
8.   if ($3 == "INFO") {info_count++}  
9.   if ($3 == "ERROR") {error_count++}  
10.   
11. }  
12.   
13. END {  
14.   print "order total count:"NR           #NR是awk内置变量，是遍历的当前行号，到了END区域自然行号就等于总数了  
15.   printf("INFO count:%d ERROR count:%d\n",info_count,error_count)  
16. } ' demo.log_after_sort  

输出：

order total count:22
INFO count:5 ERROR count:17

例子3. 对指定时间范围内的日志进行统计，包括输出INFO，ERROR总数，记录总数，每个订单记录分类统计

下面的例子综合了前面sed和sort

1. sed -f demo.sed demolog.log | sort -t@ -k2,2n -k3,3r -k1,1 | awk -f demo.awk  

2. #demo.awk  

3. BEGIN {  

4.   FS="@"  

5.   stime="2011-08-23 19:57:31"  

6.   etime="2011-08-23 19:57:37"  

7. }  

8.   

9. $1 > stime && $1 < etime {  

10.   if ($3 == "INFO") {info_count++}  

11.   if ($3 == "ERROR") {error_count++}  

12.   

13.   ++total  

14.   

15.   status[$2]=status[$2]"\t"$1"\t"$3"\t"$4"\n"  

16.   

17. }  

18.   

19. END {  

20.   for(i in status){  

21.       printf("id:%s:\n%s\n",i,status[i])  

22.   }  

23.   

24.   print "order total count:"total  

25.   printf("INFO count:%d ERROR count:%d\n",info_count,error_count)  

26. } <span style="font-size:18px;"><strong>  

27. </strong></span>  

输出：

id:10117:

2011-08-23 19:57:32
INFO  status:attr_ids成功保存为0|100104|0|100105|100107
2011-08-23 19:57:32
ERROR  status:添加属性id，但由于认证分类参数有误默认取匹配属性名称的第一个属性id：100107

id:10226:

2011-08-23 19:57:32
INFO  status:attr_ids不含0跳过
2011-08-23 19:57:32
ERROR  status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100104
2011-08-23 19:57:33
ERROR  status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100107
2011-08-23 19:57:33
ERROR  status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：46
2011-08-23 19:57:34
ERROR  status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100106
2011-08-23 19:57:35
ERROR  status:添加属性id，但由于没有属性在该分类下默认取匹配属性名称的第一个属性id：100105

#这个例子只是举例说明awk的统计用法，实际运用中可能会统计超时的次数，页面访问次数等。

补充：

其他实践时例子：

1. 在本地分支把代码修改从一个分支复制到另一个分支（例子的
b1022st.txt是一个记录了文件新增或修改的变化的文件路径名）

1. awk 'BEGIN{FS="b1022-scm/"} {system("cp -rf b1022-scm/"$2" b1022-lpscm/"$2);}' /home/nizen/b1022st.txt  

通过awk和其system命令结合，这样就把文件从b1022-scm复制到b1022-lpscm下

2.内置函数
3.内建变量 
4.shell变量传递
5.awk统计某个开始-结束范围内的关键字累加总数：

1. BEGIN {  
2.   running=

0
  

1.   count=

0
  

1.   startRow=

"begin =====>"
 id            #id,nextId是通过-v 参数从外部传入  

1.   endRow=

"begin =====>"
 nextId  

1. }  
2.   
3. $

0
 ~ startRow{    # ～是匹配运算符，判断$
0
是否满足startRow正则表达式  

1.   running = 

1
  

1. #  printf(

"start\n"
)  

1. }  
2.   
3. $

0
 ~ endRow {  

1.   running = 

0
  

1. #  printf(

"end\n"
)  

1. }  
2.   
3. {  
4.   

if
(running==
1
) {      # 仅在startRow 和 endRow 范围内统计  

1.     

if
($
0
 ~ 
"it show"
) {  

1. #        printf($

0
 
"\n"
)  

1.         str=$

0
  

1.         sub(/^.*show times:/, 

""
, str)  

1.         sub(/ .*$/, 

""
, str)  

1.         printf(str 

"\n"
)  

1.         count = count + str  
2.     }  
3.   }  
4. }  
5.   
6. END {  
7.   printf(

"showTimeCount:"
+count)  

1. }  

6. printf "10ms occur:%.2lf%%\n",t10/total*100 #输出百分比数据，精确到百分位后2位

5.日志规范化

从前面可以看出，日志文件为了要让后续工具能够对里面的内容进行提取和处理，就必须要让日志文件规范的输出。

个人想到有几个点可以规范：

1.记录日志时候可以写入一些特殊的文本语句，一遍与工具的检索和处理。

2.记录日志最好不要用中文，因为在不同语言环境下对日志的处理可能因为编码不同导致没法处理日志。

后面再贴下淘宝中找到的一些打印日志的建议：

• 正常情况下应该返回true, 却返回false的, 反正就是你在对返回值进行检查的时候, 如果不正常, log一下
• 出现异常的地方, 以前认为hsf.log会帮我们记下所有的异常, 但是这个也不一定可靠, 所以还得我们自己记一下
• 日志必须包含上下文信息
• 如果出于统计的需要, 可打可不打
• 在完成代码之后, 查看一下整个代码结构, 在一些关键的点, 加上日志, 正常的info, 少数情况出现的warning, 异常情况的error或者warning
• 打印的日志内容要容易查询, 以前我比较倾向于打中文日志, 虽然易读, 但是中文在linux下的搜索统计稍微有些麻烦,所以如果能加上英文标识(比如说用于唯一标识的前缀), 能识别不同日志, 这个对定位也是非常有好处的.

6.一些容易遇到的问题

a.处理中文出现乱码

这个主要是因为你的linux locale的配置，与编辑文件的语言环境，还有你登录ssh客户端的编码规则有关，所以最好还是不用中文记录日志。

b.正则表达式不同工具的区别

OO后记：

目前只是简单介绍了grep,sed,sort,awk的几个简单应用，实际上的日志监控回根据不同的情景进行不同的处理。比如需要对调用的耗时进行统计（平均时间或者超时记录），对访问量进行统计，但是基本原理都和本文例子出发点一致。本文一方面是为了记录下学习过程中积累的东西，另一方面为了抛砖引玉引起大家对日志记录的关注。