閒聊oracle SQL*Net相關的空閒等待事件

oliseh發表於2016-01-27
     
    空閒等待事件,從字面上理解似乎並不需要我們花多大心思去關心,就讓它等在那裡唄,萬事總有它存在的道理,特別對於SQL*Net系列等待事件而言,細細琢磨還是有不少文章可做的。



---------<    Part 1. 那些我們經常見到的SQL*Net等待   >---------
SQL*NET message to client等待事件
Server process通知client準備接收伺服器端返回的資料,通知完成後SQL*NET message to client等待事件立即結束,然後server process開始將要返回的資料從Buffer cache複製到PGA,再從PGA傳送給client。SQL*NET message to client等待事件發生的次數與SQL*NET message from client發生次數相當。在10046 Trace檔案裡我們一般可以觀察到"SQL*NET message to client"總是先於"SQL*NET message from client"出現


SQL*NET message from client等待事件
籠統的說就是伺服器程式空閒等待來自客戶端程式的訊息響應。
最常見的情況是session連線到資料庫上之後什麼事情都不幹,這時我們到v$session裡可以查詢到該session的status='ACTIVE', event='SQL*NET message from client',表示server process正在等待client process發指令,例如:
(如無特殊說明,本文中session 1用來執行測試用的SQL,session 2用來監測session 1執行時產生的統計資訊)
---session 1:
select * from v$mystat where rownum=1;
       SID STATISTIC#      VALUE
---------- ---------- ----------
       862          0          0

 ---session 2: 查詢session 1的狀態
col event format a40
set linesize 120
select sid,event,status from v$session where sid=862 and event in ('SQL*Net message to client','SQL*Net message from client');
       SID EVENT                                    STATUS
---------- ---------------------------------------- --------
       862 SQL*Net message from client              INACTIVE

---session 2: 如果session 1一直無所事事,那麼SQL*Net message from client事件的等待次數一直不會增加,直到下一次該事件被觸發total_waits、time_waited才會累計上升
select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       30       45497


select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       30       45497


total_waits比較好理解,等一次往上加1;TIME_WAITED(單位是百分之一秒)會把之前等待的事件累計上去,例如Session 1等待了30秒後再次發起了一條select * from dual,那麼在session 2裡再次執行select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client')後的結果基本就是:


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       33       48497    <---45497+空閒等待的30秒時間


所謂空閒等待事件的頭銜應該就是這樣來的吧,純粹的空閒等待事件並無任何研究價值,我們只關心"SQL*Net message from client"等待事件的次數何時會上升,根據實驗結果我們發現有以下兩種情況:
第一種情況:
client端向Server端發起一條SQL命令,只要該命令包含了命令關鍵字,"SQL*Net message from client"事件就會增長。
驗證過程如下:
   a) client端發起一條命令後有結果行返回,事件次數從30->36
       ---session 2:
        select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');
EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       30       45497


  ---session 1:
   SQL> select * from dual;
 
DUMMY
-----
X


  ---session 2:
   select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');
   EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       36      230203


   b) client端發起一條命令後無結果返回,事件次數從36->42
       ---session 2: 
       select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');
EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       36      230203


  ---session 1:
   SQL> select * from scott.empty_tab1;
 
USERNAME                          USER_ID CREATED
       ------------------------------ ---------- -----------


  ---session 2:
   select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');
   EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       42      263051


   c) client端發起一條語法正確的命令,雖然查詢的物件不存在,事件次數還是從42->47
       ---session 2:
        select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');
EVENT                                    TOTAL_WAITS TIME_WAITED
        ---------------------------------------- ----------- -----------
        SQL*Net message from client                       42      263051


  ---session 1:
   SYS@tstdb1-SQL> select * from notexist1;
select * from notexist1
              *
ERROR at line 1:
ORA-00942: table or view does not exist


  ---session 2:
  SYS@tstdb1-SQL> select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');


    EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       47      384038


   d) client端發起得命令語法檢查不透過,事件次數還是從63->68,因為命令裡包含了select這個命令關鍵字
       ---session 2:
        SYS@tstdb1-SQL> select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client')


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       63      472134


  ---session 1:
   SQL> select * fro dual;
        select * fro dual
 
ORA-00923: FROM keyword not found where expected
 
  ---session 2:
  SYS@tstdb1-SQL> select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client')


  EVENT                                    TOTAL_WAITS TIME_WAITED
  ---------------------------------------- ----------- -----------
  SQL*Net message from client                       68      477107
  
   e) client端發起的命令裡不包含任何命令關鍵字,事件次數維持不變
    ---session 2:
        SYS@tstdb1-SQL> select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       68      477107
  
   ---session 1:
   SYS@tstdb1-SQL> selec;
        SP2-0042: unknown command "selec" - rest of line ignored.  
        
        ---session 2:
   SYS@tstdb1-SQL> select event,total_waits,time_waited from v$session_event where sid=862 and event in ('SQL*Net message from client');


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       68      477107


因client在向Server端發起命令這一過程的時間非常短暫,所以我們不大容易觀察到active的session等待在SQL*NET message from client事件上。我們可以用如下的過程去模擬active session的等待
---session 2:
SYS@tstdb1-SQL> select sid,event,status from v$session where sid=862;


       SID EVENT                                    STATUS
---------- ---------------------------------------- --------
       862 SQL*Net message from client              INACTIVE
       
