常见问题场景日志解读最佳实践 - OceanBase 最佳实践

OceanBase 数据库日志模块所属的日志文件分为 observer.log 、election.log 和 rootservice.log 三种类型，默认打印 WDIAG 级别以上的日志。每类日志文件自动生成一个带有 .wf 后缀的 WARNING 日志文件（ observer.log.wf、election.log.wf 、rootservice.log.wf ），只打印了 WARN 级别以上的日志。

本文主要介绍常用日志的解读，日志文件 observer.log 、election.log 和 rootservice.log 都存放在 OBServer 服务器的 $work_dir/log 目录下。

适用版本

OceanBase 数据库 V2.x、V3.x 版本。

日志级别

OceanBase 数据库 V2.x、V3.2.3 版本

OceanBase 数据库日志划分了六个日志级别，含义如下表所示。表中的日志级别从高到低依次排列。

日志级别	含义
ERROR	严重错误。用于记录系统的故障信息，且必须进行故障排除，否则系统不可用。
USER_ERROR	用户输入导致的错误。
WARN	警告。用于记录可能会出现的潜在错误。
INFO	提示。用于记录系统运行的当前状态，该信息为正常信息。
TRACE	与 INFO 相比更细致化地记录事件消息。
DEBUG	调试信息。用于调试时更详细地了解系统运行状态，包括当前调用的函数名、参数、变量、函数调用返回值等。

OceanBase 数据库 V3.2.4 版本

OceanBase 数据库日志划分了七个日志级别，含义如下表所示。表中的日志级别从高到低依次排列。

日志级别	含义
ERROR	严重错误。用于记录系统的故障信息，且必须进行故障排除，否则系统不可用。
WARN	警告。用于记录可能会出现的潜在错误。
INFO	提示。用于记录系统运行的当前状态，该信息为正常信息。
EDIAG	Error Diagnosis, 协助故障排查的诊断信息，通常为 OceanBase 数据库程序的 Bug。
WDIAG	Warning Diagnosis, 协助故障排查的诊断信息，预期内的错误，OceanBase 数据库能进行容错。
TRACE	与 INFO 相比更细致化地记录事件消息。
DEBUG	调试信息。用于调试时更详细地了解系统运行状态，包括当前调用的函数名、参数、变量、函数调用返回值等。

查询日志

日志查询可通过 grep 命令来实现，具体语句如下：

[admin@OB /home/admin/oceanbase/log] $grep [keyword] observer.log
[admin@OB /home/admin/oceanbase/log] $grep [keyword] rootservice.log
[admin@OB /home/admin/oceanbase/log] $grep [keyword] election.log

日志数据格式

日志数据格式如下，具体格式以实际情况为准。

[time] log_level [module_name] (file_name:fine_no) [thread_id][Y_trace_id0-trace_id1] [lt=last_log_print_time] [dc=dropped_log_count] log_data_

[time] log_level [module_name] function_name (file_name:fine_no) [thread_id][Y_trace_id0-trace_id1] [lt=last_log_print_time] [dc=] log_data_

日志打印示例如下：

observer.log 日志

[admin@OB /home/admin/oceanbase/log] $tail -f -n 1 observer.log

返回结果如下：

[2016-07-17 14:18:04.845802] INFO  [RPC.OBMYSQL] obsm_handler.cpp:191 [9543][Y0-0] [lt=47] [dc=0] connection close(easy_connection_str(c)="xxx.xxx.xxx.xxx:56854_-1_0x7fb8a9171b68", version=0, sessid=2147562562, tenant_id=1, server_id=1, is_need_clear_sessid_=true, ret=0)

observer.log.wf 日志

[admin@OB /home/admin/oceanbase/log] $tail -f -n 1 observer.log.wf

返回结果如下：

[2016-07-17 14:18:28.431351] WARN  [SQL.SESSION] set_conn (ob_basic_session_info.cpp:2568) [8541][xxxxxxxxxxxx-xxxxxxxx] [lt=16] [dc=0] debug for set_conn(conn=0x7fb8a9171b68, lbt()="0x4efe71 0x818afd 0xe9ea5b 0x721fc8 0x13747bc 0x2636db0 0x2637d68 0x5054e9 0x7fb98705aaa1 0x7fb9852cc93d ", magic_num_=324478056, sessid_=2147562617, version_=0)

rootservice.log 日志

[admin@OB /home/admin/oceanbase/log] $tail -f -n 1 rootservice.log

返回结果如下：

[2016-07-17 14:18:53.701463] INFO  [RS] ob_server_table_operator.cpp:345 [8564][Y0-0] [lt=11] [dc=0] svr_status(svr_status="active", display_status=1)

rootservice.log.wf 日志

[admin@OB /home/admin/oceanbase/log] $tail -f -n 1 rootservice.log.wf

返回结果如下：

[2016-07-16 02:02:12.847602] WARN  [RS] choose_leader (ob_leader_coordinator.cpp:2067) [8570][xxxxxxxxxxxx-xxxxxxxx] [lt=8] [dc=0] choose leader info with not same candidate num(tenant_id=1005, server="xxx.xxx.xxx.xxx:2882", info={original_leader_count:0, primary_zone_count:0, cur_leader_count:1, candidate_count:1, in_normal_unit_count:1})

日志数据中的各字段含义如下表所示：

参数	说明
time	该条日志打印的时间。
log_level	该条日志的级别。
module_name	打印该条日志的语句所在模块。
function_name	该条日志的语句所在的函数。
file_name	该条日志的语句所在的文件。
file_no	该条日志的语句所在文件的具体行数。
thread_id	该条日志的线程的线程号。
trace_id0-trace_id1	该条日志的 trace_id，由 trace_id0 和 trace_id1 组成，该 trace_id 可通过 RPC 在各个 OBServer 间传递，从而可以根据 trace_id 号来获取相互之间有关联关系的日志数据。
last_log_print_time	OBServer 支持同步日志与异步日志，开启同步日志时，该参数语义表示"上一条日志消耗的时间"；开启异步日志时，该参数表示"本条日志格式化的时间"。
dropped_log_count	丢掉的日志数量。
log_data	具体的日志数据。

日志解读示例

observer.log 日志

OBServer 启动日志

统计日志

常见诊断日志

搜索关键字： [NOTICE]

日志说明：OBServer 启动过程中比较关键的日志信息。

[admin@OB /home/admin/oceanbase/log] $grep "NOTICE" observer.log

返回结果如下：

[2023-05-11 14:19:09.703272] INFO  [SERVER] ob_server.cpp:533 [95303][0][Y0-0000000000000000-0-0] [lt=9] [dc=0] [NOTICE] server instance start succeed

[2023-05-11 14:19:25.555836] INFO  [SERVER] ob_server.cpp:609 [95303][0][Y0-0000000000000000-0-0] [lt=16] [dc=0] [NOTICE] observer start service(start_service_time=1683785965555827)

日志解读：

日志信息	说明
server instance start succeed	OBServer 进程启动成功。
observer start service	OBServer 启动完成，开始提供服务；`start_service_time` 为 OBServer 开始提供服务的时间戳。

进程内存统计

搜索关键字： [CHUNK_MGR]

日志说明： 系统视角的 OBServer 进程的内存使用统计，每 10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "CHUNK_MGR" observer.log

返回结果如下：

[2023-05-15 16:24:19.728623] INFO  [COMMON] ob_tenant_mgr.cpp:643 [87101][0][Y0-0000000000000000-0-0] [lt=7] [dc=0] [CHUNK_MGR] free=40593 pushes=8989641 pops=8949048 limit=107,978,014,720 hold=106,384,326,656 used= 21,254,635,520 freelist_hold= 85,129,691,136 maps=602,804 unmaps=587,963 large_maps=599,637 large_unmaps=587,963 memalign=0   virtual_memory_used=111,853,719,552

