推断等待事件提高系统性能

推断等待事件提高系统性能

等待事件定义

最早出现于Oracle 7。在任何一个时间点，每个Oracle进程都正在忙于服务一个请求或者等待某些事件的发生，一个进程“忙”通常是其希望得到CPU，如一个专用服务器进程在一个PL/SQL块执行期间可能正在执行一个算术操作，通常称该进程是忙的，而没有在等待。此时，LGWR进程可能正在等待OS通知其redo log buffer已经成功的写入磁盘，这种情况下，LGWR是在等待的。

Oracle内核开发者定义了一系列Oracle可能等待的事件，在任何一个时间，如果进程不忙，则其肯定在等待某些事件。如专用服务器进程正在等待一个应用程序提交一条SQL语句执行，该事件在Oracle中称为"SQL*Net message from client" 。另一个进程可能正在等待orders表上的行锁释放以继续执行UPDATE语句，该事件称为"enqueue"。

通过查询v$视图，我们可以知道进程在任何时间任何情况了等待的任何事件的详细信息。如某专用服务器进程在某段时间内会花费了n秒等待OS从某个数据库文件的某个块开始读取X块。当然我们也可以看到每个进程在各种类型的事件上花费的等待。也可以指示进程写入跟踪文件。

 

等待事件信息的用处

       使用等待事件接口，可以很清楚的知道时间的花费。例如，一个月末报表可能花费了几个小时运行，通过等待事件你能够知道花费了多少时间用于全表扫描，索引查找，以及latch冲突等等。

       通过等待事件，可以得到数据库各方面的信息，如I/O，latch，并行处理，网络通信，检查点，行锁等等的详细信息。同时还能够知道如文件号，块号以及latch名以及相应的重试的次数。

       当然等待事件接口也不是万能的，它不能够给你任何诊断所需的信息，但是至少能够让你找对方向。

 

常用的等待事件名以及意义

       通常对于大多数情况下，只有极少数的等待事件有重要的作用。并且有很多仅在使用某些特征的情况下才会出现，如PX等待事件只在RAC下会出现。最常见也最有意义的事件如下：

       Enqueue：进程正在等待一个enqueue（锁，可以通过v$lock查询到），通常发生在并行更新期间；

       library cache pin：ddl过多的征兆，进程为检查希望将一个对象钉在内存的库缓存中，以确保其他进程不会同时更新对象，通常在编辑或解析一个PL/SQL/视图对象时发生；

       library cache load lock：ddl过多的征兆，进程等待机会将对象/对象片加载到库缓存中，在任何时间，只有一个进程可以将一个对象加载到库缓存中。

       latch free：进程希望得到一个被其他进程保持的latch。（注：该等待事件不应用于正在自旋等待latch的进程，进程在自旋的时候，并不属于等待）；

       buffer busy waits（10g中更改为read by other session）：进程希望访问当前不在内存中的数据块，但是其他进程已经发出I/O请求读取该块到内存中（进程等待其他进程完成将块入读内存）。

       control file sequential read：进程等待从控制文件读取一个块（控制文件事务的代价是很高的）。

       control file parallel write：进程执行了多个I/O请求并行的将块写入全部控制文件，并等待写完成（除非使用硬件镜像（还可以节约cpu），否则事实上Oracle执行的还是串行写）。

       log buffer space：日志缓冲太小的征兆，进程等待日志缓冲中的空间可用（空间仅在LGWR将当前日志缓冲的内容写入日志文件后可用）。

       log file sequential read：进程等待从在线日志文件将块读入内存，主要在实例启动和ARCH归档期间发生。

       log file parallel write：进程等待块写入在线日志文件组中的全部成员文件，LGWR通常是唯一能够看见该事件的进程。

       log file sync：提交频率的表现。进程等待LGWR刷新日志缓冲到日志文件中，在用户提交期间发生（除非恢复事务所需的全部重做都被写入磁盘，否则事务不被认为已经提交）；

       db file scattered read：全表扫描和全索引扫描的表现；

       db file sequential read：索引扫描，然后通过rowid提取的表现；

       db file parallel read：多块读的表现，但是它们并不会在并行查询和DML期间出现（两码事）；

       db file parallel write：通常是DBWR并行些脏块到到磁盘，并等待其完成。

       direct path read, direct path write：进程通过异步I/O绕过文件系统缓冲，这些等待事件通常调用了排序段。

       空闲事件如下：

