当前位置:   article > 正文

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

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

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

observer.log 日志

OBServer 启动日志

搜索关键字: [NOTICE]

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

  1. [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
  2. [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 succeedOBServer 进程启动成功
observer start serviceOBServer 启动完成,开始提供服务
start_service_timeOBServer 开始提供服务的时间戳

统计日志

进程内存统计

搜索关键字: [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

日志解读:

日志信息说明
limitOBServer 总内存限制
holdOBServer 从操作系统获取到的所有的内存
usedOBServer 实际使用到的内存(包括 Cache)
freelist_holdOBServer 未使用的内存
租户内存统计

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

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

  1. [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
  2. [MEMORY] ctx_id= DEFAULT_CTX_ID hold_bytes= 658,505,728
  3. [MEMORY] ctx_id= MEMSTORE_CTX_ID hold_bytes= 383,778,816
  4. [MEMORY] ctx_id= EXECUTE_CTX_ID hold_bytes= 16,777,216
  5. [MEMORY] ctx_id= SQL_EXEC_CTX_ID hold_bytes= 77,594,624
  6. [MEMORY] ctx_id= TRANS_CTX_MGR_ID hold_bytes= 8,388,608
  7. [MEMORY] ctx_id= REPLAY_STATUS_CTX_ID hold_bytes= 6,291,456
  8. [MEMORY] ctx_id= PLAN_CACHE_CTX_ID hold_bytes= 553,648,128
  9. [MEMORY] ctx_id= WORK_AREA hold_bytes= 27,262,976
  10. [MEMORY] ctx_id= TX_CALLBACK_CTX_ID hold_bytes= 18,874,368
  11. [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]
  12. [MEMORY] tenant_id= 1 ctx_id= DEFAULT_CTX_ID hold= 658,505,728 used= 553,301,808
  13. [MEMORY] hold= 371,125,248 used= 368,276,480 count= 139 avg_used= 2,649,471 mod=MysqlRequesReco
  14. [MEMORY] hold= 52,416,000 used= 52,403,200 count= 25 avg_used= 2,096,128 mod=OB_KVSTORE_CACHE
  15. [MEMORY] hold= 49,029,760 used= 48,846,080 count= 24 avg_used= 2,035,253 mod=SqlPlanMon
  16. [MEMORY] hold= 35,543,040 used= 35,192,202 count= 534 avg_used= 65,903 mod=SqlDtl
  17. [MEMORY] hold= 14,696,192 used= 12,591,876 count= 14 avg_used= 899,419 mod=LOCALDEVICE
  18. [MEMORY] hold= 8,386,560 used= 8,384,512 count= 4 avg_used= 2,096,128 mod=Election
  19. [MEMORY] hold= 6,298,560 used= 6,281,216 count= 257 avg_used= 24,440 mod=BlockMap
  20. [MEMORY] hold= 6,289,920 used= 6,288,384 count= 3 avg_used= 2,096,128 mod=ElectionGroup
  21. [MEMORY] hold= 2,154,240 used= 408,600 count= 24,952 avg_used= 16 mod=Number

日志解读:

日志信息说明
tenant租户 ID
limit租户的内存上限
hold租户从操作系统获取到的所有的内存
rpc_holdRPC 线程占用的内存
cache_holdKVCache 占用的内存 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 线程的统计。

  1. [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")
  2. [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")
  3. [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")
  4. [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_countScheduler 角色的活跃事务上下文数量
active_coord_ctx_countCoordinator 角色的活跃事务上下文数量
active_part_ctx_countParticipant 角色的活跃事务上下文数量
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_percentsys_io_low_percent 与配置项 sys_bkgd_io_high_percentagesys_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_countclog 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 打印一次。

  1. [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)
  2. [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)
  3. [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)
  4. [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)
  5. [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|各类后台任务的线程总数上限|

说明

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

常见诊断日志

内存分配失败

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

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

  1. [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
  2. [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
  3. [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 的日志记录。

  1. [2022-09-03 11:33:06.624063] WARN [STORAGE.TRANS] on_wlock_retry
  2. (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")

日志解读:

日志信息说明
*thiswaiter(等锁的事务)
conflict_ctxblocker(阻挡者,可能是 holder)
pkeytable_id+partition_id 的信息
rowkey_object主键
trans_id事务的相关信息
慢查询

搜索关键字: [slow query]

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

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

日志解读:

日志信息说明
[eventbegin]与[eventend]表式 SQL 执行过程中内部事件的开始(begin)与结束(end)
u=xxx两个 trace 事件之间的间隔时长
in_queue_timeSQL 开始执行前在队列中等待的时间
trace_idSQL 执行的 trace_id
sidSQL 执行所在的 session_id
stmtSQLstatement
plan_idSQL 执行的 plan_id
ret返回码(错误码)
total_timeuSQL 处理的总耗时
慢事务

搜索关键字: [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 设定系统任务的网络限速。

  1. [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):
  2. [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)
  3. [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 关注并解决的错误。

  1. [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")
  2. [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")
  3. [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 stmtDDL 执行
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

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

  1. [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)
  2. [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 执行。

  1. [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}]})

日志解读:

日志信息说明
retDDL 语句的返回码
cost执行耗时
ddl_argDDL 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 expiredleader 租约过期(需要重新选主)
leader takeover successleader 改选成功
leader revokeleader 被废除
current leader is invalid告警日志:leader 无效
leader_revoke, please attention!错误日志:leader 被废除

Leader revoke 日志解读

搜索关键字: leader revoke、leader_revoke

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

  1. [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")
  2. [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 reasonleader revoke 的触发原因
is_runing是否正在进行选举
is_changing_leader是否正在更改 Leader
self当前节点
proposal_leader被提议的 Leader
cur_leader当前的 Leader
curr_candidates当前的候选节点列表
leader_leaseleader 的租约(开始时间,结束时间)
unconfirmed_leader当前未确认的 leader 节点
leader_revoke_timestampLeaderrevoke 发生的时间
声明:本文内容由网友自发贡献,不代表【wpsshop博客】立场,版权归原作者所有,本站不承担相应法律责任。如您发现有侵权的内容,请联系我们。转载请注明出处:https://www.wpsshop.cn/w/我家小花儿/article/detail/537193
推荐阅读
相关标签
  

闽ICP备14008679号