AWR 报告深度解读：Redo Nowait指标的算法和诊断泄露二十多万名用户数据
导读：本文将对Redo Nowait指标的算法和诊断进行深度解析。
AWR知识体系：https://www.modb.pro/topic/6165（复制到浏览器打开或者点击“阅读原文”）
曾经遇到过一个性能故障，数据库的检查点执行的非常缓慢，直接导致所有日志组都处于活动状态，数据库处于不断停顿的『打嗝』工作状态。
检查V$LOG视图，可以获得日志状态，除了CURRENT日志组，其他日志都处于ACTIVE状态，而且后面的几组日志都是DBA最新添加的：
SQL> select * from v$log; GROUP# THREAD# SEQUENCE# BYTES MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIM ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- --------- 1 1 520403 31457280 1 NO ACTIVE 1.3861E+10 23-JUN-05 2 1 520404 31457280 1 NO ACTIVE 1.3861E+10 23-JUN-05 3 1 520405 31457280 1 NO ACTIVE 1.3861E+10 23-JUN-05 4 1 520406 31457280 1 NO CURRENT 1.3861E+10 23-JUN-05 5 1 520398 31457280 1 NO ACTIVE 1.3860E+10 23-JUN-05 6 1 520399 31457280 1 NO ACTIVE 1.3860E+10 23-JUN-05 7 1 520400 104857600 1 NO ACTIVE 1.3860E+10 23-JUN-05 8 1 520401 104857600 1 NO ACTIVE 1.3860E+10 23-JUN-05 9 1 520402 104857600 1 NO ACTIVE 1.3861E+10 23-JUN-05如果日志都处于Active状态，那么显然是DBWR的写出已经无法跟上Log Switch切换触发的检查点。
接下来让我们检查一下DBWR的繁忙程度:
oracle:/oracle >ps -ef|grep ora_dbw oracle 2266 1 0 Mar 31 ? 811:42 ora_dbw0_hysms02 oracle 21023 21012 0 18:52:59 pts/65 0:00 grep ora_dbw这里可以看到DBWR的进程号是2266，接下来使用Top命令观察一下其CPU资源使用情况:
oracle:/oracle >top last pid: 21145; load averages: 3.38, 3.45, 3.67 18:53:38 725 processes: 711 sleeping, 1 running, 10 zombie, 3 on cpu CPU states: 35.2% idle, 40.1% user, 9.4% kernel, 15.4% iowait, 0.0% swap Memory: 3072M real, 286M free, 3120M swap in use, 1146M swap free PID USERNAME THR PRI NICE SIZE RES STATE TIME CPU COMMAND 11855 smspf 1 59 0 1355M 1321M cpu/0 19:32 16.52% oracle 2264 oracle 1 0 0 1358M 1316M run 283.3H 16.36% oracle 11280 oracle 1 13 0 1356M 1321M sleep 79.8H 0.77% oracle 21043 oracle 1 43 0 3264K 2056K cpu/9 0:01 0.31% top 2266 oracle 1 60 0 1357M 1317M sleep 811:42 0.18% oracle 26257 smspf 82 59 0 447M 178M sleep 533:04 0.15% java注意到2266号进程消耗的CPU不过0.18%,显然并不繁忙,那么瓶颈就很可能在IO上。
gqgai:/home/gqgai>iostat -xn 3 extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device ........ 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 c0t6d0 0.3 8.3 0.3 47.0 0.0 0.1 0.0 9.2 0 8 c0t10d0 0.0 8.3 0.0 47.0 0.0 0.1 0.0 8.0 0 7 c0t11d0 11.7 65.3 197.2 522.2 0.0 1.6 0.0 20.5 0 100 c1t1d0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 hurraysms02:vold(pid238) extended device statistics r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device ........ 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 c0t6d0 0.3 13.7 2.7 68.2 0.0 0.2 0.0 10.9 0 12 c0t10d0 0.0 13.7 0.0 68.2 0.0 0.1 0.0 9.6 0 11 c0t11d0 11.3 65.3 90.7 522.7 0.0 1.5 0.0 19.5 0 99 c1t1d0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0以上监控显示存放数据库的主要卷c1t1d0的繁忙程度始终处于99~100,而写速度却只有500K/s左右，这个速度是极为缓慢的。进一步的检查确认是硬盘发生了损坏，Raid5的磁盘组中损坏了一块硬盘，导致了磁盘I/O性能下降，经过更换以后系统逐渐恢复正常。
以下是另外一则类似的问题。最初有朋友提出的问题是，实例效率里面的Redo Nowait指标代表的是什么，为什么会出现负数：
从数据库的计算公式中可以找到这些比例的计算方法，虽然很多情况下，这些比例的参考意义不大：
-- -- Instance Efficiency Percentages column ldscr format a50 column nl format a60 newline; select 'Instance Efficiency Percentages (Target 100%)' ldscr ,'~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~' ldscr ,' Buffer Nowait %:' dscr , round(100*(1-:bfwt/:gets),2) pctval ,' Redo NoWait %:' , decode(:rent,0,to_number(null), round(100*(1-:rlsr/:rent),2)) pctval ,' Buffer Hit %:' dscr , round(100*(1-(:phyr-:phyrd-:phyrdl)/:gets),2) pctval ,' In-memory Sort %:' , decode((:srtm+:srtd),0,to_number(null), round(100*:srtm/(:srtd+:srtm),2)) pctval ,' Library Hit %:' dscr , round(100*:lhtr,2) pctval ,' Soft Parse %:' , round(100*(1-:hprs/:prse),2) pctval ,' Execute to Parse %:' dscr , round(100*(1-:prse/:exe),2) pctval ,' Latch Hit %:' , round(100*(1-:lhr),2) pctval ,'Parse CPU to Parse Elapsd %:' dscr , decode(:prsela, 0, to_number(null) , round(100*:prscpu/:prsela,2)) pctval ,' % Non-Parse CPU:' , decode(:tcpu, 0, to_number(null) , round(100*1-(:prscpu/:tcpu),2)) pctval from sys.dual;从以上计算公式中可以找到：
Redo Nowait % = decode(:rent,0,to_number(null), round(100*(1-:rlsr/:rent),2)) = (1 – rlsr/rent) 100%这里的 rlsr = Redo Log space requests ，rent = Redo Entries 。从AWR报告中可以找到这两个统计值，计算一下这个比率,和报告中的计算值完全吻合：
Redo Nowait % = (1 – 133,566/44,038)*100% = -203.30 %
可是这个比率说明什么？
重做日志空间请求表明活动日志文件已满，Oracle正在等待为重做日志条目分配磁盘空间。这个比值越高说明在写出Redo条目时等待越多，当比率为负数，说明已经处于严重的写出等待之中。
那么到底是什么原因导致写出不畅呢？是因为Redo量太大，还是因为磁盘效率过低呢？通过数据库的其他统计数据可以进行进一步的分析。
这是一个 11.2.0.4的RAC集群环境，从数据库的概要信息来看，平均每秒仅仅有 7K左右的Redo日志，数据库的物理写也非常低，但是数据库的每秒DB Time却高达259.7 。
进一步的，从 Top Events数据信息中可以看出，整体的 I/O 非常缓慢，User/IO的平均等待时间高达 410毫秒，db file sequential read的平均等待时间也高达 1779毫秒，这说明I/O上出现了明显的瓶颈。
在整个数据库写出量并不大的情况下，整体I/O延时却非常高，在日志组同样处于高ACTIVE的情况下，出现大量的Log file Switch(checkpoint incomplete)等待。配合I/O层面的检查发现这个案例同样是存储损坏硬盘导致的I/O能力下降。
数据库的性能，是一个综合因素，在遇到异常分析时，也需要综合多方面的因素，才能够快速而准确的定位根因，解决问题。
DBASK，DBA的即时问答平台
往期精选
为什么SQL正在击败NoSQL，这对未来的数据意味着什么
缓存世界中的三大问题及解决方案
甲骨文因超过90亿美元的NetSuite交易起诉Larry Ellison和CEO Safra Catz
MySQL入门全套
Oracle 12c因bug导致ORA-04031问题处理过程 | 云和恩墨技术通讯精选
详述由ENQ：TX – ROW LOCK CONTENTION引起的全局死锁处理过程
不会SQL注入，连漫画都看不懂了
史上最全近百条Oracle DBA日常维护SQL脚本指令
数据泄露后，美国Web托管服务商Hostinger重置1400万用户密钥
史上最全数据库中间件详解
资源下载
关注公众号：数据和云（OraNews）回复关键字获取
help，30万+下载的完整菜单栏
2019DTCC，数据库大会PPT
2018DTCC , 数据库大会PPT
2018DTC，2018 DTC 大会 PPT
ENMOBK，《Oracle性能优化与诊断案例》
DBALIFE，“DBA 的一天”海报
DBA04，DBA 手记4 电子书
122ARCH，Oracle 12.2体系结构图
2018OOW，Oracle OpenWorld 资料
产品推荐
云和恩墨Bethune Pro2 企业版，集监控、巡检、安全于一身，你的专属数据库实时监控和智能巡检平台，漂亮的不像实力派，你值得拥有！
云和恩墨zData一体机现已发布超融合版本和精简版，支持各种简化场景部署，零数据丢失备份一体机ZDBM也已发布，欢迎关注。
云和恩墨大讲堂 | 一个分享交流的地方
长按，识别二维码，加入万人交流社群
请备注：云和恩墨大讲堂
作者：Enmotech