日志解读：

日志信息	说明
limit	OBServer 总内存限制，单位为字节。
hold	OBServer 从操作系统获取到的所有的内存，单位为字节。
used	OBServer 实际使用到的内存（包括 Cache），单位为字节。
freelist_hold	OBServer 未使用的内存，单位为字节。
maps、unmaps	OBServer 监控到的 maps、unmaps，单位为字节。
large_maps、large_unmaps	OBServer 监控到的 maps、unmaps，单位为字节。

租户内存统计

搜索关键字： [MEMORY] 或 ob_malloc_allocator.cpp

日志说明： 系统视角的租户内存使用统计，每 10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "MEMORY" observer.log

或者

[admin@OB /home/admin/oceanbase/log] $grep "ob_malloc_allocator" observer.log

返回结果如下：

[2023-06-05 12:09:21.701235] INFO  [LIB] ob_malloc_allocator.cpp:495 [88518][0][Y0-0000000000000000-0-0] [lt=5] [dc=0] [MEMORY] tenant: 1, limit: 12,884,901,888 hold: 8,524,922,880 rpc_hold: 0 cache_hold: 6,773,800,960 cache_used: 6,773,800,960 cache_item_count: 3,230
[MEMORY] ctx_id=           DEFAULT_CTX_ID hold_bytes=    658,505,728
[MEMORY] ctx_id=          MEMSTORE_CTX_ID hold_bytes=    383,778,816
[MEMORY] ctx_id=           EXECUTE_CTX_ID hold_bytes=     16,777,216
[MEMORY] ctx_id=          SQL_EXEC_CTX_ID hold_bytes=     77,594,624
[MEMORY] ctx_id=         TRANS_CTX_MGR_ID hold_bytes=      8,388,608
[MEMORY] ctx_id=     REPLAY_STATUS_CTX_ID hold_bytes=      6,291,456
[MEMORY] ctx_id=        PLAN_CACHE_CTX_ID hold_bytes=    553,648,128
[MEMORY] ctx_id=                WORK_AREA hold_bytes=     27,262,976
[MEMORY] ctx_id=       TX_CALLBACK_CTX_ID hold_bytes=     18,874,368

[2023-06-05 12:09:21.701307] INFO  [LIB] ob_tenant_ctx_allocator.cpp:167 [88518][0][Y0-0000000000000000-0-0] [lt=16] [dc=0]
[MEMORY] tenant_id=    1 ctx_id=           DEFAULT_CTX_ID hold=    658,505,728 used=    553,301,808
[MEMORY] hold=    371,125,248 used=    368,276,480 count=     139 avg_used=      2,649,471 mod=MysqlRequesReco
[MEMORY] hold=     52,416,000 used=     52,403,200 count=      25 avg_used=      2,096,128 mod=OB_KVSTORE_CACHE
[MEMORY] hold=     49,029,760 used=     48,846,080 count=      24 avg_used=      2,035,253 mod=SqlPlanMon
[MEMORY] hold=     35,543,040 used=     35,192,202 count=     534 avg_used=         65,903 mod=SqlDtl
[MEMORY] hold=     14,696,192 used=     12,591,876 count=      14 avg_used=        899,419 mod=LOCALDEVICE
[MEMORY] hold=      8,386,560 used=      8,384,512 count=       4 avg_used=      2,096,128 mod=Election
[MEMORY] hold=      6,298,560 used=      6,281,216 count=     257 avg_used=         24,440 mod=BlockMap
[MEMORY] hold=      6,289,920 used=      6,288,384 count=       3 avg_used=      2,096,128 mod=ElectionGroup
[MEMORY] hold=      2,154,240 used=        408,600 count=  24,952 avg_used=             16 mod=Number

日志解读：

日志信息	说明
tenant	租户 ID
limit	租户的内存上限，单位为字节。
hold	租户从操作系统获取到的所有的内存，单位为字节。
rpc_hold	RPC 线程占用的内存，单位为字节。
cache_hold	KVCache 占用的内存，单位为字节。
cache_hold	KVCache 所使用的内存，单位为字节。
cache_item_count	KVCache 的个数。

租户磁盘统计

搜索关键字： ob_tenant_disk_usage_mgr.cpp 或 dump tenant disk usage update info

日志说明： 租户磁盘使用情况，每 10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "ob_tenant_disk_usage_mgr.cpp" observer.log

或者

[admin@OB /home/admin/oceanbase/log] $grep "dump tenant disk usage update info" observer.log

返回结果如下：

[2023-05-15 17:30:59.055858] INFO  [STORAGE] ob_tenant_disk_usage_mgr.cpp:69 [87424][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] dump tenant disk usage update info(disk_usage={tenant_id:1, max_disk_size:0, used_data_size:935329792, used_meta_size:56623104})

日志解读：

日志信息	说明
tenant_id	租户 ID
max_disk_size	租户的磁盘上限（4.x 版本前租户没有磁盘使用量的限制）
used_data_size	租户内用户数据使用的磁盘空间
used_meta_size	租户内管理数据使用的磁盘空间

租户线程队列统计

搜索关键字： ob_multi_tenant.cpp 或 dump tenant info

日志说明： 租户线程的队列统计情况，每 10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "ob_multi_tenant.cpp" observer.log

或者

[admin@OB /home/admin/oceanbase/log] $grep "dump tenant info" observer.log

返回结果如下：

[2023-05-15 17:31:43.710008] INFO  [SERVER.OMT] ob_multi_tenant.cpp:812 [88299][0][Y0-0000000000000000-0-0] [lt=8] [dc=0] dump tenant info(tenant={id:1001, compat_mode:1, unit_min_cpu:"3.000000000000000000e+00", unit_max_cpu:"3.000000000000000000e+00", slice:"0.000000000000000000e+00", slice_remain:"0.000000000000000000e+00", token_cnt:12,  ass_token_cnt:12, lq_tokens:1, used_lq_tokens:0, stopped:false, idle_us:9509657, recv_hp_rpc_cnt:0, recv_np_rpc_cnt:0, recv_lp_rpc_cnt:0, recv_mysql_cnt:0, recv_task_cnt:0, recv_large_req_cnt:0, tt_large_quries:0, actives:12, workers:12, nesting workers:7, lq waiting workers:0, req_queue:total_size=0 queue[0]=0 queue[1]=0 queue[2]=0 queue[3]=0 queue[4]=0 queue[5]=0 , large queued:0, multi_level_queue:total_size=0 queue[0]=0 queue[1]=0 queue[2]=0 queue[3]=0 queue[4]=0 queue[5]=0 queue[6]=0 queue[7]=0 })

日志解读：

