Troubleshooting一定要逻辑严谨与逻辑自洽

Oracle数据库升级到19.28版本后,我们的监控就比较频繁收到一类告警邮件，提示告警日志中出现下面这类告警信息:

2025-11-26T15:56:10.135762+08:00
Warning: long redo log write elapsed times detected, the LG* process tracefiles have more details 

而且出现这类告警的无一例外都是升级补丁的那一批服务器。当然频率有多有少。我们从下面几方面进行了分析：

1. 首先，Oracle的告警日志出现这类告警，官方文档Doc ID 3102584.1中强调了这个是为了解决Bug 36383923,而新增的功能。logwr进程将redo信息写入联机日志文件超过阈值的信息写入到告警日志和lgwr进程的trace文件. 它不是一个bug,也不是性能问题. 具体英文如下所示:

"The root cause of these warnings is not a bug or a performance issue, but rather new functionality added in version 19.28 via below Bug fix.
This functionality writes redo write threshold warnings to the alert log file, which was not previously reported."

官方文档的详细信息如下所示:

In this Document
Symptoms
Changes
Cause
SolutionApplies to:
Oracle Database - Enterprise Edition - Version 19.28.0.0.0 and later
Information in this document applies to any platform.
Symptoms
On : 19.28.0.0.0 versionThe system is intermittently generating a warning message in the alert log after applying the 19.28 July RU patch.The exact error message is:"Warning: long redo log write elapsed times detected, the LG* process tracefiles have more details"Changes
Patched to 19.28DBRUCause
The root cause of these warnings is not a bug or a performance issue, but rather new functionality added in version 19.28 via below Bug fix. This functionality writes redo write threshold warnings to the alert log file, which was not previously reported.Bug 36383923 - REPORT LOGWRITER ELAPSED TIME CRITICAL WARNING IN ATTENTION LOGSolution
This is not a database issue, but rather an enhancement to report slow IO warnings for redo in the alert log file via Bug 36383923.Previously, these warnings were only written to LGWR tracefiles, but with the 19.28 patch, they are now also included in the alert log.No specific actions are required to address these warnings in alertlog file. However, you can review the LGWR tracefiles and alert log to understand the frequency and impact of these slow IO warnings on your system's performance.

2. 分析了升级补丁前后lgwr进程的trace文件. 发现类似下面这类告警信息都是升级补丁后出现的. 而且分析了好几个升级补丁的实例都是如此. 下面是其中一个实例的trace文件

*** 2025-11-26T14:31:51.635693+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 2930ms, size 0KB*** 2025-11-26T14:34:09.008769+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 1489ms, size 0KB*** 2025-11-26T15:19:36.438765+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 800ms, size 0KB*** 2025-11-26T15:20:41.873096+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 1069ms, size 0KB*** 2025-11-26T15:56:10.133693+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 856ms, size 0KB*** 2025-11-26T16:00:16.141489+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 644ms, size 0KB*** 2025-11-26T16:01:15.729286+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 554ms, size 0KB*** 2025-11-26T16:02:17.331034+08:00 (CDB$ROOT(1))
Warning: log write elapsed time 998ms, size 0KB

3. Zabbix监控服务器的IO性能指标正常.例如指标"Disk write request avg waiting time(w_await)"都在正常范围内.没有出现告警。但是查看指标"sdc: Disk write request avg waiting time(w_await)",通过对比分析，发现从2025-11-05开始，这些指标数据(Disk write request avg waiting time(w_await)和Disk write time(rate))就有明显上升。而数据库安装补丁是在2025-11-04日升级的。确实是安装完补丁后出现的。这个证据是确实无误的。而且不是个例，如果是个例，可能还有业务增长等各种因素影响。如果不是个例，那么可以排除这些可能性！

注意：这里只看sdc设备，是因为redo log位于sdc设备上。

上面图片可能由于时间范围拉得太长，对比不是特别明显，我们将时间范围缩小，你就能看到磁盘写的平均等待时间确实在打完补丁后上升了，如下截图所示

而且这些告警出现的时间基本上和Zabbix中指标"Disk write request avg waiting time(w_await)"数据飙升是一致的。当然也有几个不一致，可能跟指标采样频率有关系。其实是分析了好多案例，基本吻合。 这里就不一一列举了，只贴了其中一个例子

