observer节点磁盘使用率突然激增，一段时间后自动回落

OceanBase 技术问题
#1

【 使用环境 】生产环境
【 使用版本 】oceanbase-3.1.5-CE
【问题描述】2024年8月23日 00:35收到自动告警，存在运行在容器中的observer节点（ip:19.25.47.19）磁盘使用率突然暴增至97%，持续一段时间(00:47)后自动回落

【相关日志】从对应时间的observer日志中，粘贴了部分相关日志，请社区的专家帮忙看看解答解答

[2024-08-23 00:35:58.637655] WARN  [STORAGE] process (ob_partition_migrator.cpp:12317) [512][460][YB4213192F13-000618EE1AAC902C] [lt=14] [dc=0] failed to acquire sstbale(ret=0, dest_table_key={table_type:7, pkey:{tid:1100611139457202, partition_id:10, part_cnt:0}, table_id:1100611139457204, trans_version_range:{multi_version_start:1724341214314056, base_version:1724256624514108, snapshot_version:1724343000935082}, log_ts_range:{start_log_ts:1724256624514108, end_log_ts:1724343000935082, max_log_ts:1724343000935082}, version:"0-0-0"})
[2024-08-23 00:35:58.716302] WARN  [STORAGE] acquire_sstable (ob_partition_migrator.cpp:12385) [505][446][YB4213192F13-000618EE1AAC902C] [lt=5] [dc=0] failed to acquire sstable(ret=-4018, dest_table_key={table_type:7, pkey:{tid:1100611139457202, partition_id:10, part_cnt:0}, table_id:1100611139457204, trans_version_range:{multi_version_start:1724343000935082, base_version:1724343000935082, snapshot_version:1724343031743112}, log_ts_range:{start_log_ts:1724343000935082, end_log_ts:1724343031743112, max_log_ts:1724343031743112}, version:"0-0-0"})
[2024-08-23 00:35:58.716343] WARN  [STORAGE] process (ob_partition_migrator.cpp:12317) [505][446][YB4213192F13-000618EE1AAC902C] [lt=36] [dc=0] failed to acquire sstbale(ret=0, dest_table_key={table_type:7, pkey:{tid:1100611139457202, partition_id:10, part_cnt:0}, table_id:1100611139457204, trans_version_range:{multi_version_start:1724343000935082, base_version:1724343000935082, snapshot_version:1724343031743112}, log_ts_range:{start_log_ts:1724343000935082, end_log_ts:1724343031743112, max_log_ts:1724343031743112}, version:"0-0-0"})
[2024-08-23 00:35:58.773059] ERROR [STORAGE] check_disk_full (ob_store_file.cpp:860) [749][930][Y0-0000000000000000] [lt=10] [dc=0] disk is almost full(ret=-4184, required_size=0, required_count=0, free_count=86998, used_percent=90, calc_free_block_cnt=86998, calc_total_block_cnt=798330) BACKTRACE:0x9c5ff5e 0x9a33051 0x232dc60 0x232d87b 0x232d4c4 0x4882d2b 0x8a38b5f 0x8a08f5b 0x7f2c780 0x9be8cb7 0x34c5ccf 0x2d684b2 0x99e74e5 0x99e5ed2 0x99e298f
[2024-08-23 00:35:58.803671] WARN  [STORAGE] generate_weak_read_timestamp (ob_partition_loop_worker.cpp:240) [1456][2321][Y0-0000000000000000] [lt=16] [dc=0] slave read timestamp too old(pkey_={tid:1100611139456442, partition_id:10, part_cnt:0}, delta_ts=8027887, readable_info={min_log_service_ts_:1724344550775772, min_trans_service_ts_:9223372036854775807, min_replay_engine_ts_:1724344550775772, generated_ts_:1724344558803657, max_readable_ts_:1724344550775771})
[2024-08-23 00:35:58.965531] WARN  [STORAGE.TRANS] reset (ob_trans_define.cpp:1088) [1303][2036][YB4213192F13-000618EE4CDDC3D8] [lt=5] [dc=0] reset trans desc without release part ctx(*this={tenant_id:1001, trans_id:{hash:12963745167277084159, inc:2321310660, addr:"19.25.47.19:2882", t:1724344557836966}, snapshot_version:-1, trans_snapshot_version:-1, trans_param:[access_mode=1, type=3, isolation=1, magic=17361641481138401520, autocommit=0, consistency_type=0(CURRENT_READ), read_snapshot_type=2(PARTICIPANT_SNAPSHOT), cluster_version=12884967429, is_inner_trans=0], participants:[{tid:1100611139457399, partition_id:20, part_cnt:0}], stmt_participants:[], sql_no:4294967297, max_sql_no:4294967297, stmt_min_sql_no:4294967297, cur_stmt_desc:[stmt_tenant_id=1001, phy_plan_type=1, stmt_type=2, consistency_level=0, execution_id=7273548214, sql_id=652FFB38F44CFBA, trace_id=YB4213192F13-000618EE4CDDC3D7, is_inner_sql=0, app_trace_id_str=, cur_stmt_specified_snapshot_version=-1, cur_query_start_time=1724344557837348, is_sfu=0, is_contain_inner_table=0, trx_lock_timeout=-1], need_rollback:false, trans_expired_time:1724346357836859, cur_stmt_expired_time:1724387757767348, trans_type:0, is_all_select_stmt:false, stmt_participants_pla:{partitions:[{tid:1100611139457399, partition_id:20, part_cnt:0}], leaders:["19.25.47.19:2882"], type_array:[0]}, participants_pla:{partitions:[], leaders:[], type_array:[]}, is_sp_trans_exiting:false, trans_end:true, snapshot_gene_type:2, local_consistency_type:0, snapshot_gene_type_str:"NOTHING", local_consistency_type_str:"CURRENT_READ", session_id:3224875443, proxy_session_id:1377258430684109150, app_trace_id_confirmed:true, can_elr:false, is_dup_table_trans:false, is_local_trans:true, trans_need_wait_wrap:{receive_gts_ts:{mts:0}, need_wait_interval_us:0}, is_fast_select:false, trace_info:{app_trace_info:"", app_trace_id:""}, standalone_stmt_desc:{trans_id:{hash:0, inc:0, addr:"0.0.0.0", t:0}, tenant_id:0, stmt_expired_time:-1, trx_lock_timeout:-1, consistency_type:-1, read_snapshot_type:-1, snapshot_version:-1, is_local_single_partition:false, is_standalone_stmt_end:true, first_pkey:{tid:18446744073709551615, partition_id:-1, part_idx:268435455, subpart_idx:268435455}}, need_check_at_end_participant:false, is_nested_stmt:false, stmt_min_sql_no:4294967297, xid:{gtrid_str:"", bqual_str:"", format_id:1, gtrid_str_.ptr():"data_size:0, data:", bqual_str_.ptr():"data_size:0, data:"}, gc_participants:[]}, part_ctx_=0x7fbfa91a3910, lbt="0x9c5ff5e 0x8d9f163 0x8f9a7ff 0x7f982e7 0x5da5ca9 0x5da57f4 0x5da5580 0x42bc865 0x5887fd0 0x5d4d547 0x5d4e610 0x5d4e23e 0x96770c6 0x96a93f2 0x96a60d7 0x9d8e09c 0x948b31f 0x946a441 0x9489f7f 0x9468226 0x9468807 0x2d684b2 0x99e74e5 0x99e5ed2 0x99e298f")
---------
[2024-08-23 00:36:00.877907] WARN  [STORAGE.REDO] append_log_head (ob_storage_log_struct.cpp:183) [494][424][YB4213192F13-000618EE1AAC902A] [lt=5] [dc=0] The buffer is not enough, (ret=-4024, capacity_=507904, pos_=506828, len=1428)
[2024-08-23 00:36:00.877926] WARN  [STORAGE.REDO] append_log (ob_storage_log_struct.cpp:436) [494][424][YB4213192F13-000618EE1AAC902A] [lt=17] [dc=0] append log to buffer failed.(ret=-4024, trans_id=5864291, log_count_=356, subcmd=4294967329)
[2024-08-23 00:36:00.880336] WARN  [STORAGE.REDO] append_log_head (ob_storage_log_struct.cpp:183) [494][424][YB4213192F13-000618EE1AAC902A] [lt=4] [dc=0] The buffer is not enough, (ret=-4024, capacity_=507904, pos_=506940, len=1428)
[2024-08-23 00:36:00.880347] WARN  [STORAGE.REDO] append_log (ob_storage_log_struct.cpp:436) [494][424][YB4213192F13-000618EE1AAC902A] [lt=10] [dc=0] append log to buffer failed.(ret=-4024, trans_id=5864291, log_count_=711, subcmd=4294967329)