日志信息	说明
compat_mode	租户的兼容模式。
unit_min_cpu	最小 CPU 核数。
unit_max_cpu	最大 CPU 核数。
slice	租户单元的切片大小。
slice_remain	剩余的切片大小。
token_cnt	调度器分配的 token 数，一个 token 会转换为一个工作线程。
ass_token_cnt	租户当前确认的 token 数（根据 token_cnt 确认，一般两者相等）。
lq_tokens	Large Query Token 个数。
used_lq_tokens	当前持有 LQ Token 的 Worker 数。
stopped	租户 Unit 是否正在删除
idle_us	一轮（10s）中工作线程空闲的总时间和，所谓空闲实际只统计了等待队列的时间。
recv_hp_rpc_cnt recv_np_rpc_cnt recv_lp_rpc_cnt	租户累计收到不同级别的 rpc 请求数，hp( High ), np( Normal ), lp( Low )。
recv_mysql_cnt	租户累计收到的 mysql 请求数。
recv_task_cnt	租户累计收到的内部任务数。
recv_large_req_cnt	租户累计预判的大请求数，只会递增，不会清零。实际是重试的时候递增。
tt_large_quries	租户累计处理的大请求数，只会递增，不会清零。实际是打点 check 的时候递增。
actives	处于活跃状态的工作线程数。
workers	租户的 SQL 工作线程数。
nesting workers	租户持有的嵌套请求专用线程数，共 7 个线程对应 7 个嵌套层级。
lq waiting workers	处于等待调度的工作线程。
req_queue	total_size：当前处于等待队列中的请求总数
large queued	当前处于等待队列中的大查询请求数
multi_level_queue	存放嵌套请求的工作队列，1～7 对应 7 个嵌套层级（ queue [ 0 ] 暂时不用）。字段表示各层级排队请求数。

RPC 线程统计

搜索关键字： ob_net_easy.cpp 或 [RPC EASY STAT]

日志说明： RPC 线程的使用情况，每 1s 打印一次，每条日志为每一个 RPC 线程的统计。

[admin@OB /home/admin/oceanbase/log] $grep "ob_net_easy.cpp" observer.log

或者

[admin@OB /home/admin/oceanbase/log] $grep "RPC EASY STAT" observer.log

返回结果如下：

[2023-05-15 18:28:17.681483] INFO  [RPC.FRAME] ob_net_easy.cpp:601 [88307][0][Y0-0000000000000000-0-0] [lt=18] [dc=0] [RPC EASY STAT](log_str="conn count=3/4, request done=7404635/5179373, request doing=0/0")
[2023-05-15 18:28:17.682056] INFO  [RPC.FRAME] ob_net_easy.cpp:601 [88310][0][Y0-0000000000000000-0-0] [lt=8] [dc=0] [RPC EASY STAT](log_str="conn count=3/3, request done=7402021/5162953, request doing=0/0")
[2023-05-15 18:28:17.682108] INFO  [RPC.FRAME] ob_net_easy.cpp:601 [88309][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] [RPC EASY STAT](log_str="conn count=3/3, request done=7405199/5164208, request doing=0/0")
[2023-05-15 18:28:17.682108] INFO  [RPC.FRAME] ob_net_easy.cpp:601 [88308][0][Y0-0000000000000000-0-0] [lt=9] [dc=0] [RPC EASY STAT](log_str="conn count=3/3, request done=7402609/5163322, request doing=0/0")

日志解读：

日志信息	说明
conn count	该 RPC 线程服务的 connection 数量（in/out）
request done	该 RPC 线程完成的 request 数量（in/out）
request doing	该 RPC 线程正在处理的 request 数量（in/out）

如果没有 RPC 线程即 request doing=0/0，说明 RPC 线程全部处于繁忙状态。

事务上下文统计

搜索关键字： ObTransCtx statistics

**日志说明：**事务上下文的分配数量统计，每 5s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "ObTransCtx statistics" observer.log

返回结果如下：

[2023-05-15 17:29:07.955826] INFO  [STORAGE.TRANS] ob_trans_factory.cpp:175 [88157][0][YB420BA6506F-0005FB92633E1702-0-0] [lt=11] [dc=0] ObTransCtx statistics(active_sche_ctx_count=0, active_coord_ctx_count=0, active_part_ctx_count=1, total_release_part_ctx_count=156)

日志解读：

日志信息	说明
active_sche_ctx_count	Scheduler 角色的活跃事务上下文数量
active_coord_ctx_count	Coordinator 角色的活跃事务上下文数量
active_part_ctx_count	Participant 角色的活跃事务上下文数量
total_release_part_ctx_count	已释放的事务上下文数量

每一台 OBServer 上允许的最大的 scheduler ctx 数量为 10 万，participant ctx 数量为 70 万。

磁盘 IO 统计

搜索关键字： Current io stat（2.x 版本）或 current io status（3.x 版本）

日志说明： IO 统计，每 10s 打印一次。

2.x 版本日志解读

[admin@OB /home/admin/oceanbase/log] $grep "Current io stat" observer.log

返回结果如下：

[2022-12-27 17:28:19.298670] INFO [COMMON] ob_io_disk.cpp:497 [47844][406][Y0-0000000000000000] [lt=59] [dc=0] Current io stat, (fd={fd:875, disk_id:{disk_idx:0, install_seq:0}}, io_conf={sys_io_low_percent:90, sys_io_high_percent:90, user_iort_up_percent:2000, cpu_high_water_level:7680, write_failure_detect_interval:60000000, read_failure_black_list_interval:300000000, data_storage_warning_tolerance_time:10000000, data_storage_error_tolerance_time:300000000, disk_io_thread_count:8, callback_thread_count:8, large_query_io_percent:0, data_storage_io_timeout_ms:10000}, sys_io_percent=90, sys_iops_up_limit=266, user_max_rt=1.151363996887207031e+04, cpu_estimator={avg_usage:378}, user_read_io_stat={average_size:18245, average_rt_us:"4.766969696969696884e+02", old_stat:{io_cnt:5435154700, io_bytes:92266120699904, io_rt_us:2896942021380}, new_stat:{io_cnt:5435154733, io_bytes:92266121302016, io_rt_us:2896942037111}}, user_write_io_stat={average_size:0, average_rt_us:"0.000000000000000000e+00", old_stat:{io_cnt:790, io_bytes:1568509952, io_rt_us:1369408}, new_stat:{io_cnt:790, io_bytes:1568509952, io_rt_us:1369408}}, sys_read_io_stat={average_size:0, average_rt_us:"0.000000000000000000e+00", old_stat:{io_cnt:29673855, io_bytes:62197411557376, io_rt_us:62528978207}, new_stat:{io_cnt:29673855, io_bytes:62197411557376, io_rt_us:62528978207}}, sys_write_io_stat={average_size:0, average_rt_us:"0.000000000000000000e+00", old_stat:{io_cnt:24420687, io_bytes:51213892583424, io_rt_us:56376648298}, new_stat:{io_cnt:24420687, io_bytes:51213892583424, io_rt_us:56376648298}}, large_query_read_io_stat={average_size:0, average_rt_us:"0.000000000000000000e+00", old_stat:{io_cnt:0, io_bytes:0, io_rt_us:0}, new_stat:{io_cnt:0, io_bytes:0, io_rt_us:0}}, large_query_write_io_stat={average_size:0, average_rt_us:"0.000000000000000000e+00", old_stat:{io_cnt:0, io_bytes:0, io_rt_us:0}, new_stat:{io_cnt:0, io_bytes:0, io_rt_us:0}})

日志解读：

