日志分析常规操作

前言

日志是开发者用来分析程序和排查问题的重要工具。随着系统架构从早期的单体应用，演变到如今的微服务架构，日志的重要性也逐步提升。除了用日志辅助问题排查，还可以通过日志对微服务请求的全链路进行性能分析，甚至可以它用来解决分布式系统中的一致性问题。与此同时，系统产生的日志量和日志管理难度也显著增加。于是，日志管理工具随之诞生并迭代升级。从最开始登录到跳板机上查看日志，到自建分布式日志中心来统一管理日志流，到云平台厂商提供专门的日志管理服务。开发者只需要在应用中接入SDK将日志回流到日志平台，就可以使用日志平台提供智能检索、数据分析以及链路分析等能力，平台中易用的图形化界面和成熟的数据管理能力极大的提升了开发效率。

但是，日志管理平台并不是万能的，总有一些场景它会缺席（如本地调试产生的日志并不会回流到日志平台，不支持复杂的数据分析，当然还有最常见也是最令人崩溃的，数据丢失了。。。），而我们不得不和一大堆原始日志文件面面相觑。这时我们就不得不从工具包中掏出原始的武器-linux指令，开始一顿操作猛如虎。

本文将结合自己在日常开发过程中遇到的场景给出对应的日志检索语句，也欢迎大家将它收藏到自己的工具包中，或是在下方留言自己遇到的日志分析难题，博主会将其完善到文章中。

日志结构

在了解到日志分析语句之前，先简单介绍一下日志的类型和结构，后序将以这一节介绍的内容作为背景提供具体的日志分析语句。

日志类型主要有两种，一种是业务日志，即实现业务功能的过程中产生的日志，通常是开发者在程序中主动埋点触发的。还有一种是系统日志，这一类日志范围更大，底下还可以继续细分，如系统所在的宿主机各项指标的快照，或者是依赖的中间件内部打印的日志等。

业务日志和系统日志通常在不同的目录下，事实上，不同类型的系统日志一般也会用独立的目录进行隔离。以一个接入了Mysql，RocketMq的系统为例，它的日志目录结构可能如下所示：

/log
  /mysql
  /rocketmq
  /app
    /app_name1
    /app_name2

可见，app下不同的业务系统之间也会进行日志隔离，方便检索和查看。

接着看一下每个目录下日志文件的结构，这个往往没有绝对的标准，开发者通常按照系统的需要设计日志文件结构，甚至产生指定用途的日志（如mysql的bin log和relay log）。这里简单介绍一下我进行系统开发时习惯的日志结构设计。

通常我至少会区分出三个日志文件: application.log, application-error.log和application-warn.log。正如文件的名称所示，它们分别对应不同级别的日志，application.log中会包含应用生命周期中的全部日志，而application-error.log和application-warn.log日志则分别只记录error级别日志和warn级别日志，从而方便快速定位系统异常。但是，如果你直接查看目录下的所有日志文件，会发现它不止有这三个文件.

这是因为系统运行过程中会产生大量的日志，如果只用一个文件进行日志的存储，会导致文件变得极为庞大并严重消耗磁盘空间。因此，操作系统或是日志工具在经过配置后会执行日志截断，压缩和备份等操作，减少日志对整个宿主机稳定性的影响。被截断后的日志会根据配置在日志名加上后缀并保存，通常是加上时间戳。

除了上文所示的根据日志级别来划分多个日志文件，还可以从别的维度设计日志文件，比如将系统流量的入口和出口分别打印日志。流量的入口可以理解为RPC接口Server端，HTTP服务Server端，MQ接收消息日志等，与之相对的流量的出口是指RPC接口Client端，调用下游HTTP服务等。因此整个日志目录将会包含以下几个文件

application.log
appilcation-error.log
application-warn.log
rpc-client.log
rpc-server.log
mq.log

具体的日志配置不在本文的范围内，大家可以自行阅读logback等日志框架的文档。

日志分析小操作

接下来将会列出在日常开发过程中常见的日志查询和分析场景，并给出对应的指令。

查看日志

1. 查看单个日志文件
   cat是我们最常用的阅读文件的指令，通过cat ${filename}即可展示文件的内容。以application.log为例

   cat application.log

   这个指令适用于查看所有可读文件。

