通过案例学调优之--Oracle Time Model（时间模型）

通过案例学调优之--Oracle Time Model（时间模型）

数据库时间 

      优化不仅仅是缩短等待时间。优化旨在缩短最终用户响应时间和（或）尽可能减少每个请求占用的平均资源。有时这些目标可同时实现，而有时则需要进行折衷（如在并行查询时）。通常可以认为，优化就是避免以浪费的方式占用或保留资源。  

      对数据库发出的任何请求都由两个不同的段组成：等待时间（数据库等待时间）和服务时间（数据库 CPU 时间）。等待时间是各种数据库实例资源的所有等待时间的总和。CPU 时间是实际处理请求时消耗的时间的总和。这些时间不一定由一个等待时间和一个 CPU 时间块组成。通常，进程会等待数据库资源较短时间，然后在 CPU 上短暂运行，并重复执行这一系列过程。 

优化包括缩短或消除等待时间以及缩短 CPU 时间。此定义适用于任何应用程序类型、联机事务处理 (OLTP) 或数据仓库 (DW)。  

注：非常繁忙的系统的数据库 CPU 时间较长，这会增大其它时间。 

CPU 时间和等待时间优化思维 

     优化系统时，应将 CPU 时间与系统的等待时间进行比较，这一点很重要。通过将 CPU 时间与等待时间进行比较，可以确定用于有效工作的响应时间，以及用于等待可能由其它进程占用的资源的时间。通常情况下，与等待时间占主导地位的系统相比，CPU 时间占主导地位的系统需要的优化较少。但是，SQL 语句编写不佳也可能导致高 CPU 使用率。 

虽然随着系统负载的增加，等待时间与 CPU 时间的比值会不断增大，但等待时间的迅速增加是争用的迹象，必须解决这一问题才能获得良好的可扩展性。 

     增加的等待时间表明发生争用时，在节点中增加 CPU 或在集群中增加节点的作用将非常有限。相反，CPU 时间的分配比例不会随着负载增大而明显减小的系统，可扩展性会更好，并且最有可能通过添加 CPU 或 Real Application Clusters (RAC) 实例受益。 

注： 自动工作量资料档案库 (AWR) 和 Statspack 报表在“Top 5 Event（前 5 个事件）”部分显示 CPU 时间排前 5 位的事件的 CPU 时间和等待时间。

时间模型：概览 

       许多组件参与 Oracle DB 系统的优化，每个组件拥有自己的统计信息集。如何评估优化措施预计为总体系统带来的好处？例如，如果将内存从缓冲区高速缓存移至共享池，是否可以提高总体性能？整体查看系统时，时间是比较各个组件的唯一常用标尺。在 Oracle DB 服务器中，大多数建议统计信息都会以时间为单位报告其结果。还有称为“时间模型统计信息”的统计信息，显示为 V$SYS_TIME_MODEL 和 V$SESS_TIME_MODEL 性能视图。此工具帮助 Oracle DB 服务器确定对数据库操作的定量影响。 

      时间模型统计信息中最重要的是数据库时间。此统计信息代表数据库调用花费的总时间，并指示总的实例工作量，它是未等待“空闲等待事件”的所有会话（非空闲用户会话）的 CPU 时间和等待时间的总和。 

     优化 Oracle 数据库系统的目标可以表述为：缩短用户在数据库上执行某项操作花费的时间；或简单地表述为缩短数据库时间。 

其它时间模型统计信息会提供对特定操作（如登录操作、硬分析和软分析、PL/SQL 执行和 Java 执行）的量化影响（以时间为单位）。

时间模型统计信息的层次结构 

      本幻灯片列出了时间模型统计信息之间的关系。这些关系组成两个结构树：后台所用时间和数据库时间。结构树中的子项所报告的时间均包含在结构树中的相应父项内。 

      数据库时间：执行数据库用户级调用的所用时间量（微秒）。此时间不包括用于实例后台进程（如 PMON）的时间。数据库时间从实例启动时开始累计。因为数据库时间的计算方法是将所有非空闲用户会话的时间组合在一起，所以，数据库时间可能会超过从实例启动算起的实际已用时间。例如，已运行 30 分钟的实例可能有四个活动用户会话，累计的数据库时间大约为 120 分钟。 

      数据库 CPU：数据库用户级调用的 CPU 时间量（微秒）。 

      序列装入所用时间：从数据字典获取下一个序号的所用时间量。如果将序列缓存起来，则此时间是用于在高速缓存用尽时补充高速缓存的时间量。在高速缓存中能找到序号时，不会记入任何时间。对于非缓存序列，将为每个 NEXTVAL 调用记入一定时间。