日志信息	说明
fd 和 disk_id	这部分包含了文件描述符的编号 `fd` 和磁盘的索引号 `disk_idx` 以及安装序列号 `install_seq`。
io_config	这部分包含了系统的 I/O 配置参数，如系统 I/O 的低和高百分比 `sys_io_low_percent` 和 `sys_io_high_percent`，用户 I/O 的上限 `user_iort_up_percent`，CPU 的高水位线 `cpu_high_water_level`，磁盘 I/O 线程数 `disk_io_thread_count`，回调线程数 `callback_thread_count`，大查询 I/O 百分比 `large_query_io_percent`，数据存储 I/O 超时毫秒数 `data_storage_io_timeout_ms` 等。
sys_io_percent	系统 I/O 的使用百分比上限
sys_iops_up_limit	系统 2M 大小的 IOPS 上限，应与 IO bench 测试结果 `io_resource.conf` 一致
user_max_rt	用户 IO 的最大响应时间
cpu_estimator(avg_usage)	用户 IO 的平均 CPU 使用率
user_read_io_stat user_write_io_stat sys_read_io_stat sys_write_io_stat large_query_read_io_stat large_query_write_io_stat	这些部分包含了不同类型的 I/O 的统计信息，包括平均大小 `average_size`，平均响应时间 `average_rt_us`，以及旧的和新的统计数据（包括 I/O 操作数 `io_cnt`，I/O 字节数 `io_bytes` 和 I/O 响应时间 `io_rt_us`）。
io_ability	这部分包含了系统的 I/O 性能测量结果，包括不同模式（读/写）和不同大小的 I/O 操作的 IOPS（输入/输出操作每秒）和响应时间 `rt_us`。
log_io user_io sys_io prewarm_io large_query_io	这些部分包含了不同类型的 I/O 的状态和设备能力，包括是否初始化 `is_inited_`，设备能力 `device_ability_`，共享百分比 `share_percentage_` 和最后截止时间戳 `last_deadline_ts_`。
log_read log_write user_read user_write sys_read sys_write prewarm_read prewarm_write large_query_read large_query_write	这部分包含了不同类型的 I/O 操作的统计信息，包括开始的 IOPS `start_iops` ，取消的 IOPS `cancel_iops` ，失败的 IOPS `fail_iops` ，成功的 IOPS `succ_iops` ，平均字节 `avg_byte` ，设备响应时间 `device_rt_us` 和队列响应时间 `queue_rt_us`。
avg_cpu	这部分显示了系统的平均 CPU 使用率

OceanBase 数据库的 I/O 速度限制由 sys_bkgd_io_low_percentage 与 sys_bkgd_io_high_percentage 控制，分别表示 sys_io_percent 的下限与上限。

在以上 io stat 信息中，可以通过以下方法来判断是否发生了 IO 限流：

如果 sys_io_high_percent 、sys_io_low_percent 与配置项 sys_bkgd_io_high_percentage、sys_bkgd_io_low_percentage 不一致，则说明存在 I/O 限流。
如果 user_read_io_stat 的 average_size =0，则说明 IO 出现限流。

3.x 版本日志解读

[admin@OB /home/admin/oceanbase/log] $grep "current io status" observer.log

返回结果如下：

[2023-06-21 16:54:14.212314] INFO [COMMON] ob_io_struct.cpp:2129 [89617][0][Y0-0000000000000000-0-0] [lt=19] [dc=0] current io status(io_config={sys_io_low_percent_:70, sys_io_high_percent_:90, user_iort_up_percent_:100, cpu_high_water_level_:2560, write_failure_detect_interval_:60000000, read_failure_black_list_interval_:300000000, data_storage_warning_tolerance_time_:30000000, data_storage_error_tolerance_time_:300000000, disk_io_thread_count_:8, callback_thread_count_:8, large_query_io_percent_:0, data_storage_io_timeout_ms_:120000, io_memory_limit_:2147483648, enable_io_tracer_:false}, io_ability={measure_items:[[{mode:0, size:4096, iops:120191.00, rt_us:180.58}, {mode:0, size:8192, iops:155470.00, rt_us:198.67}, {mode:0, size:16384, iops:122040.00, rt_us:259.74}, {mode:0, size:32768, iops:76429.00, rt_us:416.30}, {mode:0, size:65536, iops:41826.00, rt_us:762.89}, {mode:0, size:131072, iops:21994.00, rt_us:1452.21}, {mode:0, size:262144, iops:11247.00, rt_us:2841.93}, {mode:0, size:524288, iops:5649.00, rt_us:5658.40}, {mode:0, size:1048576, iops:2828.00, rt_us:11302.68}], [{mode:1, size:4096, iops:127929.00, rt_us:247.71}, {mode:1, size:8192, iops:120343.00, rt_us:263.40}, {mode:1, size:16384, iops:115208.00, rt_us:275.45}, {mode:1, size:32768, iops:76882.00, rt_us:414.05}, {mode:1, size:65536, iops:39596.00, rt_us:805.95}, {mode:1, size:131072, iops:20989.00, rt_us:1522.00}, {mode:1, size:262144, iops:10634.00, rt_us:3004.64}, {mode:1, size:524288, iops:5355.00, rt_us:5970.53}, {mode:1, size:1048576, iops:2692.00, rt_us:11877.67}, {mode:1, size:2097152, iops:1309.00, rt_us:24402.57}]]}, log_io={is_inited_:true, device_ability_:null, share_percentage_:100, last_deadline_ts_:0}, user_io={is_inited_:true, device_ability_:null, share_percentage_:100, last_deadline_ts_:0}, sys_io={is_inited_:true, device_ability_:0x32bb7ba8, share_percentage_:90, last_deadline_ts_:1687334746495760}, prewarm_io={is_inited_:true, device_ability_:0x32bb7ba8, share_percentage_:100, last_deadline_ts_:0}, large_query_io={is_inited_:true, device_ability_:0x32bb7ba8, share_percentage_:100, last_deadline_ts_:0}, log_read={}, log_write={start_iops:29.93, cancel_iops:0.00, fail_iops:0.00, succ_iops:29.93, avg_byte:5461.33, device_rt_us:140.00, queue_rt_us:7.33}, user_read={}, user_write={}, sys_read={}, sys_write={}, prewarm_read={}, prewarm_write={}, large_query_read={}, large_query_write={}, avg_cpu=2.126034912718204453e+02)

日志解读：

日志信息	说明
io_config	这部分包含了系统的 I/O 配置参数，如系统 I/O 的低和高百分比 `sys_io_low_percent_` 和 `sys_io_high_percent_` ，用户 I/O 的上限 `user_iort_up_percent_` ，CPU 的高水位线 `cpu_high_water_level_` ，磁盘 I/O 线程数 `disk_io_thread_count_` ，回调线程数 `callback_thread_count_` ，大查询 I/O 百分比 `large_query_io_percent_` ，数据存储 I/O 超时毫秒数 `data_storage_io_timeout_ms_` ，I/O 内存限制 `io_memory_limit_` 等。
io_ability	这部分包含了系统的 I/O 性能测量结果，包括不同模式（读/写）和不同大小的 I/O 操作的 IOPS（输入/输出操作每秒）和响应时间 `rt_us` 。
log_io user_io sys_io prewarm_io large_query_io	这些部分包含了不同类型的 I/O 的状态和设备能力，包括是否初始化 `is_inited_` ，设备能力 `device_ability_` ，共享百分比 `share_percentage_` 和最后截止时间戳 `last_deadline_ts_` 。
log_read log_write user_read user_write sys_read sys_write prewarm_read prewarm_write large_query_read large_query_write	这部分包含了不同类型的 I/O 操作的统计信息，包括开始的 IOPS `start_iops` ，取消的 IOPS `cancel_iops` ，失败的 IOPS `fail_iops` ，成功的 IOPS `succ_iops` ，平均字节 `avg_byte` ，设备响应时间 `device_rt_us` 和队列响应时间 `queue_rt_us` 。
avg_cpu	这部分显示了系统的平均 CPU 使用率

在以上 io stat 信息中，可以通过以下方法来判断是否发生了 IO 限流：

如果 sys_io_high_percent 、sys_io_low_percent 与配置项 sys_bkgd_io_high_percentage、sys_bkgd_io_low_percentage 不一致，则说明存在 I/O 限流。
如果 last_deadline_ts_ 比日志打印时间大，表示 IO 被限流了。

归档线程统计

搜索关键字： print_archive_status

日志说明： 日志归档状态统计，每 10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "print_archive_status" observer.log

