Brief view on OWI ORACLE WAIT EVENTS part 1
Couple of days back,i was dead hungry waiting to order food in a queue in restaurant.It was bit frustating that my hunger ate me bit by bit rather i control it.But there were 16 people in front of me and there was only one counter to process bill. It took almost hours for the clerk to process each bill for less people.This delay can be avoided if there are more than one counter process the bill or one counter with experienced clerk who can process the bill faster.
Here there are certain points to be noted
There are 16 people in a queue waiting for a resource to consume which is paying bill and getting food.To prepare food for multiple people faster,there should be sufficient cook to cook recipe ordered by different customer.One who stands in the queue at 16th position will have to wait in the counter row and thats me eventhough i have other emergency work.
Think the same in oracle performance where 16 user processes is the customer waiting for clerk and cook to process the task. Cook and Clerk resources are CPU,memory,IO,network etc on the server which are consumed to serve the task(cooking and payment).Food(data) is the objective or result which is the expected by the customer(user).To get the food(data) some people may have huge list of food orders to be placed and some may want only coffee or snacks.If multiple people ordered coffee and vending machine is repaired or under repair,then this problem is not visible to the customer.However,the customer waits and knows that something is not right in the background which lets them wait.The problem may be due to multiple scenarios like shortage issues,repairment,lack of resource etc.These scenarios can be called as wait interface or wait events in oracle term
But if i have sufficient resource power and sufficient infrastructure in hand to serve multiple requests,then there would be win win situation for both customer and vendor.
In oracle as well,if there is less CPU resource,then parallelism cant be utilized efficiently.If there is less memory power,then sorting and cache will be in contention , starvation, swapping etc
If multiple cooks are available then food can be prepared faster.
Types of wait events:
- Foreground
- Background
- Idle
- Non Idle
RESPONSE TIME = SERVICE TIME + WAIT TIME or CPU TIME + QUEUE TIME
CPU used for normal work (CPU_W) = CPU used when call started – parse time CPU – recursive CPU usage
In 11g, below are the list of wait events which i used to describe as 4c’s in wait class .These 4c’s include Cluster,commit,concurrency and configuration.These events are most common waits in both RAC and standalone databases.We will see cluster events in another post part 2.
kish@exdbx<>select name,wait_class from v$event_name where wait_class in ('Commit','Concurrency','Configuration','Cluster') order by wait_class;
NAME WAIT_CLASS
---------------------------------------------------------------- ----------------------------------------------------------------
retry contact SCN lock master Cluster
gc buffer busy acquire Cluster
gc buffer busy release Cluster
pi renounce write complete Cluster
gc current request Cluster
gc cr request Cluster
gc cr disk request Cluster
gc cr multi block request Cluster
gc current multi block request Cluster
gc block recovery request Cluster
gc cr block 2-way Cluster
gc cr block 3-way Cluster
gc cr block busy Cluster
gc cr block congested Cluster
gc cr failure Cluster
gc cr block lost Cluster
gc cr block unknown Cluster
gc current block 2-way Cluster
gc current block 3-way Cluster
gc current block busy Cluster
log file sync Commit
enq: BB - 2PC across RAC instances Commit
latch: cache buffers chains Concurrency
Shared IO Pool Memory Concurrency
logout restrictor Concurrency
os thread startup Concurrency
Streams apply: waiting for dependency Concurrency
pipe put Concurrency
securefile chain update Concurrency
buffer busy waits Concurrency
db flash cache invalidate wait Concurrency
enq: TX - index contention Concurrency
latch: Undo Hint Latch Concurrency
latch: In memory undo latch Concurrency
latch: MQL Tracking Latch Concurrency
Streams apply: waiting to commit Configuration
checkpoint completed Configuration
Global transaction acquire instance locks Configuration
statement suspended, wait error to be cleared Configuration
enq: SQ - contention Configuration
sort segment request Configuration
Below are the wait events w.r.t application and user I/O which also should be noted when there is a performance issue
kish@exdbx<>select name,wait_class from v$event_name where wait_class in ('Application','User I/O') order by wait_class;
NAME WAIT_CLASS
---------------------------------------------------------------- ----------------------------------------------------------------
enq: PW - flush prewarm buffers Application
WCR: replay lock order Application
enq: RO - fast object reuse Application
enq: KO - fast object checkpoint Application
enq: TM - contention Application
enq: TX - row lock contention Application
Wait for Table Lock Application
enq: RC - Result Cache: Contention Application
Streams capture: filter callback waiting for ruleset Application
Streams: apply reader waiting for DDL to apply Application
SQL*Net break/reset to client Application
SQL*Net break/reset to dblink Application
External Procedure initial connection Application
External Procedure call Application
enq: UL - contention Application
OLAP DML Sleep Application
enq: RO - contention Application
Parameter File I/O User I/O
Disk file operations I/O User I/O
Disk file I/O Calibration User I/O
Disk file Mirror Read User I/O
Disk file Mirror/Media Repair Write User I/O
direct path sync User I/O
Datapump dump file I/O User I/O
dbms_file_transfer I/O User I/O
DG Broker configuration file I/O User I/O
Data file init write User I/O
Log file init write User I/O
Shared IO Pool IO Completion User I/O
Below are the dynamic views which are useful when tuning wait events
- v$session_event
- v$session_wait
- v$session_wait_class
- v$session_wait_history
- v$system_event
- v$system_wait
- v$system_wait_class
- v$event_name
- v$event_histogram
- v$active_session_history
- v$waitstat
Information gathered from v$session_* views are aggregated and collected into v$system_* views
v$session_* views show the current connections wait statistics and v$system_* views shows the collected wait stats from instance startup
v$session_wait > v$system_event
v$session_event > v$system_event
Below are the static views for tuning
- DBA_HIST_ACTIVE_SESS_HISTORY
- DBA_HIST_SQLSTAT
- DBA_HIST_SNAPSHOT
- DBA_HIST_SESSMETRIC_HISTORY
- DBA_HIST_SESS_TIME_STATS
- DBA_HIST_SERVICE_WAIT_CLASS
- DBA_HIST_WAITSTAT
Let check the histogram buckets for most common exadata wait event.There are different number of buckets in the wait_time_milli column
Cell single block physical read has 12 buckets upto 2048 ms;Cell multiblock physical read has 10 buckets upto 512 ms;
wait_count for Cell single block physical read ranges from 707*1ms to 3*2048ms
Here second bucket shows 2*1069ms of waits which is higher than the 1st bucket (707)
But if you take Cell multiblock physical read,there are few buckets(10) upto 512 ms.From this information,smaller number of long waits and large number of shorter waits can be derived.
kish@exdbx<>select event#,event,wait_time_milli,wait_count from v$event_histogram where event like '%cell%';
EVENT# EVENT WAIT_TIME_MILLI WAIT_COUNT
---------- ---------------------------------------------------------------- --------------- ----------
403 cell single block physical read 1 707
403 cell single block physical read 2 1069
403 cell single block physical read 4 691
403 cell single block physical read 8 497
403 cell single block physical read 16 1414
403 cell single block physical read 32 1492
403 cell single block physical read 64 432
403 cell single block physical read 128 93
403 cell single block physical read 256 14
403 cell single block physical read 512 6
403 cell single block physical read 1024 2
403 cell single block physical read 2048 3
404 cell multiblock physical read 1 23
404 cell multiblock physical read 2 207
404 cell multiblock physical read 4 283
404 cell multiblock physical read 8 175
404 cell multiblock physical read 16 410
404 cell multiblock physical read 32 471
404 cell multiblock physical read 64 120
404 cell multiblock physical read 128 34
404 cell multiblock physical read 256 23
404 cell multiblock physical read 512 14
33 rows selected.
Common wait events:
Buffer busy waits:
Whenever a session needs to access a datablock in buffer cache ,the same block is accessed or modified by some other session.The other session is either reading the same data block into buffer cache from datafile,or it is modifying the one in buffer cache.
To guarantee that reader session has a consistent image of the datablock with dirty block or free block,the session modifying the block marks the block header with flag to intimate other sessions know that the change is taking place and to wait until complete change is applied.Below are the most common classes of buffer which undergo BBW are,
kish@exdbx<>select * from v$waitstat where count > 0;
CLASS COUNT TIME
------------------ ---------- ----------
data block 56 61
segment header 2 7
1st level bmb 2 2
2nd level bmb 2 0
undo header 4 0
undo block 1 0Control file parallel write:
Control file parallel write(CFPW) occur if session waits until all controlfiles are updated with the latest SCN by CKPT process and other backup and recovery information to maintain consistency of datafile and redolog files.Every 3 seconds CKPT(checkpoint) process writes the checkpoint position in all members of online redologs for recovery purpose.Oracle also store the unrecoverable SCN operations like DML performed using nologging options.
Here the session waits for the I/O on OS holding CF enqueue to complete the write operations on the controlfiles.
When it is considered problematic? If there are enormous waits and elapsed time observed on CFPW,then it might be an indication of slow I/O subsystem or slow writes by CKPT process.
USERNAME SID SERIAL# EVENT
-------------------- ---------- ---------- ------------------------------
WAIT_CLASS WAIT_TIME SECONDS_IN_WAIT STATE
--------------- ---------- --------------- -------------------
(oracle) 12 1 control file sequential read
System I/O 0 0 WAITING
DB file parallel read:
Dont get fooled by the naming convention of this wait event.This event is purely occur during the recovery of the database.It also occurs during read of single or multiple block parallely from datafile to database buffer cache.
DB file parallel write:
Similar to previous event,this events is responsible for writing the dirty buffer from db buffer to datafile where DBWR plays a major role.The session waits for the I/O subsystem on OS for the writes to complete.This may also impact the read requests simultaneously during write on the same disk.DBWR perform batch writes to the datafile either synchronously or asynchronously.
If you dont see this event in your database,then disk_async_io parameter must be set to false
When db file parallel write average wait time > 100ms ,then you have slow IO subsystem.
kish@exdbx<>select KSPPINM from x$ksppi where KSPPINM in ('fast_start_mttr_target','_db_large_dirty_queue','_db_block_max_dirty_target');
KSPPINM
--------------------------------------------------------------------------------
_db_large_dirty_queue
fast_start_mttr_target
DB file scattered read:
You must have heard of this most common wait event,which occur during SELECT statement and a process waits for multiblock read to complete.Multiple datablocks from datafile are read by server process and datablocks are collected and scattered randomly into database buffercache in a non contiguous manner.Also we can notice full table scan or index fast full scan during this event
DB_FILE_MULTIBLOCK_READ_COUNT is the parameter which determines the number of datablock which can be read from the datafile.This event is usual and occur most of the time.Consider this event as a nightmare,when you observe significant amount of wait compared to other events.
SQL> select event,sample_time, session_state,count(*) from v$active_session_history where event like '%scattered%' group by event,sample_time, session_state;
EVENT SAMPLE_TIME SESSION_STATE COUNT(*)
-------------------- -------------------- -------------------- ----------
db file scattered re 29-MAR-21 11.39.35.0 WAITING 1
ad 15 AM
This wait falls under USER I/O and if there is high wait observed,then most probably it is an application issue
Three parameters are used for this event :file#,first block# and block count
kish@exdbx<>select a.sid,b.name,a.value from v$sesstat a ,v$statname b
2 where a.statistic# = b.statistic# and a.value <> 0
3 and b.name = 'table scan blocks gotten' order by 3,1;
SID NAME VALUE
---------- ---------------------------------------------------------------- ----------
50 table scan blocks gotten 1
36 table scan blocks gotten 2
51 table scan blocks gotten 38
7 table scan blocks gotten 44
5 table scan blocks gotten 187
26 table scan blocks gotten 298
62 table scan blocks gotten 501
60 table scan blocks gotten 9566
22 table scan blocks gotten 18935
9 rows selected.
DB file sequential read:
This event is also common when a process waits for a single block read to complete.This event is displayed by oracle ,when there is index scan,undo segments,table access by rowid,rebuilding controlfiles,dumping datafile headers.If you observe significant wait time for single block read,then you include this event in your trouleshooting list.
Recommendation:
- Since it is totally IO based event where we need to concentrate on reducing the physical and logical IO’s by tuning the sql query used by application. Index reads causes heavy IO when blocks are requested from disk to buffercache and if there is poor extent outline in the datafiles,then demand for IO increases.
- Reduce the average wait time by tuning the sql query
Here the thumb rule is to maintain AVERAGE_WAIT time should not be more than 10ms as a standard measure.
Clustering factor:
Clustering factor of an index should be equal to the number of blocks in a table which means rows are ordered in the table as per the index.If the clustering factor is equal to number of rows in table,then probably you have bad clustering factor.Index requires a rebuild.
Optimal solution is to rewrite the query by writing efficiently queries with better logic
DB file single write:
This event is also one of DBWR event ,occur when datafile headers are updated by oracle.If your database has ample number of datafiles ,then you see this event in your top events
Direct path read(DPR):
This event occurs when oracle directly read the datablocks using PGA instead SGA buffer.DPR can be performed using sync or async I/O based on the hardware.Init parameter DISK_AYNC_IO determine the type of IO during block read.
There are some scenarios where in DPR can be expected
- Parallel server execution
- sorting(sort by/group by clause on a select query)
- hash joins
If the session cannot attain sync IO,then it has to wait until there is a acknowledgement and IO complete.
If session can attain async IO,then multiple DPR requests are sent and they continue to process the blocks that are already cached in PGA.
Direct path write:
If a session writes datablocks using PGA from data buffer to the datafiles.Multiple write requests would be sent to continue processing.OS handles the IO operation.
Scenarios when this event is posted:
- INSERT operation with APPEND like IAS or CTAS
- Parallel DML operations
For LOB segments,specifically there is a direct path write (lob) event
USERNAME SID SERIAL# EVENT
-------------------- ---------- ---------- ------------------------------
WAIT_CLASS WAIT_TIME SECONDS_IN_WAIT STATE
--------------- ---------- --------------- -------------------
SYS 60 391 direct path write
User I/O 0 0 WAITING
Enqueue:
An enqueue is a shared memory structure which serialize the control to acquire to the database resource.To access a memory structure say for instance a particular transaction,the process must get the enqueue lock of resource.Eg: If A acquires an enqueue lock on resource X and B also needs to access resource X,then B has to wait in queue to attain the respective enqueue when A releases X
Types of enqueue
- ST – space management
- SQ – sequence wait
- TX – transaction wait
USERNAME SID SERIAL# EVENT WAIT_CLASS WAIT_TIME SECONDS_IN_WAIT STATE
-------------------- ---------- ---------- ------------------------------ --------------- ---------- --------------- -------------------
SYS 1 47 enq: PS - contention Other 0 6 WAITING
USERNAME SID SERIAL# EVENT
SYS 60 391 enq: CF - contention
Other 0 0 WAITING
Identify the sid and sqlid of the locked sessions
kish@exdbx<>select sid,sql_id from v$session where sid in ('66','58');
SID SQL_ID
---------------------------------------- -------------
58 au7znvpsmyyff
66 5s96y62hq2rhk
Find the sql which are under TX enqueue
kish@exdbx<>select sql_text,sql_id from v$sql where sql_id in ('au7znvpsmyyff','5s96y62hq2rhk');
SQL_TEXT
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID
-------------
update tabx set order_id=369 where mod(order_id,4)=1
5s96y62hq2rhk
update tabx set order_id=369 where mod(order_id,5)=1
au7znvpsmyyff
Identify the lock mode to get the lock type held on the object
kish@exdbx<>select * from v$lock where sid in ('66','58');
ADDR KADDR SID TY ID1 ID2 LMODE
---------------- ---------------- ---------------------------------------- -- ---------------------------------------- ---------------------------------------- ----------------------------------------
REQUEST CTIME BLOCK
---------------------------------------- ---------------------------------------- ----------------------------------------
00000000D3D3AD18 00000000D3D3AD70 66 AE 100 0 4
0 2357 2
00000000D3D3B098 00000000D3D3B0F0 58 AE 100 0 4
0 2350 2
00000000D3D3B798 00000000D3D3B7F0 58 TX 262167 932 0
6 1764 0
00000000D3D3BCF0 00000000D3D3BD48 66 TX 327702 1124 0
6 1772 0
Free buffer waits:
This event occurs when there is no room for datablocks to get accomodate or to build a CR image of block on the buffer cache of SGA.Either the buffer cache is small or the dirty buffers are not flushed to the disk in regular intervals.The server process will notify DBWR to clean the dirty buffers to disk as part the algorithm rules.
Latch free:
When a process holding a latch on a memory structure,another process requiring the latch needs to wait in queue.Oracle maintains consistency with the help of latch.Only one process is allowed to either update or modify the data structures on a latch.Processes which need to attain the latch need to wait
Below are the list of latchname filtered by latch.There are some more latch which were not listed here!Each latch is identified by latch#
SQL> select * from v$latchname where name like '%latch%';
LATCH# NAME HASH
---------- ---------------------------------------------------------------- ----------
2 hot latch diags 1435869216
18 ksupkttest latch 1143481739
20 ksim membership request latch 3846407325
25 ksbxic instance latch 3429070552
31 enqueue freelist latch 1930520624
.........
...........
Library cache pin:
This event is related to library cache concurrency where a session pins an object in library cache in shared pool to read or modify them.Thus preventing others sessions from updating the same object.
It occurs mainly when executing
- PL/SQL procedures
- Views
When this event is considered problematic?
- Dynamic SQL inside PL/SQL procedure has to perform recompilation of the code from the calling procedure
- Blocking session
Solution:
- Shared pool needs to be tuned
- Blocking session must be taken care
SQL> select s.sid,kglpnmod "Mode",kglpnreq "Req" from x$kglpn p,v$session s where p.kglpnuse=s.addr and kglpnhdl='&P1RAW';
Enter value for p1raw:We can get the locks and pins detail in db_object_cache view which is very useful when tuning library cache.If these locks on objects are significant,then its time to have a look on these locks
SQL> select * from (select owner,locks,pins from v$db_object_cache order by locks desc) where rownum < 6 and owner is not null;
OWNER LOCKS PINS
---------------------------------------------------------------- ---------- ----------
SYS 9 0
SYS 7 0
SYS 7 0
SYS 5 0
SYS 5 0
lets test the same with a scenario
Open two sessions A and B and execute procedure with dbms_lock upto 30 seconds time
kish@exdbx<>create or replace procedure x as
2 begin
3 dbms_lock.sleep(30);
4 end;
5 /
Elapsed: 00:00:00.15
kish@exdbx<>exec x
Elapsed: 00:00:30.01At the sametime,compile the procedure from session B.Note that the command hanged for 26 seconds until the procedure complete execution
kish@exdbx<>alter procedure x compile;
Procedure altered.
Elapsed: 00:00:26.53
Simultaneously observe the locks and pins for the procedure with recent timestamp.
kish@exdbx<>select name,owner,pins,locks,timestamp from v$db_object_cache where name like '%DBMS_LOCK%' order by timestamp;
NAME
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
OWNER PINS LOCKS
---------------------------------------------------------------- ---------------------------------------- ----------------------------------------
TIMESTAMP
----------------------------------------------------------------------------
DBMS_LOCK
SYS 1 1
2013-08-24/11:41:29Library cache lock:
A session must acquire a lock on library cache to prevent other sessions access of same object at the same time to maintain consistency or to maintain dependency or to locate an object on library cache.
Log buffer space:
When session has to write redo on log buffer,but has no space to write new information.LGWR process flush log from log buffer to redolog file as per the 3 rules of LGWR(every 3 seconds,every 1/3rd of log buffer full and user commit).This event tells us that LGWR cant write the redo information faster and cope up with the high redo transactions generated by application.
This event is posted
- Redolog files are on disks with I/O contention
- if log buffer size is not optimal
Log file parallel write:
When session waits for LGWR process to write redo information from log buffer to redolog members in group.If LGWR writes redo in ASYNC mode,then it parallely writes the redo information to the active redologfile else it writes in serial manner.
Main reason for this event to occur are
- redolog files are sized small
USERNAME SID SERIAL#
------------------------------ ---------- ----------
EVENT
----------------------------------------------------------------
WAIT_CLASS WAIT_TIME
---------------------------------------------------------------- ----------
SECONDS_IN_WAIT STATE
--------------- -------------------
(oracle) 20 1
log file parallel write
System I/O 0
0 WAITING
Log file sequential read:
When process waits for blocks to be read from online redolog files this event is posted.When ARCH process archives the redo to archivelog file,this event is posted.
USERNAME SID SERIAL# EVENT
-------------------- ---------- ---------- ------------------------------
WAIT_CLASS WAIT_TIME SECONDS_IN_WAIT STATE
--------------- ---------- --------------- -------------------
(oracle) 41 1 log file sequential read
System I/O 0 0 WAITING
Log file switch(archiving needed) and log file switch (checkpoint incomplete)
*Archiving needed* message indicates that ARCH process is not coping up with LGWR process and is slow in archiving the redo to archivelog file than writing the redo to redolog file.This occurs only if database is in archivelog mode and LGWR has to wait until the redos are archived from one of the member being full.If archiving is failed,then this event is posted
*Checkpoint incomplete* indicate that LGWR wait for log file switch to complete because checkpoint for the logfile is not completed.
This is also an indication of redolog file size being small
kish@exdbx<>select bytes/1048576 from v$log;
BYTES/1048576
----------------------------------------
50
50
50
50
Let check the current time of database
kish@exdbx<>select to_char(sysdate,'dd-mm-yy hh24:mi:ss') from dual;
TO_CHAR(SYSDATE,'
-----------------
07-04-21 23:10:05
Lets run the log advisory report for past one hour where there was high DML activity which generated high redo generation.As you can see the size recommendation is very high at time when there was application activity on the database
kish@exdbx<>SELECT
(SELECT
ROUND (AVG (BYTES) / 1024 / 1024, 2)
FROM
V$LOG) AS "Redo size (MB)",
ROUND ( (20 / AVERAGE_PERIOD) * (SELECT AVG (BYTES) FROM V$LOG) / 1024 / 1024, 2) AS "Recommended Size (MB)"
FROM
(SELECT AVG ( (NEXT_TIME - FIRST_TIME) * 24 * 60) AS
AVERAGE_PERIOD
FROM
V$ARCHIVED_LOG
WHERE
FIRST_TIME > SYSDATE - 1
AND
TO_CHAR (FIRST_TIME, 'HH24:MI') BETWEEN '22:00' AND '23:00');
Redo size (MB) Recommended Size (MB)
---------------------------------------- ----------------------------------------
50 2045.45
This doesnt mean that we blindly increase the redolog size because this also increase the mean time for recovery during instance crash(MTTR) determined by fast_start_mttr_target.Depending on the database and its behaviour,a deep analysis of optimal redo is required to determine the redolog size.
Log file sync:
User session performs DML transactions like insert,update or delete on the database and issues a commit or rollback to save the records. When user issues a commit or rollback, the changes made on the objects must be immediately saved by LGWR to members of online redolog files to maintain data protection. Until LGWR write the redo’s from log buffer to redo log files ,the server process has to wait for an acknowledgement from the LGWR.
If the session waits on same log buffer#,seq# of v$session_wait with an increment on those columns,then the session waits due to slow LGWR process.Here we need to identify if LGWR itself is slow due to short transaction commits or due to slow disks like RAID-5.
Solution:
- Tune LGWR
- Batch the transactions to reduce the commits
- Check if all the members of redolog file are equally and optimally sized
SQL*NET message from client:
This wait event is posted if a client sits in front of sqlplus or sql developer terminal and process wait for a message from the client to action.This may indicate that the client go for break and come back after sometime and the process sits idle until clients provide any input.Another scenario may be batch programs run on the system non interactively which doesnot have control over client.The event itself state that problem is not from database but from network or application layer.
SYS 60 391 SQL*Net more data from dblink
Network 0 0 WAITING
SYS 37 45 SQL*Net message to client
Network -1 0 WAITED SHORT TIME
SQL*NET message to client:
This event is contradictory to previous event.The client process is too busy in some task and server process has to wait for the acknowledgement from the client or due to network latency
USERNAME SID SERIAL# EVENT WAIT_CLASS WAIT_TIME SECONDS_IN_WAIT STATE
-------------------- ---------- ---------- ------------------------------ --------------- ---------- --------------- -------------------
SYS 74 249 SQL*Net message to client Network -1 0 WAITED SHORT TIME
ASM file metadata operation:
This event posts waits when the ASM processes perform operations very slow than the database process or the database process sends multiple request faster than the ASM can respond during a smart scan.
USERNAME SID SERIAL# EVENT
-------------------- ---------- ---------- ------------------------------
WAIT_CLASS WAIT_TIME SECONDS_IN_WAIT STATE
--------------- ---------- --------------- -------------------
(oracle) 56 643 ASM file metadata operation
Other 0 1 WAITING