赞
踩
适用版本:V2.1.x、V2.2.x、V3.1.x、V3.2.x
搜索关键字: [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 |
|
搜索关键字: 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 万。
搜索关键字: 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 使用率 |
| 这些部分包含了不同类型的 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)。 |
| 这些部分包含了不同类型的 I/O 的状态和设备能力,包括是否初始化(is_inited_),设备能力(device_ability_),共享百分比(share_percentage_)和最后截止时间戳(last_deadline_ts_)。 |
| 这部分包含了不同类型的 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 限流:
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)。 |
| 这些部分包含了不同类型的 I/O 的状态和设备能力,包括是否初始化(is_inited_),设备能力(device_ability_),共享百分比(share_percentage_)和最后截止时间戳(last_deadline_ts_)。 |
| 这部分包含了不同类型的 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 的耗时(微秒),通常在几毫米到几十毫秒之间。 |
搜索关键字: 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)
日志解读:
|日志信息|说明| |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
日志说明: 内存分配失败。
- [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 | 当前内存分配请求的内存大小 |
搜索关键字: 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 超过限流阀值的空间使用量 |
搜索关键字
日志说明: 发生行锁冲突及 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 | 事务类型:
|
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) |
搜索关键字: 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 | 错误信息 |
日志关键字 | 说明 |
---|---|
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] 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 | 副本数 |
日志关键字 | 说明 |
---|---|
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
日志说明: 分区发生切主的日志信息。
- [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 发生的时间 |
Copyright © 2003-2013 www.wpsshop.cn 版权所有,并保留所有权利。