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 '[email protected]' Active process 10258 user 'oracle' program '[email protected]' Active process 10254 user 'oracle' program '[email protected]' Active process 10401 user 'oracle' program '[email protected]' 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
因為這個使用者應用只在備庫使用，所以就導致了這個看起來奇怪的問題，看來都是事出有因，耐心一些，細緻一些還是會有發現。