作者:陶建辉
这是我在 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
原文首发于:https://mp.weixin.qq.com/s/LUz1niYajOR35UpOlfszIQ