Top 5 Timed Foreground Events
| Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
|---|---|---|---|---|---|
| db file sequential read | 1,234,292 | 6,736 | 5 | 44.97 | User I/O |
| DB CPU | 5,251 | 35.05 | |||
| log file sync | 83,846 | 1,594 | 19 | 10.64 | Commit |
| log file switch completion | 1,256 | 372 | 296 | 2.48 | Configuration |
| enq: TX – index contention | 19,327 | 310 | 16 | 2.07 |
Concurrency |
Instance Activity Stats
| Statistic | Total | per Second | per Trans |
|---|---|---|---|
| user commits | 701,112 | 193.72 |
0.8 |
1小时的AWR报告，log file sync共等待了83864次，user commits共发生了701112次。你可能会问，这两个值不应该相等吗？或者应该差不多吗？
理由听上去也是比较充分的：
log file sync是用户在commit事务的时候，产生的等待事件，等待本次事务日志刷新到磁盘。因此log file sync每次增加1，user commits就可能增加1。
但是事情要比描述的复杂一些。
比如，递归的事务也会产生log file sync等待，但是user commits次数并不增加，user commits只记录用户操作直接导致的commit次数，而不记录递归事务产生的。
以下用实验证明：
create table test (id number);
create sequence seq_test nocache;
创建了一张表和一个不带有cache的sequence。
execute snap_system_events.start_snap
execute snap_stats.start_snap
select seq_test.nextval from dual;
execute snap_stats.end_snap
execute snap_system_events.end_snap
查看统计信息输出：
Name Value
---- -----
Requests to/from client 5
opened cursors cumulative 7
user calls 7
recursive calls 16
recursive cpu usage 7
session logical reads 8
CPU used when call started 8
CPU used by this session 7
DB time 8
non-idle wait count 8
in call idle wait time 267
session uga memory 130,976
session uga memory max 130,976
messages sent 1
messages received 1
session pga memory 131,072
session pga memory max 131,072
enqueue requests 4
enqueue releases 4
physical write total IO requests 1
physical write total bytes 1,024
cell physical IO interconnect bytes 1,024
db block gets 3
db block gets from cache 3
consistent gets 5
consistent gets from cache 5
consistent gets - examination 5
logical read bytes from cache 65,536
db block changes 4
commit cleanouts 1
commit cleanouts successfully completed 1
calls to kcmgas 1
calls to get snapshot scn: kcmgss 5
redo entries 2
redo size 656
redo wastage 156
redo writes 1
redo blocks written 2
redo synch time (usec) 288
redo synch writes 1
undo change vector size 220
deferred (CURRENT) block cleanout applications 1
table fetch by rowid 1
rows fetched via callback 1
index fetch by key 2
HSC Heap Segment Block Changes 1
session cursor cache hits 4
session cursor cache count 3
buffer is not pinned count 4
parse count (total) 3
parse count (hard) 2
execute count 7
bytes sent via SQL*Net to client 1,314
bytes received via SQL*Net from client 1,565
SQL*Net roundtrips to/from client 5
PL/SQL procedure successfully completed.
Event Waits Time_outs Csec Avg Csec Max Csec
----- ----- --------- ---- -------- --------
rdbms ipc message 1 0 219 219.000 0
class slave wait 0 0 173 173.000 0
log file parallel write 1 0 0 .000 0
log file sync 1 0 1 1.000 0
db file sequential read 1 0 0 .000 0
SQL*Net message to client 9 0 0 .000 0
SQL*Net message from client 9 0 1 .111 0
PL/SQL procedure successfully completed.
发现user commits指标未发生任何变化，但是log file sync增加了1。由于我们的sequence的cache属性设置的为nocache，因此每次调用都要去修改数据字典信息，产生了递归的事务，进而导致了log file sync等待事件，但是由于是递归调用产生的事务，user commits并未增加。
那么哪些情况下，user commits增加，但是log file sync却不增加？
这种情况出现在PL/SQL里调用commit的时候。
继续拿我们上面创建的那张test表作为实验用的表。
execute snap_system_events.start_snap
execute snap_stats.start_snap
begin
for i in 1 .. 100 loop
insert into test values(i);
commit;
end loop;
end;
/
execute snap_stats.end_snap
execute snap_system_events.end_snap
上面的代码循环执行了100次的insert，每次insert后都会提交。按照常规的思考，应该user commits增加100次，log file sync增加100次。但是事实不是这样的。看下snap相关信息的输出。
user commits增加了100次，log file sync仅仅增加了1次。
Name Value
---- -----
Requests to/from client 4
opened cursors cumulative 219
user commits 100
user calls 6
recursive calls 356
recursive cpu usage 10
session logical reads 480
CPU used when call started 10
CPU used by this session 10
DB time 9
non-idle wait time 1
non-idle wait count 99
in call idle wait time 268
session uga memory 130,976
session uga memory max 65,488
messages sent 92
messages received 92
session pga memory 458,752
session pga memory max 196,608
enqueue requests 222
enqueue releases 222
physical write total IO requests 92
physical write total bytes 79,872
cell physical IO interconnect bytes 79,872
db block gets 453
db block gets from cache 453
db block gets from cache (fastpath) 20
consistent gets 27
consistent gets from cache 27
consistent gets from cache (fastpath) 8
consistent gets - examination 16
logical read bytes from cache 3,932,160
db block changes 444
free buffer requested 13
commit cleanouts 107
commit cleanouts successfully completed 107
switch current to new buffer 2
shared hash latch upgrades - no wait 1
calls to kcmgcs 7
calls to kcmgas 106
calls to get snapshot scn: kcmgss 115
redo entries 132
redo size 57,436
redo wastage 19,784
redo writes 92
redo blocks written 156
redo write time 1
redo blocks checksummed by FG (exclusive) 1
redo subscn max counts 4
redo synch time (usec) 505
redo synch writes 1
undo change vector size 14,936
no work - consistent read gets 4
immediate (CURRENT) block cleanout applications 1
deferred (CURRENT) block cleanout applications 55
IMU commits 99
IMU Flushes 3
IMU undo allocation size 56,448
IMU Redo allocation size 356
table scans (short tables) 1
table scan rows gotten 4
table scan blocks gotten 1
table fetch by rowid 1
cluster key scans 2
cluster key scan block gets 2
rows fetched via callback 1
index fetch by key 8
index scans kdiixs1 2
HSC Heap Segment Block Changes 104
Heap Segment Array Updates 1
session cursor cache hits 201
session cursor cache count 11
cursor authentications 1
buffer is not pinned count 13
parse time elapsed 1
parse count (total) 14
parse count (hard) 3
execute count 116
bytes sent via SQL*Net to client 952
bytes received via SQL*Net from client 1,603
SQL*Net roundtrips to/from client 4
sorts (memory) 1
PL/SQL procedure successfully completed.
Event Waits Time_outs Csec Avg Csec Max Csec
----- ----- --------- ---- -------- --------
rdbms ipc message 78 2 797 10.218 0
Disk file operations I/O 1 0 0 .000 0
class slave wait 0 0 217 217.000 0
DIAG idle wait 1 1 100 100.000 0
log file parallel write 92 0 1 .011 0
log file sync 1 0 0 .000 0
SQL*Net message to client 8 0 0 .000 0
SQL*Net message from client 8 0 6 .750 0
PL/SQL procedure successfully completed.
这是为什么呢？
从等待事件的几个等待次数来看，Lgwr写了92次（log file parallel write），用户会话仅仅等待了log file sync一次。那意味着用户进程发出commit命令后，并没有停下来等待lgwr刷新日志完成，就继续处理后面的事务了，并没有遵守事务的持久化原则！！如果实例在PL/SQL处理的过程中crash，那么某些提交的事务是不可恢复的。Oracle对此有一个貌似合理的解释，在PL/SQL没有处理完毕之前，你不知道已经提交了多次。Oracle不会使他们可恢复，只有在PL/SQL结束的时候，增加redo sync writes次数和进入log file sync等待。在进行PL/SQL处理期间，不停的查看等待事件，后台看不到任何的log file sync等待。值得注意的是，如果PL/SQL里包含了DBLINK，那么就会使用传统的提交方式，不会产生出这样的“异常”。还有就是统计资料里显示了会话总共向lgwr发送了92次message sent请求（请求写日志），lgwr也接受到了92次message recived信息，并且写了92次（log file parallel write）。你可能会问，到底多久，会话发送一次写请求？需要知道的是，发送写请求前，会话会去持有redo write latch，然后检查lgwr是不是已经在处理写请求了，如果已经在写了，那么不重复向LGWR发送请求了，如果没在写，才会发，因此如果你的磁盘写的速率足够快，那么lgwr就会被post的次数越多，成正比的关系。还有如果你的cpu足够强，那么PL/SQL块loop的时间就足够小，时间小了，那么lgwr被post的次数也就少了，成反比的关系（在磁盘写速率一定的情况下）。
最后提醒一句：虽然PL/SQL只有在结束的时候才会等待lgwr写完成，产生log file sync等待，但是不要认为，在PL/SQL运行过程中，实例crash掉，此次PL/SQL处理的所有事务就会丢失，不是这样的，只是可能会丢失一部分，是pl/sql在运行过程中，会话是发送写请求给lgwr的（message sent），lgwr接收到写请求后，就要写日志，只要是被写进了日志文件的事务就是可恢复的。也就是说，虽然前台没有等待log file sync，但是后台其实一直是在忙着处理你的事务日志的。
最后，我们可以来一个总结了，在awr报告里看到user commits次数不等于log file sync次数是一种正常现象，由于一些特定的情况下，会产生出一些“异常”，比如本文中提到的，递归的事务不会增加user commits，但是会产生log file sync等待，在PL/SQL里调用commit，会每次增加user commits次数，但是只是在最后一次循环时才会产生log file sync等待。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/22034023/viewspace-1214592/ ，如需转载，请注明出处，否则将追究法律责任。
请登录后发表评论
登录
全部评论
