Understanding Locking In Oracle

Understanding Locking in Oracle

Utah Oracle Users Group – DBA SIG 26 April, 2002

Tim Gorman – TruTek Technologies, Inc.

Agenda • Different types of locking in Oracle – Latches – Enqueues

• Diagnosing “hangs” in Oracle – Useful utilities in UNIX – Dumps, events, traces – YAPP report on www.oraperf.com

Latches • Latches – Low-level synchronization mechanism • Protects SGA memory structures used by many processes – Operates at the level of a server process, beneath the level of an Oracle session

– Very lightweight, very fast – Allows only exclusive access • No queueing – latches are obtained by polling

Latches • A latch is just shared memory containing an integer value – If already held, contains a process ID – If free, contains a NULL representation

• Accessed using an OS-specific test-and-set operation – Atomic machine operation to: • Test for a specific value at a location • Reset the location to specified value if test succeeds • Leave it alone if test fails

Latches • Latches are sometimes grouped into families – For protecting complex related or hierarchical data structures • Some latches are parents and must be obtained before one of the many children latches can be obtained – Allows concurrency without risk of deadlocking

• Single individual latches are regarded as parents without children • Completely hard-coded rules governing which latches are parents, which are children, and how they are accesssed

– Views V$LATCH_PARENT and V$LATCH_CHILDREN

Latches • Two types of latches – Difference between each type is hard-coded into the RDBMS – Immediate (or no-wait) • Failure to obtain the latch returns to the code as an error – Program logic handles it and does something else

– Willing-to-wait • Failure to obtain the latch results in the process waiting – Only one immediate get attempt – SPIN_COUNT spin get attempts • Each attempt spins _LATCH_SPIN_COUNT times – Infinite sleep get attempts

Latches • Tracking latch usage – Views V$LATCH (cumulative), V$LATCH_PARENT, and V$LATCH_CHILDREN (detailed) • Columns IMMEDIATE_GETS and IMMEDIATE_MISSES – counts for no-wait (or immediate) latch attempts

• Columns GETS and MISSES – Counts for first immediate stage of willing-to-wait latch attempts

• Column SPIN_GETS – Counts for second non-pre-emptive wait of willing-to-wait latch attempts

• Column SLEEPS – Counts for third pre-emptive wait stage of willing-to-wait latch attempts – Columns SLEEP1, SLEEP2, SLEEP3, SLEEP4, …, SLEEP11 provide detailed summaries based on number of waits • Since Oracle8 v8.0, only SLEEP1-3 are used…

Latches • Tracking latch usage (cont’d): – SQL*Plus script “latch.sql” • Available at http://www.EvDBT.com/library.htm • Sorts display by SLEEPS – Depicting the most heavily-contended latches

• Tracking latch usage is one thing – But how do we determine if it is a problem?

Latches • Wait-event interface for detecting latch contention – Timing of some operations can be captured • For latch operations, timing only captured on sleep gets during willing-to-wait latch operations – Latch waits that last long enough to require sleep gets can be disastrous • Process context-switching and multi-second sleep times dramatically inflate wait time for a latch

– Each sleep get can be tracked by the Oracle “waitevent” interface • Posted as a “latch free” wait-event

Latches • Session-wait interface – By default, only counts of wait-events are captured – If parameter TIMED_STATISTICS set to TRUE, then RDBMS will also capture times 1.If TIMED_STATISTICS, then get system timestamp 2.Post “wake-up” signal 3.Go to sleep, relinquish CPU (i.e. pre-emptive wait) 4.If TIMED_STATISTICS, then get system timestamp 5.Increment counter of wait-event in wait-event views 6.If TIMED_STATISTICS, then post/increment time delta to wait-event views

Latches • Tracking the latch free wait-event – In the real-time view V$SESSION_WAIT • A session whose process is waiting upon a sleep get for a latch posts a “latch free” wait-event – P1 = raw ADDR value (see V$LATCH.ADDR) – P2 = latch # (see V$LATCHNAME.LATCH#) – P3 = number of sleep get attempts (a.k.a. tries)

Latches • Tracking the latch free wait-event (cont’d) – Also, if the “SQL Trace” event 10046 has been set to level 8, same information going to V$SESSION_WAIT will go to a trace file in the USER_DUMP_DEST directory • V$SESSION_WAIT shows current real-time information • SQL Trace level 8 shows real-time information chronologically over time, logged to a trace file

