oracle等待事件3构造一个Direct Path write等待事件和构造一个Log File Sync等待事件-原创手记-慕课网

第一篇《oracle等待事件1分别用表和索引上数据的访问来产生db file scattered read等待事件》http://leonarding.blog.51cto.com/6045525/1105411

第二篇《oracle等待事件2构造一个DB File Sequential Read等待事件和构造一个Direct Path Read等待事件》http://leonarding.blog.51cto.com/6045525/1105414

第三篇《oracle等待事件3构造一个Direct Path write等待事件和构造一个Log File Sync等待事件》http://leonarding.blog.51cto.com/6045525/1105416

Dear All:

历经5天的oracle等待事件系列大功告成，不容易a多少个不眠之夜，多少次无尽猜想，在此做首打油诗留念

《2012终日有感》

壮志未酬oracle

夜点明灯苦用功

只为不白少年头

报答老师抱mm

五构造一个Direct Path write等待事件，等待事件需要在v$session_wait和10046 trace文件中显示出来，贴出整个演示过程。

Direct path write 等待事件：发生在“写入磁盘”的时候，因为写也是一种中间状态，只要是中间状态数据就没有必要共享给其他用户，所以这些数据也不会放在SGA中共享，从PGA中 -> 直接写入 -> 磁盘。

场景： append方式插入数据，这种方式插入数据的时候会跳过SGA的data_buffer_cache，直接插入数据文件，并且还不会扫描数据文件中的空闲空间直接插入到文件尾所以效率较高

当数据排序时候，如果PGA被装满，就会被写入到磁盘的temp表空间里，因为排序的数据是中间状态也不会经过SGA，所以会产生“direct path write”等待事件

LEO1@LEO1> select table_name,index_name from user_indexes where table_name='LEO1'; 利用leo1表

TABLE_NAME INDEX_NAME

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

LEO1 IDX_LEO1

LEO1@LEO1> select count(*) from leo1; 有71959行记录

COUNT(*)

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

71959

LEO1@LEO1> execute dbms_stats.gather_table_stats(ownname=>'LEO1',tabname=>'LEO1',cascade=>TRUE);

PL/SQL procedure successfully completed. 统计分析

v$session_wait视图中显示出来

LEO1@LEO1> set serveroutput on

LEO1@LEO1> create or replace procedure p4

begin

for i in 1..8

loop

insert /*+ append */ into leo1 select * from leo1;

rollback;

end loop;

dbms_output.put_line('successfully');

end;

2 3 4 5 6 7 8 9 10 11

Procedure created.

创建存储过程p4循环8次，添加了append hint执行直接插入，在这个期间会发生“direct path write”等待事件

Append 注意事项

Append方式叫做直接路径加载，使用这种方式是因为oracle不会在扫描freelist链表中的空闲块，直接在高水线之后插入数据，所以速度比较快。

（1）append方式不记录redo，一旦在插入的过程中没有保存到磁盘或者发生掉电情况那么插入的数据不能恢复

（2）由于不在利用表的空闲空间，那么这种方式比较浪费存储空间，就是以空间换时间

（3）insert /*+ append */ into leo1 select * from leo1;会对这个表添加一个6级锁，意味着在没有commit/rollback前提下任何会话 insert update delete select 等操作都不允许，否则会报错

ORA-12838: cannot read/modify an object after modifying it in parallel

解释如下：

ORA-12838 cannot read/modify an object after modifying it in parallel

Cause: Within the same transaction, an attempt was made to add read or modification statements on a table after it had been modified in parallel or with direct load. This is not permitted.

Action: Rewrite the transaction, or break it up into two transactions: one containing the initial modification and the second containing the parallel modification operation

会话133

LEO1@LEO1> execute p4; 当看到“successfully”表明这个p4执行完毕

successfully

PL/SQL procedure successfully completed.

会话157

LEO1@LEO1> select sid,event,wait_class,p1,p1text,p2,p2text,p3,p3text from v$session_wait where event like '%direct%';

SID EVENT WAIT_CLASS P1 P1TEXT P2 P2TEXT P3 P3TEXT

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

133 direct path write User I/O 5 file numbe 10528 first dba 32 block cnt

133 direct path write User I/O 5 file numbe 11232 first dba 32 block cnt

P1：写入的数据文件即 5号数据文件

P2：写入起始数据块号即 10528 11232号数据块

P3：写入了多少个数据块即 32个数据块

同理

会话133

LEO1@LEO1> create or replace procedure p5

begin

for i in 1..5

loop

insert /*+ append */ into leo1 select * from leo1 order by object_name;

rollback;

end loop;

dbms_output.put_line('successfully');

end;

2 3 4 5 6 7 8 9 10 11

Procedure created.

创建存储过程p5循环5次，先进行order by操作在插入，这会就有更多的“direct path write”等待事件

LEO1@LEO1> execute p5; 当看到“successfully”表明这个p5执行完毕

successfully

PL/SQL procedure successfully completed.

会话157

LEO1@LEO1> select sid,event,wait_class,p1,p1text,p2,p2text,p3,p3text from v$session_wait where event like '%direct%';