2. 查看多个日志文件
   上文提到，因为Logrotate机制的存在，日志文件往往会被截断成多个带有不同时间戳后缀的文件，而我们又不确定想要查询的日志具体在哪个文件中，这时候可以将多个文件都传给cat指令，cat ${filename} ${filename2} ${filename...}，cat会逐个读取文件并展示。但是如果文件数量非常大呢？幸好cat指令支持类似正则的匹配，*关键字允许我们匹配任意多个字段。

   cat application1.log application2.log application3.log
   cat application.log*

   当然，在文件数量很多的时候用cat指令查看全量日志已经不是很好的选择了，下文将会给出其它日志查询方法。

3. 查看最后几行日志
   cat指令会将整个日志文件从头到尾读取并展示在控制台，但是有时我们往往只需要看最近一段时间的日志即可。而且在日志文件特别大的时候，用cat指令不仅比较慢，而且会导致大量无关的日志充斥屏幕影响阅读。这时用tail指令就可以很好的解决这个问题。tail指令可以只读取日志最后几行内容并展示在屏幕上。

   tail application.log # 读取application.log文件最后一部分日志

   tail指令同样支持传入多个文件，它会按照顺序分别读取几个文件的最后一部分内容并打印到控制台

   tail application1.log application2.log application3.log

   如果想要指定展示最后100行的日志，则可以使用tail -n来配合查询：

   tail -n 100 application.log

4. 查看增量日志
   有时，我们希望实时查看日志文件的内容，从而更快速的捕捉到系统的行为，tail -f指令则支持动态的展示文件新增的内容。如果想要退出自动刷新，可以通过ctrl+c指令来实现：

   tail -f application.log

5. 分页查看日志
   有时，因为日志内容实在太多，导致控制台疯狂输出，直接淹没了关键信息。因此，需要一个指令能够分页查看日志内容，降低控制台刷新的频率。more指令为这个场景提供了非常好的支持。

   more application.log

   执行了more指令后，控制台将会逐屏展示文件内容，可以使用空格(space键)来展示下一屏的内容，回车（Enter键）展示下一行的内容，Q键退出more指令

至此，文件的全文查询和部分查询的主要指令已经给出，下面给出另一种类型查询，根据关键字查询，的相关指令

关键字检索

1. 根据关键字检索日志
   在分布式系统中，往往会有数十甚至数百个系统参与到流程中，这时流量的入口会生成一个唯一的logId用来串联和标记全链路请求。当我们需要上下游排查问题时，往往会将logId提供给对方来排查。同样，当我们拿到logId时也需要从日志中跟该logId有关联的日志内容查询出来。这就是一个典型的根据关键字检索日志的场景。
   grep指令很好的解决了这个问题，它能够将日志中和关键字匹配的行打印出来。

   grep "logId" application.log

   上面的指令会将application.log文件中所有包含logId的行打印出来。
   grep指令同样支持多文件查询

   grep "logId" application1.log application2.log application3.log
   grep "logId" application*.log

   还有正则表达式的匹配或者是大小写不敏感的匹配

   grep "logId" application.log -i # 大小写不敏感
   grep -E "[\w\d]*" application.log # 正则表达式

这里顺便提醒一个系统设计的注意点，在分布式系统中logId是通过写入当前线程上下文中实现传递，因此如果在当前线程中提交了一部分任务给异步线程执行，同时有希望能够用当前线程来跟踪，则务必记得将logId传递到异步线程的上下文中。

2. 查看关键字附近日志
   不知道大家在程序中是否写过这样的日志逻辑：log.error("something went wrong keyId:{}", keyId, ex)。通过这一行日志，我们期望将异常的关键id和堆栈在日志中打出来。但是，日志系统会将这一行日志和堆栈分为两行进行打印。如果直接使用grep ${keyId} application.log，则无法查询到下一行的堆栈信息。因此，我们需要查看这个关键字行附近的N行的日志帮助我们快速定位异常原因。grep也提供了这个能力：

   grep 'something went wrong' -A 100 application.log

   上面这行语句展示了something went wrong这一行日志后100行的日志，包括命中的这一行。这里-A是--after-context的缩写，方便记忆。
   同理，也可以查看匹配行前N行的日志：

   grep -B 100 application.log

   这里-B是--before-context的缩写。当然，这两个指令也可以一起使用~

