Wait Event Enhancements in Oracle 10g

1
Wait Event Enhancementsin Oracle 10g
Terry Sutton and Roger Schrag Database
Specialists, Inc. www.dbspecialists.com
2
Todays Session

• Twelve wait event interface enhancements in
  Oracle 10g that we really like.
• Documentation gaps in some areas make this
  information harder to come by.
• We will assume everyone is familiar with wait
  event concepts and the wait event interface in
  Oracle 9i or earlier.
• To learn more about wait events, read
  www.dbspecialists.com/presentations.htmlwait_even
  ts

3
White Paper

• Contains additional detail we wont have time to
  cover today.
• Includes a handy reference list of all Oracle 10g
  wait events, wait classes, and wait event
  parameters.
• Download www.dbspecialists.com/presentations

4
Twelve Oracle 10g Enhancements

• More descriptive wait event names
• Wait event classes
• vevent_name new columns
• vsql / vsqlarea new columns
• vsession_wait_history
• vsession new columns
• vevent_histogram
• vsystem_wait_class / vsession_wait_class
• Active Session History (ASH)
• Automatic Workload Repository (AWR)
• Time model statistics
• Improved session tracing

5
More Descriptive Names

• Prior to Oracle 10g many wait events had vague
  names that covered many situations
• latch free
• enqueue
• buffer busy waits
• For these waits you had to look at parameter
  values to learn the wait condition.
• Oracle 10g gives the most common of these types
  of waits more descriptive names.

6
latch free

• Prior to Oracle 10g Could indicate a wait on any
  of dozens of different latches.
• Oracle 10g The 26 most common latches have their
  own wait event.
• The rest continue to use the generic latch free
  wait event.

7
latch free Prior to Oracle 10g

• SQLgt SELECT event, state, p1, p2, p3 FROM
  vsession_wait WHERE sid 162
• EVENT STATE P1 P2 P3
• ------------- ------- ----------- ------ -----
• latch free WAITING 15113593728 97 5
• SQLgt SELECT FROM vevent_name WHERE name
  'latch free'
• EVENT NAME PARAMETER1 PARAMETER2
  PARAMETER3
• ------ ---------- --------------- ---------------
  ---------------
• 3 latch free address number
  tries
• SQLgt SELECT name FROM vlatch WHERE latch 97
• NAME
• --------------------
• cache buffers chains

8
latch free in Oracle 10g

• SQLgt SELECT event, state
• 2 FROM vsession_wait
• 3 WHERE sid 162
• EVENT STATE
• ------------------------------ -------
• latch cache buffers chains WAITING
• The more descriptive wait event name saves us the
  effort of decoding wait event parameters.

9
enqueue

• Prior to Oracle 10g Could indicate a wait on any
  of a few dozen different types of enqueues.
• Oracle 10g 184 distinct wait events replace the
  one generic enqueue wait event
• Event names differentiate the enqueue type and
  sometimes even the contention type.
• Parameter names are more descriptive than generic
  id1 and id2.

10
enqueue Prior to Oracle 10g

• SQLgt SELECT event, state, seconds_in_wait FROM
  vsession_wait WHERE sid 96
• EVENT STATE
  SECONDS_IN_WAIT
• -----------------------------------
  ------------------- ---------------
• enqueue WAITING
  24
• SQLgt SELECT sid, CHR (BITAND (p1,-16777216) /
  16777215)
• 2 CHR (BITAND (p1, 16711680) / 65535)
  enq,
• 3 DECODE (CHR (BITAND (p1,-16777216) /
  16777215)
• 4 CHR (BITAND (p1, 16711680) /
  65535),
• 5 'TX', 'Transaction (RBS)',
• ...
• 13 CHR (BITAND (p1, 16711680)
  / 65535)) enqueue_name,
• 14 DECODE (BITAND (p1, 65535), 1,
  'Null', 2, 'Sub-Share',
• 15 3, 'Sub-Exclusive', 4,
  'Share', 5, 'Share/Sub-Exclusive',
• 16 6, 'Exclusive', 'Other')
  lock_mode
• 17 FROM vsession_wait WHERE sid 96
• SID ENQ ENQUEUE_NAME
  LOCK_MODE

11
enqueue in Oracle 10g

