Oracle Real Application Clusters

13.8 Oracle's Wait interface

In the STATSPACK report discussions above, we mentioned the top 5 waits encountered by the database/application during a specific snapshot period. These wait events are retrieved by the STATSPACK process from certain data dictionary views and stored in the STATSPACK-specific tables in the PERFSTAT schema.

Oracle's wait interface (OWI) helps to identify all wait events. This helps track the number of waits and the amount of time waited for each event throughout the life of a session.

The data dictionary views that constitute the wait interface include:

• GV$SYSTEM_EVENT

• GV$SESSION_EVENT

• GV$SESSION_WAIT

• GV$EVENT_NAME

• GV$SYSSTAT

• GV$SESSTAT

Unlike the STATSPACK report that only reports information at the overall system level like that provided by querying the GV$SYSTEM_EVENT view, data dictionary views such as the GV$SESSION_EVENT and GV$SESSION_WAIT provide information at the session level.

Unlike the information in the GV$SYSTEM_EVENT, which is retained until the instance is bounced, the data available in session views is lost after the session has disconnected from the database. Due to the dynamic nature of these views and due to short span of a session's existence, collecting data from these views by querying them directly may be difficult. The workaround for this situation would be to capture the data in these views and store them in user-defined tables.

In order to retain the session statistics it is required that these statistics be written to a separate table before the session disconnects from the database. This could be implemented using the BEFORE LOGOFF ON DATABASE trigger. The BEFORE LOGOFF ON DATABASE trigger is created at the database level and is configured to capture all events from the session-related views and insert them into their respective tables.

The procedure mv_perfaudit_create.sql creates three tables, MV_AUDIT_SESSION_EVENT, MV_AUDIT_SESSION_WAIT,and MV_AUDIT_SESSION_STAT. The script also contains three trigger creation scripts used to populate the above three tables. Apart from the session information contained in the GV$SESSION_WAIT and GV$SESSION_EVENT tables, the procedure also captures additional information from the GV$SESSION view, including the SQL_ADDRESS of the statement that is related to the wait event. Using this address, the actual SQL text of the query can be obtained by joining the MV_AUDIT_SESSION_EVENT table against the V$SQL view.

COL EVENT format a30 COL USERNAME format a15 COL TIMEOUTS format 99999 COL WAIT format 99999 COL WAITED format 99999 COL SID format 9999 SELECT mvase_sid SID, mvase_username USERNAME, mvase_sql_address SQL_ADDRESS, mvase_event EVENT, mvase_total_timeouts TIMEOUTS, mvase_total_waits WAIT, mvase_time_waited WAITED, mvase_failed_over FO FROM mv_audit_session_event WHERE mvase_username IS NOT NULL ORDER BY mvase_sid; / SID SQL_ADDRESS EVENT TIMEOUTS WAIT WAITED FO --- -------------- --------------------- -------- ---- ------ ------------------ 32 0000000442A622A0 jobq slave wait 1 2 573 NO 32 0000000442A622A0 log file sync 0 1 0 NO 32 0000000442A622A0 db file sequential read 939 1145 1252 NO 32 0000000442A622A0 SQL*Net message to client 0 15 0 NO 32 0000000442A622A0 SQL*Net message from client 0 14 7126 NO 32 0000000442A622A0 db file sequential read 0 1 7 NO 32 0000000442A622A0 SQL*Net message to client 0 31 0 NO 32 0000000442A622A0 SQL*Net more data to client 0 1 0 NO 32 0000000442A622A0 SQL*Net message from client 0 30 5793 NO 32 0000000442A622A0 db file sequential read 239 145 122 NO 32 0000000442A622A0 SQL*Net message to client 0 35 0 NO

The above query output indicates that the session with SID 32 had encountered the above mentioned wait events while performing certain SQL operations. For example, the query below joins the MV_AUDIT_SESSION_EVENT table to GV$SQL view to obtain the SQL text that the session was executing which had encountered the above-mentioned waits.

SELECT SQL_TEXT FROM GV$SQL, MV_AUDIT_SESSION_EVENT WHERE ADDRESS= MVASE_SQL_ADDRESS AND MVASE_SID= 32

