Hotsos_2005_owi_10g

Oracle10g: Wait Interface Improvements

Kirtikumar Deshpande

Hotsos Symposium 2005 1

Agenda  Brief

history of Oracle Wait Interface (OWI)

 What’s  OWI

new in Oracle10g Release 1

views in Oracle10g Release 1

 Extended Q

SQL Tracing

&A 2

Brief History of OWI  Introduced  Four – – – –

in Oracle 7.0.12

V$ views:

V$SYSTEM_EVENT V$SESSION_EVENT V$SESSION_WAIT V$EVENT_NAME

 Extended

SQL Trace / Debug Event 10046

– Trace level 8 – Trace level 12

3

Brief History of OWI  Number

– – – – 

of events tracked

Oracle 7.0.12 Oracle 7.3.4 Oracle8i 8.1.7.4 Oracle9i 9.2.0.4

less then 100 little over 100 over 200 around 400

Changes to V$SESSION_EVENT View – Oracle8: MAX_WAIT – Oracle9i: TIME_WAITED_MICRO 4

What’s new in Oracle10g Release 1  Automatic

Data Gathering

 Introduction  Enhanced

of Wait Classes

existing wait event views

 Total

Number of events tracked - 811

 Over

a dozen views report wait event information

 Improved

(10g R1 HP-UX 11.11)

E2E Extended SQL Tracing 5

Automatic Data Gathering  AWR

(Automatic Workload Repository)

– Collects cumulative and differential (delta) statistics at the database level – Collects metric statistics: rate of change in the cumulative statistics – Default: Freq - 1 Hour Retention - 7 Day  ASH

(Active Session History)

– Active sessions are sampled every second  Time

Model

– Tracks time spent in internal operations (parse, execute, I/O) – Used in Self Tuning decisions

6

Introduction of Wait Classes  Enables

high-level analysis of Waits

 Classification

based on solution to correct problematic wait events

 12

Wait Classes

 Defined

in V$EVENT_NAME view 7

Enhanced V$EVENT_NAME View Name -------------------EVENT# EVENT_ID NAME PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS

Type --------------NUMBER NUMBER VARCHAR2(64) VARCHAR2(64) VARCHAR2(64) VARCHAR2(64) NUMBER NUMBER VARCHAR2(64)

Notes --------------<<<< Oracle10g

<<<< Oracle10g <<<< Oracle10g <<<< Oracle10g

8

V$EVENT_NAME EVENT# -----273 274 290 291 292 293 294

EVENT_ID ---------549236675 215477332 2652584166 506183215 1307477558 1620694733 834992820

NAME WAIT_CLASS# WAIT_CLASS ------------------------ ----------- -----------log file sequential read 9 System I/O log file single write 9 System I/O db file sequential read 8 User I/O db file scattered read 8 User I/O db file single write 8 User I/O db file parallel write 9 System I/O db file parallel read 8 User I/O

9

Wait Classes & Nbr of Events CLASS NBR_EVENTS --------------- ---------Administrative 42 Application 11 Cluster 45 Commit 1 Concurrency 17 Configuration 21 Idle 59 Network 25 Other 557 Scheduler 2 System I/O 19 User I/O 12 10 10g R1 HP-UX 11.11

Wait Classes - Examples  Administrative

(DBA tasks affecting others)

– Buffer pool resize – Offline rollback segment – Index rebuilds  Application

– Row level locks or explicit locks  Commit

– Redo log write confirmation  Concurrency

– Buffer busy waits – Library cache latch 11

Wait Classes - Examples  Configuration

– Sizing for log buffer, log files, SGA components – Contention for ST enqueue  Network

– More data to/from database link/client – Remote archive destination  User

I/O

– Database file reads, single writes, – Direct path reads and writes – BFILE reads 12

Wait Classes - Examples  System

I/O

– Redo log writes – Archiving redo logs – Control file writes  Idle

– Indicates that session is inactive, waiting for more work

13

Enhanced OWI Views  New

Columns:

– V$SYSTEM_EVENT 

EVENT_ID

NUMBER

– V$SESSION_EVENT 

EVENT_ID

NUMBER

– V$SESSION_WAIT WAIT_CLASS_ID  WAIT_CLASS#  WAIT_CLASS 

NUMBER NUMBER VARCHAR2(64) 14

Enhanced V$SESSION View 

Includes following columns from V$SESSION_WAIT SEQ# EVENT# EVENT P1TEXT P1 P1RAW P2TEXT P2 P2RAW P3TEXT P3 P3RAW WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS WAIT_TIME SECONDS_IN_WAIT STATE

