美创科技技术社区

注册

 

发新话题 回复该主题

网络传输时间和客户端处理时间的界定(批处理应用) [复制链接]

1#

    批处理的测试案例构造:
         简单的采用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对应正常的网络应答交互。

分享 转发
TOP
发新话题 回复该主题