问题背景:
一早刚上班,应用开发就在群里就发了一个语句执行ORA-01555的报错,说他们的一条跑批语句昨天晚上跑了1个小时还没跑完,最后出现了错误ORA-01555: snapshot too old: rollback segment number,让我们帮忙看一下这条跑批语句
问题分析:
应用跑批的程序是调用了一个存储过程,存储过程里面是将一条insert into select * from tab@dblink的语句改写成每10W批量插入一次的形式,通过dblink将目标端数据库表TAB_B查询的全量数据批量插入到本地数据库表O_TAB_B里面,应用执行返回的ORA-01555报错是dblink指向的目标端select查询
查看目标库表TAB_B的查询语句性能,由于查询语句没有where条件,所以肯定是一个全表的扫描操作,执行计划基本没有分析的必要,直接查看目标库的性能以及语句执行消耗,从语句的历史执行消耗来看,执行时间正常查询1600W行的数据大概在60秒左右,执行的效率还是不错的
查看语句的等待事件,没有异常的等待事件,SQL*Net more data to client查询数据发送给客户端的等待次数也很低,说明本地和目标端之间的网络也没有存在瓶颈,语句在目标库的执行性能,看起来是正常的
接下来分析本地数据库的数据插入执行情况,可以看到语句在本地数据库的执行效率很差,波动很大,平均10w一次的插入数据需要花费10秒-185秒的时间,应该是跑批语句的本地的数据插入插入过慢,导致dblink目标端的查询语句回滚段被覆盖了
分析语句插入阶段的执行等待事件,可以看到语句在执行期间出现了很多的log buffer space日志缓冲区的申请等待,这里难道是数据库的log buffer设置过小?,继续往下分析
拿了一份跑批语句执行期间的awr报告进行分析,可以看到问题期间的每秒redo生成量接近31M,log buffer的配置44M,这个配置相对日志的生成量有点小,但只要日志写磁盘的IO性能不是特别差的话,应该问题也不大,不至于导致这么多的log buffer space等待
查看跑批时间段的等待事件,都是跟日志文件的操作等待有关,log buffer space写日志缓存等待,log file switch completion日志切换等待,log file sync日志同步写磁盘日志等待,同一时间出现这么多的日志等待事件,特别是log file sync的平均等待达到635ms,很有可能是日志的写IO能力出现瓶颈
查看日志写的延时,跑批执行期间log file parallel write平均延时高达653ms,lgwr进程的后台日志也不断的出现日志写耗时警告,很明显,日志文件的IO性能出现了问题
通过osw iostat进一步确认磁盘的等待情况,可以看到部分的磁盘写平均等待很高。在磁盘写入压力不大的情况下,延时可以达到几十ms,进一步检查发现,这些出现延时比较高的磁盘都属于归档磁盘组ARCHDG
查看日志文件的配置,可以看到每个日志配置了两组路径,分别为DATADG以及ARCHDG,而写入日志文件慢,应该就是出现在写入ARCHDG磁盘
问题解决:
跟存储进一步了解底层的磁盘配置情况,DATADG使用的是NVME盘,而ARCHDG使用的是SAS盘,并且阵列卡写策略是使用直写的,没有用到阵列卡的缓存,所以ARCHDG的磁盘IO写性能很差
知道ARCHDG磁盘IO写性能很差之后,我们做了一个小的优化调整,将redo日志的路径进行了修改,只配置DATADG的路径,不往ARCHDG路径写,调整之后,立马就看到效果,平常数据库空闲log file parallel write延时都要11ms,调整之后只剩下0.29ms
到了晚上跑批,跑批的insert语句速度也得到大幅度的提升,10w一次的数据插入只需要花费3秒-5秒的时间,log buffer space的等待事件也消失了,整个跑批时间提升了10倍以上。