黄远邦小y
作者黄远邦小y2017-06-15 10:20
技术总监, 中亦科技

ORA-01555错误启示录

字数 6466阅读 2651评论 0赞 0

分享预告

对于一个生产系统的告警,如果我们是一个初/中级工程师的水平,我们应该如何通过
已有的知识体系,结合合理的推测与验证,找到问题的根因,最后能提出具有中/高级水平的风险提示和运维建议呢?下面我们来看老K是如何与新手同事一步一步分析的,并最终提出非常有意义的。

技术的楔子

熟悉老K的朋友都知道老K平常很大一部分时间是待在某总行级数据中心支持日常运维工作,该总行数据中心拥有自己的DBA团队数十人,高手技术了得,但是还是新手比较多,日常的简单运维工作主要是是新手同事们去处理,希望他们从日常的运维case的处理过程中多学到一些技术知识,当然,他们在处理case的过程中没少给老K提问题,但是,在回答他们的问题过程中,老K倒是也狠狠的扎实了一把自己的知识面。

找不到的SQL

“老K,快来帮我看个SQL,这个SQL我都找不到!”在监控现场的同事又来求助了。
这是个什么问题?什么叫SQL找不到?老K先嘀咕着,很快赶到现场,稍微了解了一下,原来监控工具报某重要系统报了ORA-01555错误,需要分析一下,监控的来源是alert日志,原错误很简单;

就是一个再简单不过的报错了,sql_id是2c1fxpx8j6z9m,在alert日志中也已经打印出来了,唯一的遗憾是ORA-01555报错后面通常会有一个duration来告诉大家SQL报错前持续执行了多久。

“为什么说找不到呢,这不是sql_id都在这了吗?用我们平时说的方法查就可以了呀!”
“历史视图和AWRSQRPT都查过了,就是找不到呀。”
说着,他还给我看了一下他的查询结果:
QQ图片20170615100032.png

QQ图片20170615100032.png

看起来,历史视图中确实是找不到这个sql。
“找不到SQL暂且先不关注,我们可以先看看,什么情况下会导致ORA-01555呢?”
“我知道呀,….”
看起来讲的不错,我们平时的交流还是很有用的啊,该学的基本概念都很扎实了。

此处用个小面板啥的~取名叫科普ORA-01555啥的

  1. SQL语句执行时间过长,UNDO表空间过小,或者说是事务量过大等,在SQL执行过程中需要构造一致性读时,UNDO块已经被覆盖了;
  2. SQL语句执行过程中涉及延迟块清除时,无法确认块的事务提交时间与SQL发起时间的先后关系,导致报错;
  3. 其他已知或者未知的bug;

“讲的不错,就是太教条化了,就我们现在的系统来说,导致ORA-01555的可能原因在哪呢?”
“我们的系统UNDO表空间还是足够的,相关参数应该是没问题的,我们以前经常遇到的ORA-01555都是执行时间过长导致的,如果这个SQL执行时间很长的话,我肯定能在历史视图中查找到呀,那这里是不是bug或者其他原因呢?应该怎么去查呢?”

嗯,好像很有道理。一个SQL,我们在历史视图中查不到,那可不就是执行很短吗?不过老K有了上面的这些信息,对于上面的结论表示深深的不认同。
你觉得呢?不妨停下来看一看,仔细思考一下,你认同上面的结论吗?

为什么无法历史视图中查找到?

老K为什么会这么说呢?我们不妨来仔细看看之前的这个图?
QQ图片20170615100228.png

QQ图片20170615100228.png

我们可以看到:

  1. SQL文本是SELECT * FROM RELATIONAL("XXX"."XXX_RT_DET");
  2. 抛错后随后即出现了ALTER SYSTEM SET service_names='SYS$SYS.KUPC类似的语句;

那么这两个特征能说明什么呢,有经验的朋友可能一眼就看出来了,没错,这里显然是在导出时抛出的错,在抛错完成后,导出任务也就结束了。有了这个信息之后,我们再通过相关查询以及与应用维护团队的沟通后,找到了相关导出的日志后,我们看到当天的导出日志信息:
QQ图片20170615100401.png