---session 1:
declare
v_sql varchar2(100);
begin
while ( true ) loop
v_sql:='select * from scott.t1';
execute immediate v_sql;
end loop;
end;
/


---session 2:在session 1執行期間觀察SQL*Net message from client處於active,表示client端正在傳送命令給server端,因為client的命令是一個無限迴圈,所以傳送命令的這一過程始終沒有結束,因此一直處於ACTIVE狀態
SYS@tstdb1-SQL> select sid,event,status from v$session where sid=862;


       SID EVENT                                    STATUS
---------- ---------------------------------------- --------
       862 SQL*Net message from client              ACTIVE
       
第二種情況: 
當伺服器程式把PGA裡的結果資料返回給客戶端之後,也會觸發SQL*NET message from client等待,這時等待的是客戶端收到結果後給伺服器程式的確認。伺服器程式在返回客戶端結果集的時候不是一次全量返回的,而是按照一定單位數量分多批次來返回,特別是在結果集記錄數較多的時候伺服器端和客戶端會經歷多次互動的過程,這一過程對終端使用者或者接收結果的應用程式來是透明的。我們最熟悉的SQL*PLUS就是一個典型的客戶端程式,我們可以透過設定set arraysize 30來限制伺服器端每次最多返回30行記錄給客戶端,若一查詢語句總共需要返回100行記錄,那麼以每30行為單位,伺服器和客戶端總共需要4個回合(30->30->30->10)才能完成100條記錄的傳送,當我們開啟SQL*PLUS裡autotrace功能執行這條查詢語句就會發現SQL*Net roundtrips to/from client的統計值為4,SQL*NET message from client等待事件發生的次數近似等於SQL*Net roundtrips to/from client的統計值,對SQL*PLUS客戶端程式而言,arraysize設定越大roundtrips就會較小,SQL*NET message from client等待事件次數也會越少,也即意味著伺服器與客戶端的通訊次數減少。針對這一情況我們也來做兩組簡單的測試:


第(1)組:設定arraysize等於返回的行數
---session 1
SYS@tstdb1-SQL> show arraysize
arraysize 15


select count(*)from scott.t1;
  COUNT(*)
----------
        21


select p.spid,s.sid,s.serial# from v$session s,v$process p where s.sid=sys_context('userenv','sid') and s.paddr=p.addr;
SPID                            SID    SERIAL#
------------------------ ---------- ----------
5439878                         266      48189
        
---session 2
col event format a40
select event,total_waits,time_waited from v$session_event where sid=266 and event in ('SQL*Net message from client');
EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       14        6875


---session 1: 設定arraysize等於表的行數
set arraysize 21


select * from scott.t1;
。。。省略輸出


---session 2
select event,total_waits,time_waited from v$session_event where sid=266 and event in ('SQL*Net message from client');
EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       17       29997


上述結果得出session 1 執行Select後"SQL*Net message from client"次數從14->17,即增加了3次,分析這3次分別在什麼時候產生的,可以透過session 1的trace檔案獲得:
*** 2016-01-22 13:41:37.686
WAIT #4573489544: nam='SQL*Net message from client' ela= 132467556 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11895166310146
CLOSE #4573458848:c=0,e=24,dep=0,type=0,tim=11895166311042
CLOSE #4573489544:c=0,e=45,dep=0,type=3,tim=11895166311131
=====================
PARSING IN CURSOR #4573469256 len=23 dep=0 uid=0 oct=3 lid=0 tim=11895166311320 hv=3534831217 ad='7000001ba6b8878' sqlid='1qgrwqv9b2gmj'
 select * from scott.t1
END OF STMT
PARSE #4573469256:c=0,e=129,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=838529891,tim=11895166311319
EXEC #4573469256:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=838529891,tim=11895166311456
WAIT #4573469256: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11895166311500
FETCH #4573469256:c=0,e=124,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=838529891,tim=11895166311659    <---r=1表示返回了21條裡的第1條
WAIT #4573469256: nam='SQL*Net message from client' ela= 271 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11895166311965
WAIT #4573469256: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11895166311995
FETCH #4573469256:c=0,e=49,p=0,cr=1,cu=0,mis=0,r=20,dep=0,og=1,plh=838529891,tim=11895166312036   <---r=20表示返回了21條裡的後20條
STAT #4573469256 id=1 cnt=21 pid=0 pos=1 obj=41088 op='TABLE ACCESS FULL T1 (cr=3 pr=0 pw=0 time=113 us cost=3 size=357 card=21)'
WAIT #4573469256: nam='SQL*Net message from client' ela= 1102 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11895166313235
PARSE #4573489544:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=11895166313300
WAIT #4573489544: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11895166313634
EXEC #4573489544:c=0,e=290,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=11895166313672


第1次出現SQL*Net message from client等待事件出現在client向server端傳送命令的時候;
第2次出現在server端程式返回第一行資料的時候,client端接收到第1行資料時對server端的確認響應;
第3次是client端在接收到的第2~21行資料後對server端作出的確認響應;


---session 1:從autotrace裡也可以看到roundtrips=2
SYS@tstdb1-SQL> select * from scott.t1;


21 rows selected.




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          3  consistent gets
          0  physical reads
          0  redo size
       1216  bytes sent via SQL*Net to client
        520  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         21  rows processed


第(2)組:設定arraysize小於返回的行數
---session 1:
SYS@tstdb1-SQL> set arraysize 15
SYS@tstdb1-SQL> show arraysize
arraysize 15