------------------------------
[2024-08-23 00:48:02.244632] WARN  [SHARE] remove (ob_partition_table_proxy.cpp:2125) [1310][2050][YB42131D1F14-000618F1E79E463C] [lt=5] [dc=0] expected deleted single row(affected_rows=0, sql=DELETE FROM __all_tenant_meta_table WHERE tenant_id = 1001 AND table_id = 1100611139457312 AND partition_id = 22 AND svr_ip = '19.25.47.19' AND svr_port = 2882)

从合并记录看，23日的合并起始时间为00:10, 结束时间为00:21,合并状态正常
目前看，所有节点的状态均为active，异常发生的节点磁盘使用率已经恢复到67%左右，与其他节点相差不大。

3 个赞
#3

ob日志还在么，麻烦压缩发过来一份

4 个赞
#4

磁盘容量超过70%便会告警，且data_disk_usage_limit_percentage该参数默认应该是90
磁盘容量超过90%会停止写入，你说的达到97%不合理，有ocp告警截图么

4 个赞
#5

我们是手工容器部署的，没有对接OCP，告警是容器平台报出来的。
从容器平台的监控看，00:36分表空间使用率达到97%，00:47自动恢复，期间没有人工介入

3 个赞
#6

文件内容超过10M了，通过网盘链接提供哈
链接：夸克网盘分享