QQ图片20170615100401.png

QQ图片20170615100418.png
QQ图片20170615100418.png

我们可以看到,非常符合,导出时间从0点开始,到11:09结束,而且导出日志中确实也是在导出XXX_RT_DET抛出了ORA-01555错误;
“然而,它为什么没有记录在ASH视图中呢?”
“稍安勿躁,且看我慢慢道来。”
QQ图片20170615100526.png

QQ图片20170615100526.png

我们可以看到,从v$active_session_history(ASH视图)通过过滤program like ‘%DW%’中找到导出过程在数据库中的活动会话,其中DW00从0点一直到11点都能采样到,也就是说ASH视图中记录了最近一整天的数据,一般来说如果sql执行过,那应该就会被采样到才对啊;
QQ图片20170615100632.png
QQ图片20170615100632.png

再看导出时执行的SQL是5m8ruy0agb6mw:
QQ图片20170615100658.png
QQ图片20170615100658.png

就是一个我们常见数据库导出的存储过程,不是具体的SQL语句,那我们是不是可以猜测说,2c1fxpx8j6z9m就是这个存储过程下的子语句呢?看起来还需要通过其它方式来论证了,而且目前还没法给出这个SQL执行了多久的答案,但是,我们可以认为,因为该SQL是导出的存储过程中的子语句,所以无法记录到相关历史视图中,也就无法确认该SQL执行时间就非常短。
可是根本问题还是没有答案,我们的SQL到底执行了多长时间呢?

换一个思路

虽然我们找到了应用没有关注的导出报错的信息,也能匹配上确实报了ORA-01555错误,但似乎还是不能帮我们确认SQL执行了多长时间,我们不妨换一个思路来看这个问题;

首先,语句在手,我们不妨看看正常情况下2c1fxpx8j6z9m的执行计划是什么样的:
QQ图片20170615100933.png

QQ图片20170615100933.png

嗯,全表扫描,没毛病;那么,这个表会有多大呢,是不是表本身就很小,执行的快但是报ORA-01555呢?
QQ图片20170615101040.png
QQ图片20170615101040.png

表可不小,89G,全表扫描可需要很长一段时间的呢。

另一方面,我们说导出也好,或者2c1fxpx8j6z9m的执行也罢,最终访问的不还是XXX_RT_DET对象吗;查不到SQL语句,我们不妨查查都在什么时间段内访问了这个对象了,以及在这个对象上的等待事件;
QQ图片20170615101118.png

QQ图片20170615101118.png

QQ图片20170615101137.png
QQ图片20170615101137.png

可以看到整个导出过程中,5m8ruy0agb6mw语句也就是导出过程对XXX_RT_DET对象的访问持续了10个小时,访问过程中主要的等待事件是db file sequential read;

“你看吧,之前的语句2c1fxpx8j6z9m应该是全表扫描,这里5m8ruy0agb6mw的等待事件是单块读,明显不一样嘛。我还是觉得,是不是导出过程中时是要通过5m8ruy0agb6mw来做,但是最后还是要另外执行2c1fxpx8j6z9m,然后报错了。”
“嗯,很有道理,对执行计划和等待事件的理解不错。不过我再看一条命令,就应该能给你一个确切的答案了。”
马上,见证奇迹的时刻就要到了……

一锤定音

前面因为有导出抛ORA-01555与alert中的匹配,已经可以知道语句2c1fxpx8j6z9m是在导出的过程中执行的了,但是还不能确认2c1fxpx8j6z9m和语句5m8ruy0agb6mw的关系,也就不能确认2c1fxpx8j6z9m到底执行了多长时间;
这里,我们其实已经知道了SQL的执行结束时间,但是其实,我们只需要知道SQL的开始时间,不就可以确认执行时间了吗?没错,就是这个方法;

QQ图片20170615101210.png

QQ图片20170615101210.png

这里可以看到,这条SQL的最近解析时间是00:52(正是ASH视图中采样到开始访问XXX_RT_DET对象的时刻),执行计划是2886419254(与explain出来的执行计划是一致的),解析的用户是expuser(导出的操作用户,从前面的用户),executions为空(意味着在00:52解析完后仅此一次失败的执行,而失败的原因当然是因为ORA-01555);