• SQLgt SELECT event, state, seconds_in_wait FROM
  vsession_wait WHERE sid 143
• EVENT STATE
  SECONDS_IN_WAIT
• -----------------------------------
  ------------------- ---------------
• enq TX - row lock contention WAITING
  495
• Separate events for separate TX issues
• SQLgt SELECT name, parameter1, parameter2,
  parameter3
• 2 FROM vevent_name
• 3 WHERE name LIKE 'enq TX'
• NAME PARAMETER1
  PARAMETER2 PARAMETER3
• ------------------------------ -------------
  --------------- -------------
• enq TX - contention namemode
  usnltlt16 slot sequence
• enq TX - row lock contention namemode
  usnltlt16 slot sequence
• enq TX - allocate ITL entry namemode
  usnltlt16 slot sequence
• enq TX - index contention namemode
  usnltlt16 slot sequence

12
enqueue in Oracle 10g

• More descriptive parameter names, too
• SQLgt SELECT name, parameter1, parameter2,
  parameter3
• 2 FROM vevent_name
• 3 WHERE name IN ('enq HW - contention',
  'enq SQ - contention')
• NAME PARAMETER1
  PARAMETER2 PARAMETER3
• ------------------------------ -------------
  --------------- -------------
• enq HW - contention namemode
  table space block
• enq SQ - contention namemode
  object 0

13
Wait Event Classes

• Every wait event belongs to one of 12 classes.
• Classes can help point toward a root cause.
• Almost 70 of all wait events belong to a class
  called Other.
• Most of the wait events that occur frequently
  belong to wait event classes with helpful names.

14
Wait Event Class Names
15
Wait Event Class Names
16
Wait Class Assignments

• SQLgt SELECT wait_class, name
• 2 FROM vevent_name
• 3 WHERE name LIKE 'enq TX'
• 4 ORDER BY wait_class, name
• WAIT_CLASS NAME
• --------------- ----------------------------------
  ------
• Application enq TX - row lock contention
• Concurrency enq TX - index contention
• Configuration enq TX - allocate ITL entry
• Other enq TX - contention

17
vevent_name

• Four new columns show which wait class a wait
  event belongs to
• SQLgt DESCRIBE vevent_name
• Name
  Null? Type
• -----------------------------------------
  -------- -------------------
• EVENT
  NUMBER
• EVENT_ID
  NUMBER
• NAME
  VARCHAR2(64)
• PARAMETER1
  VARCHAR2(64)
• PARAMETER2
  VARCHAR2(64)
• PARAMETER3
  VARCHAR2(64)
• WAIT_CLASS_ID
  NUMBER
• WAIT_CLASS
  NUMBER
• WAIT_CLASS
  VARCHAR2(64)

18
vsql and vsqlarea

• Six new columns give more information about how
  time was spent executing a SQL statement
• application_wait_time
• concurrency_wait_time
• cluster_wait_time
• user_io_wait_time
• plsql_exec_time
• java_exec_time
• Times are in microseconds.

19
vsqlarea Example

• In session 1
• SQLgt UPDATE testtab SET numcol numcol 1
  WHERE ROWNUM lt 1000
• In session 2
• SQLgt UPDATE testtab SET numcol numcol 1
  WHERE ROWNUM lt 1000
• In session 1
• SQLgt ROLLBACK
• In session 2
• SQLgt ROLLBACK
• In session 3
• SQLgt UPDATE testtab SET numcol numcol 1

20
vsqlarea Example

• SQLgt SELECT sql_id, application_wait_time appl,
• 2 concurrency_wait_time concurr,
  user_io_wait_time user_io
• 3 FROM vsqlarea
• 4 WHERE sql_text LIKE 'UPDATE testtab SET
  numcol'
