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等待。

AWR報告裡的log file sync和user commit為什麼不相等？

相關文章