NUMBER NUMBER VARCHAR2(64) VARCHAR2(64) NUMBER RAW(8) VARCHAR2(64) NUMBER RAW(8) VARCHAR2(64) NUMBER RAW(8) NUMBER NUMBER VARCHAR2(64) NUMBER NUMBER VARCHAR2(19)

15

Enhanced V$SESSION View  No

need to join V$SESSION_WAIT to V$SESSION

 No

need to query V$SESSION_WAIT view

SQL> select sid, username, event, wait_class 2

seconds_in_wait "SIW", state,

3

row_wait_obj# "RWO#",

4

row_wait_file# "RWF#"

5 6 7

from v$session where seconds_in_wait !=0 and username is not null;

16

Enhanced V$SESSION View SID USERNAME EVENT WAIT_CLASS SIW STATE RWO# RWF# --- -------- ----------------------------- ----------- --- ----------------- ---- ---43 SYSTEM db file scattered read User I/O 2 WAITED SHORT TIME 8980 5 38 KIRTI

enq: TX - row lock contention Application

41 KIRTI

SQL*Net message from client

Idle

30 WAITING

8965

5

128 WAITING

-1

0

In this example: – RWO# shows the object number the session is accessing – RWF# shows the absolute file number the session is accessing – Event for SID 38 shows the type of Enqueue the session is waiting for 17

Number of Wait Events  Over

800 wait events

 enqueue

broken into 184 wait events

– No need to decipher P1, P2 values  latch

free broken into 28 wait events

– No need to decipher P1, P2 values 10g R1 HP-UX 11.11

18

New V$ Views with Wait data             

V$ACTIVE_SESSION_HISTORY V$EVENTMETRIC V$EVENT_HISTOGRAM V$SERVICEMETRIC_HISTORY V$SERVICE_EVENT V$SERVICE_WAIT_CLASS V$SESSION_WAIT_CLASS V$SESSION_WAIT_HISTORY V$SYSMETRIC_HISTORY V$SYSTEM_EVENT V$SYSTEM_WAIT_CLASS V$WAITCLASSMETRIC V$WAITCLASSMETRIC_HISTORY

19

New DBA Views with Wait Data  DBA_HIST_EVENT_NAME  DBA_HIST_SYSTEM_EVENT  DBA_HIST_BG_EVENT_SUMMARY  DBA_HIST_WAITCLASSMET_SUMMARY  DBA_HIST_SERVICE_WAIT_CLASS  DBA_HIST_ACTIVE_SESS_HISTORY

20

V$SESSION_WAIT_HISTORY  

Shows 10 most recent waits for the session No need to repetitively query V$SESSION_WAIT view

SID SEQ# EVENT# EVENT P1TEXT P1 P2TEXT P2 P3TEXT P3 WAIT_TIME

NUMBER NUMBER  1 to 10 (latest  oldest) NUMBER VARCHAR2(64) VARCHAR2(64) NUMBER VARCHAR2(64) NUMBER VARCHAR2(64) NUMBER NUMBER  0 = waiting @snapshot time

WAIT_COUNT

NUMBER

21

V$SESSION_WAIT_HISTORY SID SEQ# EVENT P1 P2 P3 W_TM W_COUNT --- ---- --------------------------- ---------- ---- ---- ----- ------40 1 log file sync 962 0 0 0 1 40 2 SQL*Net message from client 1650815232 1 0 8721 1 40 3 SQL*Net message to client 1650815232 1 0 0 1 40 4 db file scattered read 5 225 4 0 1 40 5 db file scattered read 5 217 8 0 1 40 6 db file scattered read 5 209 8 0 1 40 7 db file scattered read 5 201 8 0 1 40 8 db file scattered read 5 193 8 1 1 40 9 db file scattered read 5 185 8 0 1 40 10 SQL*Net message to client 1650815232 1 0 0 1 10 rows selected. 22

V$EVENT_HISTOGRAM Histogram of



–

Number of waits, maximum wait, wait time for each event

Predefined buckets, or time intervals



– – 

< 1 ms, < 2 ms, < 4 ms, < 8 ms, < 16 ms …. >= 2²² ms

TIMED_STATISTICS must be TRUE 23

V$EVENT_HISTOGRAM Name ----------------EVENT# EVENT WAIT_TIME_MILLI WAIT_COUNT

Type -----------NUMBER VARCHAR2(64) NUMBER NUMBER

What’s missing? 24

V$EVENT_HISTOGRAM EVENT# EVENT WAIT_TIME_MILLI WAIT_COUNT ------- ----------------------- --------------- ---------294 db file sequential read 1 29453 294 db file sequential read 2 7319 294 db file sequential read 4 749 294 db file sequential read 8 904 294 db file sequential read 16 3395 294 db file sequential read 32 2167 294 db file sequential read 64 270 294 db file sequential read 128 56 294 db file sequential read 256 16 294 db file sequential read 512 9 295 db file scattered read 1 13397 295 db file scattered read 2 2202 295 db file scattered read 4 881 295 db file scattered read 8 822 295 db file scattered read 16 672 295 db file scattered read 32 523 295 db file scattered read 64 228

