日志切换检查点等待导致 log file sync 平均等待时间升高分析
log file switch (checkpoint incomplete) 等待事件导致 log file sync 平均等待时间升高分析
WORKLOAD REPOSITORY report for
|
DB Name |
DB Id |
Instance |
Inst num |
Startup Time |
Release |
RAC |
|
ORCL |
3184089245 |
orcl |
1 |
18-Aug-15 21:08 |
11.2.0.4.0 |
YES |
|
Host Name |
Platform |
CPUs |
Cores |
Sockets |
Memory (GB) |
|
ORCL |
AIX-Based Systems (64-bit) |
64 |
16 |
|
90.00 |
|
|
Snap Id |
Snap Time |
Sessions |
Cursors/Session |
Instances |
|
Begin Snap: |
7891 |
15-Oct-15 10:00:37 |
665 |
5.5 |
2 |
|
End Snap: |
7892 |
15-Oct-15 11:00:41 |
677 |
5.6 |
2 |
|
Elapsed: |
|
60.08 (mins) |
|
|
|
|
DB Time: |
|
111.62 (mins) |
|
|
|
|
|
|
|
|
|
|
服务器有64颗逻辑CPU，10-11点一个小时的 DB TIME是 111.62分钟（相当于只使用两颗逻辑CPU），负载时比较低的。
Report Summary
Load Profile
|
|
Per Second |
Per Transaction |
Per Exec |
Per Call |
|
DB Time(s): |
1.9 |
0.1 |
0.00 |
0.00 |
|
DB CPU(s): |
0.8 |
0.0 |
0.00 |
0.00 |
|
Redo size (bytes): |
352,737.8 |
10,983.3 |
|
|
|
Logical read (blocks): |
87,012.0 |
2,709.3 |
|
|
|
Block changes: |
1,823.4 |
56.8 |
|
|
|
Physical read (blocks): |
1,489.5 |
46.4 |
|
|
|
Physical write (blocks): |
241.0 |
7.5 |
|
|
|
Read IO requests: |
187.7 |
5.9 |
|
|
|
Write IO requests: |
182.8 |
5.7 |
|
|
|
Read IO (MB): |
11.6 |
0.4 |
|
|
|
Write IO (MB): |
1.9 |
0.1 |
|
|
|
Global Cache blocks received: |
154.6 |
4.8 |
|
|
|
Global Cache blocks served: |
86.3 |
2.7 |
|
|
|
User calls: |
665.4 |
20.7 |
|
|
|
Parses (SQL): |
162.5 |
5.1 |
|
|
|
Hard parses (SQL): |
12.0 |
0.4 |
|
|
|
SQL Work Area (MB): |
5.3 |
0.2 |
|
|
|
Logons: |
1.0 |
0.0 |
|
|
|
Executes (SQL): |
393.7 |
12.3 |
|
|
|
Rollbacks: |
1.2 |
0.0 |
|
|
|
Transactions: |
32.1 |
|
|
|
Instance Efficiency Percentages (Target 100%)
|
Buffer Nowait %: |
99.99 |
Redo NoWait %: |
99.97 |
|
Buffer Hit %: |
98.29 |
In-memory Sort %: |
100.00 |
|
Library Hit %: |
91.63 |
Soft Parse %: |
92.59 |
|
Execute to Parse %: |
58.73 |
Latch Hit %: |
99.90 |
|
Parse CPU to Parse Elapsd %: |
60.15 |
% Non-Parse CPU: |
96.17 |
Top 10 Foreground Events by Total Wait Time
|
Event |
Waits |
Total Wait Time (sec) |
Wait Avg(ms) |
% DB time |
Wait Class |
|
DB CPU |
|
3022.3 |
|
45.1 |
|
|
enq: TX - row lock contention |
13 |
541.3 |
41640 |
8.1 |
Application |
|
log file sync |
90,518 |
363.5 |
4 |
5.4 |
Commit |
|
db file scattered read |
292,898 |
220.2 |
1 |
3.3 |
User I/O |
|
db file sequential read |
313,476 |
213.6 |
1 |
3.2 |
User I/O |
|
reliable message |
219,321 |
160.6 |
1 |
2.4 |
Other |
|
gc current block 2-way |
175,552 |
104.3 |
1 |
1.6 |
Cluster |
|
log file switch (checkpoint incomplete) |
62 |
53.9 |
870 |
.8 |
Configuration |
|
gc cr block 2-way |
65,002 |
43.3 |
1 |
.6 |
Cluster |
|
gc cr multi block request |
17,643 |
29.7 |
2 |
.4 |
Cluster |
在 TOP 等待事件中，log file sync 排在第三位总等待时间是363.5秒平均等待时间是4毫秒，从负载整体性能角度来对数据库性能没什么影响。但是这次是在双十一之前做的性能巡检，预计双十一业务量可能是平时的十倍，现在
Redo size 是344.47KB平均等待时间就有4毫秒，如果 REDO 量增加10倍那平均等待时间就会很高了。于是对该
等待时间进行深入分析。
分析思路：使用排除法分析问题原因，首先把可能的问题原因列出来，然后通过分析AWR中的信息，逐个原因
排除最后定位问题原因。
可能的问题原因：
1、CPU资源紧张。
2、LGWR在申请 Latch时遇到竞争。
3、IO 有瓶颈
1、我先分析第一个原因“CPU资源紧张”，从AWR中看现在CPU资源非常富裕可以排除这个原因。
|
DB Name |
DB Id |
Instance |
Inst num |
Startup Time |
Release |
RAC |
|
ORCL |
3184089245 |
orcl |
1 |
18-Aug-15 21:08 |
11.2.0.4.0 |
YES |
|
Host Name |
Platform |
CPUs |
Cores |
Sockets |
Memory (GB) |
|
ORCL |
AIX-Based Systems (64-bit) |
64 |
16 |
|
90.00 |
|
|
Snap Id |
Snap Time |
Sessions |
Cursors/Session |
Instances |
|
Begin Snap: |
7891 |
15-Oct-15 10:00:37 |
665 |
5.5 |
2 |
|
End Snap: |
7892 |
15-Oct-15 11:00:41 |
677 |
5.6 |
2 |
|
Elapsed: |
|
60.08 (mins) |
|
|
|
|
DB Time: |
|
111.62 (mins) |
|
|
|
2、LGWR在申请 Latch时遇到竞争。在等待事件中LGWR 相关的 LATCH 等待事件。
Foreground Wait Events
- s - second, ms - millisecond - 1000th of a second
- Only events with Total Wait Time (s) >= .001 are shown
- ordered by wait time desc, waits desc (idle events last)
- %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
|
Event |
Waits |
%Time -outs |
Total Wait Time (s) |
Avg wait (ms) |
Waits /txn |
% DB time |
|
enq: TX - row lock contention |
13 |
0 |
541 |
41640 |
0.00 |
8.08 |
|
log file sync |
90,518 |
0 |
364 |
4 |
0.78 |
5.43 |
|
db file scattered read |
292,898 |
0 |
220 |
1 |
2.53 |
3.29 |
|
db file sequential read |
313,476 |
0 |
214 |
1 |
2.71 |
3.19 |
|
reliable message |
219,321 |
0 |
161 |
1 |
1.89 |
2.40 |
|
gc current block 2-way |
175,552 |
0 |
104 |
1 |
1.52 |
1.56 |
|
log file switch (checkpoint incomplete) |
62 |
0 |
54 |
870 |
0.00 |
0.81 |
|
gc cr block 2-way |
65,002 |
0 |
43 |
1 |
0.56 |
0.65 |
|
gc cr multi block request |
17,643 |
0 |
30 |
2 |
0.15 |
0.44 |
|
gc current grant busy |
40,944 |
0 |
26 |
1 |
0.35 |
0.39 |
|
gc current block busy |
1,964 |
0 |
16 |
8 |
0.02 |
0.23 |
|
gc buffer busy acquire |
14,917 |
0 |
13 |
1 |
0.13 |
0.20 |
|
gc buffer busy release |
191 |
0 |
9 |
45 |
0.00 |
0.13 |
|
gc cr block busy |
1,438 |
0 |
8 |
6 |
0.01 |
0.12 |
|
gc cr grant 2-way |
12,613 |
0 |
6 |
0 |
0.11 |
0.09 |
|
log file switch completion |
70 |
0 |
5 |
74 |
0.00 |
0.08 |
|
gc cr disk read |
11,282 |
0 |
5 |
0 |
0.10 |
0.08 |
|
row cache lock |
9,267 |
0 |
3 |
0 |
0.08 |
0.05 |
|
db file parallel read |
1,381 |
0 |
3 |
2 |
0.01 |
0.05 |
|
control file sequential read |
5,365 |
0 |
3 |
1 |
0.05 |
0.05 |
|
PX Deq: Slave Session Stats |
8,108 |
0 |
3 |
0 |
0.07 |
0.05 |
|
direct path read |
3,738 |
0 |
3 |
1 |
0.03 |
0.04 |
|
buffer busy waits |
285 |
0 |
3 |
9 |
0.00 |
0.04 |
|
enq: PS - contention |
3,008 |
7 |
3 |
1 |
0.03 |
0.04 |
|
gc current grant 2-way |
5,223 |
0 |
3 |
0 |
0.05 |
0.04 |
|
direct path write temp |
697 |
0 |
2 |
3 |
0.01 |
0.04 |
|
library cache pin |
4,366 |
0 |
2 |
1 |
0.04 |
0.03 |
|
library cache lock |
3,489 |
0 |
2 |
1 |
0.03 |
0.03 |
|
enq: HW - contention |
476 |
75 |
2 |
4 |
0.00 |
0.03 |
|
SQL*Net message to client |
1,848,921 |
0 |
2 |
0 |
15.97 |
0.03 |
|
IPC send completion sync |
3,360 |
0 |
1 |
0 |
0.03 |
0.02 |
|
direct path write |
1,831 |
0 |
1 |
1 |
0.02 |
0.02 |
|
Disk file operations I/O |
15,667 |
0 |
1 |
0 |
0.14 |
0.02 |
|
PX Deq: Signal ACK RSG |
5,292 |
0 |
1 |
0 |
0.05 |
0.02 |
|
Disk file Mirror Read |
1,343 |
0 |
1 |
1 |
0.01 |
0.02 |
|
CSS initialization |
110 |
0 |
1 |
9 |
0.00 |
0.01 |
|
SQL*Net more data to client |
23,301 |
0 |
1 |
0 |
0.20 |
0.01 |
|
rdbms ipc reply |
4,174 |
0 |
1 |
0 |
0.04 |
0.01 |
|
direct path read temp |
724 |
0 |
1 |
1 |
0.01 |
0.01 |
|
DFS lock handle |
563 |
0 |
1 |
1 |
0.00 |
0.01 |
|
PX Deq: reap credit |
69,632 |
100 |
1 |
0 |
0.60 |
0.01 |
|
CSS operation: action |
110 |
0 |
1 |
5 |
0.00 |
0.01 |
|
gc current block lost |
1 |
0 |
1 |
557 |
0.00 |
0.01 |
|
gc cr block lost |
1 |
0 |
1 |
520 |
0.00 |
0.01 |
|
name-service call wait |
6 |
0 |
1 |
83 |
0.00 |
0.01 |
|
undo segment extension |
48 |
92 |
0 |
8 |
0.00 |
0.01 |
|
SQL*Net more data from client |
14,139 |
0 |
0 |
0 |
0.12 |
0.01 |
|
enq: RC - Result Cache: Contention |
588 |
0 |
0 |
1 |
0.01 |
0.01 |
|
ADR block file read |
542 |
0 |
0 |
1 |
0.00 |
0.00 |
|
cursor: pin S wait on X |
24 |
0 |
0 |
10 |
0.00 |
0.00 |
|
ASM file metadata operation |
4 |
0 |
0 |
55 |
0.00 |
0.00 |
|
enq: TO - contention |
292 |
1 |
0 |
1 |
0.00 |
0.00 |
|
enq: FB - contention |
264 |
0 |
0 |
1 |
0.00 |
0.00 |
|
latch: cache buffers chains |
8,850 |
0 |
0 |
0 |
0.08 |
0.00 |
|
CSS operation: query |
330 |
0 |
0 |
1 |
0.00 |
0.00 |
|
enq: IV - contention |
182 |
16 |
0 |
1 |
0.00 |
0.00 |
|
enq: TX - index contention |
96 |
0 |
0 |
1 |
0.00 |
0.00 |
|
os thread startup |
2 |
0 |
0 |
67 |
0.00 |
0.00 |
|
PX Deq: Signal ACK EXT |
5,292 |
0 |
0 |
0 |
0.05 |
0.00 |
|
gcs drm freeze in enter server mode |
1 |
0 |
0 |
90 |
0.00 |
0.00 |
|
gc current block congested |
132 |
0 |
0 |
1 |
0.00 |
0.00 |
|
enq: MS - contention |
137 |
0 |
0 |
1 |
0.00 |
0.00 |
|
library cache: mutex X |
960 |
0 |
0 |
0 |
0.01 |
0.00 |
|
SQL*Net break/reset to client |
276 |
0 |
0 |
0 |
0.00 |
0.00 |
|
latch free |
32 |
0 |
0 |
2 |
0.00 |
0.00 |
|
kksfbc child completion |
1 |
100 |
0 |
50 |
0.00 |
0.00 |
|
latch: shared pool |
184 |
0 |
0 |
0 |
0.00 |
0.00 |
|
gc current multi block request |
43 |
0 |
0 |
1 |
0.00 |
0.00 |
|
enq: TT - contention |
53 |
0 |
0 |
1 |
0.00 |
0.00 |
|
read by other session |
37 |
0 |
0 |
1 |
0.00 |
0.00 |
|
gc cr block congested |
45 |
0 |
0 |
1 |
0.00 |
0.00 |
|
KJC: Wait for msg sends to complete |
980 |
0 |
0 |
0 |
0.01 |
0.00 |
|
gc current split |
21 |
0 |
0 |
1 |
0.00 |
0.00 |
|
gc current retry |
28 |
0 |
0 |
0 |
0.00 |
0.00 |
|
latch: ges resource hash list |
56 |
0 |
0 |
0 |
0.00 |
0.00 |
|
gc cr grant congested |
7 |
0 |
0 |
0 |
0.00 |
0.00 |
|
enq: TM - contention |
5 |
0 |
0 |
1 |
0.00 |
0.00 |
|
latch: row cache objects |
31 |
0 |
0 |
0 |
0.00 |
0.00 |
|
enq: ZH - compression analysis |
6 |
100 |
0 |
0 |
0.00 |
0.00 |
|
latch: gc element |
343 |
0 |
0 |
0 |
0.00 |
0.00 |
|
ADR block file write |
5 |
0 |
0 |
0 |
0.00 |
0.00 |
|
enq: JS - job run lock - synchronize |
1 |
100 |
0 |
2 |
0.00 |
0.00 |
|
enq: UL - contention |
4 |
75 |
0 |
0 |
0.00 |
0.00 |
|
enq: PI - contention |
2 |
100 |
0 |
1 |
0.00 |
0.00 |
|
enq: TX - allocate ITL entry |
2 |
0 |
0 |
1 |
0.00 |
0.00 |
|
SQL*Net message from client |
1,848,907 |
0 |
2,107,950 |
1140 |
15.97 |
|
|
Streams AQ: waiting for messages in the queue |
723 |
100 |
3,608 |
4990 |
0.01 |
|
|
jobq slave wait |
303 |
100 |
152 |
500 |
0.00 |
|
|
PX Deq: Execution Msg |
11,264 |
0 |
33 |
3 |
0.10 |
|
|
PX Deq: Execute Reply |
5,686 |
0 |
9 |
2 |
0.05 |
|
|
PX Deq: Join ACK |
5,292 |
0 |
8 |
1 |
0.05 |
|
|
PX Deq: Parse Reply |
5,292 |
0 |
5 |
1 |
0.05 |
|
|
PX Deq Credit: send blkd |
162 |
0 |
1 |
8 |
0.00 |
|
3、分析IO 有瓶颈和log file switch (checkpoint incomplete) 等待
Log file sync = CPU + Latch + Log File Parallel Write+ log file switch (checkpoint incomplete)
如果CPU资源不成问题，LGWR在申请Latch时没有遇到竞争，也没有归档日志切换检查点等待， Log file sync的等待时机将会只比 Log File Parallel Write 略大。
Foreground Wait Events
Event
Waits
%Time -outs
Total Wait Time (s)
Avg wait (ms)
Waits /txn
% DB time
enq: TX - row lock contention
13
0
541
41640
0.00
8.08
log file sync
90,518
0
364
4
0.78
5.43
Background Wait Events
Event
Waits
%Time -outs
Total Wait Time (s)
Avg wait (ms)
Waits /txn
% bg time
LNS wait on SENDREQ
193,323
0
238
1
1.67
19.87
db file parallel write
196,756
0
214
1
1.70
17.91
LGWR-LNS wait on channel
327,956
36
170
1
2.83
14.24
log file parallel write
186,524
0
120
1
1.61
10.06
log file sync 的等待时间是364秒，而 log file parallel write 的等待时间是120秒，只有 log file sync 等时间的33%，说明 log file sync 还包含其他的等待事件。
log file parallel write 96.1%的等待时间小于1毫秒，2%的等待时间大于1毫秒小于2毫秒，0.8%的等待时间小于4毫秒大于2毫秒，0.2%的等待时间大于4毫秒小于8毫秒，0.1%的时间大于8毫秒小于16毫秒，0.3%的等待时间大于16毫秒小于32毫秒，0.4%的等待时间大于32毫秒小于1秒。log file parallel write整体IO性能良好，但存在极少数的log file parallel write 等待时间比较高的情况，最高的在32毫秒到1秒这个区间。
从log file parallel write 平均等待时间分布情况结合数据库整体IO不高的情况来看，应该是有瞬间IO峰值很高的情况。
另外 log file sync 平均等待时间在32毫秒到1秒这个区间的占1.6%,但log file parallel write平均等待时间在32毫秒到1秒这个区间的只有0.4%，只有 log file sync 的四之一，
其他平均等待时间点的百分比也比 log file sync 低，说明 log file sync 等待 IO只是部分原因，还有其他的等待，结合 TOP 5 等待时间来看应该是在等待log file switch (checkpoint incomplete)。
接下来我们看物理读很高的 TOP SQL
SQL ordered by Reads
Physical Reads
Executions
Reads per Exec
%Total
Elapsed Time (s)
%CPU
%IO
SQL Id
SQL Module
SQL Text
3,126,777
2
1,563,388.50
58.24
171.90
25.14
61.06
7y6rcqzjwd672
PL/SQL Developer
select t.taskname, t.logstr 寮傚父...
1,974,099
2
987,049.50
36.77
227.86
24.43
63.93
d15cdr0zt3vtp
Oracle Enterprise Manager.Metric Engine
SELECT TO_CHAR(current_timesta...
118,542
2
59,271.00
2.21
216.36
28.99
47.28
295nmgpxumkjz
DBMS_SCHEDULER
DECLARE job BINARY_INTEGER := ...
111,317
326,419
0.34
2.07
166.18
22.01
58.96
82yfqqyakqvq1
DBMS_SCHEDULER
DELETE FROM KUYU_ESB.EIP_DATA_...
9,235
34,469
0.27
0.17
16.60
26.28
55.25
bxzuayyf91440
JDBC Thin Client
select bindingdat0_.pk_data as...
8,934
34,474
0.26
0.17
15.73
26.20
55.65
byyun47zqd8kq
JDBC Thin Client
select bindingdat0_.pk_data as...
7,008
326,418
0.02
0.13
26.30
45.79
15.91
c4mr808uavhfy
DBMS_SCHEDULER
INSERT INTO EIP_DATA_STATUS_H ...
6,425
10,613
0.61
0.12
26.65
23.56
20.71
29dmas072w8j2
JDBC Thin Client
insert into ESB_INTERFACE_LOG ...
1,832
5,050
0.36
0.03
16.56
18.02
13.06
3tfxdb5ahnbk0
JDBC Thin Client
insert into ESB_BILLCODE_RECOD...
1,735
9
192.78
0.03
30.00
61.82
0.21
6dqdr5hqg4qzy
JDBC Thin Client
select * from v_autoverifydata
排在第一位和第二位的TOP SQL占了物理读总量的95.01%；TOP SQL1执行了两次，总共消耗了171.9秒；TOP SQL2也是执行了两次，总耗时227.86秒。
由此判断是这两个SQL执行期间导致了大量的IO，影响了log file parallel write的性能，从而导致了 log file sync 的平均等待时间被提升到4毫秒。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/21582653/viewspace-1815948/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- Mysql：从一个USE DB堵塞故障展开的探讨
- Innodb:RR隔离级别下insert...select 对select表加锁模型和死锁案列
- mydumper 编译错误
- Percona XtraDB Cluster 读写分离
- 定位空闲会话事务没提交导致锁阻塞的脚本
- (何凳成博客)MySQL 加锁处理分析——学习笔记
- innodb行锁对象mutext争用导致LINUX内核态CPU使用率高诊断
- 【MySQL】sync_binlog innodb_flush_log_at_trx_commit 浅析
- 通过performance_schema视图和sys视图定位使用磁盘文件导致IO很高的SQL
- MYSQL主从复制部署MHA自动故障转移
