11g Wait Event Histograms

From 11g Oracle introduced Wait Event Histograms in the AWR report. This provides DBAs more granular information in the report for efficient diagonosis.This section splits the event counts into elapsed time buckets so that we can see if there are any suspicious or anomalous response time / frequency patterns. This is a very interesting and informational view in Oracle11g when it comes to analyzing wait time per wait event.

It shows a histogram of the number of waits, total wait time and maximum wait for each event. The bucket sizes or the time intervals in this case, for the histograms are predefined. They cannot be changed. The bucket time intervals are from < 1 ms, < 2 ms, < 4 ms, < 8 ms, < 16 ms, and so on, increasing with the power of 2, till we get to >= 2 ms. The buckets will be populated accordingly, and only when TIMED_STATISTICS is set to TRUE. From a very short report it produces an extremely useful addition to the information about lost time. 

For any event, the less number of buckets the better because the wait times they represent are shorter. The bucket boundaries are pre-set and you cannot change their values. Also, high WAIT_COUNT numbers should be in the buckets with lower WAIT_TIME_MILLI values. If you have it the other way around, then that's the event that needs further investigation.

Another good application of this view is to monitor the SQL*Net message from client event. If the WAIT_COUNT is high for the low-end buckets then it could mean that the application is communicating a lot with the client. This may cause excessive network traffic, which could be reduced with higher ARRAYSIZE or server side processing. On the other hand, if the WAIT_COUNT is high for the high-end buckets then it is more likely due to user lag time.

Below are the screen shots of the various sections of AWR representing Wait Events Statistics.

Wait Event Histogram

• Units for Total Waits column: K is 1000, M is 1000000, G is 1000000000
• % of Waits: value of .0 indicates value was <.05%; value of null is truly 0
• % of Waits: column heading of <=1s is truly <1024ms, >1s is truly >=1024ms
• Ordered by Event (idle events last)

		% of Waits
Event	Total Waits	<1ms	<2ms	<4ms	<8ms	<16ms	<32ms	<=1s	>1s
ADR block file read	8	87.5						12.5
Data file init write	7	14.3					28.6	57.1
Disk file operations I/O	587	100.0
LGWR wait for redo copy	12	91.7	8.3
SQL*Net break/reset to client	12	91.7				8.3
SQL*Net message to client	3503	100.0	.0
SQL*Net more data from client	5	100.0
asynch descriptor resize	423	100.0
buffer busy waits	86.7K	24.4	2.7	6.2	13.6	24.5	20.8	7.1	.6
buffer deadlock	2	100.0
control file parallel write	123	3.3	36.6	11.4	3.3	2.4	2.4	40.7
control file sequential read	779	99.7					.1	.1
cr request retry	181	98.3		.6	.6	.6
cursor: pin S	48	43.8	12.5	29.2	8.3	4.2	2.1
db file async I/O submit	52			5.8		1.9	1.9	30.8	59.6
db file parallel read	32	62.5	28.1	3.1	6.3
db file scattered read	195	99.5	.5
db file sequential read	2098	98.0	.1	.1	.2	.4	.4	.8
db file single write	52	30.8	19.2	13.5	5.8	1.9	5.8	23.1
direct path read	733	100.0
direct path sync	1				100.0
direct path write	2	100.0
enq: CF - contention	1								100.0
enq: HW - contention	356	37.9	8.7	20.5	9.0	2.0	5.3	16.6
enq: KO - fast object checkpoint	1								100.0
enq: TX - contention	77	74.0	26.0
enq: US - contention	41	4.9	9.8	24.4	12.2	7.3	17.1	22.0	2.4
free buffer waits	205	.5		1.0	.5	86.3	3.9	5.4	2.4
latch: In memory undo latch	5	100.0
latch: cache buffers chains	195	55.4	16.4	10.3	3.6	4.1	9.7	.5
latch: call allocation	1		100.0
latch: enqueue hash chains	11	81.8	18.2
latch: shared pool	3	100.0
library cache lock	1						100.0
library cache: mutex X	2	50.0		50.0
lock deadlock retry	3	100.0
log buffer space	93			1.1		2.2	3.2	88.2	5.4
log file parallel write	1366	69.0	2.8	2.3	1.8	2.7	4.1	16.5	.7
log file sequential read	10	100.0
log file single write	10	50.0	10.0					40.0
log file switch (checkpoint incomplete)	3							33.3	66.7
log file switch (private strand flush incomplete)	10							60.0	40.0
log file switch completion	7					28.6		57.1	14.3
log file sync	395	19.2	6.8	4.1	5.3	5.6	6.3	48.1	4.6
os thread startup	7						71.4	28.6
rdbms ipc reply	31	93.5	3.2	3.2
reliable message	32	87.5		6.3	3.1			3.1
row cache lock	28	3.6		28.6	28.6	21.4		17.9
DIAG idle wait	275								100.0
SQL*Net message from client	3742	79.3	12.8	3.1	1.6	1.0	.7	.5	.9
Space Manager: slave idle wait	19	5.3							94.7
Streams AQ: qmn coordinator idle wait	10	40.0				10.0			50.0
Streams AQ: qmn slave idle wait	5								100.0
Streams AQ: waiting for messages in the queue	27								100.0
class slave wait	1	100.0
dispatcher timer	3								100.0
jobq slave wait	396							100.0
pmon timer	67	26.9		1.5				3.0	68.7
rdbms ipc message	1101	17.2	4.9	1.2	3.9	5.1	2.7	16.0	49.0
shared server idle wait	5								100.0
smon timer	1								100.0
wait for unread message on broadcast channel	139	.7						.7	98.6

