0124奇怪的SQL*Net message from dblink

[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;
--//掛起...