Latches • Session-wait views – View V$SESSION_WAIT • Set SECONDS_IN_WAIT during wait, when STATUS = ‘WAITING’ – Process awakens every 0.5, 1.0, 2,0, 4.0 seconds • Max value set with _MAX_SLEEP_HOLDING_LATCH

• Update WAIT_TIME after wait, when STATUS = ‘WAITED KNOWN TIME’ – Also update V$SESSION_EVENT view column WAIT_TIME • Fixed table X$KSLES – Also update V$SYSTEM_EVENT view column WAIT_TIME • Fixed table X$KSLEI

Latches • Session-wait views (cont’d) – View V$SESSION_EVENT • Cumulative since start of session for all active sessions • Great diagnostic point for finding problems in currently active session

– View V$SYSTEM_EVENT • Cumulative since instance start for all sessions • Great diagnostic point for detecting overall trends for an entire instance

Latches • Determining if latch contention is a problem: select event as name, time_waited from v$session_event where sid = &&mysid union select n.name, s.value as time_waited from v$sesstat s, v$statname n where s.statistic# = n.statistic# and n.name = ‘CPU used by this session’ where s.sid = &&MySid order by 2 desc;

Latches • SQL*Plus script “sesstime.sql” – Available at http://www.EvDBT.com/library.htm • For diagnosing relative significance of wait-events for active sessions

• SQL*Plus script “systime.sql” – Downloadable from same location • For diagnosing relative significance of wait-events cumulatively since the instance was started

Latches SQL> @sesstime Enter value for usr: staging USERNAME SID NAME --------- ----------- ----------------------STAGING 38-TOAD.exe SQL*Net message from cl db file sequential read CPU used by this sessio latch free SQL*Net break/reset to virtual circuit status enqueue log file sync

Total SECS ------41.34 12.00 0.85 0.32 0.20 0.20 0.18 0.02

% Total ------75.014% 21.775% 1.542% 0.581% 0.363% 0.363% 0.327% 0.036%

% Non Idle --------5.562% 21.934% 1.554% 0.585% 0.000% 0.000% 0.329% 0.037%

Latches • Significant latches – cache buffers lru • Since Oracle7.3 there are multiple LRU latches for the Buffer Cache • Controlled by db_block_lru_latches parameter • A high # of SLEEPS could indicate a number of things: – db_block_lru_latches set too low. Set this parameter to a value of 4. – Need to scan too many buffers on the LRU to find a free buffer The buffers are either dirty or in use (pinned)

– cache buffers chains • Normally indicates data contention. Multiple sessions are going after a hot block (or a number of hot blocks)

– library cache • Could indicate a potential parsing problem. Check if application not using “bind-variables”

Latches • Significant Latches (cont’d) – shared pool • Controls memory allocation and deallocation from the Shared Pool. A relatively high number of SLEEPS could indicate: – Shared pool too small – Too many hard parses of SQL statements, possibly due to unshareable SQL statements resulting from not using “bind-variables”

– row cache objects • Protects access to the data dictionary cache in the SGA

– enqueue • Protects the adding and removing of state objects from global pool of enqueue resources

Latches • Latches represent the lowest-level concurrency mechanisms in Oracle – But before attempting to tune them, be sure that there is a problem first!

• Remember: – Increasing the number of latches rarely helps • Correct the underlying problem

Enqueues • Latches are low-level mechanisms to protect deep internal workings of RDBMS • Enqueues are used by sessions (not processes) to protect resources for a long time – Allows shared non-exclusive access – Ensures FIFO access to resources via queuing • Waits without spinning for long periods of time • Very sophisticated synchronization mechanism – Usually dependent on OS concurrency resources such as UNIX semaphores

Enqueues • Lock modes for an enqueue: – Null (NL) – Shared (S) – – – –

no session holds the resource one or more sessions are reading Exclusive (X) one session is writing Sub-shared (SS) read access to a compound resource Sub-exclusive (SX) write access to a compound resource Shared-sub-exclusive combination read access to one part (SSX) and write access to another part of a compound resource

Enqueues • Enqueue locks guard many structures: – – – – – – – –

Transaction resources (TX and TM) Buffer cache buffer (BL) Segment and extent allocation (ST) Controlfile access (CF) Direct-path index creation (DL) Distributed transactions (DL) DBMS_JOB job allocation (JQ) User-defined via DBMS_LOCK package (UL)