Similarly, the wait table MV_AUDIT_SESSION_WAIT could be queried to retrieve the various details of the waits, including the reasons for the waits. For example, the wait could be on a table when retrieving rows, could be on the SQL*Net where the Oracle process is waiting for more information from the client, or is waiting to send a message to the client.

COL SID FORMAT 9999 COL USERNAME FORMAT A15 COL EVENT FORMAT A30 COL P1 FORMAT 9999 COL P2 FORMAT 9999 COL P3 FORMAT 9999 Select MVASW_SID SID, MVASW_USERNAME USERNAME, MVASW_SQL_ADDRESS SQL_ADDRESS, MVASW_EVENT EVENT, MVASW_P1 P1, MVASW_P2 P2, MVASW_P3 P3, MVASW_WAIT_TIME WAIT, MVASW_FAILED_OVER FO FROM MV_AUDIT_SESSION_WAIT WHERE MVASW_USERNAME IS NOT NULL AND (MVASW_EVENT LIKE OR MVASW_EVENT LIKE OR MVASW_EVENT LIKE OR MVASW_EVENT LIKE OR MVASW_EVENT LIKE ORDER BY SID / SID SQL_ADDRESS EVENT P1 P2 P3 WT FO --- ---------------- ---------------------- --- ----- ------------ -- -- 30 0000000443D7CF48 db file sequential read 18 56903 1 0 NO 32 0000000442A622A0 db file sequential read 194 20683 1 0 NO 32 0000000442174720 db file sequential read 18 25804 1 0 NO 32 00000004421739C0 db file sequential read 18 11786 1 0 NO 32 0000000443AB2528 global cache null to x 18 25804 17917873152 0 NO 36 0000000442178608 db file sequential read 18 24480 1 0 NO 36 0000000442178608 global cache s to x 18 1164 17934759808 0 NO 39 00000004421781C8 global cache open x 18 28712 17968379616 0 NO 90 00000004448FE370 db file sequential read 18 15422 1 0 NO 99 0000000443D7DDD8 global cache null to x 18 11888 17045147456 0 NO 120 00000004448F9728 db file sequential read 18 11891 1 0 NO 125 00000004448F8FA0 db file sequential read 18 11864 1 0 NO 125 00000004448FE370 global cache cr request 18 23689 17028513088 0 NO

The output above indicates the various wait events and the objects that the process waited against. For example, the query above has filtered out only the events that contain %db% and others related specifically to RAC. The db file sequential read on session 32 was encountered in the previous query from the MV_AUDIT_SESSION_EVENT table. This query illustrates the reasons for the wait.

The contents of P1, P2, and P3 vary from event to event. The actual meaning for these events could be obtained by querying MVASW_P1TEXT, MVASW_P2TEXT, and MVASW_P3TEXT from the MV_AUDIT_SESSION_WAIT for column contents of P1, P2, and P3, respectively. The same infor mation could also be obtained by querying the GV$EVENT_NAME view:

COL EVENT# FORMAT 9999 COL NAME FORMAT A30 COL PARAMETER1 FORMAT A12 COL PARAMETER2 FORMAT A12 COL PARAMETER3 FORMAT A12 SELECT EVENT#, NAME, PARAMETER1, PARAMETER2, PARAMETER3 FROM GV$EVENT_NAME WHERE (NAME LIKE OR NAME LIKE OR NAME LIKE OR NAME LIKE / EVENT# NAME PARAMETER1 PARAMETER2 PARAMETER3 ------ ------------------------- ---------- ---------- ------------ 150 buffer busy global cache file# block# id 151 buffer busy global CR file# block# id 191 db file sequential read file# block# blocks 192 db file scattered read file# block# blocks 193 db file single write file# block# blocks 194 db file parallel write requests interrupt timeout 195 db file parallel read files blocks requests 196 global cache open s file# block# le 197 global cache open x file# block# le 198 global cache null to s file# block# le 199 global cache null to x file# block# le 200 global cache s to x file# block# le 201 global cache cr request file# block# le 202 global cache cr disk file# block# le request 203 global cache busy file# block# id 205 global cache bg acks count loops 206 global cache pending ast le 207 global cache retry prepare file# block# 150 buffer busy global cache file# block# id 151 buffer busy global CR file# block# id 191 db file sequential read file# block# blocks 192 db file scattered read file# block# blocks 193 db file single write file# block# blocks 194 db file parallel write requests interrupt timeout 195 db file parallel read files blocks requests 196 global cache open s file# block# le 197 global cache open x file# block# le 198 global cache null to s file# block# le 199 global cache null to x file# block# le 200 global cache s to x file# block# le 201 global cache cr request file# block# le 202 global cache cr disk block# le

From the output above it is found that the parameters for db file sequential read are file#, block#, and blocks. Applying these values to the output from the MV_AUDIT_SESSION_WAIT table above, session 32 had encountered waits on two files, file# 194 and file# 18. Further analysis indicates that session 32 had encountered waits on file# 18 twice; however, in both the situations the blocks that it waited on were different (block# 25804 and block# 11786).

Session 32 also encountered waits on global cache locks reported through the global cache null to x wait. This wait is a lock conversion for a local read-only mode to exclusive mode. Further analysis of the statistics collected in the MV_AUDIT_SESSION_WAIT table determined that this wait was also encountered on file# 18 on block# 25804.

The next step would be to identify the actual files and the tablespaces that map to these objects. Once the tablespaces are identified, the next step would be to identify which tables or indexes are contained in these tablespaces.

In this case, as illustrated below, by querying the V$DATAFILE, V$TABLESPACE, and DBA_TABLES view, we can see that the files are shared by more than one table and the blocks contention are on these tables:

COL FILE# FORMAT 9999 COL FNAME FORMAT A44 COL TNAME FORMAT A25 COL TABLE_NAME FORMAT A30 SELECT F.FILE#, F.NAME FNAME, T.NAME TNAME, TABLE_NAME FROM V$DATAFILE F, V$TABLESPACE T, DBA_TABLES WHERE F.TS#= T.TS# AND (F.FILE#= 194 OR F.FILE#= 18) AND T.NAME = TABLESPACE_NAME FILE# FNAME TNAME TABLE_NAME ---- ------------------------------------- ---------------- ------------- 18 /dev/vx/rdsk/oraracdg/partition500m_1a TBS190_DATA_P001 USER_PROFILE 18 /dev/vx/rdsk/oraracdg/partition500m_1a TBS190_DATA_P001 COMPANY 194 /dev/vx/rdsk/oraracdg/partition500m_4a TBS200_DATA_P001 USER_LOGIN 194 /dev/vx/rdsk/oraracdg/partition500m_4a TBS200_DATA_P001 USER_SECURITY

Occasional contentions need not be of concern. However, if this contention is repeatable, the reasons need to be identified. From the above analysis there are two potential areas where the problem could be mapped. Either the contention is because the raw device partition is mapped to the same set of disks or it could be because the tables are hot tables and need to be moved into their respective tablespaces to use different files to store the data.

So far we have discussed the OWI with respect to the database, in the sense that it concerns the information reported by GV$SESSION_EVENT, GV$SYSTEM_EVENT, and GV$SESSION_WAIT. These wait activities more or less relate to the database configuration or the behavior of SQL queries or the distribution of data in the database.

It is not just the database and the data that can report issues concerning bad performance; performance data from the operating system can also help in troubleshooting and problem solving. The OWI reports on system- level activities or waits at the system level such as CPU, memory etc. Similar to the database statistics reported by the other three views, the wait activities for the CPU and memory could be obtained by querying the GV$SYSSTAT and GV$SESSTAT.

Similar to GV$SYSTEM_EVENT, which reports on the wait events at the instance level, GV$SYSSTAT also reports operating system statistics at the instance level. This means that the statistics generated from this view only provide an overall health of the database. Also the data provided by this view covers the time since the instance was last bounced as indicated by the GV$INSTANCE view.

COL NAME FORMAT A40 SELECT INST_ID, NAME, VALUE FROM GV$SYSSTAT WHERE (NAME LIKE OR NAME LIKE OR NAME LIKE OR NAME LIKE INST_ID NAME VALUE ------- ----------------------------------- --------- 1 recursive cpu usage 1134363 1 global lock sync gets 4144288 1 global lock async gets 231936 1 global lock get time 206027 1 global lock sync converts 207121 1 global lock async converts 318799 1 global lock convert time 112312 1 global lock releases 4310681 1 db block gets 93786250 1 db block changes 57229650 1 global cache gets 67304228 INST_ID NAME VALUE ------- ----------------------------------- -------------- 1 global cache get time 56519113 1 global cache converts 1014750 1 global cache convert time 1136498 1 global cache cr blocks received 1816738 1 global cache cr block receive time 759748 1 global cache current blocks received 10089455 1 global cache current block 56747428 receive time 1 global cache cr blocks served 1692951 1 global cache cr block build time 13719 1 global cache cr block flush time 215520 1 global cache cr block send time 38087 INST_ID NAME VALUE ------- ----------------------------------- ------------------ 1 global cache current blocks served 28210721 1 global cache current block pin time 910030 1 global cache current block flush time 103497 1 global cache current block send time 828097 1 global cache freelist waits 3 1 global cache defers 119262 1 global cache convert timeouts 0 1 global cache blocks lost 178 1 global cache claim blocks lost 0 1 parse time cpu 76791 1 parse time elapsed 579757 1 parse count (total) 13209035 1 parse count (hard) 23307 1 parse count (failures) 133 1 OS Wait-cpu (latency) time 0 2 recursive cpu usage 1113997 2 global lock sync gets 3291355

As we have discussed earlier, in this case also, the session-based information is lost when the user disconnects his or her session from the database. Hence, the data from the GV$SESSTAT needs to be stored in a permanent table, for example, in MV_AUDIT_SESSION_STAT for future analysis.

COL SID FORMAT 999 COL USERNAME FORMAT A15 COL STAT# FORMAT 9999 COL NAME FORMAT A35 COL VALUE FORMAT SELECT MVASS_SID SID, MVASS_SQL_ADDRESS SQL_ADDRESS, MVASS_STATISTIC# STAT#, NAME, MVASS_VALUE VALUE FROM MV_AUDIT_SESSION_STAT, GV$STATNAME WHERE MVASS_STATISTIC# = STATISTIC# AND MVASS_USERNAME IS NOT NULL AND MVASS_VALUE > 0 ORDER BY MVASS_SID / SID SQL_ADDRESS STAT# NAME VALUE ---- ---------------- ----- ---------------------- ---------- 100 000000044668AD30 232 parse count (total) 1 100 000000044668AD30 219 PX local messages recv'd 2 100 000000044668AD30 218 PX local messages sent 2 100 000000044668AD30 1 logons current 1 100 000000044668AD30 0 logons cumulative 1 100 000000044668AD30 34 global lock releases 1 100 000000044668AD30 28 global lock sync gets 2 100 000000044668AD30 27 enqueue releases 1 100 000000044668AD30 25 enqueue requests 2 100 000000044668AD30 21 session pga memory max 4502576 100 000000044668AD30 20 session pga memory 4 502576 SID SQL_ADDRESS STAT# NAME VALUE ---- ---------------- ----- ---------------------- ----------- 100 000000044668AD30 16 session uga memory max 60968 100 000000044668AD30 235 execute count 1 100 000000044668AD30 34 global lock releases 1 100 000000044668AD30 28 global lock sync gets 2 100 000000044668AD30 27 enqueue releases 1 100 000000044668AD30 25 enqueue requests 2 100 000000044668AD30 21 session pga memory max 4502576 100 000000044668AD30 20 session pga memory 4502576 100 000000044668AD30 16 session uga memory max 60968 100 000000044668AD30 15 session uga memory 60968 100 000000044668AD30 14 process last non-idle time 1040613274 SID SQL_ADDRESS STAT# NAME VALUE ---- ---------------- ----- ------------------------- ---------- 100 000000044668AD30 13 session connect time 1040613274 100 000000044668AD30 15 session uga memory 60968 100 000000044668AD30 14 process last non-idle time 1040613274 100 000000044668AD30 13 session connect time 1040613274

The above output indicates the session statistics of the system. It indicates the amount of memory and CPU (not shown in the output) consumed by the session. Data from this output could be utilized for sizing the Oracle memory and if there is high CPU usage, consider tuning the query.