时间模型示例 

      所示的示例来自 AWR 报表。Statspack 报表也提供时间模型信息。统计信息按照占数据库时间值的百分比排序，因此占用时间最多的区域及其子项排在列表的第一个。本例中“sql execute elapsed time（sql 执行所用时间）”排在顶部。“Parse time elapsed（分析所用时间）”紧随其后，而“hard parse elapsed time（硬分析所用时间）”为“parse time elapsed（分析所用时间）”的子项。您马上可以看到，硬分析占用了几乎所有分析时间，而分析时间占用了数据库时间的绝大部分。 

注：各个统计信息的数据库时间百分比总和大于 100%。尽管没有将“parse time elapsed（分析所用时间）”作为“sql execute elapsed time（sql 执行所用时间）”的子项，但两者重复计入了部分元素。 

案例分析：

1、建立AWR snapshot

15:50:10 SYS@ test1 >exec dbms_workload_repository.create_snapshot();

PL/SQL procedure successfully completed.

2、进行事务操作

15:51:21 SCOTT@ test1 >conn scott/tigerConnected.15:51:28 SCOTT@ test1 >begin15:51:33   2  for i in 1..100000 loop15:51:37   3  execute immediate 'insert into t1(id) values ('||i||')';15:51:43   4  end loop;15:51:48   5  end;15:51:50   6  /PL/SQL procedure successfully completed.

2、建立AWR snapshot

15:52:31 SYS@ test1 >exec dbms_workload_repository.create_snapshot();

PL/SQL procedure successfully completed.

通过AWR Report分析如下：

可以看出系统存在大量的hard parse，占用了大量的cpu time

Top Wait Events

查看用户session占用的CPU TIME:

16:12:40 SYS@ test1 >select16:13:11   2     ss.username,16:13:11   3     se.SID,16:13:11   4     VALUE/100 cpu_usage_seconds16:13:11   5  from16:13:11   6     v$session ss,16:13:11   7     v$sesstat se,16:13:11   8     v$statname sn16:13:11   9  where16:13:11  10     se.STATISTIC# = sn.STATISTIC#16:13:11  11  and16:13:11  12     NAME like '%CPU used by this session%'16:13:11  13  and16:13:11  14     se.SID = ss.SID16:13:11  15  and16:13:11  16     ss.status='ACTIVE'16:13:11  17  and16:13:11  18     ss.username is not null16:13:11  19  order by VALUE desc;USERNAME                              SID CPU_USAGE_SECONDS------------------------------ ---------- -----------------SCOTT                                  37            128.08SYS                                    39               .48SCOTT                                  37                 0SYS                                    39                 0SCOTT                                  37                 0SYS                                    39                 0SCOTT                                  37                 0SYS                                    39                 08 rows selected.

查看系统等待事件（Wait Events）：