---session 2:
SYS@tstdb1-SQL> select event,total_waits,time_waited from v$session_event where sid=266 and event in ('SQL*Net message from client');


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       23      111804


---session 1:
select * from scott.t1;


---session 2:
SYS@tstdb1-SQL> select event,total_waits,time_waited from v$session_event where sid=266 and event in ('SQL*Net message from client')


EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                       27      198030




前後對比發現SQL*Net message from client從23->27,增長了4次,從tracefile裡可以清楚的看出這21行記錄是按照1->15->5分三批次返回的
FETCH #4573469256:c=0,e=119,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=838529891,tim=11896171488908
WAIT #4573469256: nam='SQL*Net message from client' ela= 272 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11896171489214
WAIT #4573469256: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11896171489244
FETCH #4573469256:c=0,e=40,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=838529891,tim=11896171489275
WAIT #4573469256: nam='SQL*Net message from client' ela= 735 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11896171490033
WAIT #4573469256: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11896171490068
FETCH #4573469256:c=0,e=31,p=0,cr=1,cu=0,mis=0,r=5,dep=0,og=1,plh=838529891,tim=11896171490091
STAT #4573469256 id=1 cnt=21 pid=0 pos=1 obj=41088 op='TABLE ACCESS FULL T1 (cr=4 pr=0 pw=0 time=107 us cost=3 size=357 card=21)'
WAIT #4573469256: nam='SQL*Net message from client' ela= 410 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=11896171490602


---session 1:從autotrace裡也可以看到roundtrips=3
SYS@tstdb1-SQL> set autotrace traceonly statistics
SYS@tstdb1-SQL> select * from scott.t1


21 rows selected.




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          4  consistent gets
          0  physical reads
          0  redo size
       1402  bytes sent via SQL*Net to client
        531  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         21  rows processed
         
當我們Select一個大表時,往往需要等待很長時間才能得到所有記錄,這之中的大部分時間都耗在了網路傳輸上,這期間session絕大部分情況下都處於INACTIVE狀態下,等待的事件往往是"SQL*NET message from client",就像下面這樣
SYS@tstdb1-SQL> select sid,event,status from v$session where sid=266;


       SID EVENT                                    STATUS
---------- ---------------------------------------- --------
       266 SQL*Net message from client              INACTIVE


有同學可能會問,既然結果記錄還在返回過程中,為何不是ACTIVE狀態,我們之前的測試清楚的回答了這個問題:全量的結果集是按批次返回的,每當一個批次的結果返回至客戶端,客戶端發起給伺服器端的確認響應時,才會觸發一次"SQL*Net message from client"等待事件,因為這個響應的瞬間極短,所以我們幾乎無法觀察到針對SQL*Net message from client的ACTIVE等待。


講了這麼多,可能有的人又要問了研究SQL*Net message from client對DBA而言有何意義?
答:可以大致估算伺服器與客戶端間的網路傳輸效率
我們挑選一張百萬級記錄的大表ca_mms_file來做測試