返回结果如下：

[2023-08-24 13:59:53.565584] INFO  [ARCHIVE] ob_archive_mgr.cpp:830 [11357][0][Y0-0000000000000000-0-0] [lt=13] [dc=0] print_archive_status(clog_split_task_num=0, send_task_num=2, pre_send_task_capacity=458752, pg_archive_task_count=903, archive_incarnation=1, archive_round=6, piece_id=0, piece_create_date=20230810, log_archive_status=2, has_encount_error=false)

日志解读：

日志信息	说明
clog_split_task_num	正在执行的 clog split 的任务数量
send_task_num	正在执行的 clog send 的任务数量
pre_send_task_capacity	待归档数据量
pg_archive_task_count	与分区组（pg）的相关的归档任务数量
log_archive_status	归档状态， 0：无效状态 1：开始归档状态 2：正在进行归档状态 3：正在停止归档状态 4：已经停止归档状态

搜索关键字： archive_clog_split_engine statistics

日志说明： clog split 线程的统计，每 10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "archive_clog_split_engine statistics" observer.log

返回结果如下：

[2023-08-24 14:46:13.179165] INFO  [ARCHIVE] ob_archive_clog_split_engine.cpp:1120 [11389][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] archive_clog_split_engine statistics(avg_split_task_used=51, avg_read_log_used=40, avg_read_log_size=3058, avg_get_send_task_used=11, avg_send_task_per_task=1, split_task_count=17)

日志解读：

日志信息	说明
avg_split_task_used	每个 clog split 任务的耗时（微秒）
avg_read_log_used	每次读取日志的耗时（微秒）
avg_read_log_size	每次读取日志的大小
avg_get_send_task_used	每次获取 clog send 任务的耗时（微秒）
avg_send_task_per_task	每个 clog split 任务对应的 clog send 任务数
split_task_count	clog split 任务个数

搜索关键字： archive_sender statistic

日志说明： 单个 clog send 线程的统计，每10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "archive_sender statistic" observer.log

返回结果如下：

[2023-06-12 16:15:50.311863] INFO [ARCHIVE] ob_archive_sender.cpp:1589 [25879][0][Y0-0000000000000000-0-0] [lt=5] [dc=0] archive_sender statistic in 10s(total_send_buf_size=29384, total_send_log_count=157, avg_log_size=187, total_send_task_count=2, total_send_cost_ts=2809, avg_send_task_cost_ts=1404)

日志解读：

日志信息	说明
total_send_buf_size	该归档线程在 10s 内发送的日志大小。如果开启日志传输压缩，发送量一般为未压缩的原始日志量的 1/3。
total_send_log_count	该归档线程在 10s 内发送的日志记录数量。
total_send_task_count	该归档线程在 10s 内总的网络 IO 数量。
total_send_cost_ts	该归档线程在 10s 内总的耗时（微秒）。如果接近或者超过 10s，说明 IO 已经跑满了。
avg_send_task_cost_ts	平均一个网络 IO 的耗时（微秒），通常在几毫米到几十毫秒之间。

DAG 线程统计

搜索关键字： dump_dag_status

日志说明： DAG 线程的统计信息，每 10s 打印一次。

[admin@OB /home/admin/oceanbase/log] $grep "dump_dag_status" observer.log

返回结果如下：

[2023-09-04 17:15:25.494000] INFO  [COMMON] ob_dag_scheduler.cpp:1314 [9777][0][Y0-0000000000000000-0-0] [lt=5] [dc=0] dump_dag_status(priority="DAG_PRIO_SSTABLE_MINI_MERGE", low_limit=4, running_task=0)

[2023-09-04 17:15:25.494065] INFO  [COMMON] ob_dag_scheduler.cpp:1318 [9777][0][Y0-0000000000000000-0-0] [lt=3] [dc=0] dump_dag_status(up_limit_type="DAG_ULT_MINI_MERGE", up_limit=8, running_task_per_ult=0)

[2023-09-04 17:15:25.494121] INFO  [COMMON] ob_dag_scheduler.cpp:1322 [9777][0][Y0-0000000000000000-0-0] [lt=4] [dc=0] dump_dag_status(type="DAG_MINOR_MERGE", dag_count=0)

[2023-09-04 17:15:25.494125] INFO  [COMMON] ob_dag_scheduler.cpp:1322 [9777][0][Y0-0000000000000000-0-0] [lt=3] [dc=0] dump_dag_status(type="DAG_MAJOR_MERGE", dag_count=0)

[2023-09-04 17:15:25.494210] INFO  [COMMON] ob_dag_scheduler.cpp:1324 [9777][0][Y0-0000000000000000-0-0] [lt=3] [dc=0] dump_dag_status(total_worker_cnt=52, total_running_task_cnt=0, work_thread_num=113)

日志解读：

日志信息	说明
priority	后台任务的优先级，OceanBase 会优先调度优先级高的任务。
low_limit	后台任务的线程数下限。
up_limit	后台任务的线程数上限。
type	后台任务类型。
dag_count	进入后台任务队列的请求总数。
total_worker_cnt	各类后台任务的活跃线程总数。
total_running_task_cnt	正在执行的各类后台任务个数。
work_thread_num	各类后台任务的线程总数上限。

内存分配失败

搜索关键字： [OOPS]、alloc failed、-4013、 -4030

日志说明： 内存分配失败。

[admin@OB /home/admin/oceanbase/log] $grep "OOPS|alloc failed|-4013|-4030" observer.log

返回结果如下：

[2019-11-29 13:32:19.702557] WARN  alloc_chunk (achunk_mgr.cpp:156) [116413][1492][XXXXXXXXXXXX-XXXXXXXXXXXXXXXX] [lt=10] [dc=0] oops, over total memory limit, hold=241078108160 limit=243230035968

[2019-11-29 13:32:19.703452] WARN  alloc (ob_tenant_ctx_allocator.h:111) [116413][1492][XXXXXXXXXXXX-XXXXXXXXXXXXXXXX] [lt=15] [dc=0] oops, alloc failed, tenant_id=500 ctx_id=0 ctx_name=DEFAULT_CTX_ID ctx_hold=13245612032 ctx_limit=9223372036854775807 tenant_hold=26003955712 tenant_limit=9223372036854775807

[2019-11-29 13:32:19.710755] ERROR [LIB] ob_malloc (ob_malloc.h:49) [116413][1492][XXXXXXXXXXXX-XXXXXXXXXXXXXXXX] [lt=364] [dc=0] allocate memory fail(attr=tenant_id=500, mod_id=253, ctx_id=0, prio=0, nbyte=2097152)

日志解读：

日志信息	说明
ctx_name	内存超限的内存模块（context）
ctx_hold	内存模块当前占有的内存量
ctx_limit	内存模块的内存上限
alloc_size	当前内存分配请求的内存大小

MemStore 限流

搜索关键字： report write throttle info

日志说明： 触发 Memstore 写入限流的统计日志。

[admin@OB /home/admin/oceanbase/log] $grep "report write throttle info" observer.log

返回结果如下：

2022-12-29 04:46:44.841893] INFO  [COMMON] ob_fifo_arena.cpp:333 [28948][0][XXXXXXXXXXXX-XXXXXXXXXXXXXXXXXX-X-X] [lt=16] [dc=0] report write throttle info(alloc_size=24, throttling_interval=1000, attr_=tenant_id=1005, label=15, ctx_id=1, prio=0, freed memory(MB):=0, last_base_ts=1672260404842042, cur_mem_hold=11970543616, trigger_mem_limit=21990232512, trigger_mem_remain=5497558128, tenant_memory_remain=5448400896, throttle_info_={decay_factor_:"3.002618459977128736e-04", alloc_duration_:3600000000, trigger_percentage_:80, memstore_threshold_:27487790640, period_throttled_count_:45, period_throttled_time_:315460, total_throttled_count_:181984128, total_throttled_time_:72058595126473244}, mem_overused=49157232)

