【OceanBase诊断调优】—— OceanBase 数据库日志解读

适用版本：V2.1.x、V2.2.x、V3.1.x、V3.2.x

observer.log 日志

OBServer 启动日志

搜索关键字： [NOTICE]

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

[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 打印一次。

[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 未使用的内存

租户内存统计

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

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

[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 占用的内存

租户磁盘统计

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

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

[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`	租户的磁盘上限（V4.x 版本前租户没有磁盘使用量的限制）
`used_data_size`	租户内用户数据使用的磁盘空间
`used_meta_size`	租户内管理数据使用的磁盘空间

租户线程队列统计

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

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

[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, sug_token_cnt:12, ass_token_cnt:12, lq_wait_timeout_workers:0, 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_ps_close_cnt:0, recv_mysql_cnt:0, recv_task_cnt:0, recv_large_req_cnt:0, tt_large_quries:0, pop_normal_cnt:161183951, 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, reserve 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 , recv_level_rpc_cnt:cnt[0]=0 cnt[1]=0 cnt[2]=0 cnt[3]=0 cnt[4]=0 cnt[5]=0 cnt[6]=0 cnt[7]=0 , group_map:, rpc_stat_info:})

日志解读：

日志信息	说明
`lq_tokens`	租户的大查询的活跃线程总数上限
`workers`	租户的 SQL 工作线程数
`req_queue`	total_size：当前处于等待队列中的请求总数 large_queued：当前处于等待队列中的大查询请求数

RPC 线程统计

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

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

[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 线程的 requestdoing=0/0，说明 RPC 线程全部处于繁忙状态。

事务上下文统计

搜索关键字： ObTransCtx statistics

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

[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（V2.x 版本）或 current io status（V3.x 版本）

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

V2.x 版本日志解读：

[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 出现限流。

V3.x 版本日志解读：

[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 打印一次。

[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`	归档状态，2 表示 DOING

搜索关键字： archive_clog_split_engine statistics

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

[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 打印一次。

[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 打印一次。

[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)

日志解读：

说明

系统表 __all_virtual_dag_scheduler 中记录了 DAG 任务的实时统计。

常见诊断日志

内存分配失败

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

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

[2019-11-29 13:32:19.702557] WARN  alloc_chunk (achunk_mgr.cpp:156) [116413][1492][YEF00AF4010F-00059874012A536E] [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][YEF00AF4010F-00059874012A536E] [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][YEF00AF4010F-00059874012A536E] [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 写入限流的统计日志。

2022-12-29 04:46:44.841893] INFO  [COMMON] ob_fifo_arena.cpp:333 [28948][0][YB42AC147903-0005E8A737B6EAC3-0-0] [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][YB427F000001-0005E7BCC462AAF5-0-0] [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:“127.x.x.x: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:"127.x.x.x: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 的详细信息。

[2022-02-18 11:49:32.557473] TRACE [TRACE]obmp_base.cpp:948 [1837144][3090][YB42C523140C-0005D51681C947FF] [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:YB42C523140C-0005D51681C947FF
|[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]

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

observer.log:[2021-10-08 11:45:44.313295] TRACE [TRACE]:0 [9382][2334][Y9C4064586A6B-0005CDCF253FBE70] [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.xxx.x.x", 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] /[endtrans]`	开启/结束该事务上下文
`[start_stmt] /[endstmt]`	开始/结束执行 SQL，包含 SQL 的 sql_id，trace_id 等信息
`u=xxx`	两个 trace 事件之间的间隔时长
`total_timeu`	事务处理的总耗时

网络传输慢

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

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

[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 设定系统任务的网络限速。

[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

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

[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 关注并解决的错误。

[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

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

[2023-05-10 05:22:50.862554] INFO  [RS] ob_rebalance_task_mgr.cpp:1887 [65048][0][YB420BA6506F-0005FA11F0DE7056-0-0] [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

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

[2021-04-07 10:37:16.451302] INFO  [RS] ob_daily_merge_scheduler.cpp:1840 [4532][YB420B207FC9-0005B2136F1796FF] [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][YB420B207FC9-0005B2136F17E9B7] [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][YB420BA6506F-0005FB926B9219CB-0-0] [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 执行。

[2023-05-16 10:50:10.834911] INFO  [RS] ob_rs_rpc_processor.h:249 [87188][0][YB420BA6506F-0005FB927B71B62D-0-0] [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

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

[2023-05-10 17:41:28.833956] INFO  [RS] ob_leader_coordinator.cpp:5004 [65037][0][YB420BA6506F-0005FA11E7CF1698-0-0] [lt=27] [dc=0] choose leader info(tenant_id=1005, tablegroup_id=18446744073709551615, server="192.xxx.x.x:2882", info={server_addr:"192.xxx.x.x: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

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

[2021-04-07 10:47:36.835217] INFO  [RS] ob_partition_table_util.cpp:180 [4532][YB420B207FC9-0005B2136F5C91C6] [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:"192.xxx.x.x:2882", sql_port:2881, unit_id:1017, role:1, member_list:[{server:"192.xxx.x.x:2882", timestamp:1557500921627412}, {server:"192.xxx.x.x:2882", timestamp:1560866621699092}, {server:"192.xxx.x.x:2882", timestamp:1592984233874976}, {server:"192.xxx.x.x:2882", timestamp:1614240480439532}, {server:"192.xxx.x.x: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

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

[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:"192.xxx.x.x:2882", proposal_leader:"0.0.0.0", cur_leader:"192.xxx.x.x:2882", curr_candidates:3{server:"192.xxx.x.x:2882", timestamp:1650642269999783, flag:0, need_encrypt:false}{server:"192.xxx.x.x:2882", timestamp:1651730035655503, flag:0, need_encrypt:false}{server:"192.xxx.x.x: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:"11.xxx.x.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_runing`	是否正在进行选举
`is_changing_leader`	是否正在更改 Leader
`self`	当前节点
`proposal_leader`	被提议的 Leader
`cur_leader`	当前的 Leader
`curr_candidates`	当前的候选节点列表
`leader_lease`	leader 的租约（开始时间，结束时间）
`unconfirmed_leader`	当前未确认的 leader 节点
`leader_revoke_timestamp`	Leaderrevoke 发生的时间