---session 1: 執行大表的掃描,設定arraysize=100,ad._rec_sid表用於記錄sid資訊
create table ad.rec_sid (sid number,serial# number);
truncate table ad.rec_sid;
sqlplus -S system/asdf3_14@shzwbcv1 << EOF > /dev/null
insert into ad.rec_sid select s.sid,s.serial# from v\$session s,v\$process p where s.sid=sys_context('userenv','sid') and s.paddr=p.addr;
commit;
set arraysize 100
select * from ad.ca_mms_file;
EOF


---session 2: 執行下列過程,保持對於session 1的持續統計
while [ true ]
do
sqlplus -S '/as sysdba' << EOF
set feedback off
set serveroutput on
declare
v_sql2 varchar2(2000):='select ev.sid,event,total_waits,time_waited from v\$session_event ev,ad.rec_sid rs where ev.sid=rs.sid and event in (''SQL*Net message from client'')';
v_event varchar2(300);
v_total_waits number;
v_sid number;
v_time_waited number;
begin
execute immediate v_sql2 into v_sid,v_event,v_total_waits,v_time_waited;
dbms_output.put_line(v_event||' sid:  '||v_sid||'  total_waits:'||v_total_waits||'  time_waited:'||v_time_waited);
end;
/
EOF
sleep 1
done


SQL*Net message from client sid:  2362  total_waits:42  time_waited:1725
SQL*Net message from client sid:  2362  total_waits:44  time_waited:1842
SQL*Net message from client sid:  2362  total_waits:46  time_waited:1961
SQL*Net message from client sid:  2362  total_waits:48  time_waited:2080
SQL*Net message from client sid:  2362  total_waits:50  time_waited:2194
SQL*Net message from client sid:  2362  total_waits:52  time_waited:2299
SQL*Net message from client sid:  2362  total_waits:54  time_waited:2412
SQL*Net message from client sid:  2362  total_waits:56  time_waited:2530
。。。省略了部分輸出


可以大致計算出返回的速率為(2530-1725)/(56-42)*10=575ms,因為arraysize=100,575ms是指每100條記錄的傳輸時間,嚴格來575ms=伺服器從PGA裡抓取100條記錄耗時+100條記錄傳輸到客戶端的耗時,值得一提的是因session 1將輸出重定義到了/dev/null,所以這個575ms並未包含寫入磁碟的事件,如果將Session 1的輸出重定向到磁碟上的某個檔案,那麼時長會因為包含了IO響應而明顯延長,以下是將/dev/null替換為一個檔案路徑後的輸出,可以看出100條記錄的處理時長增加到了1191ms,其中一半的時長消耗在了IO上

SQL*Net message from client sid:  2362  total_waits:26  time_waited:1507
SQL*Net message from client sid:  2362  total_waits:26  time_waited:1507
SQL*Net message from client sid:  2362  total_waits:27  time_waited:1634
SQL*Net message from client sid:  2362  total_waits:28  time_waited:1756
SQL*Net message from client sid:  2362  total_waits:29  time_waited:1877
SQL*Net message from client sid:  2362  total_waits:30  time_waited:1998
SQL*Net message from client sid:  2362  total_waits:31  time_waited:2113
SQL*Net message from client sid:  2362  total_waits:32  time_waited:2229
SQL*Net message from client sid:  2362  total_waits:33  time_waited:2341


其實還有一個決定伺服器與客戶端傳輸效率的因素,那就是SDU size,下面會有詳細闡述


SQL*NET more data to client等待事件:
客戶端透過arraysize能夠指定伺服器每一批次傳送給客戶端的記錄條數,還有一個與此功能類似但更貼近網路層面的引數SDU(Session Data Unit),SDU定義了伺服器端一次能夠向客戶端傳送多少個位元組,大小範圍從512 bytes~65535 bytes。當arraysize指定的行數換算成位元組後的值大於SDU設定值時,就會觸發SQL*NET more data to client等待。舉個例子:
客戶端的SQL*Plus裡設定了,100行為一批次進行返回
set arraysize 100
客戶端的sqlnet.ora裡定義了sdu_size=8192 bytes
default_sdu_size=8192


假設每行記錄的長度為100bytes,100行的總長度就是10000bytes,比8192要大,所以在訪問這100條記錄的過程中會觸發一次SQL*NET more data to client等待,伺服器端會先返回8192bytes給客戶端,再返回剩下的1808bytes。當然這一切對於客戶端來說是透明的:客戶端仍然是以每批次100行的速度從伺服器端獲取結果,只不過在network層面這100行會被拆分成8192bytes、1808bytes兩個包。
---session 1:作為客戶端連上database server,建立一個測試表Scott.t12
SQL> create table scott.t12 as select owner,table_name,tablespace_name from dba_tables where rownum<200;


Table created.


SQL> SELECT distinct DBMS_ROWID.rowid_block_number(rowid),DBMS_ROWID.rowid_relative_fno(rowid) from scott.t12;


DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID) DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID)
------------------------------------ ------------------------------------
                                 827                                    6


SQL> select count(*) from scott.t12;


  COUNT(*)
----------
       199


exec dbms_stats.gather_table_stats('scott','t12');


SQL> select table_name,avg_row_len from dba_tables where table_name='T12';


TABLE_NAME                     AVG_ROW_LEN
------------------------------ -----------
T12                                     24


select p.spid,s.sid,s.serial# from v$session s,v$process p where s.sid=sys_context('userenv','sid') and s.paddr=p.addr;


SPID                            SID    SERIAL#
------------------------ ---------- ----------
15859916                        730       1333


set arraysize 199     <---設定每次返回199行,因為AVG_ROW_LEN=24,所以總的位元組數為4776bytes


---session 2: 
col event format a40
set linesize 120
select sid,event,total_waits,time_waited,average_wait from v$session_event where sid=730 and event like 'SQL*Net%';
       SID EVENT                                    TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
---------- ---------------------------------------- ----------- ----------- ------------
       730 SQL*Net message to client                         27           0            0
       730 SQL*Net message from client                       26       61386         2361


---session 1: 
set arraysize 199
select * from scott.t12;


---session 2: session 1的執行後,沒有出現SQL*NET more data to client等待事件,這是因為sdu_size預設值為8192bytes > 4776bytes,所以能在一個網路包裡傳送過去
SYS@tstdb1-SQL> select sid,event,total_waits,time_waited,average_wait from v$session_event where sid=730 and event like 'SQL*Net%';


        SID EVENT                                    TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
---------- ---------------------------------------- ----------- ----------- ------------
       730 SQL*Net message to client                         29           0            0
       730 SQL*Net message from client                       28       72039      2572.82


接下來我們人工將客戶端的sdu_size調整為3072bytes,調整的方法有多種,下面有列舉:


---session 1:
select p.spid,s.sid,s.serial# from v$session s,v$process p where s.sid=sys_context('userenv','sid') and s.paddr=p.addr;
SPID                            SID    SERIAL#
------------------------ ---------- ----------
6357954                         467       6611


---session 2:
select sid,event,total_waits,time_waited,average_wait from v$session_event where sid=467 and event like 'SQL*Net%';
       SID EVENT                                    TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
---------- ---------------------------------------- ----------- ----------- ------------
       467 SQL*Net message to client                         12           0            0
       467 SQL*Net message from client                       11         468        42.52


---session 1:
set arraysize 199
select * from scott.t12;


---session 2: 觀察到多了一次SQL*Net more data to client等待,這時因為4776bytes要分為3072bytes->1704bytes兩批次進行傳送
select sid,event,total_waits,time_waited,average_wait from v$session_event where sid=467 and event like 'SQL*Net%';


       SID EVENT                                    TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
---------- ---------------------------------------- ----------- ----------- ------------
       467 SQL*Net message to client                         14           0            0
       467 SQL*Net more data to client                        1           0            0
       467 SQL*Net message from client                       13        3342       257.11
       