3. 多关键字查询
   有时我们并不一定能够拿到请求的logId，可能只有调用方法以及方法中的关键传参，如果只根据方法名称进行匹配，则可能查出许多无关的调用，反之只用关键传参查询也是，这个参数可能调用了许多别的方法，这些日志都将影响我们找到正确的关键性请求。grep同样提供了多关键字匹配的模式，假设我们现在有一个方法叫做helloWorld(String name)，并传入了值rale

   grep -e "helloWorld" -e "rale" application.log

   但是这个指令并不匹配这个场景的诉求，因为它实际上是一个或关系，即包含helloWorld或是rale的日志行都会被过滤出来。这里就要引入linux的管道操作(pipeline)。linux的管道操作符|可以将两个shell指令串联起来，其中前一个指令的Output将会是下一个指令的Input。

   grep -e "helloWorld" application.log | grep "rale"

   正如上面的指令所示，第一条grep语句将会过滤出所有包含helloWorld的日志行并传递给下一个指令，第二条grep指令则会在这个基础上在过滤出包含rale的日志行。这就构成了一个AND关系，符合我们的要求。

4. 反向查询（正向查询+反向查询）
   有时，我们可能希望反向查询日志，即查出不包含某些关键字的日志，这通常适用于问题更模糊的场景。举个例子，现在有用户提出客诉，说某一个功能出现了异常，但是作为中台服务我们往往很难立刻定位具体是哪个方法或是哪个服务出现问题，因此就会先将这个用户（假设有uid）的所有请求打印出来并过滤掉结果正常的方法。这里可以结合上面的管道指令一起使用。

   grep "$uid" application.log | grep -v "SUCCESS"

   -v是--revert-match的缩写，这里会先找出uid的所有日志，并过滤掉结果为成功SUCCESS的调用。

5. 查看时间区间内的日志
   问题排查时能够获得的信息只有更少没有最少，导致日志的查询只有更秀没有最秀。用户在反馈问题时，有时只能给到我们时间发生的大概时间，其它任何信息都没有。因此我们需要查询这一时间区间内的所有入口调用并结合上面的反向查询逐渐过滤出真正需要关心的内容。这里假设每一行日志中都有时间戳信息。

有多种方法可以实现，首先可以是用我们之前讲到的grep正则匹配模式：

grep -E '2021-10-02 19:\d\d:\d\d:' application.log

这里用正则表达式的方式匹配出2021年十月二号19点的所有日志，同理，如果想要精确到时分秒，则将对应位上的表达式改为具体的数值即可。这种方式有一个比较明显的缺点，即灵活度不够，假如我们需要查询出晚上19:58到20:02的数据，正则表达式就很难满足。

因此我们需要一个新的指令来完成这个使命: sed。
sed是一个流编辑器，相对于grep来说能够支持更加复杂的指令，和对文件的编辑。这里仅提供针对时间范围日志查询的语句，其它功能大家可以做一些扩展阅读：

sed -n '/2021-10-02 19:58:00/,/2021-10-02 20:02:00/p' application.log

-n会过滤出匹配的行，p代表打印到控制台。再看一下-n后紧跟的内容，这里,代表范围查询，这个范围可以是行号，也可以是正则表达式，或者是两个的结合。示例中给出的是精准匹配。范围查询的规则是会找到所有满足的区间都打印出，比如假如范围是/a/,/z/，则sed会顺序找出所有满足开始行包含a结束行包含z的区间。每找到一个a~z的区间，sed就开始找下一个包含a的行，找到后再找包含z的行直到文件结束。

这种查找方式在日志存在乱序的场景下会比较不利，如20:00的日志在20:02之后出现，则它可能无法被过滤出来。同理，如果日志中19:58:00和20:02:00这两个时间点恰巧没有日志，也可能会导致无法过滤出正确的内容。因此我们通常需要先打印出部分日志得到有日志行的时间戳，再用这个时间戳进行过滤。

6. 高亮关键字
   这里针对grep指令给出一个提高可读性的option，即高亮关键字，从而更快的定位日志行。

   grep "logId" application.log --color=auto

