[20180124]奇怪的SQL*Net message from dblink.txt

[20180124]奇怪的SQL*Net message from dblink.txt

--//生產系統出現大量的SQL*Net message from dblink事件,自己分析看看.

1.環境:
--//這個環境是伺服器在分院,有時候要通過dblink訪問總院的資料庫.

xxxx> @ ver1
PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

xxxx> @ ev_name.sql "SQL*Net message from dblink"
EVENT#   EVENT_ID NAME                        PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS
------ ---------- --------------------------- ---------- ---------- ---------- ------------- ----------- ----------
   356 4093028837 SQL*Net message from dblink driver id  #bytes                   2000153315           7 Network

--//P2參數表示傳輸的位元組數量.我發現一個奇特現象:

xxxx> SELECT *  FROM V$ACTIVE_SESSION_HISTORY WHERE event = 'SQL*Net message from dblink' AND p2 > 1;
no rows selected

xxxx> SELECT count(*)  FROM V$ACTIVE_SESSION_HISTORY WHERE event = 'SQL*Net message from dblink' AND p2 = 1;
  COUNT(*)
----------
    181068

--//出現問題的都是1個位元組的情況,按照道理這樣的傳輸不會出現的SQL*Net message from dblink事件,雖然分院與總院租用的電信的線路,
--//至少10M的帶寬,本想找網路管理員要網路出口的流量圖,估計沒做監控,失望.不過傳輸量這麼小,網路應該問題不大.

--//我從總院內網的一臺機器ping分院伺服器.使用
# ping -s 9000 分院伺服器
...
9 packets transmitted, 9 received, 0% packet loss, time 8007ms
rtt min/avg/max/mdev = 1.034/1.255/2.776/0.539 ms

# ping -s 9000 總院伺服器
10 packets transmitted, 10 received, 0% packet loss, time 9000ms
rtt min/avg/max/mdev = 0.303/0.342/0.402/0.039 ms

--//大約1ms往返內網網之間,應該問題不大.而我執行如下:

/* Formatted on 2018/1/24 9:24:37 (QP5 v5.269.14213.34769) */
  SELECT machine
        ,port
        ,session_id
        ,session_serial#
        ,MIN (sample_time) MIN
        ,MAX (sample_time) MAX
        ,MAX (sample_time) - MIN (sample_time) delta
    FROM V$ACTIVE_SESSION_HISTORY
   WHERE event = 'SQL*Net message from dblink'
GROUP BY machine
        ,port
        ,session_id
        ,session_serial#
ORDER BY 5 DESC;

--//我發現一個獨特的規律,delta的間隔大多數都是+00 00:15:24.369000上下相差1秒.15*60+25 = 925.另外我使用如下查詢:

SELECT sql_id,count(*)  FROM V$ACTIVE_SESSION_HISTORY WHERE event = 'SQL*Net message from dblink' group by sql_id order by 2 desc;

--//反查sql語句,居然發現靠前的幾個存在dblink訪問外.其中一些執行如下:
select sysdate from dual;

--//很明顯dblink鏈路出了問題,才會出現這樣的情況.

2.分析:
--//分析我已經在鏈接:
http://blog.itpub.net/267265/viewspace-2150434/
http://blog.itpub.net/267265/viewspace-2150431/

--//問題在於使用總院伺服器設置了SQLNET.EXPIRE_TIME參數,,定時監測服務端與客戶端連接情況.對於這裡監測dblink的連接情況.
--//但是在總院與分院之間配置的是狀態防火牆,不允許這樣的包通過,這樣總院伺服器發起的測試連接都被阻塞.而且根據前面的測試
--//一旦發出測試包發現不通,dblink的連接就出現問題.這樣用戶的應用程式如果僅僅訪問分院的伺服器資料庫不會存在問題.因為這條
--//鏈接是通的,但是一旦執行事務提交就會掛起(註使用dblink是會產生小量的redo的).這就是我們現在生產系統遇到的問題.

--//補充說明,使用dblink會產生事務的.許多開發並不知道,關於如何關閉資料庫會話的dblink,參考鏈接
--//http://blog.itpub.net/267265/viewspace-2123710/
SCOTT@book> @ &r/ver1

PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

SCOTT@book> @ &r/xid
XIDUSN_XIDSLOT_XIDSQN
------------------------------

no rows selected

SCOTT@book> select sysdate from dual@loopback ;
SYSDATE
-------------------
2018-01-24 09:43:27

SCOTT@book> @ &r/xid
XIDUSN_XIDSLOT_XIDSQN
------------------------------
10.21.21378

--//註xid.sql腳本:
select dbms_transaction.local_transaction_id()  XIDUSN_XIDSLOT_XIDSQN from dual ;

--//一種情況很特殊,如果在dg上以只讀打開資料庫,使用dblink是沒有問題在11g下(10g會存在問題),但是如果sql語句涉及2個dblink鏈
--//接,這個問題可以參考我以前的鏈接:http://blog.itpub.net/267265/viewspace-2138879/

--//這個時間大約就是925秒,與我前面鏈接http://blog.itpub.net/267265/viewspace-2150434/,http://blog.itpub.net/267265/viewspace-2150431/
--//是一致的,補充1點,我前面的測試少算了最後1次測試時間120.補上基本一致了.

3.解決訪問:
--//最佳方法就是取消狀態防火牆設置.這是最佳方案.
--//或者增加SQLNET.EXPIRE_TIME參數設置,規避伺服器發起的監測,不過這樣就失去這個參數的意義.
--//在訪問dblink後,即使select最好加一個提交.這樣雖然dblink連接不會斷開,至少一些應用不會出錯.因為一些應用的提交順帶提交訪問dblink產生的事務.
--//如果這時dblink出問題,用戶的操作也會掛起,rollback掉.

--//最後再次佩服我們的使用者,居然這樣的問題也能忍耐,要是不是一次下班路上別人給我提起,我才關註這個問題.
--//更加佩服我們的團隊,這個問題存在這麼長時間,開發反應,我們資料庫團隊把問題歸到網路,就沒有任何人靜下來思考解決問題.失望....

4.我自己也重覆測試:
xxxx> select sysdate from dual@xhlis;
SYSDATE
-------------------
2018-01-24 10:05:52

xxxx> host sleep 900

xxxx>
xxxx> select sysdate from dual ;
SYSDATE
-------------------
2018-01-24 10:23:39

--//本地可以訪問,如果你執行dml的提交問題再現

xxxx> commit;
--//掛起...