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