分类/排序

上文中给出了查询日志行的指令，下面我们将讨论一些常见的日志统计和分析的操作。以下的大部分操作日志平台都可以提供，但是不排除有时我们需要手撕一份日志文件。

1. 统计关键字出现的次数
   这个场景其实我在开发过程中真实遇到过。当时出现了一些线上问题，需要统计究竟有多少比例的流量受到影响。统计的指标就是根据方法关键字+执行结果为失败代表受到系统异常影响的请求。因为数据量也已经超过了单次查询的最大行数上限，因此最终是将机器上的日志文件下载下来自己统计。
   这时，就要提到一个新的指令wc:

   grep "methodName" application.log* | grep "FAIL" | wc -l

   这里的两个grep指令会帮我们过滤出失败的请求，wc指令会对输入流进行统计，统计的内容可以包括字节数，行数或是字符数。这里-l指令表示只展示行数。

假如统计维度升级，我们希望统计有多少的用户受到影响（日志中包含用户的uid），这时单纯的统计行数就会产生重复统计。因此我们需要根据用户id对日志行进行去重。这里又要引入一个新指令uniq，它可以对整行或者是根据行内的部分信息进行去重，并统计每一个关键字关联的行数。这里要注意，uniq仅对排序后的行生效，因此还需要将关键字截取、排序后再使用uniq才能达到预期效果

grep "methodName" application.log* | grep "FAIL" | cut -d ' ' -f 1 | sort | uniq -c

这里又冒出了一堆新的shell指令，首先是cut指令，cut指令会根据指定规则将对应位上的值复制到输出流中，类似于电脑上的ctrl+c。-d声明了切割日志行的分隔符，这里按照空格对行进行切割。-f则指定取哪一个位置上的值，cut指令后生成的字符串列表是以1作为起始下标的，因此这里取了分割后的第一个字符串（假设日志格式为userId timestamp threadId ....，当然大多数情况下userId并不会是行首的内容）。接着对所有userId进行排序，这里使用了sort指令。最后用uniq指令去重，-c选项是指在每列旁边显示该行重复出现的次数。

2. 导出结果
   假设现在我希望将上面的统计结果导出到文件中并传给别人，linux管道同样支持将输出流重定向到文件中

   ...a lot of command ... > result.txt

   这里txt文件只是一种示例，你可以声明其它格式的文件。

逆向思维-打印日志最佳实践

在上文介绍了一些日志解析和统计的方式后，也反过来想我们在系统中打印日志时的一些实践。日志格式的统一化往往可以让我们更快速的根据日志完成一系列的统计分析。目前主流的日志格式通常如下：

%level %d{yyyy-MM-dd HH:mm:ss.SSS} %F:%L %X{HOST_IP:-_} %X{LOG_ID:-_} %X{CLUSTER:-_} %X{STAGE:-_} [%t] %m%n%wEx -->

可以看到其中会包含日志级别，分布式logId，时间戳，宿主机关键信息（ip，环境），线程id等。同样的，我们在业务系统中打印的日志如果也能遵循一定的格式，也会极大增强日志排查的可读性和方便性。比如，在打印RPC Server端日志时，我通常会给出三类日志，Start日志，Finish日志和Digest日志。

   private static final String START_LOG_TEMPLATE = "[rpc_server_start] [method]:{} [request]:{}";

   private static final String FINISH_LOG_TEMPLATE = "[rpc_server_finish] [method]:{} [success]:{} [duration]:{}s [request]:{} [result]:{}";

   private static final String DIGEST_LOG_TEMPLATE = "[rpc_server_digest] [method]:{} [success]:{} [duration]:{}s";

其中Start日志是请求开始处理前打印，包含入参，调用方等信息，Finish日志则是打印入参，出参，是否成功以及耗时。Digest日志较为特殊，它不包含调用的任何请求响应信息，它只会打印出调用的方法，是否成功，耗时等信息。通常会使用Digest日志来进行快速的性能分析。

小结

本文讲的日志操作只是整个日志文件处理操作中的冰山一角，却一定是最常见也是最有可能用到的，希望对大家有所帮助。也欢迎大家将它收藏到自己的工具包中，或是在下方留言自己遇到的日志分析难题，博主会将其完善到文章中。