导出表XXX_RT_DET花费了10个小时,也就是2c1fxpx8j6z9m执行了10个小时,执行时间过长,在开门营业时间内,因为联机业务对表XXX_RT_DET存在大量的DML操作,导致了ORA-01555的出现。

“PERFECT!这样看来是不是所有的问题都得到解释了。”
“可是,它的等待事件是db file sequential read呀?这个你没有解释!”
“没错,这就是我们的问题所在,正常来说,全表扫描的话,不会出现那么多db file sequential read,也就不会那么慢,我们把这个等待事件解决了,问题就也解决了!”
“太累了,我要捋一捋思路。”

到这我们来看看,我们是如何一步一步走到现在这一步的:
  1. SQL报了ORA-01555,在ASH视图中找不到,但是其语句特征与导出密切相关;
  2. 找到导出日志,确实发现导出抛出了ORA-01555,时间也能匹配上;
  3. 通过ASH视图找到导出的5m8ruy0agb6mw并不是具体语句,那么它极有可能就调用了2c1fxpx8j6z9m;
  4. 通过2c1fxpx8j6z9m访问/导出时抛错的对象XXX_RT_DET的对象号,确认该表导出花费了10个小时;
  5. 最终通过2c1fxpx8j6z9m的解析时间/解析用户等信息与其他情况匹配,确认SQL 2c1fxpx8j6z9m就是从00:29执行到了11:09;
  6. Sql的执行计划是全表扫描,却出现了大量db sequential read,这正是导致这一问题的根本原因;目前我们的关注点也就转移到了等待事件的分析上了。

可恶的行迁移

那么,一个全表扫描的执行计划跑出来的sql通常会有哪些情况导致db file sequential read呢?通常有几种:

  1. 表上有LOB字段
  2. 表数据已经大量缓存到buffer cache中,导致direct path read/db file scatterd read时无法连续,而产生部分db file sequential read;
  3. 表上数据存在大量的行迁移/行链接的情况
  4. 还是各种bug

简单一查就能得出结论,第一条和第二条不符合我们目前面临的情况,那我们来看看怎么定位有没有行迁移呢?其实很简单,我们收一个导出时段的AWR报告,查找关键字continued row,如下:
QQ图片20170615101303.png

QQ图片20170615101303.png

可以看到存在行迁移的情况,不过这并不能说明就是这个表上存在XXX_RT_DET行迁移;这样,我们不妨通过db file sequential read等待事件中的p1、p2来做个数据块的dump确认了;
QQ图片20170615101326.png
QQ图片20170615101326.png

QQ图片20170615101343.png
QQ图片20170615101343.png

其中,需要说明的是,nrow代表的是块中记录的行数,而nrid/hrid分别代表的是行迁移指向的目标数据块和行迁移的源头块,hrid/nrid后的十六进制数字可以使用dbms_utility包转换为文件号和块号,此处不再赘述;单从此块可以看出,该表的行迁移数量还是很高的;做了多个块的dump看,确实每个都存在多条记录有行迁移的情况;
另外,我们根据等待事件粗略地估算一下整体的行迁移比例:
QQ图片20170615101412.png
QQ图片20170615101412.png

可以看到多块读的采样次数是99,单块读的采样次数是34872,数据库中db_file_multiblock_read_coun参数的值为16;如果忽略单次等待时间的影响,我们可以说表中的行迁移的比例可以简单计算为34872/(99*16+34872)=95%,也就是说表中有95%的块存在行迁移的情况;太高,真实可恶的行迁移!

根因定位