附:SDU可以透過以下三種方式進行定義:
伺服器端的sqlnet.ora定義、客戶端的sqlnet.ora定義:
default_sdu_size=3072


伺服器端的listener.ora定義
SID_LIST_LISTENER =
  (SID_LIST =
    (SID_DESC =
      (SDU=3072)    <---
      (GLOBAL_DBNAME = manaux1)
      (ORACLE_HOME = /oracle/app/oracle/product/11.2.0/db_1)
      (SID_NAME = manaux)
    )
  )


客戶端的tnsnames.ora裡定義:
tstdb1 =
  (DESCRIPTION =
    (sdu=3072)    <---
    (ADDRESS_LIST =
      (ADDRESS = (PROTOCOL = TCP)(HOST = 10.10.141.209)(PORT = 1521))
    )
    (CONNECT_DATA =
      (Service_name = tstdb1)
      (SERVER = DEDICATED)
    )
  )




在上節利用"SQL*Net message from client"事件跟蹤伺服器->客戶端傳輸效率的例子中,如果要使ad.ca_mms_file表的全表掃描更快的返回結果,我們可以調大sdu_size,調整方法如下:
select owner,table_name,avg_row_len from dba_tables where table_name='CA_MMS_FILE';


OWNER                          TABLE_NAME                     AVG_ROW_LEN
------------------------------ ------------------------------ -----------
AD                             CA_MMS_FILE                            181


array=100的情況下,Sdu_size至少應修改成> 18100 bytes (181*100),把sdu_size設為20000的情況下,得到如下統計結果
SQL*Net message from client sid:  10  total_waits:94  time_waited:3771
SQL*Net message from client sid:  10  total_waits:96  time_waited:3864
SQL*Net message from client sid:  10  total_waits:99  time_waited:4003
SQL*Net message from client sid:  10  total_waits:101  time_waited:4096
SQL*Net message from client sid:  10  total_waits:103  time_waited:4189
SQL*Net message from client sid:  10  total_waits:106  time_waited:4328
SQL*Net message from client sid:  10  total_waits:108  time_waited:4421
SQL*Net message from client sid:  10  total_waits:111  time_waited:4561
SQL*Net message from client sid:  10  total_waits:114  time_waited:4699
SQL*Net message from client sid:  10  total_waits:116  time_waited:4792
SQL*Net message from client sid:  10  total_waits:119  time_waited:4931


平均下來每傳送100條記錄耗時約為464ms,比sdu_size採用預設值的情況下降低了111ms,提速近20%,SQL*Net more data to client等待事件大大減少,
所以合理調大sdu size設定值也能顯著提高伺服器端與客戶端傳輸效率
     
---------<    Part 2 把SQL*Net 三類事件串聯起來連同session logical reads分析一下它們之間的聯絡  >---------
(1) arraysize<=SDU size, CTAS方式建立測試表
---session 1: 建立測試表
create tablespace ts0111 datafile '/oradata06/testaaaaa/ts0111.dbf' size 32m segment space management auto;


create table scott.t1 tablespace ts0111 as select * from all_users;


select count(*) from scott.t1 ;
  COUNT(*)
----------
        21


SQL> select header_file,header_block from dba_segments where segment_name='T1' and owner='SCOTT';


HEADER_FILE HEADER_BLOCK
----------- ------------
          5           130                                <---segment header
        
SELECT distinct DBMS_ROWID.rowid_block_number(rowid),DBMS_ROWID.rowid_relative_fno(rowid) from scott.t1 ;
DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID) DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID)
------------------------------------ ------------------------------------
                               131                                     5          <---真正存放資料的塊僅一個


---session 2: 獲取session基本資訊,確認所有行的長度和<SDU_SIZE,SDU_SIZE預設情況下是8192位元組
select sum(length(user_id)+length(username)+length(created)) from scott.t1 ;  <---確保所有記錄總長<預設的SDU值8192位元組,否則會出現SQL*NET more data to client事件,後面會有專針對於SQL*NET more data to client的討論
SUM(LENGTH(USER_ID)+LENGTH(USERNAME)+LENGTH(CREATED))
-----------------------------------------------------
                                                 550


SQL> select p.spid,s.sid,s.serial# from v$session s,v$process p where s.sid=sys_context('userenv','sid') and s.paddr=p.addr;


SPID                            SID    SERIAL#
------------------------ ---------- ----------
17105026                        266       1433


---session 3:記錄session 2的執行前的SQL*NET等待事件和logical reads次數
set linesize 120
col event format a40
select sid,event,total_waits,time_waited from v$session_event where sid=266 and event in ('SQL*Net message to client','SQL*Net message from client','SQL*Net more data to client');
       SID EVENT                                    TOTAL_WAITS TIME_WAITED
---------- ---------------------------------------- ----------- -----------
       266 SQL*Net message to client                        139           0
       266 SQL*Net message from client                      138      188288


col name format a26
select n.name,s.sid,s.VALUE from v$sesstat s,v$statname n where n.name='session logical reads' and sid=266 and n.statistic#=s.statistic#;
NAME                              SID      VALUE
-------------------------- ---------- ----------
session logical reads             266       4537


跟蹤session 2的sid,tracefile裡可以記錄邏輯讀訪問哪些塊,前提是必須保證這些塊不在buffer cache裡,可以先flush buffer_cache
exec DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id=>266,serial_num=>1433,waits=>TRUE,plan_stat=>NULL);