• SQL_ID APPL CONCURR USER_IO
• ------------- --------- --------- -----------
• 038m56cp4am0c 178500000 0 20000
• fd5mxhdbf09ny 0 10000 105040000
• SQLgt SELECT sql_id, sql_text
• 2 FROM vsqlarea
• 3 WHERE sql_id IN ('fd5mxhdbf09ny','038m56cp4a
  m0c')
• SQL_ID SQL_TEXT
• ------------- ------------------------------------
  -----------------------
• 038m56cp4am0c UPDATE testtab SET numcol numcol
  1 WHERE ROWNUM lt 1000
• fd5mxhdbf09ny UPDATE testtab SET numcol numcol
  1

21
vsession_wait_history

• New view in Oracle 10g.
• Similar to vsession_wait, but shows the last ten
  wait events for each session.
• The seq column is supposed to show the order in
  which the waits occurred, with 1 being the most
  recent wait
• Different from seq in vsession.
• Does not appear to work as documented (on our
  10.1.0.3 system on Solaris).

22
vsession_wait_history

• SQLgt DESCRIBE vsession_wait_history
• Name Null?
  Type
• -----------------------------------------
  -------- --------------------------
• SID
  NUMBER
• SEQ
  NUMBER
• EVENT
  NUMBER
• EVENT
  VARCHAR2(64)
• P1TEXT
  VARCHAR2(64)
• P1
  NUMBER
• P2TEXT
  VARCHAR2(64)
• P2
  NUMBER
• P3TEXT
  VARCHAR2(64)
• P3
  NUMBER
• WAIT_TIME
  NUMBER
• WAIT_COUNT
  NUMBER

23
vsession_wait_history Example

• SQLgt SELECT sid, seq, event, wait_time, p1,
  p2, p3
• 2 FROM vsession_wait_history
• 3 WHERE sid 154
• 4 ORDER BY seq
• SID SEQ EVENT WAIT_TIME
  P1 P2 P3
• --- ---- ------------------------ ----------
  ------ ------ ------
• 154 1 db file sequential read 28
  4 3547 1
• 154 2 log buffer space 18
  0 0 0
• 154 3 log buffer space 36
  0 0 0
• 154 4 db file sequential read 0
  4 3559 1
• 154 5 db file sequential read 0
  4 1272 1
• 154 6 db file sequential read 0
  4 3555 1
• 154 7 log buffer space 9
  0 0 0
• 154 8 db file sequential read 0
  4 3551 1
• 154 9 db file sequential read 6
  4 1268 1
• 154 10 log buffer space 8
  0 0 0

24
vsession

• All columns from vsession_wait have been added
  to vsession
• Saves us the effort of joining the two views..
• New blocking_session, blocking_session_status
  columns
• blocking_session shows the SID of the session
  holding the resource blocking this session.
• blocking_session_status contains VALID when
  blocking_session is populated.

25
vsession Example

• Prior to Oracle 10g
• SQLgt SELECT s.sid, w.state, w.event,
  w.seconds_in_wait siw,
• 2 s.sql_address, s.sql_hash_value
  hash_value, w.p1, w.p2, w.p3
• 3 FROM vsession s, vsession_wait w
• 4 WHERE s.sid w.sid
• 5 AND s.sid 154
• Oracle 10g
• SQLgt SELECT sid, state, event,
  seconds_in_wait siw,
• 2 sql_address, sql_hash_value
  hash_value, p1, p2, p3
• 3 FROM vsession
• 4 WHERE sid 154

26
Another Example

• Why is session 154 waiting? And who is blocking
  session 154?
• SQLgt SELECT sid, blocking_session,
  blocking_session_status block_status,
• 2 username, event, seconds_in_wait
  siw
• 3 FROM vsession
• 4 WHERE sid 154
• BLOCKING
• SID _SESSION BLOCK_STATUS USERNAME EVENT
  SIW
• --- -------- ------------ --------
  ------------------------------ ---
• 154 157 VALID TSUTTON enq TX -
  row lock contention 318

27
vevent_histogram

• New view in Oracle 10g.
• Shows instance-wide summary wait event statistics
  like vsystem_event, but provides a wait time
  histogram for each. Buckets
• Less than 1 mS.
• 1 mS to 2 mS.
• 2 mS to 4 mS.
• 4 mS to 8 mS.
• ... and so on

28
vevent_histogram

• SQLgt DESCRIBE vevent_histogram
• Name Null?
  Type
• -----------------------------------------
  -------- ---------------------------
• EVENT
  NUMBER
• EVENT
  VARCHAR2(64)
• WAIT_TIME_MILLI
  NUMBER
• WAIT_COUNT
  NUMBER

29
vevent_histogram Example

• How significant is the row lock contention on our
  system?
• SQLgt SELECT event, total_waits, time_waited,
  average_wait
• 2 FROM vsystem_event
• 3 WHERE event 'enq TX - row lock
  contention'
• EVENT TOTAL_WAITS
  TIME_WAITED AVERAGE_WAIT
• ----------------------------- -----------
  ----------- ------------
• enq TX - row lock contention 17218
  2101966 122
• Does the average wait of 1.22 seconds indicated
  by vsystem_event paint an accurate picture?

30
vevent_histogram Example

• SQLgt SELECT event, wait_time_milli, wait_count
• 2 FROM vevent_histogram
• 3 WHERE event 'enq TX - row lock
  contention'
• EVENT WAIT_TIME_MILLI
  WAIT_COUNT
• ----------------------------- ---------------
  ----------
• enq TX - row lock contention 1
  833
• enq TX - row lock contention 2
  635
• enq TX - row lock contention 4
  372
• enq TX - row lock contention 8
  395
• enq TX - row lock contention 16
  781
• enq TX - row lock contention 32
  3729
• enq TX - row lock contention 64
  3050
• enq TX - row lock contention 128
  410
• enq TX - row lock contention 256
  47
• enq TX - row lock contention 512
  46
• enq TX - row lock contention 1024
  37
• enq TX - row lock contention 2048
  3
• enq TX - row lock contention 4096
  6880

31
vsystem_wait_class and vsession_wait_class

• New views in Oracle 10g.
• Show wait counts and total time waited since
  instance startup and session start.
• Similar to vsystem_event and vsession_event,
  but summarized by wait class.
• Times are in centiseconds.

32
vsystem_wait_class and vsession_wait_class

• SQLgt DESCRIBE vsystem_wait_class
• Name Null?
  Type
• -----------------------------------------
  -------- ---------------------------
• WAIT_CLASS_ID
  NUMBER
• WAIT_CLASS
  NUMBER
• WAIT_CLASS
  VARCHAR2(64)
• TOTAL_WAITS
  NUMBER
• TIME_WAITED
  NUMBER
• SQLgt DESCRIBE vsession_wait_class
• Name Null?
  Type
• -----------------------------------------
  -------- ---------------------------
• SID
  NUMBER
• SERIAL
  NUMBER
• WAIT_CLASS_ID
  NUMBER
• WAIT_CLASS
  NUMBER
• WAIT_CLASS
  VARCHAR2(64)
• TOTAL_WAITS
  NUMBER
• TIME_WAITED
  NUMBER

33
vsystem_wait_class Example

• SQLgt SELECT wait_class, time_waited
• 2 FROM vsystem_wait_class
• 3 ORDER BY time_waited DESC
• WAIT_CLASS TIME_WAITED
• ------------- -----------
• Idle 777450022
• System I/O 1261584
• User I/O 116667
• Configuration 116481
• Application 72301
• Other 12432
• Commit 3496
• Concurrency 319
• Network 1

34
Active Session History

• New MMNL background process samples vsession
  once each second.
• Data captured on active sessions is available in
  vactive_session_history, usually for 1-4 hours.
• Automatic Workload Repository captures one out of
  every ten samples in its hourly snapshots.

35
Active Session History

• SQLgt DESCRIBE vactive_session_history
• Name Null?
  Type
• -----------------------------------------
  -------- ---------------------------
• SAMPLE_ID
  NUMBER
• SAMPLE_TIME
  TIMESTAMP(3)
• SESSION_ID
  NUMBER
• SESSION_SERIAL
  NUMBER
• USER_ID
  NUMBER
• SQL_ID
  VARCHAR2(13)
• SQL_CHILD_NUMBER
  NUMBER
• SQL_PLAN_HASH_VALUE
  NUMBER
• SQL_OPCODE
  NUMBER
• SERVICE_HASH
  NUMBER
• SESSION_TYPE
  VARCHAR2(10)
• SESSION_STATE
  VARCHAR2(7)
• QC_SESSION_ID
  NUMBER
• QC_INSTANCE_ID
  NUMBER
• EVENT
  VARCHAR2(64)
• EVENT_ID
  NUMBER

36
Active Session History

• vactive_session_history shows detailed wait
  information, current SQL statement,
  object/file/block information, and more.
• When a wait that was sampled by ASH completes,
  Oracle fills in the time_waited column in the
  vactive_session_history row with the actual
  duration of the wait.

37
ASH is Always On

• You may not have to turn on tracing or begin
  monitoring v views when users report a problem,
  because ASH is already sampling data.
• In some cases you may be able to diagnose and
  resolve a problem on first detection, even if you
  learn of the problem after the fact.
• You may not need to get users to reproduce the
  problem.

38
Sampling versus Collecting

• ASH samples vsession once each second. Very
  different from extended SQL trace, which collects
  data on every wait and every OCI call.
• A session could encounter hundreds of waits in
  one second, and ASH will only capture data for
  one of them.
• Use ASH to view aggregate data on many sessions
  over a period of time.
• Dont use ASH to count waits, get maximum wait
  times, or look at a short time period.

39
ASH Example

• SQLgt SELECT DECODE (session_state, 'WAITING',
  event, NULL) event,
• 2 session_state, COUNT(), SUM
  (time_waited) time_waited
• 3 FROM vactive_session_history
• 4 WHERE module 'ARXENV'
• 5 AND sample_time gt SYSDATE - (2/24)
• 6 GROUP BY DECODE (session_state, 'WAITING',
  event, NULL),
• 7 session_state
• EVENT SESSION_STATE
  COUNT() TIME_WAITED
• ------------------------------ -------------
  -------- -----------
• ON CPU
  124 0
• log file sync WAITING
  2 52686
• db file scattered read WAITING
  2 28254
• db file sequential read WAITING
  1 6059
• control file sequential read WAITING
  1 9206
• SQLNet break/reset to client WAITING
  1 9140
• enq TX - row lock contention WAITING
  922 930864016

40
Automatic Workload Repository

• Conceptually similar to Statspack.
• Collects snapshots of system-wide performance
  statistics, plus ASHs sampling of session
  activity.
• You can generate activity reports using
  awrrpt.sql or Enterprise Manager interface.
• Out of the box, Oracle 10g databases collect
  snapshots hourly and retain data for seven days.

41
AWR Management

• Snapshot data is stored in SYS-owned tables in
  the SYSAUX tablespace.
• Use dbms_workload_repository to
• Collect a snapshot on demand.
• Purge snapshots.
• Adjust snapshot interval.
• Adjust snapshot retention period.
• Disable AWR snapshot collection.

42
AWR versus Statspack

• AWR benefits
• More tightly integrated into Oracle kernel,
  reducing snapshot collection overhead.
• Snapshots include sampling of ASH data.
• Data collected by AWR is accessible via views
  with names starting DBA_HIST.
• DBA_HIST views are documented.
• Statspack has been updated to be 10g aware.

43
Time Model Statistics

• New concept in Oracle 10g.
• Two new views provide a more detailed picture of
  how Oracle spends time
• Separates out background and user processes.
• Provides data not previously available, such as
  how much time was spent in PL/SQL execution.
• Times are in microseconds.

44
Time Model Statistics

• SQLgt DESCRIBE vsys_time_model
• Name Null?
  Type
• ----------------------------------------
  -------- ---------------------------
• STAT_ID
  NUMBER
• STAT_NAME
  VARCHAR2(64)
• VALUE
  NUMBER
• SQLgt DESCRIBE vsess_time_model
• Name Null?
  Type
• ----------------------------------------
  -------- ---------------------------
• SID
  NUMBER
• STAT_ID
  NUMBER
• STAT_NAME
  VARCHAR2(64)
• VALUE
  NUMBER

45
Time Model Statistics

• Some important notes about these statistics
• Statistics do not include background processes
  unless background appears in the statistic
  name.
• DB time shows elapsed time spent in Oracle
  calls. (Basically CPU time plus non-idle waits.)

46
Time Model Statistics Example

• SQLgt SELECT stat_name, value / 1000000 seconds
  FROM vsys_time_model
• 2 ORDER BY seconds DESC
• STAT_NAME
  SECONDS
• ------------------------------------------------
  ----------
• DB time
  80970.190
• sql execute elapsed time
  75057.271
• DB CPU
  44448.628
• background elapsed time
  29333.160
• PL/SQL execution elapsed time
  8824.538
• background cpu time
  5170.311
• parse time elapsed
  1270.147
• hard parse elapsed time
  838.068
• PL/SQL compilation elapsed time
  176.731
• sequence load elapsed time
  112.334
• connection management call elapsed time
  44.644
• failed parse elapsed time
  11.946
• hard parse (sharing criteria) elapsed time
  5.579
• hard parse (bind mismatch) elapsed time
  4.610

47
Tracing Improvements

• Enabling extended SQL trace in another session is
  now more convenient.
• Tracing sessions in a connection pooling or
  shared server environment is no longer
  impractical.
• New dbms_monitor package offers these two
  benefits and more.

48
Tracing Prior to Oracle 10g

• Tracing sessions in Oracle 9i and earlier had
  annoyances
• dbms_support usually missing or not installed.
• dbms_system.set_ev not officially supported.
• ALTER SESSION SET EVENTS to set 10046 event has a
  syntax hard (for some of us) to remember.

49
Easier Tracing in Oracle 10g

• Control tracing of your own session
• EXECUTE dbms_monitor.session_trace_enable
  (waitsgtTRUE, bindsgtTRUE)
• EXECUTE dbms_monitor.session_trace_disable
  ()
• Control tracing of another session
• EXECUTE dbms_monitor.session_trace_enable
  (session_idgt153, waitsgtTRUE)
• EXECUTE dbms_monitor.session_trace_disable
  (session_idgt153)
• Tracing sessions in Oracle 10g is easier because
  dbms_monitor is provided and installed in every
  Oracle 10g database by default.

50
Tracing Prior to Oracle 10g

• Straightforward if session being traced uses
  dedicated server connection.
• Tracing session using shared server architecture
  leads to multiple trace files that have to be
  merged manually.
• Tracing an end-user session that does not map to
  one Oracle session (eg connection pooling or
  multiplexing) is not practical.

51
New Tracing Features in 10g

• Tracing can be enabled for sessions with a
  specific client identifier
• EXECUTE dbms_session.set_identifier ('client
  identifier')
• EXECUTE dbms_session.clear_identifier ()
• Tracing can be enabled for sessions with specific
  service / module / action combination
• EXECUTE dbms_application_info.set_module
  ('module name', 'action name')
• EXECUTE dbms_application_info.set_action
  ('action name')
• Trace data split over multiple trace files can be
  merged into one trace file for TKPROF processing
• trcsess output clientid service
  module action session

52
Connection Pooling Example

• Application server connection pooling code
• EXECUTE dbms_session.set_identifier ('session_id
  from application table')
• ...do the work for this end user session...
• EXECUTE dbms_session.clear_identifier ()
• Trace the end-user session assigned session_id
  12345 in the applications sessions table
• SQLgt EXECUTE dbms_monitor.client_id_trace_enable
  -
• gt (client_idgt'12345', waitsgtTRUE,
  bindsgtTRUE)
• Consolidate trace data into one trace file
  suitable for use by TKPROF
• cd ORACLE_BASE/admin/ORACLE_SID/udump
• trcsess outputmytracefile.trc clientid12345

53
Twelve Oracle 10g Enhancements

• More descriptive wait event names
• Wait event classes
• vevent_name new columns
• vsql / vsqlarea new columns
• vsession_wait_history
• vsession new columns
• vevent_histogram
• vsystem_wait_class / vsession_wait_class
• Active Session History (ASH)
• Automatic Workload Repository (AWR)
• Time model statistics
• Improved session tracing

54
Wrapping Up

• Oracle 10g includes many enhancements to the wait
  event interface that should make performance
  management using wait event methodologies easier
  than ever.
• Some are just conveniences
• More descriptive event names, wait event classes,
  dbms_monitor.session_trace_enable...
• Some provide data previously unavailable
• New vsql columns, time model statistics,
  vevent_histogram...

55
White Paper

• Contains additional detail we didnt have time to
  cover today.
• Includes a handy reference list of all Oracle 10g
  wait events, wait classes, and wait event
  parameters.
• Download www.dbspecialists.com/presentations

56
Contact Information

• Terry Sutton and Roger Schrag
• Database Specialists, Inc.
• 388 Market Street, Suite 400
• San Francisco, CA 94111
• Tel [phone]
• Toll-free 888/648-0500
• www.dbspecialists.com
• tsutton_at_dbspecialists.com
• rschrag_at_dbspecialists.com