分享

出奇制胜还是水到渠成?-从一个常见ORA错误的分析过程看工程师的必备技能-技术人生系列第五十一期-我...

 nanatsg 2018-06-21

前言:

时间一晃已经来到了6月,技术人生系列文章已经半年没有更新了,在过去的半年时间里,我们技术人生系列文章的作者们一直奋战在工作一线,同时不忘积累和总结,为我们的文章提供更深厚的底蕴;如今,技术人生系列将携中亦课堂正式回归,依旧严谨深刻,生动再现客户现场处理问题的点点滴滴,希望在传递更多知识点的同时给大家带来更多深度的思考。

在这里,首先感谢一直以来支持技术人生系列的小伙伴们,你们的支持与转发是我们持续分享的动力。


一、 问题来了

某个周五的悠闲晚上,正在窗前思考人生的老k,接到了一个客户的问题,客户现场的DBA处理了有一些日子了,准备在周末的时间窗口重启来解决该问题,不过客户还是很谨慎的嘱咐说,估计重启后该问题可能就没法重现了,我们需要在重启前找到问题的触发根因,避免再次出现此类问题。

那么具体问题是什么呢?客户描述的信息如下:

应用在执行某些SQL的时候经常出现ORA-01410的错误,但是这样的错误只是偶尔出现,手动执行的时候并不一定能遇到,因为涉及到的表可能有多个,经过前期分析,怀疑是内存错乱导致的,预计在下个周末进行操作系统重启来解决该问题,目前可以试着从数据库层面来分析该问题,看能不能有什么发现;

从跟客户的交流来看,似乎已经被这个问题折磨了很久,而现在已经对分析这个问题的原因不报太大的希望,只是报着试一试的心态来分析这个问题;

客户只是报着试一试的心态给我们转交了这个问题,但是我们作为服务商,就必须以全力以赴的态度来解决客户的问题。

 

二、 摸清情况

要尽快解决问题,只能远程分析,于是我联系到客户的接口DBA,通过远程连接到客户的服务器,了解了相关环境,分析问题;具体情况如下:

操作系统:REDHAT 6

数据库:oracle 10.2.0.5 单节点

具体现象:某些表的访问报ORA-01410,很明显的对于一个SQL语句,如果在SQL中去掉该表,整个SQL就不会报错;另外存在这种情况的表有多个;该现象不会一直出现,偶尔会出现;

首先跟客户DBA沟通,拿到了几个存在该问题的SQL,直接执行这些语句,在试验很多次后,确实遇到了好几次错,特别是执行时间较长的SQL;

选取其中较简单的一个语句,其语句和执行计划如下:

这个SQL语句中,出现问题的表是XXXstatelog,这个表比较小,只有60M;

而出现的ORA-1410错误是什么呢?

[oracle@test10g ~]$ oerr ora 1410

01410, 00000, 'invalid ROWID'

// *Cause:

// *Action:

ORA-1410错误是因为有无效的ROWID,ORACLE并未提示出现该类情况的可能原因;

 

三、 交流与搜索

现在基本情况了解了,不过客户DBA已经分析了有一些时间了,而且他们更了解整体的应用、硬件以及相关的变化情况,在接手现场问题的时候,我都习惯多与客户DBA进行更多的沟通,一方面可以借鉴他们的已有经验,避免重复发明轮子,另一方面,旁观者清,也许也可以给他们指出一些纰漏之处,发现问题的关键;总之,充分利用已有的资源来快速分析问题,更何况网络时断时续的,相关操作还需要客户帮忙执行和收集。

问:最近有做过什么变化吗?

答:数据库并未做什么调整,对于应用版本的调整了解的并不多;

 

问:应用端除了这个报错外,还有什么其他的问题吗,如wrong result之类的?

答:并没有这样的反馈;

 

问:这样的报错有什么规律吗?

答:只知道出现这样情况的表又五六个,并没有发现时间上、频度上有什么特别的规律;通常失败了的操作,再执行一次,好像就并没有什么问题。

 看来并没有更多信息,那先思考一下吧;再看看这个报错:

[oracle@test10g ~]$ oerr ora 1410

01410, 00000, 'invalid ROWID'

// *Cause:

// *Action:

两个关键信息:ROWID和invalid

首先,什么时候会用到ROWID呢,通常来说,ROWID是一个伪列,并不存在于表的数据块中,似乎只有索引的叶子块中才会存储ROWID用以定位数据位置;

另外,INVALID,似乎意味着存储在索引中的rowid出现了异常,或者在读到内存中后出现了混乱?

 

没有更多信息的情况下,不如借鉴MOS上已有的经验,看看导致ORA-1410的现象都有哪些情况,于是找到了一篇解释该类错误的文章:

 

其中描述了ORA-1410的触发情况:

 

从这里给出的一系列描述看,主要可能的原因包括:数据块损坏、索引块损坏、内存损坏、DDL操作导致的异常以及各种bug;

从我们遇到的情况看,数据块/索引块的损坏似乎不存在,因为多次执行并不会总是出现错误;