25

V$FILE_HISTOGRAM FILE# SINGLEBLKRDTIM_MILLI SINGLEBLKRDS ---------- -------------------- -----------5 1 5608 5 2 401 5 4 96 5 8 41 5 16 53 5 32 23 5 64 10 5 128 3 5 256 5 5 512 1 10 rows selected. 26

V$TEMP_HISTOGRAM FILE# SINGLEBLKRDTIM_MILLI SINGLEBLKRDS ---------- -------------------- -----------1 1 26 1 2 1 1 4 0 1 8 0 1 16 0 1 32 2 6 rows selected.

27

V$SYSTEM_WAIT_CLASS  Instance

level waits by Wait Class

 High-level

wait information

 Sample

information over time to track Wait Classes of interest

28

V$SYSTEM_WAIT_CLASS Name -------------------WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS TOTAL_WAITS TIME_WAITED

Type ----------NUMBER NUMBER VARCHAR2(64) NUMBER NUMBER

29

V$SYSTEM_WAIT_CLASS WAIT_CLASS_ID WC# WAIT_CLASS TOTAL_WAITS TIME_WAITED ------------- ---- ---------------- ----------- ----------3875070507 4 Concurrency 270 1596 3290255840 2 Configuration 378 1222 4217450380 1 Application 3680 321401 1893977003 0 Other 10394 65063 3386400367 5 Commit 28164 17657 1740759767 8 User I/O 72340 22764 2000153315 7 Network 79141 200 4108307767 9 System I/O 206748 174050 2723168908 6 Idle 1156193 364114196 9 rows selected.

What Classes are missing? Why?

30

V$SESSION_WAIT_CLASS  Session

level waits by Wait Class

 Somewhat  Helps

High-level wait information

identify area(s) of concern

– Query by SID – Query by WAIT_CLASS# or WAIT_CLASS_ID – Use V$SESSION_EVENT to drill down 31

V$SESSION_WAIT_CLASS Name ------------------SID SERIAL# WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS TOTAL_WAITS TIME_WAITED

Type ------------NUMBER NUMBER NUMBER NUMBER VARCHAR2(64) NUMBER NUMBER 32

V$SESSION_WAIT_CLASS 

Sample output for WAIT_CLASS# = 8

SID SERIAL# WAIT_CLASS_ID WC# WAIT_CLASS TOTAL_WAITS TIME_WAITED ----- ------- ------------- --- ------------ ----------- ----------42 3399 1740759767 8 User I/O 5605 397 43 643 1740759767 8 User I/O 35 70 47 1 1740759767 8 User I/O 1 0 49 1 1740759767 8 User I/O 333 297 53 1 1740759767 8 User I/O 98 126 54 1 1740759767 8 User I/O 5 5 55 1 1740759767 8 User I/O 809 816 56 1 1740759767 8 User I/O 190 25 57 1 1740759767 8 User I/O 10 1 58 1 1740759767 8 User I/O 6 3 10 rows selected.

33

V$SESSION_WAIT_CLASS 

Sample output for SID = 42

SID SERIAL# WAIT_CLASS_ID WC# WAIT_CLASS TOTAL_WAITS TIME_WAITED ----- ------- ------------- --- ------------ ----------- ----------42 3399 1893977003 0 Other 1 0 42 3399 4217450380 1 Application 5 0 42 3399 3386400367 5 Commit 1 0 42 3399 2723168908 6 Idle 46116 234575 42 3399 2000153315 7 Network 46118 39 42 3399 1740759767 8 User I/O 5605 397 42 3399 4108307767 9 System I/O 3 0 7 rows selected.

34

V$ACTIVE_SESSION_HISTORY 

Shows Sampled Active Session Activity, including waits



Sample frequency typically 1 second



Active Session : Session w/ Waits not in Idle Wait Class



Data stored in a circular buffer for 30 minutes



Busy system may not show all the data



AWR flushes the data to disk – Viewable via DBA_HIST_ACTIVE_SESS_HISTORY

35

V$ACTIVE_SESSION_HISTORY SAMPLE_ID SAMPLE_TIME *SESSION_ID *SESSION_SERIAL# *USER_ID SQL_ID SQL_CHILD_NUMBER SQL_PLAN_HASH_VALUE SQL_OPCODE SERVICE_HASH SESSION_TYPE SESSION_STATE QC_SESSION_ID QC_INSTANCE_ID EVENT EVENT_ID