Idle Wait Events
client message	PX Idle Wait
dispatcher timer	rdbms ipc message
lock manager wait for remote message	smon timer
Null event	SQL*Net message from client
parallel query dequeue	SQL*Net message to client
pipe get	SQL*Net more data from client
PL/SQL lock timer	virtual circuit status
pmon timer	wakeup time manager

 

等待事件不能提供的信息

       ·使用CPU花费的时间；

       ·等待CPU可用花费的时间；

       ·等待请求的内存交换回物理内存花费的时间；

       但是，很重要的一点是有一个非常容易的陷阱。有可能在处理一个查询很慢的语句时发现并没有很大的等待事件，这可能会被误解为真的需要这么长时间运行。事实上，查询可能实际上执行了可以通过重写查询减少的大量的逻辑读和缓冲读。

       当Oracle需要访问块并且块已经在缓冲缓存中的时候，将会发生逻辑读而没有物理读。进程将会读取块而不会发生等待，大量的CPU时间将会消耗在大量的逻辑读上，而等待事件接口则不会显示该延迟。

 

关于timed_statistics参数

       Oracle默认不会收集基于时间的统计，可以使用以下命令更改：

        ALTER SYSTEM SET timed_statistics = TRUE;

        ALTER SESSION SET timed_statistics = TRUE;

       也可以在初始化参数文件中设置：

       timed_statistics = true

 

收集等待事件信息

       等待接口信息主要由4个视图组成，任何具有SELECT ANY TABLE或SELECT_CATALOG_ROLE角色的用户都可以访问。但是只有以SYSDBA连接的用户才能设置其他会话的系统事件。

       v$system_event和v$session_event分别聚集了系统范围内和会话范围内的信息。v$session_wait视图提供了每个进程当前/最近的等待的详细信息。v$event_name视图列出了所有的事件名和相关的参数。

       10046事件也可以提供会话级别的等待事件的详细信息。

       v$system_event视图中为每个事件包含一行，以及进程等待该事件的总次数，超时的次数，等待的总时间，平均每次的等待时间。

      Name                            Null?      Type

    -------------------------------                  -------- ----

    EVENT                                     VARCHAR2(64)

    TOTAL_WAITS                            NUMBER

    TOTAL_TIMEOUTS                        NUMBER

    TIME_WAITED                             NUMBER

    AVERAGE_WAIT                            NUMBER

       TOTAL_WAITS列的等待包括了共享服务器进程，专用服务器进程，PMON和SMON等的等待；

       TIME_WAITED和AVERAGE_WAIT的单位是0.01秒。

       v$session_event包含了会话的信息，但是如果等待为0，时间也不会出现在该视图中。

    Name                               Null?      Type

    -------------------------------                 --------   ----

    SID                                    NUMBER

    EVENT                                    VARCHAR2(64)

    TOTAL_WAITS                          NUMBER

    TOTAL_TIMEOUTS                        NUMBER

    TIME_WAITED                             NUMBER

    AVERAGE_WAIT                            NUMBER

    MAX_WAIT                                NUMBER

       MAX_WAIT指示进程等待事件的最长时间。

SELECT event, total_waits, time_waited, max_wait
  FROM v$session_event
 WHERE SID =
       (SELECT sid FROM v$session WHERE audsid = USERENV('sessionid'))

       v$session_wait视图为每个进程进程显示一行，并且是瞬时的。

Name                            Null?    Type

    ------------------------------- -------- ----

SID                                      NUMBER

SEQ#                                     NUMBER

EVENT                                    VARCHAR2(64)

P1TEXT                                   VARCHAR2(64)

P1                                       NUMBER

P1RAW                                    RAW(4)

P2TEXT                                   VARCHAR2(64)

P2                                       NUMBER

    P2RAW                                    RAW(4)

P3TEXT                                   VARCHAR2(64)

