|
|
|
|
公众号矩阵

Log File Sync等待超高案例浅析

监控工具DPA(SolarWinds的Database Performance Analyzer)发现海外一台Oracle数据库服务器DB Commit Time指标告警,超过红色告警线(40毫秒左右,黄色告警线是10毫秒,红色告警线是20毫秒)。

作者: 潇湘隐者 来源:DBA闲思杂想录 |2021-02-06 13:00

本文转载自微信公众号「DBA闲思杂想录」,作者潇湘隐者 。转载本文请联系DBA闲思杂想录公众号。 

监控工具DPA(SolarWinds的Database Performance Analyzer)发现海外一台Oracle数据库服务器DB Commit Time指标告警,超过红色告警线(40毫秒左右,黄色告警线是10毫秒,红色告警线是20毫秒),如下截图所示,生成了对应时段的AWR报告,分析时发现Top 5 Timed Events里面,log file sync等待事件的平均等待时间为37毫秒,log file parallel write等待事件的平均等待时间为40毫秒

如果对'Tanel Poder::Understanding LGWR, Log File Sync Waits and Commit Performance'这篇文章所讲述的内容很熟悉的话(经典图如下),那么通过等待事件log file sync与log file parallel write的Avg Wait(ms)指标:37ms & 40ms,基本上就可以判断redo log所在的磁盘I/O出现了性能问题