16:12:29 SYS@ test1 >SELECT  2     wait_class,  3     NAME,  4     ROUND (time_secs, 2) time_secs,  5     ROUND (time_secs * 100 / SUM (time_secs) OVER (), 2) pct  6  FROM  7     (SELECT  8        n.wait_class,  9        e.event NAME, 10        e.time_waited / 100 time_secs 11      FROM 12        v$system_event e, 13        v$event_name n 14      WHERE 15         n.NAME = e.event AND n.wait_class <> 'Idle' 16      AND 17         time_waited > 0 18      UNION 19      SELECT 20        'CPU', 21        'server CPU', 22        SUM (VALUE / 1000000) time_secs 23      FROM 24        v$sys_time_model 25      WHERE 26        stat_name IN ('background cpu time', 'DB CPU')) 27  ORDER BY 28*    time_secs DESC； WAIT_CLASS           NAME                                     TIME_SECS    PCT-------------------- ------------------------------ ------------------- ------CPU                  server CPU                                  113.80  31.36System I/O           control file parallel write                  96.43  26.57System I/O           db file async I/O submit                     31.03   8.55Other                enq: CF - contention                         20.43   5.63System I/O           log file parallel write                      19.78   5.45System I/O           flashback log file write                     14.93   4.11Other                wait for stopper event to be i               10.11   2.79                     ncreasedOther                rdbms ipc reply                               8.97   2.47Configuration        free buffer waits                             7.99   2.20User I/O             db file sequential read                       5.55   1.53Configuration        log buffer space                              4.98   1.37User I/O             Parameter File I/O                            4.43   1.22Configuration        flashback buf free by RVWR                    4.06   1.12Other                control file heartbeat                        4.00   1.10Other                ARCH wait for process start 3                 2.00    .55WAIT_CLASS           NAME                                     TIME_SECS    PCT-------------------- ------------------------------ ------------------- ------User I/O             flashback log file sync                       1.89    .52Other                change tracking file synchrono                1.75    .48                     us writeConcurrency          os thread startup                             1.69    .47User I/O             db file single write                          1.62    .45Other                buffer exterminate                            1.41    .39User I/O             db file scattered read                        1.15    .32Configuration        checkpoint completed                           .84    .23System I/O           log file sequential read                       .80    .22Other                ADR block file read                            .61    .17Commit               log file sync                                  .49    .14System I/O           log file single write                          .35    .10System I/O           flashback log file read                        .33    .09User I/O             Disk file operations I/O                       .27    .07System I/O           db file parallel write                         .21    .06Other                SGA: allocation forcing compon                 .18    .05WAIT_CLASS           NAME                                     TIME_SECS    PCT-------------------- ------------------------------ ------------------- ------                     ent growthOther                ADR block file write                           .18    .05User I/O             direct path sync                               .17    .05Other                enq: PR - contention                           .07    .02User I/O             direct path read                               .06    .02Concurrency          latch: shared pool                             .06    .02Concurrency          buffer busy waits                              .05    .01System I/O           control file sequential read                   .04    .01System I/O           Log archive I/O                                .03    .01Other                PX Deq: Signal ACK EXT                         .03    .01Concurrency          latch: row cache objects                       .03    .01User I/O             Disk file Mirror/Media Repair                  .02    .01                     WriteConcurrency          library cache: mutex X                         .01    .00User I/O             db file parallel read                          .01    .00WAIT_CLASS           NAME                                     TIME_SECS    PCT-------------------- ------------------------------ ------------------- ------Other                latch: cache buffers lru chain                 .01    .00Other                reliable message                               .01    .00Concurrency          latch: cache buffers chains                    .01    .00Other                latch: redo allocation                         .01    .00Other                cr request retry                               .01    .0048 rows selected.

案例分析：

CPU使用信息统计：

1、发现那些SQL运行了大量的PARSE

select sql_text, parse_calls, executions from v$sqlarea where rownu <4 order by parse_calls desc;11:52:47 SYS@ test1 >select sql_text, parse_calls, executions from v$sqlarea where rownum <4 order by 2SQL_TEXT                                                               PARSE_CALLS EXECUTIONS---------------------------------------------------------------------- ----------- ----------insert into t1 (id) values (55135)                                               1         1insert into t1 (id) values (55443)                                               1          1insert into t1 (id) values (55243)                                               1          1

2、SYS的总的PARSE情况

select name, value from v$sysstat where name like 'parse count%';

11:53:05 SYS@ test1 >select name, value from v$sysstat where name like 'parse count%'NAME                                                                  VALUE---------------------------------------------------------------- ----------parse count (total)                                                   88502parse count (hard)                                                    86643parse count (failures)                                                    0parse count (describe)                                                    0

3、CPU空间及繁忙情况