---session 2: 執行select * from scott.t1 ;
set arraysize 21
select /*+ dynamic_sampling(0) */ * from scott.t1 ;


---session 3:記錄session 2的執行後的SQL*NET等待事件,session logical reads次數
set linesize 120
col event format a40
select sid,event,total_waits,time_waited from v$session_event where sid=266 and event in ('SQL*Net message to client','SQL*Net message from client','SQL*Net more data to client');


       SID EVENT                                    TOTAL_WAITS TIME_WAITED
---------- ---------------------------------------- ----------- -----------
       266 SQL*Net message to client                        142           0
       266 SQL*Net message from client                      141      199871


select n.name,s.sid,s.VALUE from v$sesstat s,v$statname n where n.name='session logical reads' and sid=266 and n.statistic#=s.statistic#;
NAME                              SID      VALUE
-------------------------- ---------- ----------
session logical reads             266       4541
       
結束session 2的跟蹤
exec DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id=>266,serial_num=>1433);       
如果出現了物理讀,跟蹤的結果中就會發現 5/130(seg hdr)、5/131(data blk)兩個block會被訪問到,在tracefile裡可以觀察到如下的字樣:
WAIT #4573470248: nam='db file sequential read' ela= 16513 file#=5 block#=130 blocks=1 obj#=41088 tim=11189835682677
WAIT #4573470248: nam='db file sequential read' ela= 3417 file#=5 block#=131 blocks=1 obj#=41088 tim=11189835686504


如果沒有經過物理讀我們也可以透過跟蹤基表x$bh來發現,方法如下:
***記錄x$bh當前值:
SYS@tstdb1-SQL> select file#,dbablk,tch from x$bh where obj=41088;


     FILE#     DBABLK        TCH
---------- ---------- ----------
         5        128          0
         5        128          0
         5        130          2
         5        130          0
         5        129          0
         5        129          0
         5        129          0
         5        131          2
         5        131          0
         5        131          0
         5        131          0
         5        131          0
         5        131          0
         5        131          0
         5        131          0


15 rows selected.


***執行了select * from scott.t1;


***再次獲取x$bh當前值後發現5/130、5/131兩個block的touch count均增加了1,值得注意的是雖然只有兩個block被訪問過但並不一定意味著只會產生兩次logical reads,這時因為x$bh裡對於同一個block的訪問在3秒鐘內只會計數一次,一個block被訪問可能會造成多次logical reads
 select file#,dbablk,tch from x$bh where obj=41088


     FILE#     DBABLK        TCH
---------- ---------- ----------
         5        128          0
         5        128          0
         5        130          3
         5        130          0
         5        129          0
         5        129          0
         5        129          0
         5        131          3
         5        131          0
         5        131          0
         5        131          0
         5        131          0
         5        131          0
         5        131          0
         5        131          0


總結,arraysize<=SDU size, CTAS方式建立的測試表執行select前後:
logical reads從4537->4541,共4次,其中2次用於讀取segment header,1次用於讀取表裡的第一行,1次用於讀取block裡的剩餘行
SQL*Net message to client從139->142,共3次,其中1次用於將表裡的第一行資料從buffer cache複製到PGA前,Server process通知client準備接收伺服器端返回的第一行資料;1次用於將表中block裡除第一行外的剩餘行從buffer cache複製到PGA前,Server process通知client準備接收伺服器端返回的剩餘行資料;另1次的用途未知;讀取segment header時不會產生"SQL*Net message to client"事件,因為客戶端請求訪問的永遠是表裡的資料而不是段頭資訊。
SQL*Net message from client從138->141,共3次,其中1次用於client向server傳送命令,1次在用於Server process將PGA裡的第一行資料返回給client後client給server process的確認響應,1次用於Server process將PGA裡該block裡的剩餘資料返回給client後client給server process的確認響應。


上述場景使用的測試表scott.t1裡的記錄是在CTAS建表的同時插入進來的,實踐發現與CTAS建立完空表後再用insert into插入記錄所形成的測試表其在SQL*Net事件的等待次數上有所差異


(2) arraysize<=SDU size, CTAS方式建立空表,之後使用insert into語句往這張空表插入記錄
---session 1: 建立測試表
create tablespace ts0111 datafile '/oradata06/testaaaaa/ts0111.dbf' size 32m segment space management auto;


create table scott.t11 tablespace ts0111 as select * from all_users where 1=2;


insert into scott.t11 select * from all_users;


SQL> select header_file,header_block from dba_segments where segment_name='T11' and owner='SCOTT';


HEADER_FILE HEADER_BLOCK
----------- ------------
          5           154                                <---segment header
        
SELECT distinct DBMS_ROWID.rowid_block_number(rowid),DBMS_ROWID.rowid_relative_fno(rowid) from scott.t11 ;
DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID) DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID)
------------------------------------ ------------------------------------
                               159                                     5            <---真正存放資料的塊僅一個


---session 2: 獲取session基本資訊,確認所有行的長度和<SDU_SIZE,SDU_SIZE預設情況下是8192位元組
select sum(length(user_id)+length(username)+length(created)) from scott.t1 ;  <---確保所有記錄總長<預設的SDU值8192位元組,否則會出現SQL*NET more data to client事件,後面會有專針對於SQL*NET more data to client的討論
SUM(LENGTH(USER_ID)+LENGTH(USERNAME)+LENGTH(CREATED))
-----------------------------------------------------
                                                 550