日志解读：

日志信息	说明
cur_mem_hold	当前 Memstore 的空间使用量
trigger_mem_limit	触发限流的 Memstore 的空间使用阀值
trigger_mem_remain	触发限流时 Memstore 的剩余空间
tenant_memory_remain	当前 Memstore 的剩余空间
mem_overused	当前 Memstore 超过限流阀值的空间使用量

锁冲突

搜索关键字

写写冲突：on_wlock_retry、lock_for_write conflict
读写冲突：lock_for_read retry、lock_for_read fail

日志说明： 发生行锁冲突及 retry 的日志记录。

[2022-09-03 11:33:06.624063] WARN  [STORAGE.TRANS] on_wlock_retry
(ob_memtable_context.cpp:345) [4198][0][XXXXXXXXXXXX-XXXXXXXXXXXXXXXXXX-X-X] [lt=16] [dc=0] lock_for_write conflict(*this=alloc_type=0 ctx_descriptor=45479 … abs_expired_time=1662179586523672 stmt_timeout=3599900482 … pkey={tid:1100611139453777, partition_id:0, part_cnt:0} trans_id={hash:16499054864673064020, inc:284227, addr:“xxx.xxx.xxx.xxx:2882”, t:1662175982313772} checksum_log_ts=0, key=table_id=1100611139453777 rowkey_object=[{“NUMBER”:“1”}] , conflict_ctx=“alloc_type=0 ctx_descriptor=45354 … stmt_start_time=1662175972255438 abs_expired_time=1662179572155922 stmt_timeout=3599900484 … pkey={tid:1100611139453777, partition_id:0, part_cnt:0} trans_id={hash:15878544715862172232, inc:283677, addr:"xxx.xxx.xxx.xxx:2882", t:1662175972255438} checksum_log_ts=0")

日志解读：

日志信息	说明
*this	waiter（等锁的事务）
conflict_ctx	blocker（阻挡者，可能是 holder）
pkey	table_id+partition_id 的信息
rowkey_object	主键
trans_id	事务的相关信息

慢查询

搜索关键字： [slow query]

日志说明： 慢查询日志包含了 SQLTrace 的详细信息。

[admin@OB /home/admin/oceanbase/log] $grep "slow query" observer.log

返回结果如下：

[2022-02-18 11:49:32.557473] TRACE [TRACE]obmp_base.cpp:948 [1837144][3090][XXXXXXXXXX-XXXXXXXXXXXXXX] [lt=2] [dc=0] [slow query]
(TRACE=begin_ts=1645156047499895 2022-02-18 03:47:27.499895
|[process_begin] u=0 in_queue_time:16, receive_ts:1645156047499878, enqueue_ts:1645156047499879
|[query_begin] u=1 trace_id:XXXXXXXXXX-XXXXXXXXXXXXXX
|[session] u=4 sid:3221502589, tenant_id:1|
......
|[parse_begin] u=17 stmt:"select count(*) from TEST1 fetch first 1000 rows only", stmt_len:58
|[cache_get_plan_begin] u=3 |[cache_get_plan_end] u=18
......
|[cg_begin] u=1 |[cg_end] u=137
|[plan_id] u=96 plan_id:91455
|[exec_begin] u=2 arg1:false, end_trans_cb:false
|[do_open_plan_begin] u=2 plan_id:91455
......
|[result_set_close] u=0 ret:-5066, arg1:-5066, arg2:0, arg3:-5066, async:false
|[session] u=34 sid:3226669564, tenant_id:1034
|[exec_end] u=21
|[query_end] u=125
|[process_end] u=38 run_ts:1645156047499900
|total_timeu=125057508)

日志解读：

日志信息	说明
[eventbegin]与[eventend]	表式 SQL 执行过程中内部事件的开始（begin）与结束（end）
u=xxx	两个 trace 事件之间的间隔时长
in_queue_time	SQL 开始执行前在队列中等待的时间
trace_id	SQL 执行的 trace_id
sid	SQL 执行所在的 session_id
stmt	SQLstatement
plan_id	SQL 执行的 plan_id
ret	返回码（错误码）
total_timeu	SQL 处理的总耗时

慢事务

搜索关键字： [slow trans]

日志说明： 记录了事务执行期间的调用链及耗时。

[admin@OB /home/admin/oceanbase/log] $grep "slow trans" observer.log

返回结果如下：

observer.log:[2021-10-08 11:45:44.313295] TRACE [TRACE]:0 [9382][2334][XXXXXXXXXX-XXXXXXXXXXXXXXXXX] [lt=23] [dc=39] [slow trans] (TRACE=begin_ts=1633664744167732 2021-10-08 03:45:44.167732 [init] u=0 arg1:140542173395392, ctx_type:"scheduler", trans_type:2, trans_id:{hash:7103234888693285108, inc:532846, addr:{ip:"192.168.1.1", port:40000}, t:1633664744167658}, pkey:{tid:1000, partition_id:1000, part_cnt:1000}, arg1:false, uref:1073741824 [set_stc] u=1 stc:1633664744167733 [start_trans] u=2 ret:0, uref:1073741825 [start_stmt] u=7 ret:0, tenant_id:1003, sql_no:4294967297, phy_plan_type:3, stmt_type:2, sql_id:"AA2155E24549E97", trace_id:Y9C4064586A6B-0005CDCF253FBE70, start_time:1633664744166256, uref:1073741825 [end_stmt] u=30832 ret:0, is_rollback:false, rollback_to:4294967297, rollback_from:4294967297, uref:1073741825 [start_stmt] u=50000 ret:0, tenant_id:1003, sql_no:4294967298, phy_plan_type:3, stmt_type:2, sql_id:"AA2155E24549E97", trace_id:Y9C4064586A6B-0005CDCF253FBE70, start_time:1633664744166256, uref:1073741825 [end_stmt] u=10 ret:0, is_rollback:false, rollback_to:4294967298, rollback_from:4294967298, uref:1073741825 [submit_commit] u=52 ret:0, uref:1073741824 [end_trans] u=35 ret:0, is_rollback:false, uref:1073741825 [exiting] u=114618 uref:1073741824, arg1:3221531139, arg2:7230647234361492284 [handle_message] u=1 ret:0, msg_type:1, uref:1 [end_trans_cb] u=13 ret:0, param:0, param:true [destroy] u=1 uref:0 total_timeu=195572)

日志解读：

日志信息	说明
ctx_type	事务上下文的类型：scheduler 、coordinator 、participant
trans_type	事务类型： 0：SP_TRANS(single partition) 1：MINI_SP_TRANS(read-only single partition) 2：DIST_TRANS(distributed)
trans_id	事务的 ID 信息
pkey	当前事务上下文修改的 object 信息（table_id+partition_id）
[start_trans] /[end_trans]	开启/结束该事务上下文
[start_stmt] /[end_stmt]	开始/结束执行 SQL，包含 SQL 的 sql_id，trace_id 等信息
u=xxx	两个 trace 事件之间的间隔时长
total_timeu	事务处理的总耗时

网络传输慢

搜索关键字： packet fly cost too much time

日志说明： RPC 线程发送 packet 耗时太久。

[admin@OB /home/admin/oceanbase/log] $grep "packet fly cost too much time" observer.log

返回结果如下：

[2022-10-27 23:09:58.317505] WARN  [RPC.OBRPC] decode (ob_rpc_net_handler.cpp:119) [31273] [Y00000000000000000] [lt=8] packet fly cost too much time(pcode=2311, fly_ts=769195, send_timestamp=1666883397548305)

日志解读：

日志信息	说明
pcode	处理事件代码，具体含义可以从 `__all_virtual_obrpc_stat` 查询
fly_ts	从源端发送和编码 packet，到目标端接收和解码 packet 的耗时
send_timestamp	远端发送 packet 的时间戳

说明

RPC 传输慢很可能与网络延迟、时钟偏差以及系统负载和 RPC 线程的繁忙有关。

网络限速

搜索关键字： network speed changed、reload_bandwidth_throttle_limit、init_bandwidth_throttle

日志说明： OBServer 设定系统任务的网络限速

[admin@OB /home/admin/oceanbase/log] $grep "network speed changed|reload_bandwidth_throttle_limit|init_bandwidth_throttle" observer.log

返回结果如下：

[2021-06-10 11:10:49.397019] INFO  [SERVER] ob_server.cpp:2018 [72580][0][Y0-0000000000000000-0-0] [lt=8] [dc=0] succeed to init_bandwidth_throttle(sys_bkgd_net_percentage_=60, network_speed=1310720000, rate=786432000):

[2021-06-10 11:14:44.905396] INFO  [SERVER] ob_server.cpp:2385 [72582][0][Y0-0000000000000000-0-0] [lt=11] [dc=0] network speed changed(from=1310720000, to=1048576000)

[2021-06-10 11:14:44.905421] INFO  [SERVER] ob_server.cpp:2055 [72582][0][Y0-0000000000000000-0-0] [lt=3] [dc=0] succeed to reload_bandwidth_throttle_limit(old_percentage=60, new_percentage=60, network_speed=1048576000, rate=629145600)

日志解读：

日志信息	说明
sys_bkgd_net_percentage_	系统配置项 sys_bkgd_net_percentage 的值，是后台线程的网络带宽占比，默认是网卡带宽的60%
network_speed	网卡带宽，根据相关配置文件来设置
rate	后台线程的网络带宽，rate= network_speed * sys_bkgd_net_percentage

日志写盘失败

搜索关键字： submit_log failed

日志说明： 日志写盘失败。

[admin@OB /home/admin/oceanbase/log] $grep "submit_log failed" observer.log

返回结果如下：

[2023-02-14 16:51:10.255801] ERROR [CLOG] submit_log (ob_partition_log_service.cpp:468) [893][0][Y0-0000000000000000-0-0] [lt=19] submit_log failed(ret=-4264, partition_key={tid:1099511627916, partition_id:0, part_cnt:0}, buff=0xfff80a4aef70, size=805, base_timestamp=1676065578191066, is_trans_related_log=true, role=1, state=4)

日志解读：

日志信息	说明
ret	错误码
partition_key	相关的object（table_id+partition_id）

需要 DBA 关注的错误

搜索关键字： ERROR issue_dba_error

日志说明： 系统发生需要 DBA 关注并解决的错误。

[admin@OB /home/admin/oceanbase/log] $grep "ERROR issue_dba_error" observer.log

返回结果如下：

2023-05-11 16:05:27.966611] ERROR issue_dba_error (ob_log.cpp:2322) [79165][0][Y0-0000000000000000-0-0] [lt=18] [dc=0][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=0, file="ob_log_file_group.cpp", line_no=412, info="clog disk is almost full")

