60秒定位问题，十倍程序员的Debug日常

2021 年 3 月 12 日
笔记
tdengine, TDengine技术博客, 十倍程序员, 日志分析, 时序数据库, 物联网大数据平台

作者：陶建辉

这是我在 2020 年 5 月写的一篇内部博客，当时是希望研发和技术支持同学能够帮助用户快速定位 Bug，解决问题。2020 年 12 月我又迭代了一版，并还针对此进行了内部的培训。这段时间我也一直在关注微信群中的提问，发现有不少用户觉得分析 TDengine 的日志或任何其他分布式系统的日志是有难度的。现在将我这篇博客公开，以分析 TDengine 的日志为例，介绍一套方法，如果你能掌握，那么分析分布式系统的日志就会变得极其之简单。

TDengine 是一个集群系统，任何一个操作，都会涉及到 APP、taosc、mnode 和 vnode 等逻辑节点。这些节点之间是通过 Socket 进行通讯的。而且在测试中，可能有多个 TDengine 实例，这让分析变得更为复杂。对于一个操作，如何将不同逻辑节点的日志匹配串通起来，高效过滤处理，成为分析问题的关键。

本文总结了一套方法，能够让大家快速找到 Bug 所在。

打开相关日志开关

TDengine 每个独立的模块都有自己的 debugFlag, 包括 taosc, dnode, vnode, mnode, tsdb, wal, sync, query, rpc, timer 等。目前每个模块的日志输出可以控制到：

Fatal/Error，错误，日志上会显示 ERROR
Warning，警告, 日志上会显示 WARN
Info，重要信息
Debug，一般信息
Trace，非常详细且反复出现的调试信息
Dump，原始数据

输出的日志可以控制输出到：

文件
屏幕

上述的控制全部由 debugFlag 的一个字节控制，这个字节里的 bit 图如下：

因此，如果要将 error, warning, info,debug 输出到日志文件，那么 debug 要设置为：135；如果还想输出 trace 级别的日志，那么 debug 要设置为：143；如果仅仅输出 error 和 warning, debug 设置为 131。正常情况下，建议将 debug 设置为 135 即可。

每个模块的 debug flag 的设置全部由配置文件 taos.cfg 控制，具体各模块的参数以及日志显示的模块名如下：

如果嫌配置参数过多，最简单的方式，是设置 debug 的总参数 debugFlag, 这个参数设置后，除 tmr 日志外，所有模块的 debug 全部统一设置为同一个参数 debugFlag。debugFlag 的默认值为 0，当 debugFlag 为非 0 值时，将会覆盖所有的日志配置参数。
除非特殊 case, 不建议设置 util, timer 的 debugFlag 为 135，设置为 131 合适。

日志文件

TDengine 会生成客户端以及服务器端日志，存放在日志目录里，缺省日志目录是/var/log/taos, 但可以通过修改 taos.cfg 里的配置参数 logDir 指定

客户端日志文件名为 taoslogY.X (因为可以运行多个客户端，因此一台机器上可以生成多个日志文件）
服务器端日志文件为 taosdlog.X

日志文件的大小有控制，达到一定行数（taos.cfg 里配置参数 numOfLogLines 控制）后，会生成新的日志文件。但 TDengine 仅仅保留两个日志文件，文件名以 0 或 1 结尾，交替。

日志格式：

日志文件，从左到右，分为四大块

时间戳，精确到微妙
线程 ID，因为是多线程，这个参数很重要，因为只有同一个线程输出的日志才是有时序保证的，是按设计的 flow 输出的
模块名，三个字母
每个模块输出的日志

分析日志的几大步骤

当测试或客户报告一个 Bug，无论是手动还是自动，都是执行某个具体操作发生的。这个具体操作一般都是执行一个 SQL 语句。这个问题可能是客户端导致，也可能是服务器代码导致。下面以 create table 为例，解释日志的分析，为便于聚焦解释，图中去掉时间戳。

先看客户端

最先需要查看的是客户端日志，示例截图如下：

先找到出问题的 SQL 语句，在客户端日志里搜索 “SQL: “，就可以看到(截图第二行）。日志里搜索“SQL result:”（截图第 11 行）, 如果成功，会显示 ”SQL result:success”, 否则会显示“SQL result: xxxx”, 其中 xxxx 是错误信息。如何快速找到失败的 SQL，需要知道大概的时间范围，SQL 语句是什么，这么搜索会很快。
taoc 的日志数据，有个很重要的参数是 pSql，是分配给内部 SQL Obj 的一个地址。taosc 把这个地址信息放在所有 taosc 日志的最前面，紧接 TSC 之后。这个值很关键，是传统客户端与服务器日志的关键。在上面的截图中，用绿色背景标出。
pSql 这个参数会作为 ahandle 传递至 RPC 模块，RPC 在所有消息里，都会将其打印处理（绿色背景）。因为很多模块都会调用 RPC 模块，RPC 也会把谁调用的打印出来，比如截图中，是 TSC 调用的，就会打印 RPC TSC 出来。
RPC 会把消息 create-table 发往服务器，RPC 日志会打印出来（截图第 8 行), 告知发往到了哪个 dnode 的 End Point, 截图中显示发往了 hostname: 9be7010a917e, port 为 6030。如果有问题，那我们就需要检查这个 End Point 所在的服务器日志了。
能看到，RPC 模块收到了服务器的回应，但为避免转换消耗资源，日志仅仅显示了 16 进制的 IP 地址（截图第 9 行，0x20012ac)以及端口号。RPC 模块的日志很关键，因为它把各个逻辑节点串通起来。