SID EVENT WAIT_CLASS P1 P1TEXT P2 P2TEXT P3 P3TEXT

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

133 direct path write User I/O 5 file numbe 18816 first dba 32 block cnt

133 direct path write User I/O 5 file numbe 17984 first dba 32 block cnt

133 direct path write User I/O 5 file numbe 17856 first dba 32 block cnt

产生的密度大

10046 trace文件中显示出来

LEO1@LEO1> select name,value from v$diag_info where name='Default Trace File'; 当前会话写入trace文件名

NAME VALUE

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

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_19807.trc

[oracle@leonarding1 trace]$ > LEO1_ora_19807.trc

先把这个19807trace文件清空，方便看新生成的内容

LEO1@LEO1> alter session set events '10046 trace name context forever,level 12'; 启动10046事件

Session altered.

LEO1@LEO1> insert /*+ append */ into leo1 select * from leo1; 直接路径加载

143918 rows created.

LEO1@LEO1> rollback; 回滚

Rollback complete.

LEO1@LEO1> insert /*+ append */ into leo1 select * from leo1 order by object_name; 先排序在加载

143918 rows created.

LEO1@LEO1> rollback; 再回滚

Rollback complete.

LEO1@LEO1> alter session set events '10046 trace name context off'; 关闭10046事件

Session altered.

LEO1@LEO1> select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

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

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_19807.trc

LEO1@LEO1> !vim /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_19807.trc 查看trace文件内容

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

insert /*+ append */ into leo1 select * from leo1 直接路径加载

END OF STMT

PARSE #4:c=3999,e=76261,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3641460699,tim=1356802437870566

WAIT #4: nam='direct path write' ela= 207 file number=5 first dba=17028 block cnt=28 obj#=-1 tim=1356802437889828

WAIT #4: nam='direct path write' ela= 160 file number=5 first dba=17056 block cnt=32 obj#=-1 tim=1356802437895744

WAIT #4: nam='direct path write' ela= 166 file number=5 first dba=17088 block cnt=32 obj#=-1 tim=1356802437900674

WAIT #4: nam='direct path write' ela= 392 file number=5 first dba=17120 block cnt=32 obj#=-1 tim=1356802437905561

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

insert /*+ append */ into leo1 select * from leo1 order by object_name 先排序在加载

END OF STMT

PARSE #13:c=1000,e=945,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3541504125,tim=1356802457804803

WAIT #13: nam='db file sequential read' ela= 29628 file#=5 block#=9334 blocks=1 obj#=73717 tim=1356802457932078

WAIT #13: nam='db file sequential read' ela= 1211 file#=5 block#=9336 blocks=1 obj#=73717 tim=1356802457933541

WAIT #13: nam='db file scattered read' ela= 1015 file#=5 block#=9338 blocks=6 obj#=73717 tim=1356802457934811

WAIT #13: nam='db file scattered read' ela= 6766 file#=5 block#=9346 blocks=77 obj#=73717 tim=1356802457942608

WAIT #13: nam='db file scattered read' ela= 2076 file#=5 block#=9423 blocks=49 obj#=73717 tim=1356802457951133

WAIT #13: nam='db file scattered read' ela= 4840 file#=5 block#=9474 blocks=77 obj#=73717 tim=1356802457960205

WAIT #13: nam='db file scattered read' ela= 1960 file#=5 block#=9551 blocks=49 obj#=73717 tim=1356802457968629

WAIT #13: nam='db file scattered read' ela= 5017 file#=5 block#=9602 blocks=77 obj#=73717 tim=1356802457976948

WAIT #13: nam='db file scattered read' ela= 2079 file#=5 block#=9679 blocks=49 obj#=73717 tim=1356802457984742

WAIT #13: nam='db file scattered read' ela= 4975 file#=5 block#=9730 blocks=77 obj#=73717 tim=1356802457994911

WAIT #13: nam='db file scattered read' ela= 4289 file#=5 block#=9807 blocks=49 obj#=73717 tim=1356802458005146

WAIT #13: nam='db file scattered read' ela= 29 file#=5 block#=9858 blocks=4 obj#=73717 tim=1356802458009596

WAIT #13: nam='direct path write' ela= 177 file number=5 first dba=17028 block cnt=28 obj#=73717 tim=1356802458061160

WAIT #13: nam='direct path write' ela= 300 file number=5 first dba=17056 block cnt=32 obj#=73717 tim=1356802458069767

WAIT #13: nam='direct path write' ela= 116 file number=5 first dba=17088 block cnt=32 obj#=73717 tim=1356802458078466

WAIT #13: nam='direct path write' ela= 1237 file number=5 first dba=17120 block cnt=32 obj#=73717 tim=1356802458087435

WAIT #13: nam='direct path write' ela= 358 file number=5 first dba=17152 block cnt=32 obj#=73717 tim=1356802458095653

WAIT #13: nam='direct path write' ela= 174 file number=5 first dba=17184 block cnt=32 obj#=73717 tim=1356802458103262

WAIT #13: nam='direct path write' ela= 187 file number=5 first dba=17216 block cnt=32 obj#=73717 tim=1356802458113053