select * from v$osstat;STAT_NAME                                               VALUE  OSSTAT_ID COMMENTS                                 CUM-------------------------------------------------- ---------- ---------- ---------------------------------------- ---NUM_CPUS                                                    1          0 Number of active CPUs                    NOIDLE_TIME                                               35790          1 Time (centi-secs) that CPUs have been in YES                                                                          the idle stateBUSY_TIME                                                5632          2 Time (centi-secs) that CPUs have been in YES                                                                          the busy stateUSER_TIME                                                3867          3 Time (centi-secs) spent in user code     YESSYS_TIME                                                 1673          4 Time (centi-secs) spent in the kernel    YESIOWAIT_TIME                                              4248          5 Time (centi-secs) spent waiting for IO   YESNICE_TIME                                                   0          6 Time (centi-secs) spend in low-priority  YES                                                                         user codeRSRC_MGR_CPU_WAIT_TIME                                      0         14 Time (centi-secs) processes spent in the YES                                                                          runnable state waitingLOAD                                               .659179688         15 Number of processes running or waiting o NOSTAT_NAME                                               VALUE  OSSTAT_ID COMMENTS                                 CUM-------------------------------------------------- ---------- ---------- ---------------------------------------- ---                                                                         n the run queuePHYSICAL_MEMORY_BYTES                              1236480000       1008 Physical memory size in bytes            NOTCP_SEND_SIZE_MIN                                        4096       2000 TCP Send Buffer Min Size                 NOTCP_SEND_SIZE_DEFAULT                                   16384       2001 TCP Send Buffer Default Size             NOTCP_SEND_SIZE_MAX                                     3489792       2002 TCP Send Buffer Max Size                 NOTCP_RECEIVE_SIZE_MIN                                     4096       2003 TCP Receive Buffer Min Size              NOTCP_RECEIVE_SIZE_DEFAULT                                87380       2004 TCP Receive Buffer Default Size          NOTCP_RECEIVE_SIZE_MAX                                  3489792       2005 TCP Receive Buffer Max Size              NOGLOBAL_SEND_SIZE_MAX                                  1048586       2006 Global send size max (net.core.wmem_max) NOGLOBAL_RECEIVE_SIZE_MAX                               4194304       2007 Global receive size max (net.core.rmem_m NO                                                                         ax)

4、查看每个Session的CPU利用情况：

select ss.sid,se.command,ss.value CPU ,se.username,se.program        from v$sesstat ss, v$session se  where ss.statistic# in       (select statistic#  from v$statname       where name = 'CPU used by this session')       and se.sid=ss.sid       and ss.sid>6 order by CPU desc;

11:55:19 SYS@ test1 >select ss.sid,se.command,ss.value CPU ,se.username,se.program11:55:55   2  from v$sesstat ss, v$session se11:55:55   3  where ss.statistic# in11:55:55   4  (select statistic#11:55:55   5  from v$statname11:55:55   6  where name = 'CPU used by this session')11:55:55   7  and se.sid=ss.sid11:55:55   8  and ss.sid>6 order by CPU desc;       SID    COMMAND        CPU USERNAME                       PROGRAM---------- ---------- ---------- ------------------------------ ------------------------------------------------        34          2       8963 SCOTT                          [e-mail] (TNS V1-V3)        40          0         59                                [e-mail] (CJQ0)        15          3         34                                [e-mail] (MMON)        13          0          2                                [e-mail] (SMON)         9          0          0                                [e-mail] (MMAN)        12          0          0                                [e-mail] (CKPT)        14          0          0                                [e-mail] (RECO)         8          0          0                                [e-mail] (DIA0)        16          0          0                                [e-mail] (MMNL)        18          0          0                                [e-mail] (RVWR)        20          0          0                                [e-mail] (ARC0)        21          0          0                                [e-mail] (ARC1)        22          0          0                                [e-mail] (ARC2)        23          0          0                                [e-mail] (ARC3)        28          0          0                                [e-mail] (CTWR)         7          0          0                                [e-mail] (PSP0)        10          0          0                                [e-mail] (DBW0)       SID    COMMAND        CPU USERNAME                       PROGRAM---------- ---------- ---------- ------------------------------ ------------------------------------------------        11          0          0                                [e-mail] (LGWR)18 rows selected.

5、比较一下哪个session的CPU使用时间最多，然后查看该Session的具体情况：

select s.sid, s.event, s.MACHINE,s.OSUSER,s.wait_time, w.seq#, q.sql_text  from v$session_wait w, v$session s, v$process p, v$sqlarea q  where s.paddr=p.addr and  s.sid=&p        and  s.sql_address=q.address;