SQL> select p.spid,s.sid,s.serial# from v$session s,v$process p where s.sid=sys_context('userenv','sid') and s.paddr=p.addr;


SPID                            SID    SERIAL#
------------------------ ---------- ----------
5374224                         467       3927


---session 3:記錄session 2的執行前的SQL*NET等待事件和logical reads次數,x$bh中的touch count,並且執行flush buffer_cache
set linesize 120
col event format a40
select sid,event,total_waits,time_waited from v$session_event where sid=467 and event in ('SQL*Net message to client','SQL*Net message from client','SQL*Net more data to client');
       SID EVENT                                    TOTAL_WAITS TIME_WAITED
---------- ---------------------------------------- ----------- -----------
       467 SQL*Net message to client                         42           0
       467 SQL*Net message from client                       41      108403


col name format a26
select n.name,s.sid,s.VALUE from v$sesstat s,v$statname n where n.name='session logical reads' and sid=467 and n.statistic#=s.statistic#;
NAME                              SID      VALUE
-------------------------- ---------- ----------
session logical reads             467       1407


alter system flush buffer_cache;


SYS@tstdb1-SQL> set pagesize 20
SYS@tstdb1-SQL> select file#,dbablk,tch from x$bh where obj=41299;


     FILE#     DBABLK        TCH
---------- ---------- ----------
         5        157          0
         5        157          0
         5        154          0
         5        154          0
         5        159          0
         5        159          0
         5        156          0
         5        156          0
         5        153          0
         5        158          0
         5        158          0
         5        155          0
         5        155          0
         5        152          0


跟蹤session 2的sid,tracefile裡可以記錄邏輯讀訪問哪些塊,前提是必須保證這些塊不在buffer cache裡,可以先flush buffer_cache
exec DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id=>467,serial_num=>3927,waits=>TRUE,plan_stat=>NULL);


---session 2: 執行select * from scott.t11
set arraysize 21
select /*+ dynamic_sampling(0) */ * from scott.t11 ;


---session 3:記錄session 2的執行後的SQL*NET等待事件,session logical reads次數
set linesize 120
col event format a40
select sid,event,total_waits,time_waited from v$session_event where sid=467 and event in ('SQL*Net message to client','SQL*Net message from client','SQL*Net more data to client');


       SID EVENT                                    TOTAL_WAITS TIME_WAITED
---------- ---------------------------------------- ----------- -----------
       467 SQL*Net message to client                         45           0
       467 SQL*Net message from client                       44      136331


col name format a30
select n.name,s.sid,s.VALUE from v$sesstat s,v$statname n where n.name='session logical reads' and sid=467 and n.statistic#=s.statistic#;
NAME                                  SID      VALUE
------------------------------ ---------- ----------
session logical reads                 467       1415
       
結束session 2的跟蹤
exec DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id=>467,serial_num=>3927);    
   
生成的Tracefile裡包含的內容:
*** 2016-01-14 14:48:52.745
WAIT #4574029704: nam='SQL*Net message from client' ela= 279270707 driver id=1650815232 #bytes=1 p3=0 obj#=41299 tim=11207996794058   <--第1次"SQL*Net message from client"等待
CLOSE #4573414144:c=0,e=25,dep=0,type=0,tim=11207996794949
CLOSE #4574029704:c=0,e=48,dep=0,type=3,tim=11207996795047
=====================
PARSING IN CURSOR #4573414144 len=51 dep=0 uid=0 oct=3 lid=0 tim=11207996795258 hv=3660860863 ad='7000001b8499ec0' sqlid='0ckm0urd38mdz'
select /*+ dynamic_sampling(0) */ * from scott.t11
END OF STMT
PARSE #4573414144:c=0,e=156,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=711494848,tim=11207996795257
EXEC #4573414144:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=711494848,tim=11207996795393
WAIT #4573414144: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=41299 tim=11207996795436   <--第1次"SQL*Net message to client"等待
WAIT #4573414144: nam='db file sequential read' ela= 466 file#=5 block#=154 blocks=1 obj#=41299 tim=11207996796009   <--發生1次session logical reads
WAIT #4573414144: nam='db file scattered read' ela= 433 file#=5 block#=155 blocks=5 obj#=41299 tim=11207996796755     <--又發生5次session logical reads
FETCH #4573414144:c=0,e=1384,p=6,cr=7,cu=0,mis=0,r=1,dep=0,og=1,plh=711494848,tim=11207996796853
WAIT #4573414144: nam='SQL*Net message from client' ela= 292 driver id=1650815232 #bytes=1 p3=0 obj#=41299 tim=11207996797184   <--第2次"SQL*Net message from client"等待
WAIT #4573414144: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=41299 tim=11207996797220  <--第2次"SQL*Net message to client"等待
FETCH #4573414144:c=0,e=50,p=0,cr=1,cu=0,mis=0,r=20,dep=0,og=1,plh=711494848,tim=11207996797260
STAT #4573414144 id=1 cnt=21 pid=0 pos=1 obj=41299 op='TABLE ACCESS FULL T11 (cr=8 pr=6 pw=0 time=1375 us cost=2 size=819 card=21)'
WAIT #4573414144: nam='SQL*Net message from client' ela= 1157 driver id=1650815232 #bytes=1 p3=0 obj#=41299 tim=11207996798516  <--第3次"SQL*Net message from client"等待
PARSE #4574029704:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=11207996798594
WAIT #4574029704: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=41299 tim=11207996798997   <--第3次"SQL*Net message to client"等待
EXEC #4574029704:c=0,e=345,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=11207996799039
~