那么这种告警到底是正常还是不正常呢？或者说到底是IO性能问题还是不是呢？官方又说不是性能问题(The root cause of these warnings is not a bug or a performance issue。). 而没有打补丁前，确实告警日志和lgwr进程的trace文件几乎没有这类告警。但是打完补丁后出现了大量这类告警，你说它不是性能问题吧， 那么指标"Disk write request avg waiting time(w_await)"数据确实对比打补丁之前有所增长。 而且不是个例， 于是我怀疑数据库打了Oracle 19.28补丁后会出现性能下降， 但是官方文档也没有明确的例子说打了Oracle 19.28补丁会出现性能下降。 而且网上也没有看到相关网友反馈这个问题。这里面总有一个逻辑不自洽的问题在里面，一时间让我也有点没有头绪。虽然没有找到root cause，但是现象不会说谎。 只是我没有理清这团乱麻。

如果一眼难以看清真相，那么我们就捋清线索，一条条自证与排除。

1. 首先告警日志中出现"Warning: long redo log write elapsed times detected, the LG* process tracefiles have more details ",这类告警，确实是打了Oracle 19.28补丁后出现的。确实也是为了解决Bug而新增的功能。这里没有什么争议与质疑。
   那么出现这个告警是否意味着IO性能下降呢？ 官方文档"The root cause of these warnings is not a bug or a performance issue, but rather new functionality added in version 19.28 via below Bug fix"这句话，一度让我怀疑自己的英语水平。
   它说出现这类告警不意味着性能问题。其实后面我自己认为这个可能要结合上下文语境来看，之前lgwr进程写redo log可能也有这种时延，只是它不写入告警日志。写入告警日志不意味着真的就出现了性能下降。这样理解就对了，如果真的出现IO性能下降，出现这类告警，怎么不是性能下降呢？ 英语毕竟不是母语，况且中文也会话里有话，或者表达的话。不同人不同的理解，出现存在争议的点。

2. 为什么打完补丁后，出现IO性能下降？ 首先确认事实，打完补丁后，数据库服务器IO性能确实出现性能下降(仅从指标"Disk write request avg waiting time(w_await)"来看)，但是这个是补丁引起的吗？ 我并不能给出证据，或者说我不能给出无可辩驳的铁证。虽然，打了补丁数据库服务器有不少出现这类告警，但是也有一些数据库服务器没有出现这类告警。

3. 综上所述，这里出现了一个逻辑不自洽。 虽然打补丁后出现性能下降，但是并不能说就是补丁引起的。那么肯定还有我遗漏或忽略的线索。 后面下班路上，我脑瓜里突然想起每次打补丁前，我们会找系统管理员做一个快照(VMware虚拟机），方便出现问题的时候，我们回滚操作。因为快照没有及时删除，会带来IO性能问题。为了验证猜想，第二天找系统管理员确认后，让他删除了快照。

最后通过验证发现，快照删除后，lgwr进程的trace文件没有了写redo log写超过阈值的warning信息了，Zabbix监控的也能印证这个。如下截图所示：

到此可以说真的找到root cause了。因为打补丁前， 我们做了VMware的快照，一般来说这些快照需要保留一段时间，而有时候系统管理员没有及时删除这些快照，就引起了IO性能问题，导致lgwr进程写redo log时出现超过阈值的情况。而由于从Oracle 19.28开始，这些告警会写入告警日志，我们的监控程序捕获并触发告警。到此，这些推理与证据链完整逻辑自洽。

写到此处，突然又想起了一个笑话：

为验证蜘蛛的听觉是否在脚上，科学家做了以下实验：
先是把一只蜘蛛放在实验台上，然后冲蜘蛛大吼了一声，蜘蛛吓跑了!
然后割掉蜘蛛的脚，再对它大吼，蜘蛛一动不动；
于是得出结论：蜘蛛的听觉在脚上

我们做Troubleshooting或分析的时候，也很容易闹这个笑话。所以，很多时候分析、诊断，推理都必须逻辑严谨与逻辑自洽。否则可能会得到一个错误的结论。

参考资料

"Warning: long redo log write elapsed times detected" in Alertlog After applying 19.28 July RU Patch (Doc ID 3102584.1)