[2023-05-11 16:45:58.135783] ERROR issue_dba_error (ob_log.cpp:2322) [77332][0][Y0-0000000000000000-0-0] [lt=8] [dc=0][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4264, file="ob_partition_log_service.cpp", line_no=468, info="submit_log failed")

[2023-05-11 16:45:59.448092] ERROR issue_dba_error (ob_log.cpp:2322) [77584][0][Y0-0000000000000000-0-0] [lt=10] [dc=0][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=0, file="ob_election.cpp", line_no=2077, info="leader_revoke, please attention!")

日志解读：

日志信息	说明
internal errcode	错误码
file	检测到错误的 sourcecode
info	错误信息

rootservice.log 日志

日志关键字	说明
Rebalance task manager	负载均衡任务统计信息
[DDL] execute ddl like stmt	DDL 执行
choose leader info	分区切主
partition can't replicate	分区副本无法复制
check merge progress success	合并进度
replica not merged	分区合并失败

统计日志

常见诊断日志

负载均衡任务统计

搜索关键字： Rebalance task manager statistics

日志说明： 负载均衡任务的统计信息。

[admin@OB /home/admin/oceanbase/log] $grep "Rebalance task manager statistics" observer.log

返回结果如下：

[2023-05-10 05:22:50.862554] INFO  [RS] ob_rebalance_task_mgr.cpp:1887 [65048][0][XXXXXXXXXX-XXXXXXXXXXXXXX-X-X] [lt=14] [dc=0] Rebalance task manager statistics(waiting_replication_task_cnt=0, executing_replication_task_cnt=0, waiting_migration_task_cnt=0, executing_migration_task_cnt=0)

日志解读：

日志信息	说明
waiting_replication_task_cnt	等待中的复制任务数
executing_replication_task_cnt	执行中的复制任务数
waiting_migration_task_cnt	等待中的迁移任务数
executing_migration_task_cnt	执行中的复制任务数

合并进度

搜索关键字： check merge progress success 或 succ to finish zone merge

日志说明： 合并进度相关的日志。

[admin@OB /home/admin/oceanbase/log] $grep "check merge progress success" observer.log

或者

[admin@OB /home/admin/oceanbase/log] $grep "succ to finish zone merge" observer.log

返回结果如下：

[2021-04-07 10:37:16.451302] INFO  [RS] ob_daily_merge_scheduler.cpp:1840 [4532][XXXXXXXXXX-XXXXXXXXXXXXXX] [lt=34] succeed to add_finish_zone_merge_op(zone=bank.ea133_8, last_merged_version=10044, all_merged_version=10044)
[2021-04-07 10:37:18.114716] INFO  [RS] ob_daily_merge_scheduler.cpp:1986 [4532][XXXXXXXXXX-XXXXXXXXXXXXXX] [lt=14] succ to finish zone merge(zone=bank.ea133_8, last_merged_version=10044, all_merged_version=10044)

或

[2023-05-16 20:04:48.270903] INFO  [RS] ob_partition_table_util.cpp:317 [87321][0][XXXXXXXXXX-XXXXXXXXXXXXXX] [lt=10] [dc=0] check merge progress success(version=38, all_majority_merged=false, all_progress=[{zone:"zone1", unmerged_partition_cnt:2301, unmerged_data_size:126884638603, merged_partition_cnt:0, merged_data_size:0, smallest_data_version:37, merged_partition_percentage:0, merged_data_percentage:0}, {zone:"zone2", unmerged_partition_cnt:0, unmerged_data_size:0, merged_partition_cnt:2301, merged_data_size:126884950766, smallest_data_version:38, merged_partition_percentage:100, merged_data_percentage:100}, {zone:"zone3", unmerged_partition_cnt:2301, unmerged_data_size:126884638603, merged_partition_cnt:0, merged_data_size:0, smallest_data_version:37, merged_partition_percentage:0, merged_data_percentage:0}], checking_time_us=202635)

日志解读：

日志信息	说明
version	当前合并的大版本号
all_majority_merged	全部 zone 都已经完成合并：true/false
all_progress	每个 zone 的合并进度

DDL 执行

搜索关键字： [DDL] execute ddl like stmt

日志说明： DDL 执行。

