网络传输时间和客户端处理时间的界定（批处理应用）

      批处理的测试案例构造：
     简单的采用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/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/92650/viewspace-775240/