Oracle的等待事件是衡量Oracle运行状况的重要依据及指标。等待事件的概念是在Oracle 7.0.1.2中引入的，大致有100个等待事件。在Oracle 8.0中这个数目增加到了大约150个，在Oracle 8i中大约有200个事件，而在Oracle 9i中大约有360个等待事件。
等待事件主要分为两种类别，即空闲（idle）等待事件和非空闲（non-idle）等待事件。其中空闲事件指Oracle正等待某种工作，在诊断和优化数据库的时候，我们不用过多注意这部分事件。
关于等待事件，《深入浅出Oracle──DBA入门、进阶与应用实例》一书中曾经有一章专门介绍，这里仅通过一个实例来说明等待事件的时间及计数本质。
db file scattered read是一个常见的等待事件，通常被称为“DB文件分散读取”，这个等待事件通常与全表扫描（Full Table Scans）或快速全索引扫描（Index Fast Full Scans）相关。
当数据库进行全表扫时，基于性能的考虑，数据会分散（scattered）读入Buffer Cache。如果这个等待事件比较显著，可能说明对于某些全表扫描的表，没有创建索引或者没有创建合适的索引，因此就可能需要检查这些数据表是否已进行了正确的设置。
然而这个等待事件不一定意味着性能低下，在某些条件下Oracle会主动使用全表扫描来替换索引扫描以提高性能，这和访问的数据量有关。在CBO下Oracle会进行更为智能的选择，在RBO下Oracle更倾向于使用索引。
因为全表扫描被置于LRU（Least Recently Used，最近最少适用）列表的冷端（cold end），对于频繁访问的较小的数据表，可以选择把它们Cache到内存中，以避免反复读取。
当这个等待事件比较显著时，可以结合v$session_longops动态性能视图来进行诊断，该视图中记录了长时间（运行时间超过6秒的）运行的事物，可能很多是全表扫描操作（不管怎样，这部分信息都是值得注意的）。
下面通过一个案例分析来熟悉一下这个等待事件：
DB Name DB Id Instance Inst Num Release OPS Host
---------- ----------- ---------- -------- ---------- ---- ----------
K2 1999167370 k2 1 8.1.5.0.0 NO k2
这是一个8.1.5版本的数据库系统，通过脚本增强，可以在8.1.5的数据库上使用Statspack来进行数据库诊断。
Start Id End Id Start Time End Time (Minutes)
-------- -------- -------------------- -------------------- -----------
170 176 25-Feb-03 10:00:11 25-Feb-03 15:00:05 299.90
注意这里的采样时间为300分钟，也就是大约5个小时。
Cache Sizes
~~~~~~~~~~~
db_block_buffers: 64000
db_block_size: 8192
log_buffer: 8388608
shared_pool_size: 157286400
………………
Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total
Event Waits Time (cs) Wt Time
---------------------------------------- ------------ -----------------------
db file scattered read 16,842,920 3,490,719 43.32
latch free 844,272 3,270,073 40.58
buffer busy waits 114,421 933,136 11.58
db file sequential read 2,067,910 117,750 1.46
enqueue 464 110,840 1.38
-------------------------------------------------------------
这是一个典型的性能低下的系统，几个重要的等待事件都在Top 5中出现，其中，前3个等待极为显著，需要进行相应的调整。在5小时的采样间隔内，其中db file scattered read累计等待时间约10小时，已经成为影响系统性能的主要原因。
注意这里的等待次数已经达到16842920次，也就是说：
db file scattered read waits/s = 16842920 / 5 / 60 /60 ≈ 936
这里的Top 5等待事件都来自v$system_event视图中的累计等待统计，很多读者朋友会对这些等待事件的单位及具体含义表示疑惑，可以通过测试来简单说明一下。首先在eygle用户下创建一个数据表：
SQL> connect eygle/eygle
Connected.
SQL> alter session set events '10046 trace name context forever,level 8';
Session altered.
SQL> create table fullscan as select * from dba_objects;
Table created.
此后重新连接，找出新的session的sid，设置10046跟踪事件，并执行一个查询，这个查询将使用全表扫描来完成：
SQL> connect eygle/eygle
Connected.
SQL> @gettrcname
TRACE_FILE_NAME
-----------------------------------------------------
/opt/oracle/admin/eygle/udump/eygle_ora_4668.trc
SQL> select sid from v$mystat where rownum <2;
SID
----------
9
SQL> alter session set events '10046 trace name context forever,level 8';
Session altered.
SQL> select count(*) from fullscan;
COUNT(*)
----------
6186
可以在另外一个session中查询vsession_event视图获得这个session的相关等待信息，每个session的等待信息最后都将累积记入vsystem_event视图，v$system_event视图是整个数据库的等待事件汇总。
在查询执行前，可以记录一下两个视图的相关信息：
SQL> select * from v$system_event where event='db file scattered read';
EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT TIME_WAITED_MICRO
---------------------- ----------- -------------- ----------- ------------ -----------------
db file scattered read 18062 0 1526 0 15264694
SQL> select * from v$session_event where sid=9;
SID EVENT TOTAL_WAITS TIME_WAITED AVERAGE_WAIT MAX_WAIT TIME_WAITED_MICRO
--- ------------------------------ ----------- ----------- ------------ ---------- -----------------
9 control file sequential read 3 0 0 0 209
9 SQL*Net message to client 25 0 0 0 123
9 SQL*Net message from client 24 7272 303 6844 72716416
执行查询之后，等待事件变更为：
SQL> select * from v$system_event where event='db file scattered read';
EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT TIME_WAITED_MICRO
------------------------------ ----------- -------------- ----------- ------------ -----------------
db file scattered read 18068 0 1527 0 15268041
SQL> select * from v$session_event where sid=9;
SID EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT MAX_WAIT TIME_WAITED_MICRO
--- ------------------------------ ----------- -------------- ----------- ------------ ---------- -----------------
9 control file sequential read 3 0 0 0 0 209
9 db file scattered read 6 0 0 0 0 3347
9 SQL*Net message to client 28 0 0 0 0 143
9 SQL*Net message from client 27 0 13208 489 6844 132078209
再来看一下跟踪文件记录的信息：
.........
*** 2007-03-06 10:54:23.768
*** SESSION ID:(9.3744) 2007-03-06 10:54:23.768
APPNAME mod='SQL*Plus' mh=3669949024 act='' ah=4029777240
=====================
PARSING IN CURSOR #1 len=67 dep=0 uid=41 oct=42 lid=41 tim=1145653968524169 hv=2075329282 ad='54ab0ccc'
alter session set events '10046 trace name context forever,level 8'
END OF STMT
EXEC #1:c=0,e=236,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1145653968523472
WAIT #1: nam='SQL*Net message to client' ela= 6 p1=1650815232 p2=1 p3=0
*** 2007-03-06 10:54:56.228
WAIT #1: nam='SQL*Net message from client' ela= 31699120 p1=1650815232 p2=1 p3=0
=====================
PARSING IN CURSOR #1 len=29 dep=0 uid=41 oct=3 lid=41 tim=1145654000224403 hv=3491394078 ad='54a8aa0c'
select count(*) from fullscan
END OF STMT
PARSE #1:c=0,e=274,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1145654000224381
EXEC #1:c=10000,e=314,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1145654000224906
WAIT #1: nam='SQL*Net message to client' ela= 8 p1=1650815232 p2=1 p3=0
WAIT #1: nam='db file scattered read' ela= 670 p1=3 p2=2508 p3=13
WAIT #1: nam='db file scattered read' ela= 627 p1=3 p2=2522 p3=15
WAIT #1: nam='db file scattered read' ela= 610 p1=3 p2=2538 p3=15
WAIT #1: nam='db file scattered read' ela= 675 p1=3 p2=2554 p3=15
WAIT #1: nam='db file scattered read' ela= 608 p1=3 p2=2570 p3=15
WAIT #1: nam='db file scattered read' ela= 157 p1=3 p2=2586 p3=3
FETCH #1:c=10000,e=15679,p=76,cr=79,cu=0,mis=0,r=1,dep=0,og=4,tim=1145654000240737
WAIT #1: nam='SQL*Net message from client' ela= 966 p1=1650815232 p2=1 p3=0
FETCH #1:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1145654000242254
WAIT #1: nam='SQL*Net message to client' ela= 6 p1=1650815232 p2=1 p3=0
*** 2007-03-06 11:36:02.992
WAIT #1: nam='SQL*Net message from client' ela= -1886037425 p1=1650815232 p2=1 p3=0
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=79 r=76 w=0 time=15637 us)'
STAT #1 id=2 cnt=6186 pid=1 pos=1 obj=10082 op='TABLE ACCESS FULL FULLSCAN (cr=79 r=76 w=0 time=11686 us)'
=====================
这里记录了关于db file scattered read的等待正是6次，p3列代表的是每次全表扫描访问的IO请求的Block数量，这个数量和初始化参数db_file_multiblock_read_count的设置有关：
SQL> show parameter block_read
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_file_multiblock_read_count integer 16
再看时间，这里的ela指elapsed time ，也就是操作所消耗的时间。以上6次db file scattered read IO访问共计消耗时间为：
SQL> select 670 + 627 + 610 + 675 + 608 + 157 tim from dual;
TIM
----------
3347
从Oracle 9i开始，这里的计时单位为microsecond（一百万分之一秒，微秒），从v$session_event的TIME_WAITED_MICRO列可以看到，这个等待正是3347，Time_waited列存储的时间是centisecond（百分之一秒，厘秒），3347微秒不足1厘秒，所以未记入：
SID EVENT TOTAL_WAITS TIME_WAITED AVERAGE_WAIT MAX_WAIT TIME_WAITED_MICRO
--- ---------------------- ----------- ----------- ------------ ---------- -----------------
9 db file scattered read 6 0 0 0 3347
而在v$system_event的TIME_WAITED_MICRO列，这个时间被精确累计：
SQL> select 15268041 - 15264694 from dual;
15268041-15264694
-----------------
3347
通过这个例子，可以顺便再看看其余两个空闲等待事件：SQLNet message to client和SQLNet message from client。
- SQL*Net message from client：是指服务器进程正在等待客户端进程发送消息，由于这个等待是服务器进程处于空闲状态的一种等待，所以并不消耗系统资源，因而被归入空闲等待事件之列。
- SQL*Net message to client：是指服务器进程向客户端发送消息的时间。
从上面的跟踪文件中可以看到，SQLNet message to client与SQLNet message from client等待各出现了3次，这两个空闲等待同样被累积。
继续前面Statspack的问题分析，了解了等待事件以后就可以进一步查看相关SQL，看是否存在可疑的SQL语句。
SQL ordered by Gets for DB: K2 Instance: k2 Snaps: 170 - 176
Gets % of
Buffer Gets Executes per Exec Total Hash Value
-------------- ------------ ------------ ------ ------------
SQL statement
------------------------------------------------------------------------------
6,480,163 12 540,013.6 2.4 3791855498
SELECT "PROCESS_REQ"."WORK_ID", "PROCESS_REQ"."STOCK_NO", "PROCESS_R
3,784,566 16 236,535.4 1.4 2932917818
SELECT * FROM FIND_LATER_WO ORDER BY NOTE,ORDER_NO
1,200,976 3 400,325.3 .4 4122791109
SELECT "ITEM_STOCK"."ITEM_NO", "ITEM"."NOTE", "ITEM"
923,944 9 102,660.4 .3 2200071737
SELECT "ITEM_STOCK"."ITEM_NO" , "ITEM_STOCK"."STOCK_NO" ,
921,301 3 307,100.3 .3 2218843294
SELECT "ITEM_STOCK"."ITEM_NO", "ITEM"."NOTE", "ITEM"
911,285 3 303,761.7 .3 1769130587
SELECT "LISTS"."ITEM_NO" , "LISTS"."SUB_ITEM" , "LISTS"
831,439 2 415,719.5 .3 1349577999
SELECT "GROUP_OPER"."ITEM_NO" , "GROUP_OPER"."PROCESS_ID" ,
802,918 1 802,918.0 .3 3613809507
SELECT "LISTS"."ITEM_NO" , "LISTS"."SUB_ITEM" , "ITEM".
800,548 2 400,274.0 .3 2643788247
SELECT "ITEM_STOCK"."ITEM_NO", "ITEM"."NOTE", "ITEM"
666,085 2 333,042.5 .2 3391363608
SELECT "ITEM_STOCK"."ITEM_NO", "ITEM_STOCK"."STOCK_NO",
………..
注意到以上很多查询导致的Buffer Gets都非常庞大，我们非常有理由怀疑索引存在问题，甚至缺少必要的索引。以上记录的是SQL的片段，通过Hash Value值结合vsql_text就可以获得完整的SQL语句。在这次诊断中，我紧接着去查询的是vsession_longops数据表，一个分组查询的结果如下：
TARGET COUNT(*)
---------------------------------------------------------------- ----------
SA.PPBT_GRAPHOBJTABLE 418
SA.PPBT_PPBTOBJRELATTABLE 53
发现这些问题SQL的全表扫描（结合v$session_longops视图中的OPNAME）主要集中在PPBT_GRAPHOBJTABLE和PPBT_PPBTOBJRELATTABLE两张数据表上。进一步研究发现这两个数据表上没有任何索引，并且有相当的数据量：
SQL> select count(*) from SA.PPBT_PPBTOBJRELATTABLE;
COUNT(*)
----------
1209017
SQL> select count(*) from SA.PPBT_GRAPHOBJTABLE;
COUNT(*)
----------
2445
在创建了合适的索引后，系统性能马上得到了大幅度的提高。