[admin@OB /home/admin/oceanbase/log] $grep "[DDL] execute ddl like stmt" observer.log

返回结果如下：

[2023-05-16 10:50:10.834911] INFO  [RS] ob_rs_rpc_processor.h:249 [87188][0][XXXXXXXXXX-XXXXXXXXXXXXXX] [lt=17] [dc=0] [DDL] execute ddl like stmt(ret=0, cost=44039, ddl_arg={ddl_stmt_str:“CREATE INDEX ”IND_PA_ACCTSENIOR“ on ”T_PA_ACCTSENIOR“ ( ”FSENIOR_CODE“ ) GLOBAL", exec_tenant_id:1005, ddl_id_str:"", is_replay_schema:false, based_schema_object_infos:[{schema_id:1105009185964905, schema_type:5, schema_version:1684205410682568}]})

日志解读：

日志信息	说明
ret	DDL 语句的返回码
cost	执行耗时
ddl_arg	DDL statement
schema_type	创建的对象类型

切主

搜索关键字： choose leader info

日志说明： 分区发生切主的日志信息。

[admin@OB /home/admin/oceanbase/log] $grep "choose leader info" observer.log

返回结果如下：

[2023-05-10 17:41:28.833956] INFO  [RS] ob_leader_coordinator.cpp:5004 [65037][0][XXXXXXXXXX-XXXXXXXXXXXXXX-X-X] [lt=27] [dc=0] choose leader info(tenant_id=1005, tablegroup_id=18446744073709551615, server="192.168.1.1:2882", info={server_addr:"192.168.1.1:2882", zone:"zone2", balance_group_score:9223372036854775807, region_score:{region_:"beijing", region_score_:0}, not_merging:true, start_service:true, zone_candidate_count:1, candidate_count:1, is_candidate:true, not_excluded:true, migrate_out_or_transform_count:0, zone_migrate_out_or_transform_count:0, in_normal_unit_count:1, zone_score:{zone_:"zone2", zone_score_:0}, original_leader_count:0, random_score:3, cur_leader_count:1, in_revoke_blacklist_count:0, partition_id:0}, is_stopped=false, is_zone_active=true)

日志解读：

日志信息	说明
tablegroup_id	发生切主的分区或者表组的 ID
server	新主所在的 observer 位置
is_stopped	新主所在的 observer 状态
is_zone_active	新主所在的 zone 的状态

分区合并失败

搜索关键字： replica not merged

日志说明： 负载均衡任务的统计信息。

[admin@OB /home/admin/oceanbase/log] $grep "replica not merged" observer.log

返回结果如下：

[2021-04-07 10:47:36.835217] INFO  [RS] ob_partition_table_util.cpp:180 [4532][XXXXXXXXXX-XXXXXXXXXXXXXX] [lt=5] replica not merged to version(version=10044, replica={table_id:{value:1106108697592732, first:1006, second:50076}, partition_id:0, partition_cnt:1, zone:"bank.mub_2", server:"xxx.xxx.xxx.xxx:2882", sql_port:2881, unit_id:1017, role:1, member_list:[{server:"xxx.xxx.xxx.xxx:2882", timestamp:1557500921627412}, {server:"xxx.xxx.xxx.xxx:2882", timestamp:1560866621699092}, {server:"xxx.xxx.xxx.xxx:2882", timestamp:1592984233874976}, {server:"xxx.xxx.xxx.xxx:2882", timestamp:1614240480439532}, {server:"xxx.xxx.xxx.xxx:2882", timestamp:1614911835988424}], row_count:8635155074, data_size:2061390087129, data_version:10043, data_checksum:3763772143, row_checksum:row:[0], modify_time_us:1617652580558918, create_time_us:1560880959641988, member_time_us:1560866621699092, is_original_leader:false, in_member_list:true, rebuild:false, to_leader_time:1603047186742602, replica_status:"REPLICA_STATUS_NORMAL", replica_type:0, required_size:2295137828864, status:"REPLICA_STATUS_NORMAL", is_restore:0, partition_checksum:14438911093, quorum:5})

日志解读：

日志信息	说明
version	合并的全局版本号
table_id:{value:v0, first:v1, second:v2}	v0 table_id; v1 tenant_id; v2 pure table_id
data_version	当前分区的大版本号
replica_type	副本类型：0 - full; 5 logonly; 16 readonly
quorum	副本数

election.log 日志

日志关键字	说明
leader lease is expired	leader 租约过期（需要重新选主）
leader takeover success	leader 改选成功
leader revoke	leader 被废除
current leader is invalid	告警日志：leader 无效
leader_revoke, please attention!	错误日志：leader 被废除

Leader revoke 日志解读

搜索关键字： leader revoke、leader_revoke

日志说明： 分区发生切主的日志信息。

[admin@OB /home/admin/oceanbase/log] $grep "leader revoke|leader_revoke" observer.log

返回结果如下：

[2022-05-08 22:41:38.827689] INFO  [ELECT] ob_election.cpp:2072 [201777][0][Y0-0000000000000000-0-0] [lt=1526] take the initiative leader revoke(partition={tid:1100611139404082, partition_id:0, part_cnt:0}, revoke reason="clog disk full")

[2022-05-08 22:41:38.827723] ERROR [ELECT] leader_revoke (ob_election.cpp:2077) [201777][0][Y0-0000000000000000-0-0] [lt=8] leader_revoke, please attention!(revoke reason="clog disk full", election={partition:{tid:1100611139404082, partition_id:0, part_cnt:0}, is_running:true, is_changing_leader:false, self:"xxx.xxx.xxx.xxx:2882", proposal_leader:"0.0.0.0", cur_leader:"xxx.xxx.xxx.xxx:2882", curr_candidates:3{server:"xxx.xxx.xxx.xxx:2882", timestamp:1650642269999783, flag:0, need_encrypt:false}{server:"xxx.xxx.xxx.xxx:2882", timestamp:1651730035655503, flag:0, need_encrypt:false}{server:"xxx.xxx.xxx.xxx:2882", timestamp:1650642269999783, flag:0, need_encrypt:false}, curr_membership_version:1651730068793522, leader_lease:[1651816304570000, 1651816418400000], election_time_offset:5570000, active_timestamp:1651808137937449, T1_timestamp:1651816404000000, leader_epoch:1651816299000000, state:1, role:1, stage:-1, type:-1, replica_num:3, unconfirmed_leader:"xxx.xxx.xxx.xxx:2882", unconfirmed_leader_lease:[1651816304570000, 1651816419000000], takeover_t1_timestamp:1651816402600000, is_need_query:false, valid_candidates:0, change_leader_timestamp:0, ignore_log:false, leader_revoke_timestamp:1651816301770881, vote_period:4, lease_time:9800000, move_out_timestamp:1651816300405697, eg_part_array_idx:40, eg_id_hash:6130129687449640250}) BACKTRACE:0xf5c6965 0xf45eeca 0xf44866a 0x530ea4d 0x9bbea6b 0x9b2c627 0x9b2c0cc 0x9b77a60 0x987a46b 0xb472a62 0x93845b5 0x9384519 0x5260906 0x66daf5d 0xf33ee22 0xf33ec7e 0xf5da8ce

日志解读：

日志信息	说明
revoke reason	Leader revoke 的触发原因
is_running	是否正在进行选举
is_changing_leader	是否正在更改 Leader
self	当前节点
proposal_leader	被提议的 Leader
cur_leader	当前的 Leader
curr_candidates	当前的候选节点列表
leader_lease	Leader 的租约（开始时间，结束时间）
unconfirmed_leader	当前未确认的 Leader 节点
leader_revoke_timestamp	Leader revoke 发生的时间