Enqueues • Real-time session-level views: – V$LOCK • Displays current enqueues held and requested by sessions – Excellent for seeing all enqueue information for a session

– V$LOCKED_OBJECT • Useful subset of V$LOCK where type = ‘TM’ – Ties into V$SESSION via XID columns, too

Enqueues • Excellent fully-decoded scripts for querying V$LOCK available on MetaLink – TFS script “tfsclock.sql, doc ID #1020008.6

• Script “lock.sql” is very similar to “tfsclock.sql” • From http://www.EvDBT.com/library.htm

– Stored procedure ENQWAIT in “enqwait.sql” and “run_enqwait.sql” • exhaustive analysis of blockers/waiters • “temp_enqwait.sql” uses PL/SQL anonymous block

Enqueues Waiter: SID=281 (ACTIVE), Logged on at 03-MAR 10:45 ....... REQUESTED LOCK|MODE=TX (Transaction) | Exclusive (655425,51351) ....... AppsUser=STILLAU ....... OS PID=10870 .... TXN ID=51.7.50922 (ACTIVE) started=03/03/02 10:46:34 undo=1b/1r ....... DML Lock: PO.RCV_SHIPMENT_HEADERS (TABLE) - LOCK HELD=Sub-Exclusive ....... DML Lock: PO.RCV_TRANSACTIONS_INTERFACE (TABLE) - LOCK HELD=Sub-Exclus .... SQL Statement currently executing: ....... DELETE FROM RCV_TRANSACTIONS_INTERFACE WHERE TO_NUMBER(:b1) = GR ....... OUP_ID ==>BLOCKER: SID=151,2 (ACTIVE), Logged on at 01-MAR 03:36 ........... HELD LOCK|MODE=TX (Transaction) | Exclusive ........... AppsUser=MIKETAC ........... OS PID=12711 ....... TXN ID=10.65.51351 (ACTIVE) started=03/01/02 10:46:34 undo=2b/30r ........... DML Lock: PO.RCV_TRANSACTIONS (TABLE) - LOCK HELD=Sub-Exclusive ........... DML Lock: PO.PO_NOTE_REFERENCES (TABLE) - LOCK HELD=Sub-Exclusive ....... SQL currently executing (not necessarily the blocking SQL): ........... insert into mtl_material_transactions_temp(transaction_temp_id,t ........... ransaction_header_id,source_code,source_line_id,transaction_mode

UNIX diagnostics • If you cannot get “into” Oracle to do diagnostics, some UNIX utilities may be helpful: – top, ps – trace utilities • truss (Solaris, AIX, Dynix) • tusc (HP-UX) • strace (Linux)

UNIX diagnostics • UNIX utility “top” – Continual reports about state of the system • Including list of “top” CPU-using processes

– Goals • Provide an accurate snapshot of system- and process-state • Portable • Should not be a “top” CPU-using process itself!

UNIX diagnostics System: proddw Sat Mar 23 12:03:24 2002 Load averages: 2.64, 2.63, 2.47 284 processes: 248 sleeping, 36 running CPU LOAD USER NICE SYS IDLE BLOCK SWAIT INTR SSYS 0 2.40 84.2% 0.0% 6.9% 8.9% 0.0% 0.0% 0.0% 0.0% 1 2.63 75.2% 0.0% 6.9% 17.8% 0.0% 0.0% 0.0% 0.0% 2 3.03 81.2% 0.0% 5.0% 13.9% 0.0% 0.0% 0.0% 0.0% 3 2.51 78.2% 0.0% 5.9% 15.8% 0.0% 0.0% 0.0% 0.0% ------ ----- ----- ----- ----- ----- ----- ----- ----avg 2.64 80.2% 0.0% 5.9% 13.9% 0.0% 0.0% 0.0% 0.0% Mem: 1459956K (1286788K) real, 724328K (175844K) virtual, 56900K free CPU TTY 0 pts/tb 2 pts/tb 2 pts/th 3 ?

PID 22509 22515 22890 22712

USERNAME tgorman tgorman tgorman oracle

PRI 240 152 236 154

NI SIZE RES STATE 20 1788K 880K run 20 6788K 5652K run 20 716K 316K run 20 9344K 1904K sleep

TIME 3:39 2:57 0:52 1:38

%WCPU 16.55 14.01 11.44 11.34

%CPU 16.52 13.99 11.42 11.32

COMMAND bcp sqll dump orac

UNIX diagnostics • UNIX utility “ps” – Standard SysV version

$ ps -eaf – XPG3/4 (X/Open Portability Guide v3/4)

$ ps –eo opt[,opt…] – Provides info about processes • Status, PID, user, command text, • Cumulative and recent CPU • Memory (virtual, resident)

UNIX diagnostics • An easy home-grown “top” command $ ps –eaf | sort –n +3 | tail oracle tgorman Oracle tgorman tgorman tgorman tgorman tgorman

15848 21167 20371 21395 20176 21416 21471 21410

1 21164 1 21392 20167 21407 21468 21407

228 232 235 235 239 240 240 252

09:51:28 11:15:59 10:57:05 11:24:52 10:51:52 11:24:58 11:25:07 11:24:58

? 19:34 ora_lgwr_dssdwp0 pts/td 2:59 bcp dss.dbo.modi ? 7:05 oracledssdwp01 ( pts/tf 0:19 /home/tgorman/dd pts/ta 7:16 sqlldr parfile=t pts/tg 0:24 sqlldr parfile=t pts/th 0:18 /home/tgorman/dd pts/tg 0:27 /home/tgorman/dd

UNIX diagnostics • Another home-grown “top” command – More accurate than “ps –eaf” – Also displays memory consumption in Kbytes $ ps -eo user,pid,pcpu,vsz,rss,comm | sort -n +2 | tail root oracle oracle oracle oracle root oracle oracle

28103 20334 20881 18626 18624 3 18626 28077

0.1 0.1 0.1 3.3 12.2 14.3 15.3 30.8

3240 495056 711552 463240 465112 0 463240 486824

2560 447056 634144 428032 429480 0 428032 450200

/usr/local/sbin/sshd oracleACTION oracleACTION ora_lgwr_ACTION ora_dbw0_ACTION fsflush ora_lgwr_ACTION oracleACTION

UNIX diagnostics • Use “top” and “ps” to identify processes in UNIX – – – – –

By current CPU activity By time started By total CPU time consumed By process name By UNIX account

UNIX diagnostics • Trace utilities – truss (Solaris, AIX, Dynix) – tusc (HP-UX) – strace (Linux)

• Attach to or run a process and then trace: – UNIX system calls executed – Signals received – Machine faults incurred • (optional) entry/exit trace of user level function calls

UNIX diagnostics • Output from “truss” (of PMON process) on Solaris 8: . . . semop(196608, 0xFFBEE7F4, 1) (sleeping...) Received signal #14, SIGALRM, in semop() [caught] semop(196608, 0xFFBEE7F4, 1) Err#91 ERESTART sigprocmask(SIG_BLOCK, 0xFFBEE320, 0x00000000) = 0 sigprocmask(SIG_UNBLOCK, 0xFFBEE320, 0x00000000) = 0 getcontext(0xFFBEE0E0) setcontext(0xFFBEE0E0) sigprocmask(SIG_BLOCK, 0xFFBEE5FC, 0x00000000) = 0 setitimer(ITIMER_REAL, 0xFFBEE584, 0x00000000) = 0 sigprocmask(SIG_UNBLOCK, 0xFFBEE5FC, 0x00000000) = 0 getcontext(0xFFBEE4E8) sigprocmask(SIG_BLOCK, 0xFFBEE5FC, 0x00000000) = 0 . . . .

UNIX diagnostics • Output from “strace” (of server process using “SQL Trace”) on SuSe Linux 7.2: . . . 15:26:02.348564 gettimeofday({1003530362, 348588}, NULL) = 0 15:26:02.348659 pread(409, "\6\2\0\0\240\27\200\0\325\227\7\0\0\0\2\0\0\0\0\0\1\0\7\0_\f\0\0\ 210I\7\0\0\0\24P\2\6\3\0\30/\200\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0 \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0 \0\0\1\236\0\0\0N\1\354\3R\6R\6\0\0\236\0\1\0\2\0\3\0\4\0\5\0".. ., 8192, 12386304) = 8192 15:26:02.348995 gettimeofday({1003530362, 349035}, NULL) = 0 15:26:02.349174 gettimeofday({1003530362, 349209}, NULL) = 0 15:26:02.349260 write(6, "WAIT #1: nam=\'db file sequential read\' ela= 0 p1=2 p2=6048 p3=1", 63) . . .

UNIX diagnostics • Output from “tusc” (of SQL*Plus process) on HP-UX 11.11: . . . (Attached to process 8825 ("sqlplus scott") [64-bit] ) read(0, 0x4005a5f8, 8192).......................... [sleeping] read(0, "\n", 8192)....................................... = 1 write(1, "S Q L > ", 5)................................. = 5 read(0, 0x4005a5f8, 8192).......................... [sleeping] read(0, "s e l e c t d u m m y f r o ".., 8192)...... = 24 lseek(9, 89600, SEEK_SET)............................. = 89600 read(9, "\01113+ \0\0\0n 13, \0\0\0a21388".., 512)...... = 512 lseek(9, 12800, SEEK_SET)............................. = 12800 read(9, "\01c0390\0\0\0b00391\0\0\0c90392".., 512)...... = 512 lseek(8, 0, SEEK_CUR)................................ = 119218 lseek(8, 0, SEEK_CUR)................................ = 119218 write(8, "n i o q s n : e n t r y \n", 14)............. = 14 . . .

UNIX diagnostics • Less-useful UNIX utilities for diagnosing Oracle problems: – vmstat and sar • Displays cumulative VM statistics only • Displays redundant CPU statistics (“ps” and “top”) • Displays useless I/O statistics

– iostat and other standard UNIX-based I/O utilities • Practically useless now due to widespread use of logical volume managers (LVMs)

Events, traces, and dumps • Events are an undocumented back-door into the RDBMS – Immediate “dumps” into trace files • Initiated using ALTER SESSION command

– Tracing “traps” upon occurrence of specified errors • Initiated using “init.ora” parameters only

– Tracing of certain operations • Initiated using ALTER SESSION or “init.ora” parameters

– Change RDBMS behavior • Initiated using “init.ora” parameters only

Events, traces, and dumps • File dumps: – Dump contents of the control file(s): SQL> ALTER SESSION SET EVENTS 'immediate trace name controlf level 10';

– Dump contents of the datafile headers: SQL> ALTER SESSION SET EVENTS 'immediate trace name file_hdrs level 10';

– Dump contents of the online redo log headers: SQL> ALTER SESSION SET EVENTS 'immediate trace name redohdr level 10';

Events, traces, and dumps • File dumps (cont’d): – ALTER SYSTEM DUMP command • [ DATAFILE | TEMPFILE ] [ nn | ‘filename’ ] BLOCK xxxxx – Dumps a single database block xxxxx

• [ DATAFILE | TEMPFILE ] [ nn | ‘filename’ ] BLOCK MIN yyyyy BLOCK MAX zzzzz – Dumps the range of blocks between yyyyy and zzzzz

• Completely replaces event BLOCKDUMP and the need for event SET_TSN_P1 in Oracle8,8i, and 9i

Events, traces, and dumps • For example: SQL> ALTER SYSTEM DUMP DATAFILE 1 BLOCK 527; System altered. SQL> ALTER SYSTEM DUMP TEMPFILE 1 BLOCK MIN 20 BLOCK MAX 30; System altered.

Events, traces, and dumps • File dumps (cont’d): – ALTER SYSTEM DUMP command (cont’d) • UNDO HEADER rbs-name – Dumps header block of rollback segment specified

• UNDO BLOCK rbs-name XID xidusn xidslot xidsqn – Dumps rollback segment blocks related to the specified transaction

• LOG ‘redo-log-filename’ – Dumps the entire contents of the online or archived redo log file

Events, traces, and dumps • For example: SQL> SELECT XIDUSN, XIDSLOT, XIDSQN FROM V$TRANSACTION WHERE ADDR IN (SELECT TADDR FROM V$SESSION WHERE SID = nnn); SQL> SELECT NAME FROM V$ROLLNAME WHERE USN = xidusn; SQL> ALTER SYSTEM DUMP UNDO HEADER “_SYSSMU01$”; SQL> ALTER SYSTEM DUMP UNDO BLOCK “_SYSSMU01$” XID 1 45 20908;

Events, traces, and dumps • File dumps are useful in situations where some form of corruption is suspected – Each dump will indicate if corruption is present • If it cannot interpret the data

– Usually used to provide information to Oracle Support – Extremely cryptic output • But educational if you are willing to examine them

Events, traces, and dumps • Process dumps: – Dump memory structures for process: SQL> ALTER SESSION SET MAX_DUMP_FILE_SIZE = UNLIMITED; SQL> ALTER SESSION SET EVENTS 'immediate trace name processstate level 10';

– Or for another process from SQL*Plus: SQL> ORADEBUG SETOSPID OS-spid SQL> ORADEBUG UNLIMIT SQL> ORADEBUG DUMP PROCESSSTATE 10

Events, traces, and dumps • Process dumps (cont’d): – Dump program stack trace for process: SQL> ALTER SESSION SET MAX_DUMP_FILE_SIZE = UNLIMITED; SQL> ALTER SESSION SET EVENTS 'immediate trace name errorstack level 3';

– Or for another process from SQL*Plus: SQL> ORADEBUG SETOSPID OS-spid SQL> ORADEBUG UNLIMIT SQL> ORADEBUG DUMP ERRORSTACK 3

Events, traces, and dumps • System SGA dumps: – Dump memory structures for process: SQL> ALTER SESSION SET MAX_DUMP_FILE_SIZE = UNLIMITED; SQL> ALTER SESSION SET EVENTS 'immediate trace name systemstate level 10';

– Or for another process from SQL*Plus: SQL> ORADEBUG SETOSPID OS-spid SQL> ORADEBUG UNLIMIT SQL> ORADEBUG DUMP SYSTEMSTATE 10

Events, traces, and dumps • Process and system memory dumps are of most use to Oracle Support – Not supported! Be vewwy, vewwy careful!

• Extremely cryptic output – Can only be interpreted by Oracle Support and Development

Events, traces, and dumps • Besides immediate dumps, traps can be set to cause dumps on receipt of a specified error • Using “init.ora” parameters at instance startup

Event = “904 trace name ERRORSTACK level 3” • Using ALTER SESSION

alter session set events '904 trace name ERRORSTACK level 3‘;

Events, traces, and dumps • SQL Tracing: – For a session by that session: • ALTER SESSION SET SQL_TRACE = TRUE; • ALTER SESSION SET EVENTS ‘10046 trace name context forever, level n’; – – – –

Level Level Level Level

1 = traces SQL operations 4 = outputs “bind variable” values 8 = outputs wait-event info 12 = all of the above

• dbms_session.set_sql_trace(TRUE)

Events, traces, and dumps • SQL tracing (cont’d): – For a session by another session: • dbms_system.set_sql_trace_in_session(sid, serial#, TRUE); • ORADEBUG SETOSPID OS-spid ORADEBUG UNLIMIT ORADEBUG EVENT 10046 trace name context forever, level 12

• CBO decision-tree tracing – ALTER SESSION SET EVENTS ‘10053 trace name context forever, level n’;

Events, traces, and dumps • Reading “raw” SQL trace files: – PARSING IN CURSOR #cc len=0 dep=0 uid=0 oct=0 lid=0 tim=0 hv=0 ad=‘x’ SQL-Statement-text END OF STMT • • • • • • • • •

cc = cursor number (used to identify all operations for a SQL statement) len = length of the text of the SQL statement in bytes dep = recursive execution depth (0 = user-level, 1=recursive level 1, etc) uid = user parsing statement, from DBA_USERS.USERID value oct = Oracle command type Lid = logical user executing statement, from DBA_USERS.USERID Tim = timestamp measured in 1/100ths of second Hv = decimal hash value, from V$SQLAREA.HASH_VALUE Ad = hexadecimal address, from V$SQLAREA.ADDRESS

Events, traces, and dumps • Reading “raw” SQL trace files (cont’d): – PARSE #cc: c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 – EXEC #cc: c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 – FETCH #cc: c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=0 • • • • • • • •

cc = cursor number (same as PARSING IN CURSOR statement) c = CPU time (measured in 1/100ths of seconds) e = elapsed time (measured in 1/100ths of seconds) p = number of physical reads or disk I/Os cr = number of “consistent gets” on buffer cache in the SGA cu = number of “db block gets” (or “current gets”) on buffer cache in the SGA mis = number library cache misses r = number of rows affected or retrieved

• dep = recursive execution depth (0 = user-level, 1=recursive level 1, etc) • og = optimizer goal: 1=ALL_ROWS, 2=FIRST_ROWS, 3=RULE, 4=CHOOSE • tim = timestamp measured in 1/100ths of seconds

Events, traces, and dumps • Reading “raw” SQL trace files (cont’d): – ERROR #cc: err=0 tim=0 • cc = cursor number (same as PARSING IN CURSOR statement) • err = Oracle error message number • tim = timestamp measured in 1/100ths of seconds

– XCTEND rlbk=0 rd_only=0 • Transaction end marker (COMMIT or ROLLBACK) • COMMIT is “rlbk=0”, ROLLBACK is “rlbk=1” • READ ONLY transaction is “rd_only=1”, otherwise “rd_only=0”

– STAT #cc: id=0 cnt=0 [pid=0 pos=0 obj=0 op=‘text '] • EXPLAIN PLAN information from cursor “cc”

Events, traces, and dumps • Events are documented (very briefly) on UNIX platforms – File “oraus.msg” in directory “$ORACLE_HOME/rdbms/mesg” • Used by “oerr” utility • Events reside in numeric ranges from 10000 until 10999 only

YAPP Reports • Yet Another Performance Profiler – Available from http://www.oraperf.com • Unofficial website run by members of Oracle Server Technologies division

– Upload either BSTAT/ESTAT report.txt file or STATSPACK report file – Returns an HTML page containing an amazing response-time analysis report

YAPP Reports • Organized from overview to hyperlinked detail sections – Header (version info, time span of report, etc) – Response-time breakout • CPU Time or time spent processing SQL – Parse, recursive, and other CPU Time breakouts

• Wait Time or time not spent processing SQL

– Initialization parameter settings – Tuning advise summary

YAPP Reports General Information The following comments were generated while processing file C:\Temp\sp_5349_5350.lst: Disclaimer: Use information at own risk ! • All timing information is in 1/100 sec, unless stated otherwise. • The timing period in this report is too long to get any useful tuning advise. • End Buffer Gets Threshold: 100000 • Note that resources reported for PL/SQL includes the resources used by all SQL statements called within the PL/SQL code. As individual SQL statements are also reported, it is possible and valid for the summed total 10021160010 exceed 100 • End Executions Threshold: 1000 • only latches with sleeps are shown • ordered by name, sleeps desc NoWait Waiter • Please be advised that running STATSNAP on releases before Oracle8i can give problems. • Please be advised that Oracle8 version 8.0.6 is the terminal release for Oracle8. You are on an older release. • Uploaded 167060 bytes in 5.10 seconds

YAPP Reports

Response Time Time

Percentage

Per Execute

Per User Call

Per Transactions

Response Time

20985219

100.00%

2.92

4.81

544.72

CPU Time

20367938

97.06%

2.83

4.67

528.69

Wait Time

617281

2.94%

0.09

0.14

16.02

YAPP Reports CPU Time Time Total

20367938

Parse CPU

Percentage Per Execute Per User Call

Per Transaction

100.00%

2.83

4.67

528.69

46637

0.23%

0.01

0.01

1.21

Recursive CPU

1184109

5.81%

0.16

0.27

30.74

Other CPU

19137192

93.96%

2.66

4.39

496.75

YAPP Reports Wait Time Event

Time

Perc

Per Execute

Per User Call

Per Transaction

latch free

612795

99.27%

0.09

0.14

15.91

enqueue

153

0.02%

0.00

0.00

0.00

log file sync

117

0.02%

0.00

0.00

0.00

buffer deadlock

37

0.01%

0.00

0.00

0.00

write complete waits

5

0.00%

0.00

0.00

0.00

buffer busy waits

5

0.00%

0.00

0.00

0.00

YAPP Reports MaxGain %

What

3

Reduce the number of buffer gets or executions

2

Tune the cache buffers chain

1

Reduce data block contention

Detail Check SQL statement "SELECT /*+ choose */DS.SHIPMENT_ID SHIPMENT_ID,DPA_SHIPPING_PRO" (hash value 370972535). Check SQL statement "SELECT /*+ choose */DS.SHIPMENT_ID,DS.DELIVERY_ID,DT. DEPARTURE_ID FROM DPA_SHIPMENTS DS,DPA_TRUCKS DT WHERE DS.TRUCK_ID = DT" (hash value 73620072). Check SQL statement "SELECT ROW_ID,HEADER_ID,CUSTOMER_NAME, No detailed information is available yet Check the objects that are inserted into that they have enough freelists

Q&A