Wait Event Histogram Detail (64 msec to 2 sec)

• Units for Total Waits column: K is 1000, M is 1000000, G is 1000000000
• Units for % of Total Waits: ms is milliseconds s is 1024 milliseconds (approximately 1 second)
• % of Total Waits: total waits for all wait classes, including Idle
• % of Total Waits: value of .0 indicates value was <.05%; value of null is truly 0
• Ordered by Event (only non-idle events are displayed)

		% of Total Waits
Event	Waits 64ms to 2s	<32ms	<64ms	<1/8s	<1/4s	<1/2s	<1s	<2s	>=2s
ADR block file read	1	87.5	12.5
Data file init write	4	42.9	14.3	14.3		14.3	14.3
buffer busy waits	6525	92.3	3.7	.8	.6	.6	1.2	.5	.2
control file parallel write	50	59.3	8.1	10.6	12.2	4.9	4.9
control file sequential read	1	99.9	.1
db file async I/O submit	37	9.6	1.9	1.9	7.7	7.7	11.5	40.4	19.2
db file sequential read	16	99.2	.6	.1		.0	.0
db file single write	12	76.9	13.5	1.9	3.8	1.9	1.9
enq: CF - contention	1							100.0
enq: HW - contention	59	83.4	.3	6.2		10.1
enq: US - contention	10	75.6	4.9	17.1				2.4
free buffer waits	16	92.2	.5		.5	1.0	3.4	2.4
latch: cache buffers chains	1	99.5	.5
log buffer space	86	6.5	5.4	18.3	12.9	24.7	26.9	4.3	1.1
log file parallel write	235	82.7	4.0	4.4	3.4	2.0	2.7	.7	.1
log file single write	4	60.0		10.0	20.0		10.0
log file switch (checkpoint incomplete)	1					33.3			66.7
log file switch (private strand flush incomplete)	8		10.0			20.0	30.0	20.0	20.0
log file switch completion	5	28.6			14.3	14.3	28.6	14.3
log file sync	206	47.3	10.4	9.4	10.6	9.4	8.4	4.1	.5
os thread startup	2	71.4	28.6
reliable message	1	96.9				3.1
row cache lock	5	82.1	17.9

Wait Event Histogram Detail (4 sec to 2 min)

• Units for Total Waits column: K is 1000, M is 1000000, G is 1000000000
• Units for % of Total Waits: s is 1024 milliseconds (approximately 1 second) m is 64*1024 milliseconds (approximately 67 seconds or 1.1 minutes)
• % of Total Waits: total waits for all wait classes, including Idle
• % of Total Waits: value of .0 indicates value was <.05%; value of null is truly 0
• Ordered by Event (only non-idle events are displayed)

		% of Total Waits
Event	Waits 4s to 2m	<2s	<4s	<8s	<16s	<32s	< 1m	< 2m	>=2m
buffer busy waits	156	99.8	.2
db file async I/O submit	10	80.8	19.2
enq: KO - fast object checkpoint	1		100.0
log buffer space	1	98.9	1.1
log file parallel write	1	99.9	.1
log file switch (checkpoint incomplete)	2	33.3	66.7
log file switch (private strand flush incomplete)	2	80.0	20.0
log file sync	2	99.5	.5

 It is always good if you see the " No data exists " in the 4 min to 1 hr segment and 4 sec to 2 min segment.