ADG备库批量查询失败的原因分析(r8笔记第33天)

目前线上有一套环境是10gR2的，采用了一主两备的架构。在其中一个备库上每天凌晨会开放一个窗口运行一些批量的查询，目前使用dg broker会在指定的时间把备库置为read-only,查询完毕之后修改为online状态。 但是近几天开发的同事突然找到我说，最近几天开始批量查询会频频报错，希望我帮忙查看一下。 语句运行报错，听起来原因应该很简单吧，最大的可能就是备库没有打开，或者是ddl,dml语句之类的。但是看到错误日志，让我着实有些奇怪。 错误日志如下，可以看到是一条查询语句。 [2016.03.06 04:10:02.352]org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [select bind_flag from test_billing where cn_master=?]; SQL state [60000]; error code [604]; ORA-00604: error occurred at recursive SQL level 1

[2016.03.06 04:10:02.352]ORA-16000: database open for read-only access

[2016.03.06 04:10:02.352]; nested exception is java.sql.SQLException: ORA-00604: error occurred at recursive SQL level 1

[2016.03.06 04:10:02.352]ORA-16000: database open for read-only access

[2016.03.06 04:10:02.352] 除了这些信息，应用端就没有更多的日志了，而从数据库层面来看，得到的日志如下。

 	Completed: ALTER DATABASE OPEN READ ONLY 
 	Mon Mar 07 03:45:14 CST 2016 
 	Redo Shipping Client Connected as PUBLIC 
 	-- Connected User is Valid 
 	RFS[99]: Assigned to RFS process 28797 
 	RFS[99]: Identified database type as 'physical standby' 
 	RFS[99]: Archived Log: '/U01/app/oracle/admin/acccomdb/arch/1_24776_782846320.dbf' 
 	Mon Mar 07 07:02:59 CST 2016 
 	ORA-1652: unable to extend temp segment by 128 in tablespace                 TEMP2  
 	Mon Mar 07 07:02:59 CST 2016 
 	ORA-1652: unable to extend temp segment by 128 in tablespace                 TEMP2  
 	Mon Mar 07 08:10:03 CST 2016 
 	Stopping background process MMNL 
 	Mon Mar 07 08:10:04 CST 2016 
 	Stopping background process MMON 
 	Mon Mar 07 08:10:05 CST 2016 
 	Active process 10256 user 'oracle' program 'oracle@testdb.cyou.com' 
 	Active process 10258 user 'oracle' program 'oracle@testdb.cyou.com' 
 	Active process 10254 user 'oracle' program 'oracle@testdb.cyou.com' 
 	Active process 10401 user 'oracle' program 'oracle@testdb.cyou.com' 
 	CLOSE: waiting for server sessions to complete. 
 	CLOSE: all sessions shutdown successfully. 

通过上面的日志也分析不出哪里可能有很明显的错误，TEMP的也算是一个引子吧。在排查了各种可能出现的场景后，却始终得不到有效的思路。 我在备库想看看这个问题是否发生。于是根据日志中的语句查询了一下，发现没有任何问题。

 	select bind_flag from test_billing where cn_master=?  语句可以顺利输出结果。

自己也尝试了dml的情况，错误信息也会有所不同。

 	SQL> update test_billing set  bind_flag=0 where cn_master='660078174'; 
 	update test_billing set  bind_flag=0 where cn_master='660078174' 
 	       * 
 	ERROR at line 1: 
 	ORA-01552: cannot use system rollback segment for non-system tablespace 'ACC_DATA' 

这个时候就停下来，开始理一理思路，之前从来没有反馈过这个问题，而问题是在最近发生的。那么应用端是否在最近有什么变化呢，得到的反馈是在1月中下旬有一次变更，但是这都过去好久了，不足以佐证现在的问题。

那数据库端有什么变化吗？唯一的变更就是在最近把这个批量查询从备库2迁到了备库1去做。这个也是近1个月以前完成的事情了，也不足以证明最近的问题。

而从数据库层面，如果存在问题，那看似只有bug的可能性了，但是查了mos一圈，发现了几种可能的场景，但是都和目前的情况不符合，目前查到有两种场景，一种是略微复杂的查询，一种是带有db link的查询。参考链接如下：

 	Dblink on Physical standby - ORA-16000 (Doc ID 1296288.1) 
 	ORA-16000 With A Semantic Query On A Read-only Database (Doc ID 1928638.1) 

目前的情况是这个语句非常简单，实在找不出来可能的原因了。

开发的同事也催的比较紧，但是感觉从数据库层面得到的信息着实有限。无奈之下，开启了手工debug方式。就从alert日志中的那个关于temp的报错开始分析。

还是采用之前的一种分析方式，用两个脚本来分析。

