乐于分享
好东西不私藏

OB源码级分析尝试:探索日志压缩删除机制

OB源码级分析尝试:探索日志压缩删除机制
点击上方“蓝字”关注我们
案情谍报
                 东区·挨踢重案组

   在 OB 运维的战线上,有一道长期困扰的难题始终挥之不去 ——集群日志。

它是还原现场的重要线索,却也是最容易断裂的证据链。

要勘破疑案,就得让日志开口更多;可日志一旦畅所欲言,集群日志便以惊人的速度膨胀,留存窗口被挤压到极致。等真正需要回溯案情时,关键证据可能早已随时间灰飞烟灭。

日志开得越细,存得就越短;存得越短,真到排查问题时就越抓瞎 —— 这是一个看似无解的死循环。

直到高版本交付了一项新武器 ——日志压缩功能。它的目标是用更小的空间,装下更多的日志信息。

然而,每一件新武器投入战场之前,总有些雷区,还没有人替你踩过……

今天,我们用一个真实案例,拆解这项功能的台前与幕后。

01
问题描述
EAST REGION IT MAJOR CRIMES

环境信息

问题发现

问题的起因是因为数据库最近连续出现几次问题都没有日志进行分析,所以扒一扒官网看到有日志压缩功能。

但是开启日志压缩后,第二次问题复现时发现,依然没有日志。

日志并没有按照我们设置的进行压缩。

日志配置含义是开启压缩(压缩策略:zstd_1.3.8),保留100个日志不压缩,空间上限300G。

alter system set syslog_compress_func='zstd_1.3.8';

alter system set syslog_file_uncompressed_count=100;

alter system set syslog_disk_size='300G';

02
分析过程
EAST REGION IT MAJOR CRIMES

分析日志压缩情况

分析日志压缩情况发现可以看到1、3节点的observer.log、trace.log都保留100个未压缩文件和5000-6000个压缩文件

而2节点observer.log、trace.log有1000个未压缩文件(尤其是trace日志有900个未压缩),只有500个压缩文件。因为总的日志空间上限是300G,如果未压缩文件过多就会导致压缩文件保留很少。(压缩比能够达到15倍)

对比trace日志生成量

对比3个节点每小时的trace日志生成量,发现2节点每小时会多生成40个左右的日志。

查看日志记录

压缩删除日志的信息也会记录到 observer.log 日志中,

可以通过 log_compress_loop_ 关键字检索。

从日志中发现一个现象,压缩的文件数量有小于删除的文件数量的情况,说明可能存在还没压缩完的文件就被删除了。但是也不可能是操作系统瓶颈,因为我们测试过,压缩100个日志其实也挺快的。这里显然和压缩删除程序的判断逻辑有问题。

亦·泵神

5分钟前:

     从官网看 OB 的开启日志压缩是达到设置空间阈值了才会触发压缩、删除,感觉是压缩删除的逻辑存在问题,2 节点多的那几十个日志成为了最后的稻草。

工单确认

提工单并且最终和研发进行了线上沟通,了解到了这块的压缩删除逻辑:

比如日志空间设置为300G,那么将会在296G时(剩余空间还有4G)触发压缩动作,298G时(剩余空间还有2G)触发删除动作(fast_delete_log_mode=true)。

触发压缩和触发删除动作中间之间只给了2G的缓冲地带,对于现在的磁盘性能,2G很快就写完了,这就可能导致,当日志量很大的节点触发压缩的时候,还没把空间压下去,2G就写满了,直接触发删除了。

官方解决方案:

研发反馈这个问题会在 435bp6 hotfix5 修复解决。

工单已经给出了大概的压缩和删除的触发机制,但是详细的触发和处理机制是什么或者如果没有提工单,我们是否有解决此类问题的能力?

如果是Oracle这类闭源数据库产品,基本不可能!

但是OB各版本已经做了社区版开源(部分企业级高级特性还是闭源的),O记DBA梦寐以求的源码级分析能力终于可以得偿所愿了。

OB源码级分析

快速删除模式(fast_delete_log_mode=true) 不是简单由“剩余空间小于 2GB”直接触发,而是由一次循环中的压缩、删除结果决定。

满足以下任一条件,会进入快速删除模式(不压缩直接删):

  1. 本轮既压缩了文件,又删除了文件(说明当前压缩已经滞后了)

  2. 本轮删除达到 20 个文件:

从我们上面日志看,确实是有即压缩又删除的情况,所以肯定是触发了快速删除模式。

日志约占 296G → 剩余不足 4G → 开始压缩

日志约占 298G → 剩余不足 2G → 开始删除