然后在用lfsdiag.sql脚本分析一下详细的统计数据,如下所示:

  1. HISTOGRAM DATA FOR LFS AND OTHER RELATED WAITS: 
  2.   
  3. APPROACH: Look at the wait distribution for log file sync waits 
  4. by looking at "wait_time_milli". Look at the high wait times then 
  5. see if you can correlate those with other related wait events. 
  6.   
  7.    INST_ID EVENT                                    WAIT_TIME_MILLI WAIT_COUNT 
  8. ---------- ---------------------------------------- --------------- ---------- 
  9.          1 log file sync                                          1       4363 
  10.          1 log file sync                                          2        835 
  11.          1 log file sync                                          4       1650 
  12.          1 log file sync                                          8       4937 
  13.          1 log file sync                                         16     146252 
  14.          1 log file sync                                         32     606674 
  15.          1 log file sync                                         64     263377 
  16.          1 log file sync                                        128     253254 
  17.          1 log file sync                                        256          2 
  18.          1 log file switch completion                             1        124 
  19.          1 log file switch completion                             2          9 
  20.          1 log file switch completion                             4         19 
  21.          1 log file switch completion                             8         21 
  22.          1 log file switch completion                            16         35 
  23.          1 log file switch completion                            32         97 
  24.          1 log file switch completion                            64        133 
  25.          1 log file switch completion                           128        326 
  26.          1 log file switch completion                           256       1736 
  27.          1 log file switch completion                           512       3042 
  28.          1 log file switch completion                          1024       2020 
  29.          1 log file parallel write                                1          0 
  30.          1 log file parallel write                                2          0 
  31.          1 log file parallel write                                4         80 
  32.          1 log file parallel write                                8       2142 
  33.          1 log file parallel write                               16     170987 
  34.          1 log file parallel write                               32     779205 
  35.          1 log file parallel write                               64     311463 
  36.          1 log file parallel write                              128      79688 
  37.          1 log file parallel write                              256      42763 
  38.          1 log file parallel write                              512      13052 
  39.          1 log file parallel write                             1024      20468 
  40.          1 log file parallel write                             2048      14020 
  41.          1 log file parallel write                             4096        921 
  42.          1 log file parallel write                             8192         96 
  43.          1 log file parallel write                            16384         18 
  44.          1 log file parallel write                            32768         18 
  45.          1 log file parallel write                            65536          8 
  46.          1 log file parallel write                           131072          2 
  47.          1 LGWR wait for redo copy                                1       8516 
  48.          1 LGWR wait for redo copy                                2         20 
  49.          1 LGWR wait for redo copy                                4         19 
  50.          1 LGWR wait for redo copy                                8         20 
  51.          1 LGWR wait for redo copy                               16         11 
  52.   
  53. ORDERED BY WAIT_TIME_MILLI 
  54.   
  55.    INST_ID EVENT                                    WAIT_TIME_MILLI WAIT_COUNT 
  56. ---------- ---------------------------------------- --------------- ---------- 
  57.          1 log file sync                                          1       4363 
  58.          1 log file switch completion                             1        124 
  59.          1 log file parallel write                                1          0 
  60.          1 LGWR wait for redo copy                                1       8516 
  61.          1 log file sync                                          2        835 
  62.          1 log file switch completion                             2          9 
  63.          1 log file parallel write                                2          0 
  64.          1 LGWR wait for redo copy                                2         20 
  65.          1 log file sync                                          4       1650 
  66.          1 log file switch completion                             4         19 
  67.          1 log file parallel write                                4         80 
  68.          1 LGWR wait for redo copy                                4         19 
  69.          1 log file sync                                          8       4937 
  70.          1 log file switch completion                             8         21 
  71.          1 log file parallel write                                8       2142 
  72.          1 LGWR wait for redo copy                                8         20 
  73.          1 log file sync                                         16     146252 
  74.          1 log file switch completion                            16         35 
  75.          1 log file parallel write                               16     170987 
  76.          1 LGWR wait for redo copy                               16         11 
  77.          1 log file sync                                         32     606674 
  78.          1 log file switch completion                            32         97 
  79.          1 log file parallel write                               32     779205 
  80.          1 log file sync                                         64     263377 
  81.          1 log file switch completion                            64        133 
  82.          1 log file parallel write                               64     311463 
  83.          1 log file sync                                        128     253254 
  84.          1 log file switch completion                           128        326 
  85.          1 log file parallel write                              128      79688 
  86.          1 log file sync                                        256          2 
  87.          1 log file switch completion                           256       1736 
  88.          1 log file parallel write                              256      42763 
  89.          1 log file switch completion                           512       3042 
  90.          1 log file parallel write                              512      13052 
  91.          1 log file switch completion                          1024       2020 
  92.          1 log file parallel write                             1024      20468 
  93.          1 log file parallel write                             2048      14020 
  94.          1 log file parallel write                             4096        921 
  95.          1 log file parallel write                             8192         96 
  96.          1 log file parallel write                            16384         18 
  97.          1 log file parallel write                            32768         18 
  98.          1 log file parallel write                            65536          8 
  99.          1 log file parallel write                           131072          2 
  100.   
  101. REDO WRITE STATS 
  102.   
  103. "redo write time" in centiseconds (100 per second
  104. 11.1: "redo write broadcast ack time" in centiseconds (100 per second
  105. 11.2: "redo write broadcast ack time" in microseconds (1000 per millisecond) 
  106.   
  107. VERSION              INST_ID NAME                                                     VALUE        MILLISECONDS 
  108. ----------------- ---------- ---------------------------------------- --------------------- ------------------- 
  109. 10.2.0.5.0                 1 redo write time                                        9551524        95515240.000 
  110. 10.2.0.5.0                 1 redo writer latching time                                   51 
  111. 10.2.0.5.0                 1 redo writes                                            1434931 
  112.   
  113. AWR WORST AVG LOG FILE SYNC SNAPS: 

从上面数据可以看到,log file sync等待事件数量最多的是32ms这个区间的,log file parallel write等待事件发生最多的也是32ms这个区间的,其实这个值已经远远超过了正常值7ms,极其不正常。log file parallel write事件是LGWR进程专属的等待事件,发生在LGWR将log_buffer中的重做日志信息写入联机重做日志文件组的成员文件,LGWR在该事件上等待该写入过程的完成。该事件等待时间过长,说明日志文件所在磁盘缓慢或存在争用。log file sync和log file parallel write是相互关联的。换句话讲,假设log file parallel write的时间非常长,那么必定导致log file sync等待时间拉长。如果log file parallel write 等待非常高,那么可能一般是物理磁盘I/O的问题

另外,我们也检查了一下redo log的切换频率,如下所示,redolog_sitch_time.sql查看发现redo log切换的次数并不频繁,生成的归档日志的量也并不大。大部分时候一小时切换零次或一次。

然后我们找了一台服务器(上述指标正常的服务器)简单对测试了一下IO的速度,这个方法极其简单,就是看看生成一个大文件需要多长时间,简单测试一下I/O性能(没有考虑cache等,测试采样也不详尽),但是对比数据也基本能验证、反馈磁盘IO存在问题)。

问题服务器:

  1. time dd if=/dev/zero of=./test bs=512k count=2048 oflag=direct 
  2.  
  3. 2048+0 records in 
  4.  
  5. 2048+0 records out 
  6.  
  7. 1073741824 bytes (1.1 GB) copied, 88.271 seconds, 12.2 MB/s 
  8.  
  9.   
  10.  
  11. real    1m28.273s 
  12.  
  13. user    0m0.010s 
  14.  
  15. sys     0m0.655s 

对比服务器(正常的服务器):

  1. time dd if=/dev/zero of=./test bs=512k count=2048 oflag=direct 
  2.  
  3. 2048+0 records in 
  4.  
  5. 2048+0 records out 
  6.  
  7. 1073741824 bytes (1.1 GB) copied, 2.48344 seconds, 432 MB/s 
  8.  
  9.   
  10.  
  11. real    0m2.485s 
  12.  
  13. user    0m0.004s 
  14.  
  15. sys     0m0.386s 

如上对比所示,两台服务器生成同样一个大小文件,耗费的时间,I/O性能差别非常大,完全验证了告警的服务器所在的存储I/O存在性能问题,但是公司分工非常明确,DBA也不清楚底层存储出了什么问题,只能将这个问题反馈出来,等待海外负责维护系统和存储的同事的回复。

【编辑推荐】

  1. 6个巨好用的Java程序员高效工具
  2. Web常用开发工具有哪些?常用工具推荐
  3. Python疫情监控完整项目实战
  4. IBM System 3650 M4服务器规划RAID安装win2008R2(韩利辉老师讲解)
  5. 用Python制作一个数据预处理小工具,多种操作,一键完成,非常实用!
【责任编辑:武晓燕 TEL:(010)68476606】

点赞 0
分享:
大家都在看
猜你喜欢

订阅专栏+更多

数据湖与数据仓库的分析实践攻略

数据湖与数据仓库的分析实践攻略

助力现代化数据管理:数据湖与数据仓库的分析实践攻略
共3章 | 创世达人

5人订阅学习

云原生架构实践

云原生架构实践

新技术引领移动互联网进入急速赛道
共3章 | KaliArch

31人订阅学习

数据中心和VPDN网络建设案例

数据中心和VPDN网络建设案例

漫画+案例
共20章 | 捷哥CCIE

217人订阅学习

视频课程+更多

订阅51CTO邮刊

点击这里查看样刊

订阅51CTO邮刊

51CTO服务号

51CTO官微