11:56:00 SYS@ test1 >select username,sid from v$session where username is not null;USERNAME                              SID------------------------------ ----------SYS                                     1SCOTT                                  3411:58:33 SYS@ test1 >select s.sid, s.event, s.MACHINE,s.OSUSER,s.wait_time, w.seq#, q.sql_text  2  from v$session_wait w, v$session s, v$process p, v$sqlarea q  3  where s.paddr=p.addr and  4  s.sid=&p and  5* s.sql_address=q.addressEnter value for p: 34SID EVENT                          MACHINE              OSUSER      WAIT_TIME       SEQ#---------- ------------------------------ -------------------- ---------- ---------- ----------SQL_TEXT--------------------------------------------------        34 db file sequential read        RH6.cuug.net         oracle             -1        797insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1       1056insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1        136insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1          7insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1       1320insert into t1 (id) values (80178)       SID EVENT                          MACHINE              OSUSER      WAIT_TIME       SEQ#---------- ------------------------------ -------------------- ---------- ---------- ----------SQL_TEXT--------------------------------------------------        34 db file sequential read        RH6.cuug.net         oracle             -1        636insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1        849insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1        155insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1         87insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1        221insert into t1 (id) values (80178)       SID EVENT                          MACHINE              OSUSER      WAIT_TIME       SEQ#---------- ------------------------------ -------------------- ---------- ---------- ----------SQL_TEXT--------------------------------------------------        34 db file sequential read        RH6.cuug.net         oracle             -1         64insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1        284insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1         17insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1       3815insert into t1 (id) values (80178)        34 db file sequential read        RH6.cuug.net         oracle             -1         11insert into t1 (id) values (80178)       SID EVENT                          MACHINE              OSUSER      WAIT_TIME       SEQ#---------- ------------------------------ -------------------- ---------- ---------- ----------SQL_TEXT--------------------------------------------------        34 db file sequential read        RH6.cuug.net         oracle             -1        266insert into t1 (id) values (80178)

6、占用CPU最高的10个Session及其SQL语句

select s.sid,w.wait_time,w.seconds_in_wait,w.state,w.wait_time_micro,w.time_remaining_micro,w.time_since_last_wait_micro,p.USERNAME,  status,server,schemaname,osuser,machine,p.terminal,p.program,logon_time,w.event,w.wait_class,tracefile,sql_text,last_active_time       from v$session_wait w, v$session s, v$process p, v$sqlarea q       where s.paddr=p.addr and  s.sid  in       ( select sid from  (  select ss.sid             from v$sesstat ss, v$session se  where ss.statistic# in                (  select statistic# from v$statname                where name = 'CPU used by this session' )                and se.sid=ss.sid and ss.sid>6 order by ss.value desc  )              where rownum<11 )  and s.sql_address=q.address;

12:00:59 SYS@ test1 >select s.sid,w.wait_time,w.seconds_in_wait,w.state,w.wait_time_micro,w.time_remaining_micro,w.time_since_last_wait_micro,p.USERNAME,  2  status,server,schemaname,osuser,machine,p.terminal,p.program,logon_time,w.event,w.wait_class,tracefile,sql_text,last_active_time  3  from v$session_wait w, v$session s, v$process p, v$sqlarea q  4  where s.paddr=p.addr and  5  s.sid  6  in  7  ( select sid from  8  (  9  select ss.sid 10  from v$sesstat ss, v$session se 11  where ss.statistic# in 12  ( 13  select statistic# from v$statname 14  where name = 'CPU used by this session' 15  ) 16  and se.sid=ss.sid and ss.sid>6 order by ss.value desc 17  )where rownum<4 18  ) 19* and s.sql_address=q.address;        SID  WAIT_TIME SECONDS_IN_WAIT STATE               WAIT_TIME_MICRO TIME_REMAINING_MICRO---------- ---------- --------------- ------------------- --------------- --------------------TIME_SINCE_LAST_WAIT_MICRO USERNAME        STATUS   SERVER    SCHEMANAME                     OSUSER-------------------------- --------------- -------- --------- ------------------------------ ----------MACHINE              TERMINAL                       PROGRAM                                          LOGON_TIME-------------------- ------------------------------ ------------------------------------------------ ------------EVENT                          WAIT_CLASS------------------------------ ----------------------------------------------------------------TRACEFILE------------------------------------------------------------------------------------------------------------------------SQL_TEXT                                           LAST_ACTIVE_-------------------------------------------------- ------------        34         -1               0 WAITED SHORT TIME                 2                       134 oracle          ACTIVE   DEDICATED SCOTT                          oracleRH6.cuug.net         UNKNOWN                        [e-mail] (TNS V1-V3)                  26-DEC-14asynch descriptor resize       Other/u01/app/oracle/diag/rdbms/test1/test1/trace/test1_ora_2280.trcbegin for i in 1..100000 loop execute immediate 'i 26-DEC-14nsert into t1 (id) values ('||i||')'; end loop; en......(省略）