在先不考虑bug的情况下,就只有DDL操作或者内存异常的情况了,那么是不是DDL操作导致的问题呢?

 

四、思考与推断

目前看到的这篇MOS文档讲述的还算比较全面,于是我先发送给客户DBA讨论;

然而,客户DBA表示,已经仔细阅读过这篇文档了,而且他们跟应用沟通过,出现问题的时段应该是不会有DDL操作,只会在晚上的固定一个时间段存在一些TRUNCATE操作;另外,他们也在自己的环境也测试过了,truncate并没有导致ORA-1410的报错,而且以过往的经验来看,以前遇到过的truncate导致的查询错误报的都是ORA-8103;所以,这里客户认为可能还是内存的问题或者ORACLE的bug导致的;看来客户DBA还是很有经验的。

 

对于客户的看法,我是有几分认同的:

1. ORA-1410我似乎很少遇到过,以前遇到过都是索引异常的情况;

2. 另外truncate导致SQL执行报错的情况通常报的是ORA-8103,对象不存在;

3. 如果真的是没有意识到的truncate操作,那前端业务可能已经受到影响了;

 

这样好像不应该是truncate导致的,但是现象上时好时坏又是怎么产生的呢?如果真的是内存中的异常,那它是怎么好的呢?它的触发条件是什么呢?

趁着与客户网络断断续续的情况,我开始了独自思考。

 

根据mos 文档的描述问题出现的原因主要有几类:

1. 数据库中存在着频繁的DDL 语句。

2. 某个索引或者数据块出现了损坏,也就是坏块导致的问题

3. 硬件层面,例如:内存出现了问题 

4. Oracle 的bug

 

再仔细回顾一下这个问题的现象逐一思考各种可能原因:

1. DDL语句导致的,但是用户已经确认了DDL语句只会在特定的时间执行。

2. 某个数据块或者索引块损坏,这个可以通过下面的语句来进行判断

SQL>analyze table validate structure cascade;

在和用户确认过之后,发现着命令并没有返回坏块相关的信息,基本可以排除坏块的可能。

3. 内存层面的问题,如果是内存层面的问题,更大的可能性是当访问某个表的某一些数据块的时候会出现问题。而且硬件工程师也确认了,内存并没有问题,所以,也基本上可以排除,内存出现问题的可能性。

4. Oracle 的 bug,在 mos上进行了一些搜索之后,也没有找到类似的问题。

 

五、 测试与模拟

经过上面的思考后,我还是认为truncate操作导致异常的可能性更大,对于这样的case如果能重现出来,相信会非常有说服力,嗯,这样的重现应该是比较简单的,不如直接重现;

 

于是,我开始在自己的测试环境,同样是10g数据库,Redhat linux环境中来重现,实现操作如下:

 

1. 创建表,生成更多数据,创建索引

create table test0611 as select * from dba_objects ;

 insert into test0611 as select * from test0611;--执行多次

 create index T0611_IDX1 on test0611(object_id);

2. 构造通过索引访问数据的语句

因为rowid只有在索引中才会用到,我们这里使用hint的方式,让SQL执行过程中先访问索引,再通过索引返表,这是一个比较差的执行计划这个SQL执行时间会比较长;

3. 在进行上述查询的过程中,我们在另一个会话中执行trauncate操作

truncate table test0611;

 4. 观察第2步的查询操作,确认是否出现报错

 

先后执行了几次上述模拟案例测试,并未能重现ORA-1410的错误或者其他错误,查询正常完成。问题似乎陷入了僵局,难道truncate 语句真的不是问题的原因? 我们反过来想一下,如果要推翻自己的分析,最直接的办法就是拿到更多的证据来证明自己的分析是错误的。那就再来搜集更多的信息吧。

 

 

六、 意外发现与解决问题

在自己的环境没能快速重现出问题来,看来还得到生产环境继续挖掘其他线索,争取在重启前搜集足够的信息;

 

在查看的过程中,意外发现,这个环境上竟然部署了OGG(oracle goldengate),而它是作为源端将整个SCHEMA的表同步到目标端的ORACLE实例,这似乎给定位问题带来了转机:如果是内存层面的异常,理论上是不会传导到ogg目标端的ORACLE实例上的;而如果是表本身或者索引本身的问题,那么在ogg目标端的ORACLE实例上也就应该能重现;

 

接下来,我们就在ogg目标数据库上执行相关查询,经过半个小时的测试发现,同样的语句在ogg目标数据库上也会报错,不过与生产环境不同的是,报错信息是ORA-8103;

 

[oracle@11g dmp]$ oerr ora 8103

08103, 00000, 'object no longer exists'

// *Cause:  The object has been deleted by another user since the operation

//          began, or a prior incomplete recovery restored the database to

//          a point in time during the deletion of the object.

// *Action: Delete the object if this is the result of an incomplete

//          recovery.

 

ORA-8103就比较熟悉了,通常是因为对象被drop掉或者truncate掉导致的;同时,我们发现目标数据库的版本是11g的数据库,顿时我们觉得问题就简单多了,在11g数据库中,存在一个参数enable_ddl_logging来控制是否将DDL操作记录到alert日志中,而这源端的10g数据库时没有这个功能的;

 

