关于日志:日志分析常规操作

前言

日志是开发者用来分析程序和排查问题的重要工具。随着零碎架构从晚期的单体利用，演变到现在的微服务架构，日志的重要性也逐渐晋升。除了用日志辅助问题排查，还能够通过日志对微服务申请的全链路进行性能剖析，甚至能够它用来解决分布式系统中的一致性问题。与此同时，零碎产生的日志量和日志治理难度也显著减少。于是，日志管理工具随之诞生并迭代降级。从最开始登录到跳板机上查看日志，到自建分布式日志核心来对立治理日志流，到云平台厂商提供专门的日志治理服务。开发者只须要在利用中接入 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 日志来进行疾速的性能剖析。

小结

本文讲的日志操作只是整个日志文件解决操作中的冰山一角，却肯定是最常见也是最有可能用到的，心愿对大家有所帮忙。也欢送大家将它珍藏到本人的工具包中，或是在下方留言本人遇到的日志剖析难题，博主会将其欠缺到文章中。