乐趣区

关于oceanbase:技术分享-OceanBase-错误日志分析

jiezi

作者：操盛春

技术专家，任职于爱可生，专一钻研 MySQL、Ocean Base 源码。

本文起源：原创投稿

* 爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。

OceanBase 运行时会产生很多各种级别的日志，如果呈现了谬误，想要从数量繁多的谬误日志中定位到谬误起因，是件不太容易的事。

谬误日志是咱们定位谬误起因的次要路径，本文咱们就来聊聊怎么从 OceanBase 谬误日志中找到咱们想要的错误信息。

1. 日志文件

OceanBase 日志分为 3 类：

  • 选举模块日志：寄存 选举模块 产生的日志。
  • 总控服务（RootService）模块日志：寄存 总控服务模块 产生的日志。
  • 启动、运行日志：寄存除选举模块、总控服务模块之外的 其它所有模块 产生的日志。

每类日志又蕴含 2 种日志文件：

  • .log、.log.YYYYmmDDHHMMSS 文件中蕴含该类型 所有级别 的日志。
  • .log.wf、.log.wf.YYYYmmDDHHMMSS 文件中蕴含该类型 WARN、USER_ERROR、ERROR 3 个级别的日志（须要把系统配置 enable_syslog_wf 的值设置为 true）。

每类日志都写入到对应的 .log(.log.wf) 文件中，写满 256M 之后，把 .log(.log.wf) 文件改名（加上 .YYYYmmDDHHMMSS 后缀），而后再创立新的 .log（.log.wf）文件。

通过 ls -l 查看 OceanBase 日志目录，能够看到相似如下的日志文件：

-rw-r--r-- 1 admin admin  18688919 10 月  9 02:08 election.log
-rw-r--r-- 1 admin admin   4998884 10 月  9 02:07 election.log.wf
-rw-r--r-- 1 admin admin  75158675 10 月  9 02:08 rootservice.log
-rw-r--r-- 1 admin admin 268437081 10 月  8 23:25 rootservice.log.20221008232523
-rw-r--r-- 1 admin admin  61688030 10 月  9 02:08 rootservice.log.wf
-rw-r--r-- 1 admin admin 227610855 10 月  8 23:25 rootservice.log.wf.20221008232523
-rw-r--r-- 1 admin admin 156856561 10 月  9 02:08 observer.log
-rw-r--r-- 1 admin admin 268435919 10 月  9 01:25 observer.log.20221009012502
-rw-r--r-- 1 admin admin  91282191 10 月  9 02:08 observer.log.wf
-rw-r--r-- 1 admin admin 158605686 10 月  9 01:25 observer.log.wf.20221009012502

2. 日志格局

依照日志谬误级别不同，OceanBase 格局分为 2 种：

  • DEBUG、TRACE、INFO 日志记录格局
[time] log_level [module_name] file_name:fine_no [thread_id][coroutine_id][Ytraceid0-traceid1] [lt=last_log_print_time] [dc=dropped_log_count] log_data
  • WARN、USER_ERROR、ERROR 日志记录格局
[time] log_level [module_name] function_name (file_name:fine_no) [thread_id][coroutine_id][Ytraceid0-traceid1] [lt=last_log_print_time] [dc=dropped_log_count] log_data

2 种日志格局的不同之处是：WARN、USER_ERROR、ERROR 日志记录多了 function_name 字段。

这些日志字段中，须要重点介绍 3 个字段：

trace_id： 格局为 Ytraceid0-traceid1，例如：YB420ABA3C91-0005E98FC3148792。

一条 SQL 在整个 OBServer 集群中对应 惟一的 trace_id，通过 trace_id 能够找到一条 SQL 执行过程中在整个集群中打印的所有日志。

