备库批量查询失败的原因分析

目前线上有一套环境是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
因为这个用户应用只在备库使用，所以就导致了这个看起来奇怪的问题，看来都是事出有因，耐心一些，细致一些还是会有发现。