于是,我们在目标端数据库实例中调整了该参数后,alert日志中很快就捕捉到了truncate的信息;

Tue Jun 01 20:11:18 2018

ALTER SYSTEM SET enable_ddl_logging=TRUE SCOPE=BOTH;

Tue Jun 01 20:16:34 2018

truncate table XXXstatelog

至此,似乎就真相大白了,正是应用在代码里加了truncate的操作,比较频繁的truncate操作导致相关表的查询出现报错中断,接下来客户DBA要做的就是和开发沟通其truncate操作的目的,并对此进行相应的调整;

 

将频繁的truncate操作去掉,改成定期的truncate操作后,便没有再在业务时间段出现ORA-1410或者ORA-8103的错误了,这样事情就告一段落了。

 

七、 研究与重现

客户的问题是解决了,但是新的疑惑又开始萦绕在我的脑中,只不过现在没有客户的压力,没有时间的紧迫性,可以静下心来慢慢研究这个问题:

1. 为什么在我的环境中测试,truncate并没有影响到select操作,而客户环境中的truncate操作却影响到了select操作,那么这种区别来自于哪呢?

2. 对于10g环境报错信息为ORA-1410,而对于11g环境,则报的是ORA-8103,这两者的区别又是什么呢?

 

要回答第一个问题,我们还是先要了解一下truncate操作对表/索引到底做了什么:

1) 对于普通的堆表来说,truncate操作只是截断了表和索引,主要是修改了数据字典信息和段头信息; 

2) 对于我们简单的通过索引访问表数据的情况,在查询过程中执行truncate了后,truncate修改了段头信息,而我们需要访问的具体的索引块和数据块都没有发生改变情况下,自然是不会发生报错的;

3) 而我们将truncate的数据块覆盖掉,或者让我们的查询需要访问到段头信息时,ORA-1410或者ORA-8103的报错就出来了;

理解了上面的几点,我们再来重现错误,就很简单了;下面我们来构建几个重现场景:

 

首先构造两张表,其中T06182表比较大,T06183表比较小,在object_id列上存在索引:

构造查询用的语句:

测试场景一:

一个会话执行简单的查询,另一个会话在查询期间执行了truncate操作,truncate操作完成后,查询能继续完成而没有报错;

(注:truncate的完成时间是11:13:59,在查询过程中,查询未受影响)

测试场景二:

一个会话执行简单的查询,另一个会话在查询期间执行truncate操作,truncate操作完成后,继续执行flush buffer cache 的操作,出现ORA-1410报错;

 

(注:truncate完成时间是11:22:06,flush buffer_cache的开始时间是11:22:15,同期查询报错)

测试场景三:

一个会话执行简单的查询,另一个会话在查询期间执行truncate操作,truncate操作完成后,继续执行 insert操作,出现ORA-1410报错;

(注:truncate完成时间是11:20:05,insert执行时间是11:20:16,同期查询报错,truncate后插入数据,extent被重用,导致访问数据时报错)

 

对于第二个问题,其实在充分理解了ORA-1410和ORA-8103的错误后,我们也就能知道他们的共同之处了,看起来只是在10g报ORA-1410,而11g报ORA-8103;

 

可以看到,同样的case,在11g数据库环境中出现的是ORA-8103错误;

而且MOS上还可以找到类似的一些文章来说明这个问题:


小  结

从整个问题来看,其实就是一系列truncate引发的问题,在最开始阶段怀疑到最后确认问题,中间走了一些弯路,导致问题的分析显得有些复杂;马后炮的来看,其实如果怀疑到truncate,我们直接去查看对象的last_ddl_time和DATA_OBJECT_ID,就可以直接的定位了;亦或者在处理问题时没有那么紧张,仔细阅读MOS 的1410.1文档,也能很快的确定几个方向,并逐一去确认;然而,这正是高压力下实时处理问题和事后分析的区别所在,庆幸的是,正好因为这个问题还算费了一些时间,反而让我进一步试图去重现问题,反思整个过程,进而有了更多发现,总结一下,也是一线工程师的一些必备技能,写给自己也分享给大家:

1. 对于原理的理解,在解决问题特别是想重现故障的时候,极为重要,否则很有可能出现重现达不到预期效果而导致错误结论的情况;

2. 对于实时处理问题,即使压力再大,时间再赶,对于不了解的细节,对于未读过的文章,还是需要静下心来仔细阅读,否则就有可能错失那个让你一蹴而就的知识点;

3. 试着去重现你遇见的问题,这会比解决问题让你印象更加深刻。

    本站是提供个人知识管理的网络存储空间,所有内容均由用户发布,不代表本站观点。请注意甄别内容中的联系方式、诱导购买等信息,谨防诈骗。如发现有害或侵权内容,请点击一键举报。
    转藏 分享 献花(0

    0条评论

    发表

    请遵守用户 评论公约

    类似文章 更多