lt： lt = last_log_print_time，写日志形式不同，此字段值示意的含意也不同：

  • 异步写日志：该字段值示意本条日志格式化耗费的工夫，格式化指的是：源码中把本条日志所有字段拼接到一起失去字符串格局内容的过程。

  • 同步写日志：该字段值示意上一条日志从格式化到写入日志文件胜利耗费的工夫。依据这个写入工夫和上一条日志的内容长度，可能反映出写上一条日志时的磁盘 IO 负载。

    为什么记录的是上一条日志，而不是本条日志写入过程耗费的工夫？

    因为在格式化本条日志的时候，还不晓得本条日志胜利写入日志文件须要耗费多长时间，记录本条日志耗费的工夫就只能留给后来者（也就是本条日志的下一条日志）去做了。

dc： dc = dropped_log_count，示意自上一条日志胜利写入日志文件以来，到以后这条日志为止，两头有多少条日志（蕴含所有级别的日志）写入失败了，只有异步日志记录中有这个字段。

异步写入日志失败的起因有以下几种：

  • 为日志记录分配内存失败。
  • 格式化日志失败（格式化的定义参照后面 lt 字段异步写日志中的定义）。
  • 每秒写入的日志量超过最大限度了。
  • 日志内容期待退出日志队列超时，队列中最多能退出的日志数量由 MAX_BUFFER_ITEM_CNT 常量管制，固定值为 524288。

3. 剖析日志

如果执行某条 SQL 呈现了谬误，OceanBase 会给出错误码和错误信息，有时候这个错误信息并不明确，想要找到更明确的信息，能够依照 2 个步骤进行。

3.1 依据错误码找到 trace_id

因为 trace_id 在一个集群中惟一标识一条 SQL，所以第一步是从谬误日志中找到 trace_id，依照以下程序进行：

  • 先依据错误码去 observer.log.wf 文件找 trace_id。
  • 如果 observer.log.wf 中没找到，再去 rootservice.log.wf 文件找。
  • 如果 rootservice.log.wf 中没找到，再去 election.log.wf 文件找。

为什么要按下面的文件程序找 trace_id？

  • 选举过程并不是只波及到选举模块，还会波及到总控服务模块（RS）、其它模块，所以选举过程中，在 observer.log.wf、rootservice.log.wf、election.log.wf 中都会产生日志记录。
  • 总控服务提供的性能，最终也要由集群中的 OBServer 执行，整个过程除了会波及总控服务模块，还会波及其它模块。
  • 鉴于以上 2 点，不论执行的是什么 SQL，都要由最终干活的角色去执行，而 observer.log.wf 中记录的就是最终干活的角色产生的日志，这里最有可能记录着谬误的源头，为此先从 observer.log.wf 动手。

接下来以 OceanBase 创立资源池为例，介绍从日志文件中查找错误信息的过程：

obclient [(oceanbase)]> CREATE RESOURCE POOL mini_pool_t4 unit=mini_1,unit_num=1;
ERROR 4624 (HY000):  machine resource 'z1' is not enough to hold a new unit

创立资源池报错，错误码为 4624，先依据错误码从 observer.log.wf文件中过滤谬误日志，过滤字符串的格局为：ret=- 错误码（留神错误码 后面的负号）。