在了解上述情况后,我们再回头来检查应用以往的导出日志,我们还是会发现,XXX_RT_DET表的导出总是最晚的,不过并不一定报ORA-01555,不过现在ORA-01555已经并不是我们关注的重点了,因为我们已经知道,如果让导出不跑到联机时段,是不不会报ORA-01555的;而且,该表的导出偏晚并不是一个逐步的过程,是由某一天突然变化的,那么问题又来了,这又是为什么呢?
因为历史太久,数据库的历史视图已经看不到当时的变化前后的情况了,这里就需要把几种产生行迁移的可能给应用团队列出来,看看咱们的业务符合哪个特征:

  1. 频繁的update表,而且update的字段存在字段长度变长的现象;
  2. 使用modify修改过表的列或者为表增加过非空的列;
    将可能的原因列出来之后,应用团队通过自己的变更排查最终找到了确实是导出变慢的前一天有过为表增加字段并且字段存在默认值的情况!

“不过,增加一个字段会导致95%的块都存在行迁移的情况吗?太厉害了吧!”
“嗯,很有道理!这个我们就需要查一查了!”
不查不知道,这里简单搜一下MOS,就能看到下面的文章(截取精华部分):
QQ图片20170615101535.png

QQ图片20170615101535.png

原来,如果有行迁移,而导出时使用默认的DIRECT_PATH方式导出的话,db file sequential read的等待事件会特别特别高,所以前面的行迁移估算可能需要修正!

这样,我们这里的根本原因,我们可以认为是两条:

  1. 表上做过列修改,导致表本身产生了大量的行迁移!
  2. 数据泵导出时,默认对该表使用DIRECT_PATH方式导出,导致导出非常慢!

风险提示与排查方法

其实我们看到上述案例中,行迁移导致的数据泵导出缓慢只是其中一种现象;同理,我们可以知道,如果一个表上存在大量的行迁移,可能会导致表的访问性能出现严重下降,简单来说,当SQL访问到某条记录在A块中,但是该条记录又被链接到B块,那么这时SQL访问一条记录就读取了两个块,而且,如果是类似本CASE中的全表扫描,还会出现高比例的db file sequential read等待事件的情况;所以,我们应该要规避行迁移;
如何规避行迁移:

  1. 业务逻辑上存在update导致字段长度变长的那些表,我们将其pct_free值设置的更大一些;
  2. 对于存在需要修改列定义长度变化,以及新增列的情况,我们建议尽量避免在原表上修改,而通过构造新表来实现;
  3. 针对于单条记录非常大的,我们建议使用单独的更大块表空间来存放这类表(实际上这里就是针对的行链接的情况)

那么,对于已有的系统,我们应该如何针对单个表来排除呢?像上文提到的使用导出时的比例统计因为bug原因可能并不准确;需要更精确的方法:

  1. 官方命令里有一个analyze table XXX list chained rows的方法,但是该命令会对表持有表级锁,进而阻塞其他针对该表的DML操作;
  2. 如前文所提到的,我们可以通过table fetch continued row统计值来统计表中存在行迁移的行数;具体如下:
    1) 已知一个会话sid,执行下述语句:
    QQ图片20170615101616.png

    QQ图片20170615101616.png

    2) 然后针对想检查的表做一个全表扫描,注意需要加上full的hint
    QQ图片20170615101639.png
    QQ图片20170615101639.png

    最好先确认该语句确实是全表扫描;
    3) 再次查看tablefetch continued row的值
    QQ图片20170615101725.png
    QQ图片20170615101725.png

    4) 前后两次值相减即为该表中的行迁移/行链接的条数,214-13即该表中行迁移的记录数为201条。

    解决方案

    针对目前的情况,我们的解决方案分两部分:
    临时性的方案:针对XXX_RT_DET表,我们单独拎出来导出,指定导出的access_method为external_table模式,避免再出现导出时间非常长的情况,进而避免ORA-01555的情况;但是该方案只能是针对导出的。
    根本性解决方案:针对XXX_RT_DET表,及检查到的类似的表,通过DBMS_REDEFINITION的包重定义表,消除行迁移;其他表如果存在日常业务大量导致字段长度变长的update操作,在重定义时,增加表的pct_free值。

目前,该表已经重定义完成,完成后表的大小变化不多,但是导出已经从10个小时下降到十几分钟。

如果觉得我的文章对您有用,请点赞。您的支持将鼓励我继续创作!

0

添加新评论0 条评论

Ctrl+Enter 发表

作者其他文章

相关文章

相关问题

相关资料

X社区推广