NUMBER TIMESTAMP(3) NUMBER NUMBER NUMBER VARCHAR2(13) NUMBER NUMBER NUMBER NUMBER VARCHAR2(10) VARCHAR2(7) NUMBER NUMBER VARCHAR2(64) NUMBER

EVENT#

NUMBER

SEQ#

NUMBER

P1

NUMBER

P2

NUMBER

P3

NUMBER

WAIT_TIME

NUMBER

TIME_WAITED

NUMBER

CURRENT_OBJ#

NUMBER

CURRENT_FILE#

NUMBER

CURRENT_BLOCK#

NUMBER

PROGRAM

VARCHAR2(48)

MODULE

VARCHAR2(48)

ACTION

VARCHAR2(32)

CLIENT_ID

VARCHAR2(64) 36

V$SESS_TIME_MODEL  Shows

accumulated time model statistics at session level

Name ----------SID STAT_ID STAT_NAME VALUE

Type ----------------------NUMBER NUMBER VARCHAR2(64) NUMBER 37

V$SESS_TIME_MODEL SID --40 40 40 40 40 40 40 40 40 40 40 40 40 40 40 40 40

STAT_NAME VALUE ---------------------------------------- ---------DB time 19376451 DB CPU 11492220 background elapsed time 0 background cpu time 0 sequence load elapsed time 0 parse time elapsed 62228 hard parse elapsed time 51538 sql execute elapsed time 19291646 connection management call elapsed time 36309 failed parse elapsed time 0 failed parse (out of shared memory) elap 0 hard parse (sharing criteria) elapsed ti 0 hard parse (bind mismatch) elapsed time 0 PL/SQL execution elapsed time 1508 inbound PL/SQL rpc elapsed time 0 PL/SQL compilation elapsed time 0 Java execution elapsed time 0

17 rows selected

38

E2E Extended SQL Tracing  Trace

Event 10046 with level 8, 12  End to End Application Tracing by – – – – –

SID, SERIAL# Service Name Application Module Application Action Client Identifier

 DBMS_MONITOR  Utility

Package Procedures

– trcsess 39

Tracing for SID, SERIAL# 

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE – ( session_id => 40, serial_num => 98, waits => true, binds => true );



EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE – ( session_id => 40, serial_num => 98 );

40

Tracing for Service, Module, Action 

Service Name must be set – Init.ora parameter: SERVICE_NAMES – TNSNAMES.ora parameter: SERVICE_NAME – V$SESSION shows SERVICE_NAME



Defaults: – SYS$BACKGROUND (for all Oracle BG processes) – SYS$USERS (for all User processes)



DBMS_SERVICE package procedures – CREATE_SERVICE – DELETE_SERVICE – DISCONNECT_SESSION – START_SERVICE – STOP_SERVICE

41

Tracing for Service, Module, Action 

Module Name must be set in the Application code – OCI Attribute OCI_ATTR_MODULE – DBMS_APPLICATION_INFO.SET_MODULE



Action name must be set in the Application code – OCI Attribute OCI_ATTR_ACTION – DBMS_APPLICATION_INFO.SET_ACTION



Default – Module  

‘SQL*Plus’ for connections via SQL*Plus Client program name

– Action 

None

42

Tracing for Service, Module, Action 

EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE – ( service_name => ‘APPS1’, module_name => ‘GLEDGER’, action_name => ‘DEBIT_ENTRY’, waits => true, binds => true, instance_name => null );



EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE – ( service_name => ‘APPS1’, module_name => ‘GLEDGER’, action_name => ‘DEBIT_ENTRY’, waits => true, binds => true, instance_name => null ); 43

Tracing for Client Identifier 

Client Identifier must be set by the Application – – – –

OCI attribute OCI_ATTR_CLIENT_INFO DBMS_APPLICATION_INFO.SET_CLIENT_INFO DBMS_SESSION.SET_IDENTIFIER V$SESSION shows CLIENT_IDENTIFIER



EXEC DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE ( client_id => ‘KirtiD’, waits => true, binds => true );



EXEC DBMS_MONITOR.CLIENT_ID_TRACE_DISABLE ( client_id => ‘KirtiD’);

44

Utility – trcsess 

Consolidates trace information into one output file from multiple trace files



The output file can be processed by TKPROF



It is a shell script running a Java Application



Options: – Session Id – Client Id – Service – Module – Action

45

Utility – trcsess  Syntax:

trcsess [output = file_name] [session = SID.SERIAL# ] [client_id = ‘client identifier’] [service = ‘service name’ ] [module = ‘module name’ ] [action = ‘action name’ ] [input_file_1 input_file2 …]

46

Oracle10g: Wait Interface Improvements Q&A

47