[[email protected] log]$ grep "ret=-4624" observer.log.wf
[2022-10-09 06:39:25.317545] WARN  [SQL.ENG] execute (ob_resource_executor.cpp:42) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=63] [dc=0] rpc proxy create resource_pool failed(ret=-4624)
[2022-10-09 06:39:25.317883] WARN  [SQL] open_cmd (ob_result_set.cpp:84) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] execute cmd failed(ret=-4624)
[2022-10-09 06:39:25.317994] WARN  [SQL] sync_open (ob_result_set.cpp:133) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=96] [dc=0] fail to exec execute()(ret=-4624)
[2022-10-09 06:39:25.353385] WARN  [SERVER] response_result (ob_sync_cmd_driver.cpp:60) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=14] [dc=0] close result set fail(cret=-4624)
[2022-10-09 06:39:25.353471] WARN  [SERVER] test_and_save_retry_state (ob_query_retry_ctrl.cpp:117) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=29] [dc=0] ddl, and errno is not OB_EAGAIN or OB_SNAPSHOT_DISCARDED or OB_ERR_PARALLEL_DDL_CONFLICT, do not need retry(client_ret=-4624, err=-4624, retry_type_=0)
[2022-10-09 06:39:25.353593] WARN  [SERVER] response_result (ob_sync_cmd_driver.cpp:64) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] result set open failed, check if need retry(ret=-4624, cli_ret=-4624, retry_ctrl_.need_retry()=0)
[2022-10-09 06:39:25.353969] WARN  [SERVER] do_process (obmp_query.cpp:674) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=9] [dc=0] execute query fail(ret=-4624, timeout_timestamp=1665298548583953)
[2022-10-09 06:39:25.354347] WARN  [SERVER] process (obmp_query.cpp:291) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=18] [dc=0] fail execute sql(sql_id="", sql=CREATE RESOURCE POOL mini_pool_t4 unit=mini_1,unit_num=1, sessid=3221633143, ret=-4624, ret="OB_MACHINE_RESOURCE_NOT_ENOUGH", need_disconnect=false)

下面过滤出来的谬误日志中，YB420ABA3C91-0005E98FC5948785 就是 trace_id。

从 observer.log.wf 文件中，个别都能找到 trace_id，如果万一没找到，再顺次从 rootservice.log.wf、election.log.wf 中找。

如果从下面 3 个日志文件中都没找到，那就是碰上非凡状况了，能够用报错中的错误信息顺次从 observer.log.wf、rootservice.log.wf、election.log.wf 中找，例如：

[[email protected] log]$ grep "machine resource'z1'is not enough to hold a new unit" observer.log.wf
[2022-10-09 08:17:02.170951] WARN  log_user_error_and_warn (ob_rpc_proxy.cpp:300) [13567][2307][YB420ABA3C91-0005E98FC5C48785] [lt=7] [dc=0]  machine resource 'z1' is not enough to hold a new unit

3.2 依据 trace_id 查找谬误日志

从 3.1 依据错误码找到 trace_id 大节能够看到，依据错误码或者错误信息也能过滤出很多谬误日志，为什么还要多此一举，再依据 trace_id 查找谬误日志？

因为通过错误码或错误信息过滤出来的日志，有可能把十分要害的日志记录给过滤掉了，而通过 trace_id 可能拿到更残缺的日志。

依据 trace_id 查找谬误日志，也一样先从 observer.log.wf 中开始找，如果找到了可能确定谬误起因的信息，就此结束，否则再接着到 rootservice.log.wf、election.log.wf 中找。

这一步的流程就是通过 grep trace_id 从各个 .log.wf 文件中找到谬误日志，不开展举例了。

4. 存在的问题

理论应用过程中，有时候并不能通过 Oceanbase 的谬误日志找到明确的谬误起因，这种状况下要找到谬误起因，就只能靠咱们的教训了。

依据后面介绍的步骤，从谬误日志中找到蛛丝马迹，而后依照 猜想 - 验证 流程，一点一点排查。

例如：OBServer 集群用以下 SQL 进行 BOOTSTRAP 选举，报 Timeout 谬误，最终就不能通过谬误日志间接定位到起因：

obclient [(none)]> ALTER SYSTEM BOOTSTRAP ZONE 'z1' SERVER 'xx.xx.xx.xx:2882',ZONE 'z2' SERVER 'xx.xx.xx.xx:2882',ZONE 'z3' SERVER 'xx.xx.xx.xx:2882';
ERROR 4012 (HY000): Timeout

通过多轮 猜想 - 验证 流程确定谬误起因之后，反过来查看谬误日志，发现最靠近理论状况的日志如下：