3 个赞
#7

这个集群有30个节点，从容器平台的监控看，只有这一个节点出现磁盘超过90%，我理解不至于出现集群停写的情况，我疑惑的点在于：

  1. 从合并时间看，00:21 合并已经结束了，为什么00:35出现磁盘激增的现象
  2. 我怀疑过是节点分区负载均衡的缘故，有分区正在搬往目标节点，但我从日志里面没有检索相关的信息（当然也有可能是日志内容太多，我没有查到有用的信息）
  3. 当天凌晨那个时间段并没有什么特别的写入/查询任务，检查过对应的应用日志，只有几个定时备份数据的任务（通过SELECT语句读取数据库的数据然后备份到大数据平台）
  4. 截止8月24日上午十点，这个单节点磁盘激增的现象没有再发生，而且8月23日0点到1点没有人为介入处理，该节点的磁盘使用率是自动恢复到正常水平的（就自动恢复这一点要给OB点个赞）
mysql> select *from __all_zone where name like '%merge%';
+----------------------------+----------------------------+-------+---------------------+------------------+------+
| gmt_create                 | gmt_modified               | zone  | name                | value            | info |
+----------------------------+----------------------------+-------+---------------------+------------------+------+
| 2024-05-20 16:42:04.349269 | 2024-05-20 16:42:04.349269 |       | is_merge_error      |                0 |      |
| 2024-05-20 16:42:04.349269 | 2024-08-23 00:21:58.241193 |       | last_merged_version |              102 |      |
| 2024-05-20 16:42:04.349269 | 2024-08-23 00:21:58.241193 |       | merge_status        |                0 | IDLE |
| 2024-05-20 16:42:04.350324 | 2024-08-23 00:21:23.938620 | zone1 | all_merged_version  |              102 |      |
| 2024-05-20 16:42:04.350324 | 2024-08-23 00:21:23.938620 | zone1 | is_merge_timeout    |                0 |      |
| 2024-05-20 16:42:04.350324 | 2024-08-23 00:21:23.938620 | zone1 | last_merged_time    | 1724343683937895 |      |
| 2024-05-20 16:42:04.350324 | 2024-08-23 00:21:23.938620 | zone1 | last_merged_version |              102 |      |
| 2024-05-20 16:42:04.350324 | 2024-08-23 00:10:21.912357 | zone1 | merge_start_time    | 1724343021912115 |      |
| 2024-05-20 16:42:04.350324 | 2024-08-23 00:21:23.938620 | zone1 | merge_status        |                0 | IDLE |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:36.045036 | zone2 | all_merged_version  |              102 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:36.045036 | zone2 | is_merge_timeout    |                0 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:36.045036 | zone2 | last_merged_time    | 1724343696043839 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:36.045036 | zone2 | last_merged_version |              102 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:10:21.913411 | zone2 | merge_start_time    | 1724343021913683 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:36.045036 | zone2 | merge_status        |                0 | IDLE |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:47.309847 | zone3 | all_merged_version  |              102 |      |
| 2024-05-20 16:42:04.352432 | 2024-08-23 00:21:47.308793 | zone3 | is_merge_timeout    |                0 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:47.308793 | zone3 | last_merged_time    | 1724343707308738 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:21:47.308793 | zone3 | last_merged_version |              102 |      |
| 2024-05-20 16:42:04.351378 | 2024-08-23 00:10:21.915498 | zone3 | merge_start_time    | 1724343021915185 |      |
| 2024-05-20 16:42:04.352432 | 2024-08-23 00:21:47.309847 | zone3 | merge_status        |                0 | IDLE |
+----------------------------+----------------------------+-------+---------------------+------------------+------+

