備庫批量查詢失敗的原因分析

目前線上有一套環境是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
因為這個使用者應用只在備庫使用，所以就導致了這個看起來奇怪的問題，看來都是事出有因，耐心一些，細緻一些還是會有發現。

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/23718752/viewspace-2052930/，如需轉載，請註明出處，否則將追究法律責任。