[2022-10-09 09:05:32.052665] WARN  [BOOTSTRAP] execute_bootstrap (ob_bootstrap.cpp:759) [16840][446][YB420ABA3C91-0005EA9633379D17] [lt=21] [dc=0] failed to wait all rs online(ret=-4622)

谬误日志中的 failed to wait all rs online，阐明 BOOTSTRAP 操作正在期待所有 RootService 服务上线。

这个问题是因为集群中 3 个 OBServer 实例启动时，-z 参数都是 z1，而 BOOTSTRAP 指定的 RootService 服务器的 zone 却是 z1、z2、z3。

3 个 RootService 服务器都启动了，端口也是失常监听状态，OceanBase 却没有辨认进去，谬误日志中也就没能精确的记录错误信息了。

5. 两点期待

在日志方面，对于行将正式出品的 OB 4.0 版本有两点期待:

期待 1：如果 OceanBase 可能精确辨认谬误产生的起因，并记录到日志中，对于咱们日常运维将会十分有帮忙。

期待 2：.log.wf 文件中的谬误日志记录，目前不能体现触发打印日志的办法之间的调用层级关系，不不便间接找到最初一个被调用的办法产生的谬误日志。

如果可能在每条谬误日志中记录触发打印以后日志的办法的调用层级，咱们运维过程中就可能疾速找到产生谬误的办法，从而晋升定位谬误起因的效率。

调用层级相似上面这种模式（process、do_process 等办法后面的序号）：

[[email protected] log]$ grep "YB420ABA3C91-0005E98FC5948785" observer.log.wf
[2022-10-09 06:39:25.317429] WARN  3.2.1.1.1 log_user_error_and_warn (ob_rpc_proxy.cpp:300) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=5] [dc=0]  machine resource 'z1' is not enough to hold a new unit
[2022-10-09 06:39:25.317545] WARN  [SQL.ENG] 3.2.1.1 execute (ob_resource_executor.cpp:42) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=63] [dc=0] rpc proxy create resource_pool failed(ret=-4624)
[2022-10-09 06:39:25.317883] WARN  [SQL] 3.2.1 open_cmd (ob_result_set.cpp:84) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] execute cmd failed(ret=-4624)
[2022-10-09 06:39:25.317994] WARN  [SQL] 3.2 sync_open (ob_result_set.cpp:133) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=96] [dc=0] fail to exec execute()(ret=-4624)
[2022-10-09 06:39:25.353385] WARN  [SERVER] 3 response_result (ob_sync_cmd_driver.cpp:60) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=14] [dc=0] close result set fail(cret=-4624)
[2022-10-09 06:39:25.353471] WARN  [SERVER] 3.1 test_and_save_retry_state (ob_query_retry_ctrl.cpp:117) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=29] [dc=0] ddl, and errno is not OB_EAGAIN or OB_SNAPSHOT_DISCARDED or OB_ERR_PARALLEL_DDL_CONFLICT, do not need retry(client_ret=-4624, err=-4624, retry_type_=0)
[2022-10-09 06:39:25.353593] WARN  [SERVER] 3 response_result (ob_sync_cmd_driver.cpp:64) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=21] [dc=0] result set open failed, check if need retry(ret=-4624, cli_ret=-4624, retry_ctrl_.need_retry()=0)
[2022-10-09 06:39:25.353969] WARN  [SERVER] 2 do_process (obmp_query.cpp:674) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=9] [dc=0] execute query fail(ret=-4624, timeout_timestamp=1665298548583953)
[2022-10-09 06:39:25.354347] WARN  [SERVER] 1 process (obmp_query.cpp:291) [3414][2255][YB420ABA3C91-0005E98FC5948785] [lt=18] [dc=0] fail execute sql(sql_id="", sql=CREATE RESOURCE POOL mini_pool_t4 unit=mini_1,unit_num=1, sessid=3221633143, ret=-4624, ret="OB_MACHINE_RESOURCE_NOT_ENOUGH", need_disconnect=false)
退出移动版