透過跟蹤基表x$bh也可以發現,scott.t11表裡有154~159六個block被訪問過了:
SYS@tstdb1-SQL> select file#,dbablk,tch from x$bh where obj=41299;


     FILE#     DBABLK        TCH
---------- ---------- ----------
         5        157          1
         5        157          0
         5        157          0
         5        154          1
         5        154          0
         5        154          0
         5        159          1
         5        159          0
         5        159          0
         5        156          1
         5        156          0
         5        156          0
         5        153          0
         5        158          1
         5        158          0
         5        158          0
         5        155          1
         5        155          0
         5        155          0
         5        152          0


15 rows selected.


總結,arraysize<=SDU size, CTAS方式建立了空表,再用insert into往空表中插入記錄的場景下,對測試表執行select前後:
logical reads從1407->1415,共8次,其中2次用於讀取segment header,1次用於讀取表裡的第一行,1次用於讀取第一個block 155裡的剩餘行,剩餘4次用於讀取156~159這四個塊
SQL*Net message to client從139->142,共3次,其中1次在讀取block裡的第一行時,Server process通知client準備接收伺服器端返回的第一行資料,1次在讀取block裡的剩餘行時,Server process通知client準備接收伺服器端返回的剩餘行資料,另1次用途未知
SQL*Net message from client從138->141,共3次,其中1次用於client向server傳送命令,1次用於Server process將PGA裡的第一行資料返回給client後client給server process的確認響應,另1次用於Server process將PGA裡該block裡的剩餘資料返回給client後client給server process的確認響應。


(1)和(2)的區別在於session logical reads數量增加了,SQL*NET系列等待事件數量保持一致,這是因為CTAS建立出來的表其佔用的blocks數量是最少的剛好能夠存放下現有的記錄,而insert into建立出來的表是按照extent為基本單位擴充套件的,因此HWM比前者要高,進而全表掃描時經歷的blocks會更多,session logical reads值也就更大了。有興趣的TX可以使用dbms_space.space_usage,或者dump segment header觀察這兩種方式建立出來的表的HWM各是多少


(3) arraysize > SDU size的情況
以我們之前建立的scott.t12表為例,設定客戶端的Sdu_size=3072 bytes
---session 1: 連線上資料庫
select count(*) from scott.t12;
  COUNT(*)
----------
       199
       
select owner,table_name,avg_row_len from dba_tables where table_name='T12';


OWNER                          TABLE_NAME                     AVG_ROW_LEN
------------------------------ ------------------------------ -----------
SCOTT                          T12                                     24


select p.spid,s.sid,s.serial# from v$session s,v$process p where s.sid=sys_context('userenv','sid') and s.paddr=p.addr;


SPID                            SID    SERIAL#
------------------------ ---------- ----------
15138938                        664          3
       
set arraysize 199


---session 2: 
select sid,event,total_waits,time_waited,average_wait from v$session_event where sid=664 and event like 'SQL*Net%';
     SID EVENT                                    TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
---------- ---------------------------------------- ----------- ----------- ------------
       664 SQL*Net message to client                         19           0            0
       664 SQL*Net message from client                       18       27997      1555.38
       
select n.name,s.sid,s.VALUE from v$sesstat s,v$statname n where n.name='session logical reads' and sid=664 and n.statistic#=s.statistic#;
NAME                                                                    SID      VALUE
---------------------------------------------------------------- ---------- ----------
session logical reads                                                   664        776


---session 1:
select * from scott.t12;


---session 2:
select sid,event,total_waits,time_waited,average_wait from v$session_event where sid=664 and event like 'SQL*Net%';
        SID EVENT                                    TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
---------- ---------------------------------------- ----------- ----------- ------------
       664 SQL*Net message to client                         22           0            0
       664 SQL*Net more data to client                        1           0            0
       664 SQL*Net message from client                       21       36219      1724.73
       
select n.name,s.sid,s.VALUE from v$sesstat s,v$statname n where n.name='session logical reads' and sid=664 and n.statistic#=s.statistic#;
NAME                                                                    SID      VALUE
---------------------------------------------------------------- ---------- ----------
session logical reads                                                   664        779


logical reads從776->779,共3次,其中1次用於讀取segment header,1次用於讀取表裡的第一行,1次用於讀取第一個block裡的剩餘行
SQL*Net message to client從19->22,共3次,其中1次在讀取block裡的第一行時,Server process通知client準備接收伺服器端返回的第一行資料,1次在讀取block裡的剩餘行時,Server process通知client準備接收伺服器端返回的剩餘行資料,另1次用途未知
SQL*Net message from client從18->21,共3次,其中1次用於client向server傳送命令,1次用於Server process將PGA裡的第一行資料返回給client後client給server process的確認響應,另1次用於Server process將PGA裡該block裡的剩餘資料返回給client後client給server process的確認響應。
SQL*Net more data to client 的1次用於網路層拆分成3072bytes->1704 bytes兩個包進行傳送所致


簡單總結一下: 
SQL*NET message to client與SQL*NET message from client成對出現;
儘可能將arraysize調大以使結果集在較少的批次內返回,以降低伺服器和客戶端的互動次數,減少session logical reads;
儘可能調大sdu_size,以減少SQL*NET more data to client事件的發生次數,提高伺服器與客戶端間的傳輸效率;












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

相關文章