11724466892_.pic copy
11724466892_.pic copy1100×968 153 KB

2 个赞
#8

OB 的数据文件 blockfile 只会增长不会缩小， clog 的空间也是参数 log_disk_size 确定的。所以你说的这个 “磁盘使用率” 具体是什么的使用率？是文件系统监控报出来的，还是 OB 数据文件内部使用率监控？

可以提供一些目录相关的信息。

  • 查看 OB 数据目录相关
show parameters like 'data_dir';

查出目录后看看这个目录的结构

ls -lrth /home/admin/oceanbase/store/obdemo01

然后展示实际目录的容量 以及所在文件系统

du -sh /data/1/
df -h
3 个赞
#9
  1. 这里所说的磁盘使用率是容器平台的文件系统监控报出来的，observer部署在容器里面
  2. 因为告警是发生在凌晨，当日值班的同事对OB不熟悉，没有及时采用SQL语句去查询表空间的真实使用率，等到第二天再排查的时候，用上面的SQL语句查询，磁盘使用率是正常的
  3. 容器是专用的，除了observer的进程不会有其他应用的进程干扰
  4. 第二天检查过该节点运行容器的物理机日志，没有发现文件系统相关的错误，同时主机组也确认该物理机没有出现硬件故障
  5. blockfile所在目录的容量应该是data_disk_usage_limit_percentage参数设置来控制的，我印象里是80%
1 个赞
#10

监控的应该是文件系统，有可能是data下的磁盘中可能出现了什么临时文件
几分钟时间自动恢复了也可以排除掉节点宕机导致产生了core文件问题。
还是再观察观察看看会不会复现

#11

问题复现过么，或者看一下容器除ob外还有其他东西么，监控一下其他应用使用情况

#12

OB 跟容器结合后，OB 自身倒没什么，就是 OB 运维情况要复杂一点。这个复杂度主要是容器技术引入的。
容器的 网络、存储 需要单独了解一下。
就拿这个问题来说，容器里的 OB 的数据目录所用的卷是 容器默认的，还是容器启动时将外部文件系统目录映射进去的。建议的是后者这种。 容器的空间监控也就变得复杂一点。
最好是有一定的容器使用运维经验，然后再将 OB 用于容器中，而不是直接选了 OB 的那个容器部署方法（那个就是给初学者玩玩，用不得生产环境）。

1 个赞
#13

持续观察了几天，没有再出现类似的情况。容器上只有observer的进程，容器都是专用的。
通过容器平台的日志检查了对应时间范围内也没有后台登录的操作，后面如果有复现的话再来本帖继续讨论

1 个赞
#14

我们是将自己的容器平台和OB的部署结合起来的，容器平台负责提供容器运行环境，使用自己开发的启动脚本来启动observer的进程。
不是直接选了 OB 的那个容器部署方法。

2 个赞
#15

可以部署个监控脚本，我怀疑是多版本临时文件导致的，可以参考select svr_ip,table_type,
SUM(size/1024/1024/1024) size
FROM __all_virtual_table_mgr where size<>0
group by svr_ip,table_type order by 1,3;
这个语句观察下磁盘使用高的时候是哪部分占比异常的

1 个赞