当前位置：首页 > article >正文

【OceanBase 诊断调优】—— 日志归档延迟或日志归档慢的原因和解决方法

article 2025/1/21 8:54:01

问题现象

CDB_OB_ARCHIVELOG 视图中对应租户的 checkpoint_scn 字段已经落后于当前时间很多。（前提是日志归档还在进行，即 CDB_OB_ARCHIVELOG 视图中对应租户的 staus 仍然是 DOING，且 checkpoint_scn 还在往前推。）

关键信息

检查 OBServer 的网络带宽限速。

OBServer 中通过 sys_bkgd_net_percentage 用来设置备份恢复、迁移复制等系统任务的网络带宽使用比例（上限），其实际的网络带宽依据网卡速度来进行计算。如果获取到了错误的网卡速度，则实际使用的网络带宽可能偏小。

详情参见：OBServer 如何获知网卡速度？和网卡速度识别错误导致迁移任务执行慢的问题判断网络带宽限速是否有问题。
检查配置项。

首先检查配置项 show parameters like "log_archive_target"，该配置项用于控制日志归档的延迟时间，如果 checkpoint_scn 落后的时长和该配置项的时长差不多，则符合预期。详情参见：archive_lag_target

如果落后时长明显大于 log_archive_target，则根据日志进一步确定原因。
查找最慢日志流。

租户的整体归档进度由最慢日志流的归档进度决定，而归档又是由日志流 Leader 进行的，所以我们需要找到最慢日志流的 Leader所在的机器。
1. 找到最慢日志流。
```
select ls_id from oceanbase.__all_virtual_ls_log_archive_progress where tenant_id = $tenant_id and  checkpoint_scn = (select checkpoint_scn from oceanbase.cdb_ob_archivelog where tenant_id = $tenant_id);
```
  将这里的 $tenant_id 替换成归档租户的租户 id。
2. 找到最慢日志流 Leader 所在的机器。
```
select svr_ip, svr_port from oceanbase.__all_virtual_ls_meta_table where tenant_id = $tenant_id  and ls_id = $ls_id and role = 1;
```
  将这里的 $tenant_id 替换成归档租户的租户 id，$ls_id 替换成上一步查询出来的 ls_id。
3. 进入到对应节点的 log 目录查询 OBServer 日志。

归档速率统计。

归档线程会定期统计过去 10 秒的归档日志量。

grep "archive_sender statistic in 10s" observer.log.xxx observer.log

打印如下日志。

observer.log.20240621235653303:[2024-06-21 23:56:14.955385] INFO  [ARCHIVE] statistic (ob_archive_sender.cpp:893) [38513][T1002_ArcSender][T1002][xxxxx-xxxxx-xxxxx-xxxxx] [lt=3] archive_sender statistic in 10s(total_send_log    _size=67104768, total_send_buf_size=67104768, total_send_task_count=1, total_send_cost_ts=99872811, avg_task_lsn_size=67104768, avg_task_buf_size=67104768, avg_task_cost_ts=99872811)

其中 total_send_buf_size 是归档线程发送的日志量（Byte），total_send_cost_ts 是发送日志的耗时（us），例如上述日志表示归档线程 10s 发送了 6.7MB 日志，实际归档速率只有 0.67MB/s。

IO 慢日志。

当单次 IO 用时超过 1 秒时，OBServer 的 IO 接口也会打印慢日志。

grep print_access_storage_info observer.log.xxx observer.log

打印如下日志。

z1/observer_11.161.204.236_11000/observer.log.20240616190435920:[2024-06-16 18:50:48.176611] WDIAG [STORAGE] print_access_storage_log (ob_storage.cpp:50) [119270][T1002_BACKUP_DA][T1002][xxxxx-xxxxx-xxxxx-xxxxx] [lt=4][errcode=0] access storage op=storage multipart writer uri=s3://xxx_bucket/obdata/data/421_storage_ha_regression/backup_file/obtest_backup/ob_backup_oracle_tenant/data/backup_set_1_full/logstream_1001/major_data_turn_1_retry_0/macro_block_data.0.obbak size=16631 Byte cost_ts=1184927 us speed=0.01 MB/s

上述日志表示一次 IO 向 S3 写入了16631 Byte 的数据，写入速率是 0.01MB/s。

如果步骤 3 （查找最慢日志流 这一节）中算出的写入速率很小，步骤 4 （归档速率统计 这一节）有大量日志打印且写入速率很小，则可以确定是备份介质慢。

确认是否触发限流。

如果备份介质是 OSS，还可以进一步检查是否触发了限流。

grep "delay_time\=" observer.log.xxx observer.log | grep "print_oss_info"

打印如下日志。

observer.log.20240529213152163:[2024-05-29 21:31:15.383256] WDIAG print_oss_info (ob_storage_oss_base.cpp:688) [54020][T1002_BACKUP_IN][T1002][YBBD0B7C05A6-000619978DE40D30-0-0] [lt=37][errcode=0] oss info (aos_ret->code=200, aos_ret->error_code=NULL, aos_ret->error_msg=NULL, aos_ret->req_id=66572E23B32FB3303236CB92, delay_time=1 ms, oss_account_.oss_domain_=xxx, oss_endpoint_=xxx, oss_account_.oss_id_=xxx)

上述日志表示触发了 OSS 的限流，单次 IO 将有 1ms 的延迟。