Locking

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 – If TIMED_STATISTICS, then get system timestamp – Post “wake-up” signal – Go to sleep, relinquish CPU (i.e. pre-emptive wait) – If TIMED_STATISTICS, then get system timestamp – Increment counter of wait-event in wait-event views – 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 PID COMMAND 0 pts/tb 22509 2 pts/tb 22515 2 pts/th 22890 3 ? 22712

USERNAME PRI NI tgorman tgorman tgorman oracle

240 152 236 154

SIZE

RES STATE TIME %WCPU

20 1788K 880K run 20 6788K 5652K run 20 716K 316K run 20 9344K 1904K sleep

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

16.55 14.01 11.44 11.34

%CPU 16.52 13.99 11.42 11.32

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

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

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

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