P3                                       NUMBER

    P3RAW                                    RAW(4)

    WAIT_TIME                                NUMBER

    SECONDS_IN_WAIT                          NUMBER

    STATE                                    VARCHAR2(19)

       SEQ#对于每个进程从1开始，并且在进程开始新的等待时每次加1。

       STATE指示应该如何诊断输出的内容。如果为WAITING，则进程当前正在等待，WAIT_TIME列将为0，并且SECONDS_IN_WAIT（单位s）将指示进程已经等待的时间；否则进程当前没有在等待；如果STATE列为WAITED KNOWN TIME, WAIT_TIME（cs）列将显示最后一次等待的长度，SECONDS_IN_WAIT的值不相关；STATE也可以为WAITED UNKNOWN TIME或WAITED SHORT TIME，后者指示最后一次等待不超过1cs。

       P1TEXT是参数名，P1是值，P1RAW是值的二进制形式。

       系统事件10046

       ALTER SYSTEM SET sql_trace = TRUE;

ALTER SESSION SET sql_trace = TRUE;

       EXECUTE SYS.dbms_system.set_sql_trace_in_session (sid, serial#, TRUE);

       虽然10046事件的代价很高，但是对于解决具体的性能问题特别有用。

       其原始跟踪文件的格式如下：

        =====================

        PARSING IN CURSOR #1 len=80 dep=0 uid=502 oct=3 lid=502 

        tim=2293771931 hv=2293373707 ad='511dca20'

        SELECT /*+ FULL */ SUM (LENGTH(notes))

        FROM   customer_calls

        WHERE  status = :x

        END OF STMT

        PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=2293771931

        BINDS #1:

         bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 

         size=24 offset=0

           bfp=09717724 bln=22 avl=02 flg=05

           value=43

        EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2293771931

        WAIT #1: nam='SQL*Net message to client' ela= 0 p1=675562835 p2=1 p3=0

        WAIT #1: nam='db file scattered read' ela= 3 p1=17 p2=923 p3=8

        WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=931 p3=8

        WAIT #1: nam='db file scattered read' ela= 2 p1=17 p2=939 p3=8

        WAIT #1: nam='db file sequential read' ela= 0 p1=17 p2=947 p3=1

        WAIT #1: nam='db file scattered read' ela= 3 p1=17 p2=1657 p3=8

        WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1665 p3=8

        WAIT #1: nam='db file scattered read' ela= 2 p1=17 p2=1673 p3=8

        WAIT #1: nam='db file scattered read' ela= 0 p1=17 p2=1681 p3=8

        WAIT #1: nam='db file scattered read' ela= 3 p1=17 p2=1761 p3=8

        WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1769 p3=8

        WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1777 p3=8

        WAIT #1: nam='db file scattered read' ela= 0 p1=17 p2=1785 p3=8

        WAIT #1: nam='db file scattered read' ela= 2 p1=17 p2=1841 p3=8

        WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1849 p3=8

 

使用等待信息提高系统性能的方法

       如果客户抱怨OLTP的性能差，通常在用户执行后立刻查询v$session_event视图会有较大的帮助，从这里可以知道时间的主要花费，如：

       EVENT                          TOTAL_WAITS TIME_WAITED

        ------------------------------ ----------- -----------

        db file scattered read                  15           3

        db file sequential read               6209         140

        latch free                               2           1

        SQL*Net message to client                8           0

        SQL*Net message from client              7       21285

       很高的db file sequential read值通常表明执行了大量的索引扫描，其中的1.4秒还不包括CPU时间。然后就可以去应用中查询索引的数据分布图。

       对于批处理的性能问题，可以使用以下脚本段收集一个短期内的快照查看进程的主要事件消耗：

CREATE TABLE previous_events
AS
  SELECT SYSDATE timestamp, v$system_event.* FROM v$system_event;

EXECUTE dbms_lock.sleep (30);

SELECT A.event,
       A.total_waits - NVL(B.total_waits, 0) total_waits,
       A.time_waited - NVL(B.time_waited, 0) time_waited
  FROM v$system_event A, previous_events B
 WHERE B.event(+) = A.event
 ORDER BY A.event;

       当然，也可以使用Statspack, utlbstat等工具。

       可能会得到类似如下的结果：

        EVENT                          TOTAL_WAITS TIME_WAITED

        ------------------------------ ----------- -----------

        LGWR wait for redo copy                115          41

        buffer busy waits                       53          26

        control file parallel write             45          44

        control file sequential read            25           0

        db file scattered read                 932         107

        db file sequential read              76089        6726

        direct path read                       211          19

        direct path write                      212          15

        enqueue                                 37        5646

        file identify                            2           0

        file open                               37           0

        free buffer waits                       11         711

        latch free                              52          44

        log buffer space                         2           8

        log file parallel write               4388        1047

        log file sequential read               153          91

        log file single write                    2           6

        log file switch completion               2          24

        write complete waits                     6         517

       从这里可以看到，在30秒内进程在锁上花费了56秒多。队列等待中最常见的锁是TM(表锁)和TX（行锁/事务队列）。

       队列等待事件的P1RAW的前两个字节是锁类型的ASCII代码，最后两个字节是请求的锁类型。P2,P3则对应于v$lock视图的ID1和ID2列。

       为了得到锁冲突更详细的信息，可以在批处理中使用oradebug工具激活10046事件，虽然这会严重的影响性能，但是只需要一次，并且可以知道冲突的原因，通常是可行的。

        SQL> oradebug setorapid 13

        Unix process pid: 19751, image: [e-mail] (TNS V1-V3)

        SQL> oradebug session_event 10046 trace name context forever, level 8

        Statement processed.

        SQL>

       得到跟踪文件可能类似如下：

        EXEC #5:c=0,e=0,p=3,cr=2,cu=1,mis=0,r=1,dep=1,og=4,tim=2313020980

        XCTEND rlbk=0, rd_only=0

        WAIT #1: nam='write complete waits' ela= 11 p1=3 p2=2 p3=0

        WAIT #4: nam='db file sequential read' ela= 4 p1=10 p2=12815 p3=1

        WAIT #4: nam='db file sequential read' ela= 1 p1=10 p2=12865 p3=1

        WAIT #4: nam='db file sequential read' ela= 5 p1=3 p2=858 p3=1

        =====================

        PARSING IN CURSOR #4 len=65 dep=1 uid=502 oct=6 lid=502 

        tim=2313021001 hv=417623354 ad='55855844'

        UPDATE CUSTOMER_CALLS SET ATTR_3 = :b1 WHERE CUSTOMER_CALL_ID=:b2

        END OF STMT

        EXEC #4:c=1,e=10,p=3,cr=2,cu=3,mis=0,r=1,dep=1,og=4,tim=2313021001

        WAIT #5: nam='db file sequential read' ela= 0 p1=10 p2=5789 p3=1

        WAIT #5: nam='enqueue' ela= 307 p1=1415053318 p2=196705 p3=6744

        WAIT #5: nam='enqueue' ela= 307 p1=1415053318 p2=196705 p3=6744

        WAIT #5: nam='enqueue' ela= 53 p1=1415053318 p2=196705 p3=6744

        WAIT #5: nam='db file sequential read' ela= 0 p1=10 p2=586 p3=1

        WAIT #5: nam='db file sequential read' ela= 1 p1=3 p2=858 p3=1

        EXEC #5:c=0,e=668,p=3,cr=5,cu=3,mis=0,r=1,dep=1,og=4,tim=2313021669

       然后通过将p1转换为16进制，得到54580006，然后将54转换为相应的T，58转换为相应的X，0006相应于排斥模式。

       但是以上查询还是没有指出具体发生锁冲突的表和行，在发生期间查询v$locked_object或v$session的ROW_WAIT_OBJ#和ROW_WAIT_ROW#列。通过跟踪文件，也可以看出主要发生在处理游标号为5的语句上，我们可以通过向上查找游标号为5的SQL语句得到具体的对象。

       然后就可以考虑安排不同的时间段执行。

       另外，在C/S结构下，还要考虑的重要一点是每次的传送量问题。通常每次100条较好。

       通常在服务器性能很差的情况下会查询v$system_event。

       如果latch free的值过大，将查询v$latch_misses视图查看latch冲突。然后查看查询v$sql视图查看共享SQL区域的SQL语句数。并检查绑定变量的使用情况。

       通常库缓存命中率过低的措施是增加共享池的大小，但是如果应用程序不使用榜定变量，未命中率和唯一的SQL语句的数量是成正比的，共享池越大，Oracle需要搜索匹配的语句就越多，需要维护的LRU列表也就越长。