压缩后仍发生删除 → 触发fast_delete_log_mode=true 进入到fast快速删除模式

正常的压缩和删除机制是,当有效剩余空间:

  • 剩余空间< 4GB:尝试压缩;

  • 剩余空间< 2GB:删除最老日志。

有效剩余空间取两者较小值:

min(文件系统实际剩余空间, syslog_disk_size【300G】 - 当前日志总大小)

剩余空间< 4GB:尝试压缩:

剩余空间< 2GB:删除最老日志:

满足以下任一条件,会进入快速删除模式(不压缩直接删):

  1. 本轮既压缩了文件,又删除了文件(说明当前压缩已经滞后了)

  2. 本轮删除达到 20 个文件:

进入fast 模式后的变化:

  • 跳过压缩,直接进行删除;

  • 循环间隔由正常的约 5 秒缩短到 100ms;

  • 目标是优先快速释放磁盘空间。

完整的逻辑如下:

亦·泵神

5分钟前:

     研发反馈会在下一个版本修复,但是下一个版本还有2个月才发版,这期间不可能一直等待,所以问题还是需要进一步分析。

找到一个绕过去的方案。逻辑其实很简单:日志多那就降低日志量。

降低 TRACE 日志采样比例

因为多的是trace日志,这里面主要是OB的全链路跟踪日志,默认SQL采样比例是10%,这里我们租户级别调整为5%。

call dbms_monitor.ob_tenant_trace_disable(); 

call dbms_monitor.ob_tenant_trace_enable(1, 0.05, 'SAMPLE_AND_SLOW_QUERY');

亦·泵神

5分钟前:

    调整 5% 后,预期本来日志量会降低一半,但是最后发现没有任何效果,那可能就需要分析日志的来源。

对比trace日志生成量(每分钟)

对比3个节点每分钟的trace日志生成量,发现1、3节点每分钟日志量都很均衡,但是2节点日志再每小时0分开始暴增。

这里其实感觉是什么定时运行的业务导致的。

分析日志来源

分析每小时产生日志最多的 trace_id,发现每小时都是有2个日志量比较大的trace_id,说明可能是2个每小时运行1次的SQL导致的。

为什么 SQL 会产生这么大量的 trace

通过gv$ob_sql_audit 视图找到对应的SQL_ID和FLT_SQL_ID

分析SQL的SQL TRACE发现SQL中有298万次的 pl_execute 执行,查看SQL文本也发现了自建函数,显然是这自建函数大量循环调用导致一个SQL 生成了几十G的 TRACE LOG。

obdiag analyze flt_trace --flt_trace_id 00065751-bb63-cfc7-e822-52a0b76791be

亦·泵神

5分钟前:

    这里其实也暴露一个问题,单个SQL日志量太大,没有限制。这里有时候也能理解研发人员的无奈,不生成大量的日志很多问题真的没法分析。

尝试关闭这个 SQL 的 SQL TRACE

亦·泵神

5分钟前:

     已经定位到SQL,其实这里当时想可能就只需要会话级别关闭SQL TRACE 就行。但是后面发现也不好实现。

一开始准备从SQL级别关闭,但是没有找到对应的HINT和优化器参数。

退而求其次就准备从会话级别关闭。找到了对应的内部包。

## 测试disable命令发现,关闭只是恢复租户级别设置,并不是完全关闭

call dbms_monitor.ob_session_trace_disable(null);

## 测试enable命令发现,这里只能无限设置为接近0的值,并不能直接设置为0(但是官网上显示可以设置为0)

## 最终通过这个方案解决了这个问题【加到程序代码里】

call dbms_monitor.ob_session_trace_enable(null,1,0.00001,'ALL');

亦·泵神

5分钟前:

     大家可能没有关注过这个问题,如果发现 trace.log 日志量很大,其实也可以通过上面方式进行处理。
03
总结建议
EAST REGION IT MAJOR CRIMES

虽然第一次使用日志压缩就遇到了BUG,但是我们依然建议开启这个功能,因为大部分的TP类集群没有这么大的日志量,不会遇到这个问题,而就算遇到这个问题,也好过不压缩(官方很快也会修复这个BUG)。

压缩比例可以达到惊人的15倍,再也不用担心分析问题没有日志了。

本次问题中存在几个可以优化的点,期待OB 未来能够做的更好:

1)日志压缩、删除逻辑有待优化

2)某些场景SQL生成的 TRACE 日志量太大,可以加一些限制条件

3)希望能够添加SQL级别关闭全链路跟踪的HINT

4)会话级别无法完全关闭全链路跟踪

亦·泵神

5分钟前:

我们的一切努力都是为了信创有一个更好的明天。