第一个脚本是 check_temp.sh

 	function get_temp_usage 
 	{ 
 	sqlplus -s  / as sysdba <<eof </eof<>
 	set time on 
 	set pages 100 
 	set linesize 200 
 	col sysdate format a10 
 	col username format a15 
 	col sid format 9999 
 	col serial# format 99999 
 	col blocks format 99999999 
 	col sql_text format a70  
 	set feedback off 
 	select systimestamp from dual; 
 	set feedback on 
 	SELECT sysdate,a.username, a.sid, a.serial#, a.osuser, b.blocks, c.sql_text 
 	  FROM v\$session a, v\$sort_usage b, v\$sqlarea c 
 	  WHERE b.tablespace = 'TEMP' 
 	  and a.saddr = b.session_addr 
 	  AND c.address= a.sql_address 
 	  AND c.hash_value = a.sql_hash_value 
 	  AND b.blocks*8192 > 0 
 	  ORDER BY b.tablespace, b.blocks; 
 	EOF 
 	} 
 	get_temp_usage 

第二个脚本 是tmp.sh

 	for i in {1..36000}  
 	do 
 	sh check_temp.sh >> check_temp.log 
 	sleep 10  
 	done
然后在第二天上班的时候就会得到一个比较详细的列表了。

但是今天到公司之后查看详细记录，发现竟然返回都是空行，看来这些语句运行都成了问题。

打开备库又运行了一次查询，sqlplus中运行没有任何问题。

这个时候就有些怀疑是jdbc驱动的问题了，但是这个似乎还是无从考证了。而且查看mos也没有得到确凿的证据。

于是打电话给开发，进一步做了确认，想他们确认连接的IP，端口和用户，然后得到了下面的这个配置信息。 select bind_flag from test_billing where cn_master=? jdbc:oracle:thin:@10.127.1.17:1525:acccomdb TEST_SHINK 看起来也没有什么问题，TEST_SHINK是一个连接用户，会连接到owner用户的表。

和开发进一步进行沟通和协调，想让他们给半个小时左右的时间继续跑一下失败的批量查询，看看我从数据库端能够发现什么。

但是应用运行之后，查看系统级，没有任何的抖动，数据库层面也可以看到应用是连接进来了。

然后开发就提供了最新的日志。 [2016.03.09 11:04:56.274]org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [select bind_flag from test_billing where cn_master=?]; SQL state [60000]; error code [604]; ORA-00604: error occurred at recursive SQL level 1 [2016.03.09 11:04:56.274]ORA-16000: database open for read-only access [2016.03.09 11:04:56.274]; nested exception is java.sql.SQLException: ORA-00604: error occurred at recursive SQL level 1 [2016.03.09 11:04:56.274]ORA-16000: database open for read-only access 这个错误和之前的基本是一致的。

看着这个日志就坐在那里发呆，还有什么特别的方式来调试一下这个问题呢。实在不行就只能10046来做一些分析了。但是在做这个之前，我还是耐着性子再看一看。

于是我切换到了这个连接用户， alter session set current_schema= TEST_SHINK; 然后再次运行这个报错的语句，终于得到了期望之中的报错。 SQL> select bind_flag from test_billing where cn_master= '660078174'; select bind_flag from test_billing where cn_master= '660078174' * ERROR at line 1: ORA-00604: error occurred at recursive SQL level 1 ORA-16000: database open for read-only access 有了报错信息，就有了处理问题的方向，于是换了一个方式。采用owenr用户的方式来查看，就没有问题了。 SQL> select bind_flag from acc.test_billing where cn_master= '660078174'; BIND_FLAG ---------- 689537

这个问题是怎么回事呢？

TEST_SHINK下的都是同义词，指向ACC这个owner用户，那么这个同义词有什么特别的呢。进一步查看，发现同义词test_billing是INVALID的。 看起来这个问题总算有了解决的思路，我们可以在主库直接编译运行即可，然后这部分变更会同步到备库。当然同义词为失效的时候，直接查询也会自动编译。所以在主库只需要运行一条select语句即可。在主库中确认，发现TEST_SHINK下的同义词test_billing确实也是INVALID的。

那么在主库运行下面的sql即可。 > select count(*)from TEST_SHINK.TEST_BILLING where cn_master= '660078174'; COUNT(*) ---------- 1

然后再次查看状态，同义词的状态就自动为VALID的了。 然后在备库开启日志应用，然后切换回只读状态，再次验证就没有问题了，然后让应用进一步确认，发现终于正常了。 那么还有一个问题需要解决的就是，根据开发的反馈，应该是从3月4日开始出现了问题，这个test_billing是否在3月3日左右出现了一些变化，导致同义词失效呢。

可以从dba_objects进行论证，当然也是带着一丝侥幸，得到了期望的结果。最新的一次ddl操作是在3月3日的早晨。

> SELECT OWNER,OBJECT_NAME,OBJEcT_TYPE,LAST_DDL_TIME,STATUS FROM DBA_OBJECTS WHERE OBJECT_NAME='TEST_BILLING'; OWNER OBJECT_NAME OBJECT_TYPE LAST_DDL_TIME STATUS -------------------- -------------------- ------------------- ------------------- ---------- ACC TEST_BILLING TABLE 2016-03-03 07:38:28 VALID APP_ACC_USER TEST_BILLING SYNONYM 2016-03-03 07:38:29 VALID TEST_SHINK TEST_BILLING SYNONYM 2016-03-09 11:16:59 VALID 因为这个用户应用只在备库使用，所以就导致了这个看起来奇怪的问题，看来都是事出有因，耐心一些，细致一些还是会有发现。