再看服务器

分析了客户端日志，服务器日志很关键，下面仍然以 create-table 为例，请看截图:

从客户端日志里，找到 pSql，值是 0x5572c4fab3a0，因此在 taosdlog 里直接搜索 0x5572c4fab3a0，就可以看到截图中绿色背景的日志。因此 pSql 是将客户端与服务器日志串起来很重要的参数。
对于 create-table 这个具体操作而言，是有 mnode 处理。截图中，是因为创建第一张表，因此需要先创建 vnode, 然后创建 table 等系列操作，牵涉到很多模块，就不细解释。
最后，mnode 创建完 table, 通过 RPC 模块发回 response(截图第 52 行，最后一行），因此可以清晰的看出服务器工作正常。

注意：dnode 模块收到消息后，会根据消息类型，将消息分发到 mnode, vnode 的消息队列。然后工作线程会消费消息队列里的消息，对消息进行处理。对于 vnode 而言，里面的子模块 tsdb, wal, sync, cq 都是单线程执行的，因此在找到 pSql 之后（截图第二行），需要根据线程的 ID，顺序往下看，就能知道整个流程，很好分析。

几个关键点

先找到失败 SQL 语句
找到 pSql 的值，拷贝下来, 假设为 xxxxx
grep “xxxxx” taoslogx.x, 找到与这条 SQL 相关的客户端日志，看能否找到问题
打开 taosdlog 服务器日志，搜索 pSql 的值 xxxxx, 检查时间戳，看是否是失败的那条操作
然后分析服务器日志

RPC 模块的消息十分关键。有一点很重要，对于每一条 RPC 消息，都会打印 parse code: xx, 这是协议解析结果，0 表示没有问题，其他值说明协议解析就不成功。但同时，消息本身还有 code: 0xXX, 这是发送方带来的错误码，一般是服务器发往客户端的，正确的话，code 是 0，否则就是报错。

另外一个日志匹配方法

客户端通过 RPC 模块发出一条消息时，日志上带有类似

sig:0x01000000:0x01000000:55893

这是 RPC 的 source ID, dest ID, 以及 transcation ID，三个参数组合在一起，能唯一标识来自一个客户端的链接。每条新消息的发送，都会将 transcation ID 加一，因此在一段时间内具有唯一性（transcation ID 是两字节，会循环的)。

1.6 版本只能依赖 sig 这个字符串将客户端与服务器日志匹配起来，但需要看很多上下文，因此麻烦，效率不够。

2.0 版将 pSql 传至服务器侧，这样客户端与服务器的日志匹配将大大加速。

熟悉日志的方法

首先要了解 TDengine 的设计，了解每个主要操作的流程。
打开所有日志开关(将 debugFlag 设为 135), 所有的 SQL 语句都执行一次，对照每条 SQL，检查对应的客户端与服务器日志。

查看客户端执行的 SQL 语句

客户端会产生很多日志，查看执行的 SQL 语句，便于分析和重复问题。找出系统到底执行了什么样的 SQL 语句，有几种方法

如果客户端日志打开，执行: grep “SQL: ” taoslog*, 会看到日志中所有执行的 SQL 语句。
如果用 taos，手工执行 SQL 语句，请在 home 目录里，查看隐藏的文件.taos_history, 里面会有 taos 执行的所有历史命令。
对客户端进行配置，在配置文件中，将 tscEnableRecordSql 参数设置为 1，即将客户端输入的 SQL 语句打印到单独的文件（tscnote-xxxx.0，xxxx 是 pid），与客户端日志所在目录相同。
对于 resetful 接口，在 taosd 的配置文件中将 httpEnableRecordSql 参数设置为 1，会将 htpp 请求打印到单独的文件（httpnote.0），与服务端日志所在目录相同。

动态修改日志

有时不能重启服务器或客户端，但日志的设置又不正确，这个时候需要动态设置，执行如下几步：

show dnodes；// 查找每个 dnode 的 ID
alter dnode id debugFlag 143;  // 设置相应的 debugFlag

其中第二步的 id 是第一步获取的。

有时需要把后续日志输出到一个新文件，方便日志的查看及搜索，执行：

alter dnode id resetlog;

有时 shell 根本链接不上，这时可以在 taosd 运行的机器，给进程发送 SIGUSR1 命令，如：

kill -SIGUSR1 pidxxx

原文首发于：//mp.weixin.qq.com/s/LUz1niYajOR35UpOlfszIQ

Tags: tdengine TDengine技术博客十倍程序员日志分析时序数据库物联网大数据平台