WAIT #13: nam='direct path write' ela= 180 file number=5 first dba=17248 block cnt=32 obj#=73717 tim=1356802458120071

WAIT #13: nam='direct path write' ela= 166 file number=5 first dba=17280 block cnt=32 obj#=73717 tim=1356802458126193

小结：trace文件中也能看到db file sequential read和db file scattered read，当然更多的是direct path write事件！

六构造一个Log File Sync等待事件，并从相关视图中找到等待事件的信息，贴出整个演示过程。

Log File Sync等待事件：发生在“写入redo log file”的时候，既然要写入文件那么就会有磁盘I/O，有磁盘I/O就需要时间，有时间就会发生等待。

场景： commit/rollback 操作会做2个动作

（1）触发LGWR进程把log_buffer中重做日志数据写入到log_file中。

（2）然后会同步在线日志文件与控制文件的scn号，此时会发生“log file sync”等待事件

注：commit一次就会发生一次“log file sync”事件

我们还是利用Leo1表来实验，都是现成的，比较方便了，有个表有个索引

LEO1@LEO1> select table_name,index_name from user_indexes where table_name='LEO1';

TABLE_NAME INDEX_NAME

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

LEO1 IDX_LEO1

我们先做个小实验，修改数据块（就会产生redo数据）然后commit提交看看v$session_event视图的统计值是不是根据commit一次提交-> log file sync的值增加了一个

会话157

LEO1@LEO1> select sid,event,total_waits,time_waited from v$session_event where event like '%log file sync%';

SID EVENT TOTAL_WAITS TIME_WAITED

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

133 log file sync 45 206

会话133

删除11220行 -> 修改了数据块内容 -> 也就产生了redo数据

LEO1@LEO1> delete from leo1 where object_type='leonarding';

11220 rows deleted.

LEO1@LEO1> commit; 提交

Commit complete.

会话157

LEO1@LEO1> select sid,event,total_waits,time_waited from v$session_event where event like '%log file sync%';

SID EVENT TOTAL_WAITS TIME_WAITED

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

133 log file sync 46 209

log file sync总次数增加了1次，等待时间增加了3秒

会话133

LEO1@LEO1> update leo1 set object_type='leonarding' where object_type='VIEW'; 修改了表内容也当然于修改数据块

20112 rows updated.

LEO1@LEO1> commit; 提交

Commit complete.

会话157

LEO1@LEO1> select sid,event,total_waits,time_waited from v$session_event where event like '%log file sync%';

SID EVENT TOTAL_WAITS TIME_WAITED

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

133 log file sync 47 209

总次数又增加了1次，由于很快所以时间没有变

注：有时update一次不一定会增加TOTAL_WAITS次数，可以多操作几遍就会有反应的（因为1次数据量太少oracle的LGWR进程立刻就处理完了还来不及生成log file sync等待事件，所以总次数没有变化）

会话133

LEO1@LEO1> insert into leo1 select * from leo1; 插入记录改变数据块内容

276616 rows created.

LEO1@LEO1> commit; 提交

Commit complete.

会话157

LEO1@LEO1> select sid,event,total_waits,time_waited from v$session_event where event like '%log file sync%';

SID EVENT TOTAL_WAITS TIME_WAITED

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

133 log file sync 48 215

log file sync总次数增加了1次，等待时间增加了6秒，这次时间长了一点

如果有频繁的DML操作而且伴随着频繁的commit动作，LGWR进程处理不过来，等待事件就会经常发生。

会话133 测试rollback动作产生log file sync事件

LEO1@LEO1> insert into leo1 select * from leo1;

553232 rows created.

LEO1@LEO1> rollback;

Rollback complete.

会话157

LEO1@LEO1> select sid,event,total_waits,time_waited from v$session_event where event like '%log file sync%';

SID EVENT TOTAL_WAITS TIME_WAITED

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

133 log file sync 49 550

我们看到在v$session_event视图中TOTAL_WAITS又增加了1次，等待时间累加到550

10046事件

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

rollback

END OF STMT

PARSE #11:c=0,e=190,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1356716970693590

XCTEND rlbk=1, rd_only=0, tim=1356716970693691

WAIT #11: nam='db file sequential read' ela= 33 file#=201 block#=3329 blocks=1 obj#=-1 tim=1356716970798534

EXEC #11:c=71989,e=105375,p=1,cr=35,cu=8914,mis=0,r=0,dep=0,og=0,plh=0,tim=1356716970799035

WAIT #11: nam='log file sync' ela= 18162 buffer#=6808 sync scn=1478996 p3=0 obj#=73718 tim=1356716970817237

WAIT #11: nam='SQL*Net message to client' ela= 10 driver id=1650815232 #bytes=1 p3=0 obj#=73718 tim=1356716970817390

WAIT #11: nam='SQL*Net message from client' ela= 652 driver id=1650815232 #bytes=1 p3=0 obj#=73718 tim=1356716970818072

小结：10046的trace文件中我们也看到rollback操作导致的log file sync等待事件，完结！如有建议务必提，共同学习共进步

Leonarding

2012.12.30

天津&winter

分享技术~成就梦想

Blog：www.leonarding.com

oracle等待事件性能优化