網路傳輸時間和客戶端處理時間的界定（批處理應用）

      批處理的測試案例構造：
     簡單的採用Jmeter來進行測試，類似於實現下面簡單的邏輯： 
      declare
         l_n number;   
     begin
          for i 1..300 loop
               select 1 into l_n from dual;
               dbms_lock.sleep(1);
          end loop;
     end;
     /

    用以下指令碼來獲取資料：
    declare
  -- Local variables here
  i integer;
  n integer;
  m number;
begin
  -- Test statements here
  --select sid,serial# into m,n from v$session where program is null;
  m:=135;
  n:=39;
  delete from mc$sess_time_model;
  delete from mc$system_event;
  delete from mc$sesstat;
  delete from mc$session_event;
  insert into mc$sess_time_model select 0,a.* from v$sess_time_model a where sid=m;
  insert into mc$system_event select 0,a.* from v$system_event a;
  insert into mc$session_event select 0,a.* from v$session_event a where sid=m;
  insert into mc$sesstat select 0,a.* from v$sesstat a where sid=m;
  commit;
  dbms_monitor.session_trace_enable(m,n,true);
  dbms_lock.sleep(300);
  dbms_monitor.session_trace_disable(m,n);
  insert into mc$sess_time_model select 1,a.* from v$sess_time_model a where sid=m;
  insert into mc$system_event select 1,a.* from v$system_event a;
  insert into mc$session_event select 1,a.* from v$session_event a where sid=m;  
  insert into mc$sesstat select 1,a.* from v$sesstat a where sid=m;
  commit;
end;
/

 以下是獲取資料的結果：
  v$sess_time_model的快照比較
 1    DB time    3551790
2    DB CPU    1014006
3    parse time elapsed    84637
4    sql execute elapsed time    1269753

 v$sesstat的快照比較
 3    session logical reads    8601
4    CPU used when call started    23
5    CPU used by this session    23
6    DB time    18
22    execute count    5734
23    bytes sent via SQL*Net to client    825563
24    bytes received via SQL*Net from client    361242
25    SQL*Net roundtrips to/from client    8601

v$session_event的快照比較
4    SQL*Net message to client    8601    3
5    SQL*Net message from client    8601    29651

v$system_event的快照比較
24    SQL*Net message to client    9187    3
25    SQL*Net message from client    9192    211455
26    SQL*Net more data from client    1    0
27    SQL*Net break/reset to client    20    0

v$sqlarea的快照比較
       FETCHS    EXECUTES    BUFFER_GETS    DB_TIME    CPU_TIME    ROWS_PROCESSED
1    2867           2867                8601                        515830       78000             2867

v$event_histogram的快照比較

1    SQL*Net message from client    1    6225
2    SQL*Net message from client    2    25
3    SQL*Net message from client    4    10
4    SQL*Net message from client    8    3
5    SQL*Net message from client    16    2
6    SQL*Net message from client    64    3
7    SQL*Net message from client    128    2865
8    SQL*Net message from client    256    2
9    SQL*Net message from client    2048    1
10    SQL*Net message from client    16384    30
11    SQL*Net message from client    32768    4
12    SQL*Net message from client    65536    19
13    SQL*Net message from client    131072    2
14    SQL*Net message from client    524288    1

v$eventmetric的最近2分鐘
 NAME    NUM_SESS_WAITING    TIME_WAITED    WAIT_COUNT
1    SQL*Net message from client    15    41622.2885    1878
2    SQL*Net message from client    14    65794.8271    1860

10046跟蹤事件資訊
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     2869      0.09       0.08          0          0          0           0
Execute   5738      0.01       0.18          0          0          0           0
Fetch     5738      0.03       0.49          0       8607          0        5738
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    14345      0.14       0.76          0       8607          0        5738

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    8607        0.00          0.02
  SQL*Net message from client                  8607        0.26        296.41

 
很明顯的可以看到v$sysstat和v$sess_time_model計算CPU和DB time有所不同，兩者的差異很大。
在一個300秒的快照區間內，可以看到以下基本資料：
DB time:= 3551790 = 3.5秒
也就是資料庫的處理時間的花銷為0.38秒，其他時間都應該為網路傳輸和客戶端處理。
SQL*Net message from client ： =296s

從絕對的最終數字驗證，DB time的計算還是比較準確的。而SQL*Net message from client基本表示了網路傳輸以及客戶端處理的時間。也就是在批處理中可以採用：SQL*Net message from client來代表客戶端處理，當然為了更加準確應該做如下描述：
SQL*Net message from client  + SQL*Net message to client + SQL*Net more data to client + SQL*Net more data from client，在網路速度正常的情況下，其他三項基本可以忽略，但是當網路速度緩慢的時候其他三項可能將會產生比較大的影響，在網路傳輸不足以支撐網路快取的時候，將導致to事件阻塞。

 1    DB time    3551790
2    DB CPU    1014006
3    parse time elapsed    84637
4    sql execute elapsed time    1269753

3.55-1.02 = 2.53s
從常規而言，這個2.35s表示等待時間，但不知道等什麼，可能是不可計數的等待事件被過濾掉了。
同樣可以看到在SQL層面也存在著這個問題：
       FETCHS    EXECUTES    BUFFER_GETS    DB_TIME    CPU_TIME    ROWS_PROCESSED
1    2867           2867                8601                        515830       78000             2867

db_time:= 0.52s
cpu_time:=0.078s，同樣存在著有時間花在等待之上。

關閉10046事件之後發現：
1    DB time    2540195
2    DB CPU    2527216
3    parse time elapsed    85226
4    sql execute elapsed time    703491

現在可以認為：10046事件引起了一些額外的開銷，這些開銷導致了變更。

不管結果變化如何，有一點可以完全確認在批處理業務中，可以採用SQL*Net Message from client事件的等待時間來表示客戶端處理。

另外，我們可以看到：執行了5734次，網路互動了8601次，我們固定延時時間為100ms，可以發現等待事件柱狀圖集中在1ms和128ms，128ms對應了100ms的延遲，1ms對應正常的網路應答互動。



 









 


   

    
    

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