ࡱ> / ( "-  @,http://www.oraperf.com#cpu #wait&#parsecpu"#reccpu&#othercpu*#latch free$#enqueue0#log file sync4 #buffer deadlock>*#write complete waits8$#buffer busy waitsT_@http://www.EvDBT.com/library.htmTq@http://www.EvDBT.com/library.htmTs@http://www.EvDBT.com/library.htm2www.oraperf.comN/ 0|DTimes New Roman 2v 0( 0xDArialNew Roman 2v 0( 0x" DTahomaew Roman 2v 0( 0x"0DCourier Newman 2v 0( 0x1@DArial Unicode MSv 0( 0c(.  @n?" dd@  @@``  HF      lg1&#%()*+$"', 2-./1456789023:;<=>?@ABQCfDE,!            A@ A1  8c8c     ?1 d0u0@Ty2 NP'p<'p@A)BCD|E? @845x g4CdCdv 0ppp@ <4!d!d` 0L2<4BdBd` 0L2R g4PdPdv 0Dp@ ppuʚ;2Nʚ;<4dddd{ 0~___PPT9`/ 0D,? O =Understanding Locking in Oracle AgendaBDifferent types of locking in Oracle Latches Enqueues Diagnosing  hangs in Oracle Useful utilities in UNIX Dumps, events, traces YAPP report on www.oraperf.com L%O%O4- [!0cLatches4Latches 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$6R9.$,    (    ( #LatchesVA 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~:ZOZ5ZZ|Z:O  | $LatchesLatches 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:,Z?ZfZ/ZZ*Z# ,# *   J      * *LatchesTwo 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 attemptsHZQZ<Z1ZZ;Z<Z+ZZ: <1 ;   +   "LatchesTracking 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& ZLZ,Z1ZZCZZIZZZ,ZL,                w,%LatchesTracking 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?vF.",F. ",*6 _!0Hh&LatchesWait-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  wait-event interface Posted as a  latch free wait-event4*aJbC$4*. -     7 5$'LatchesxSession-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 viewsxZZ$ Ze #LatchesJTracking 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)#%`~   * -\    LatchesTracking 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 filet,  $ ?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$KSLEIZZ9Z1Z,Z?Z2ZZ1ZZ91 ,?21 LatchesSession-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 instanceb|| 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;2.ZZ. m6 Y (LatchesfSQL*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 .H `.H `jZq!0,LLatchesSQL> @sesstime Enter value for usr: staging Total % % Non USERNAME SID NAME SECS Total Idle --------- ----------- ----------------------- ------- ------- --------- STAGING 38-TOAD.exe SQL*Net message from cl 41.34 75.014% 5.562% db file sequential read 12.00 21.775% 21.934% CPU used by this sessio 0.85 1.542% 1.554% latch free 0.32 0.581% 0.585% SQL*Net break/reset to 0.20 0.363% 0.000% virtual circuit status 0.20 0.363% 0.000% enqueue 0.18 0.327% 0.329% log file sync 0.02 0.036% 0.037%Ux;78 ^LatchesSignificant 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 ZZZZZnZZ\ZRA  n\H"[S*LatchesSignificant 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 v8X v     i   X |PH  G !LatchesLatches 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`DK .DK . EnqueuesLatches 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 semaphoresZPZ]ZFZL   &P F;    $L <EnqueuesLock modes for an enqueue: Null (NL) no session holds the resource Shared (S) 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 resourcevZyZ.~  ,EnqueuesEnqueue 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)*%ZZ%${ -EnqueuesReal-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, too9;*) 9; *)+EnqueuesExcellent 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 blockJZ,Z4Z&Z@ZWZJ,4&@W|V> 4"s!0,EnqueuessWaiter: 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_modetZtb  a= 7UNIX diagnosticsLIf 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):W8W8P\& UNIX diagnosticsUNIX 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!,-s,-   .   & dUNIX diagnosticsSystem: 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 TTYPID USERNAME PRI NI SIZE RES STATE TIME %WCPU %CPU COMMAND 0 pts/tb 22509 tgorman 240 20 1788K 880K run 3:39 16.55 16.52 bcp 2 pts/tb 22515 tgorman 152 20 6788K 5652K run 2:57 14.01 13.99 sqll 2 pts/th 22890 tgorman 236 20 716K 316K run 0:52 11.44 11.42 dump 3 ? 22712 oracle 154 20 9344K 1904K sleep 1:38 11.34 11.32 oracZ&> * * qUNIX diagnosticsUNIX 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)ZZ Z'ZZZVZ '  V t  *eUNIX diagnosticspAn easy home-grown  top command $ ps  eaf | sort  n +3 | tail oracle 15848 1 228 09:51:28 ?19:34 ora_lgwr_dssdwp0 tgorman 21167 21164 232 11:15:59 pts/td 2:59 bcp dss.dbo.modi Oracle 20371 1 235 10:57:05 ? 7:05 oracledssdwp01 ( tgorman 21395 21392 235 11:24:52 pts/tf 0:19 /home/tgorman/dd tgorman 20176 20167 239 10:51:52 pts/ta 7:16 sqlldr parfile=t tgorman 21416 21407 240 11:24:58 pts/tg 0:24 sqlldr parfile=t tgorman 21471 21468 240 11:25:07 pts/th 0:18 /home/tgorman/dd tgorman 21410 21407 252 11:24:58 pts/tg 0:27 /home/tgorman/ddZ! #G &@     |]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 28103 0.1 3240 2560 /usr/local/sbin/sshd oracle 20334 0.1 495056 447056 oracleACTION oracle 20881 0.1 711552 634144 oracleACTION oracle 18626 3.3 463240 428032 ora_lgwr_ACTION oracle 18624 12.2 465112 429480 ora_dbw0_ACTION root 3 14.3 0 0 fsflush oracle 18626 15.3 463240 428032 ora_lgwr_ACTION oracle 28077 30.8 486824 450200 oracleACTION~!ZHZZ H8|p5/8" " %L&) 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&1c1cjUNIX diagnosticsTrace 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 calls8+D98  3    >% kUNIX diagnosticsOutput 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 . . . .<4Z;Z3;:Y 4 ( )   ( * )  1lUNIX diagnosticsXOutput 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) . . . N_NbBcccccccc<cc<ccbc# +<<<amUNIX diagnosticsOutput 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 . . .09Z7Z97 JIyy9!0chUNIX diagnosticsLess-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);z3P;z,P b;L-wEvents, traces, and dumpsEvents 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 only4Z#Z&Z4Z+ZZ7ZZ+Z #&4+ 7 +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'; &H'I.G &H'I. G>e ln Events, traces, and dumpsFile 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 9if8$L2\            "      R       I #]Events, traces, and dumpsFor 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 dumpsFile 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 #1.CB# 1      C  >DA Events, traces, and dumpsRFor 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;v ZZ  o1s,|1tEvents, 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 thembO1 O3O1 O3 Events, traces, and dumps3Process 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$&X$&    9   , L:Events, traces, and dumpspProcess 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&&U&&    6   , J7Events, traces, and dumps4System 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$&W$&    8   , L9Events, traces, and dumpsProcess 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 DevelopmentpB):B :,U\Events, traces, and dumpsBesides 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 ;Y1,? :1+?  Events, traces, and dumpszSQL 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 1 = traces SQL operations Level 4 = outputs  bind variable values Level 8 = outputs wait-event info Level 12 = all of the above dbms_session.set_sql_trace(TRUE) j! f!Events, traces, and dumpspSQL 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 ;Z"ZVZKZZFZ"%K  B>8!)Events, traces, and dumpsReading  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.ADDRESSG C 5t4H7aEvents, 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`(U(Ep(? HHnEvents, traces, and dumpsReading  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 (4*( ,      )tDO9Events, traces, and dumpsEvents 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 onlyN78S7 -SP=# F YAPP ReportsYet 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!'I 'I I!00F  YAPP Reports5Organized 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 summary7ZGZ&Z/Z+Z8Z G/   " 8  YAPP ReportsGeneral 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 secondsrZZW   YAPP Reports   YAPP Reports   YAPP Reports  YAPP Reports u[Q&A /8<`PB ` ___f3f` ___3f` 999MMM>?" dd@,|?" dd@   " @ `"  n?" dd@   @@``@n?" dd@  @@``PR    @ ` ` p>>     ( $ pF  q0a  q 0a2  C BUCENG HZI8Qf3? جU,جU,8`T,8`T q0a2  C BUCENG HZIDQD? U8U8D`T8D`T 2  C BUCENG HZIEQ[? U9U9E`T9E`T dn"   G/*d6?@33@@@sf 4  Zxgֳgֳ ?  T Click to edit Master title style! !:  T {gֳgֳ ?0  RClick to edit Master text styles Second level Third level Fourth level Fifth level!     S    `gֳgֳ ?`  Z*    `gֳgֳ ?   \*    `gֳgֳ ?   \*H  0޽h? ??0 ___f3f Fireball   k c 0  ( p0p0 pF  0    0 2  C BUCENG HZI8Qf3? جU,جU,8`T,8`T 0 2  C BUCENG HZIDQD? U8U8D`T8D`T 9Y 2  C BUCENG HZIEQ[? U9U9E`T9E`T "   G/*d6?@33@@@sf   Z8c~gֳgֳ ?` ~ T Click to edit Master title style! !  T`gֳgֳ ?0 `   ~ W#Click to edit Master subtitle style$ $    `dgֳgֳ ?`  Z*    `fgֳgֳ ?   \*    `(jgֳgֳ ?   \*H  0޽h? ??0 ___f3f*0 P (    <TՁ ??P    `*  ^   S  ?  "   <ׁ ?? @  RClick to edit Master text styles Second level Third level Fourth level Fifth level!     S   <܁ ??    b*(    BT݁ ??`P   `*     B ??`   b*( B  s *޽h ? ̙33 aY`(    <O ??P    OTim Gorman & Mary Crystal    <tU ??    `*(   BU ??`P   |FMANAGING PERFORMANCE IN ORACLE APPLICATIONS RELEASE 11 USING STATSPACKG G   B<^ ??`   `*( B  s *޽h ? ̙33:    h(  r  S v@`     Zwgֳgֳ ? @` ,Utah Oracle Users Group  DBA SIG 26 April, 2002 Tim Gorman  TruTek Technologies, Inc.>Y2 ?B  s *޽h ?    p *(  r   S pe   x   c $,f?  B  s *޽h ?   $(  r  S Q   r  S 1  H  0޽h ? ___f3f  , $(  , r , S s   r , S lt  H , 0޽h ? ___f3f   0(   x  c $   x  c $Ё  H  0޽h ? ___f3f  < $(  < r < S |   r < S xP  H < 0޽h ? ___f3f  t $(  t r t S ,   r t S 貐  H t 0޽h ? ___f3f   $(   r  S Ȑ   r  S Ȑ0  H  0޽h ? ___f3f  | $(  | r | S Lΐ   r | S ϐ  H | 0޽h ? ___f3f   0(   x  c $PӐ   x  c $ Ԑ  H  0޽h ? ___f3f  p $(  p r p S ܐ   r p S $[  H p 0޽h ? ___f3f   D :(  D r D S D~  ~  D S 1~  ~ "P@08XH D 0޽h ? ___f3f  0P $(  P r P S P~  ~ r P S 8~ ~ H P 0޽h ? ___f3f  @H $(  H r H S    r H S \  H H 0޽h ? ___f3f  PL $(  L r L S    r L S    H L 0޽h ? ___f3f  ` $(   r  S h   r  S     H  0޽h ? ___f3f  pT $(  T r T S    r T S x0P   H T 0޽h ? ___f3f  X $(  X r X S |   r X S 8P  H X 0޽h ? ___f3f   $(   r  S +   r  S P,    H  0޽h ? ___f3f  h $(  h r h S 0   r h S T10  H h 0޽h ? ___f3f  0 $(  0 r 0 S 1   r 0 S     H 0 0޽h ? ___f3f  4 $(  4 r 4 S  E   r 4 S E`0  H 4 0޽h ? ___f3f  8 $(  8 r 8 S K   r 8 S O   H 8 0޽h ? ___f3f   0(   x  c $g   x  c $DhP  H  0޽h ? ___f3f   0(   x  c $    x  c $h0P  H  0޽h ? ___f3f   0(   x  c $$q   x  c $q   H  0޽h ? ___f3f  ( $(  ( r ( S Ly   r ( S z0  H ( 0޽h ? ___f3f   x $(  x r x S    r x S P  H x 0޽h ? ___f3f  0$(  r  S    r  S H    H  0޽h ? ___f3f  @t 0(  t x t c $   x t c $0  H t 0޽h ? ___f3f  P$(  r  S 8   r  S 8    H  0޽h ? ___f3f  `$(  r  S Ľ   r  S  Э`  H  0޽h ? ___f3f  p| $(  | r | S ˭   r | S x˭ 0  H | 0޽h ? ___f3f  $(  r  S lí   r  S ĭPPp   H  0޽h ? ___f3f  $(  r  S    r  S    H  0޽h ? ___f3f  $(  r  S    r  S lP  H  0޽h ? ___f3f  $(  r  S "   r  S 0#P  H  0޽h ? ___f3f   $(   r  S 9   r  S \:`  H  0޽h ? ___f3f   $(   r  S 3   r  S 44   H  0޽h ? ___f3f   $(   r  S B   r  S LC   H  0޽h ? ___f3f   $(   r  S a   r  S tbP  H  0޽h ? ___f3f   $(   r  S h   r  S (i0  H  0޽h ? ___f3f   $(   r  S R   r  S S`  H  0޽h ? ___f3f    $(   r  S    r  S T0  H  0޽h ? ___f3f  0 $(   r  S t   r  S |u0  H  0޽h ? ___f3f  @ $(   r  S }   r  S p~  H  0޽h ? ___f3f  P $(   r  S    r  S x   H  0޽h ? ___f3f  ` $(   r  S    r  S   H  0޽h ? ___f3f  p $(   r  S 8   r  S h0  H  0޽h ? ___f3f   $(   r  S    r  S p`    H  0޽h ? ___f3f   $(   r  S    r  S t P  H  0޽h ? ___f3f   $(   r  S `   r  S 0  H  0޽h ? ___f3f   $(   r  S Р   r  S P   H  0޽h ? ___f3f   $(   r  S    r  S hP  H  0޽h ? ___f3f   $(   r  S h   r  S $P  H  0޽h ? ___f3f   0(   x  c $   x  c $D0  H  0޽h ? ___f3f   0(   x  c $D   x  c $0  H  0޽h ? ___̙3f   0(   x  c $\   x  c $x0  H  0޽h ? ___̙3f   0(   x  c $   x  c $`PP  H  0޽h ? ___̙3f1  11 PP 1(   x  c $       `1??z  # l1?? G@ G Response Time   # l1?? 1 .L   #   +-N      N  @    @     `1?? @    Z ?? @N  @     @    3 r1?? @ BTime"    Z ?? @N   @     @   3 rX1??  @ H Percentage"     Z ??  @N  @    @   3 rZ1?? @ I Per Execute"     Z ?? @N  @    @   3 r41?? @ K Per User Call"    Z ?? @N  @    @   3 r 91?? @ NPer Transactions"   Z ?? @N @`   @`   3 r$1??@` ? Response Time   Z ??@`N @`   @`   3 r1??@` :20985219     Z ??@`N @ `    @ ` !  3 r$1??@ ` 9100.00% "  Z ??@ `N  @` #   @` $  3 r(1?? @` 62.92 %  Z ?? @`N @` &  @` '  3 r+1??@` 64.81 (  Z ??@`N @` )  @` *  3 r.1??@` 8544.72 +  Z ??@`N ` ,  ` -  3 r,21??` jCPU Time  !0 .  Z ??`N ` /  ` 0  3 r|61??` :20367938   1  Z ??`N `  2  `  3  3 rP:1??`  897.06% 4  Z ??` N  ` 5   ` 6  3 r=1?? ` 62.83 7  Z ?? `N ` 8  ` 9  3 r@1??` 64.67 :  Z ??`N ` ;  ` <  3 rHD1??` 8528.69 =  Z ??`N  >   ?  3 rG1?? k Wait Time  !0  @  Z ??N  A   B  3 r L1?? 8617281 C  Z ??N   D    E  3 rO1??  72.94% F  Z ?? N   G    H  3 rR1??  60.09 I  Z ?? N  J   K  3 rtV1?? 60.14 L  Z ??N  M   N  3 rY1?? 716.02 O  Z ?? P  T ??H  0޽h ? ___̙3f>  >>0ee =>(   x  c $\\      `1??22  # l`1??0@4P BCPU Time   # lf1??Rr  W9L E  #  po8N  B    BN  @    @     `1?? @    Z ?? @N  @     @    3 rj1?? @ BTime"    Z ?? @N   @     @   3 rm1??  @ H Percentage"     Z ??  @N  @    @   3 rLs1?? @ I Per Execute"     Z ?? @N  @    @   3 r\x1?? @ K Per User Call"    Z ?? @N  B@    B@   3 r}1?? B@ MPer Transaction"   Z ?? B@N @`   @`   3 r1??@` 7Total   Z ??@`N @`   @`   3 r1??@` :20367938     Z ??@`N @ `    @ ` !  3 rȉ1??@ ` 9100.00% "  Z ??@ `N  @` #   @` $  3 rH1?? @` 62.83 %  Z ?? @`N @` &  @` '  3 r,1??@` 64.67 (  Z ??@`N @B` )  @B` *  3 r̔1??@B` 8528.69 +  Z ??@B`N ` ,  ` -  3 r1??` k Parse CPU  !0  .  Z ??`N ` /  ` 0  3 r1??` 746637 1  Z ??`N `  2  `  3  3 r41??`  70.23% 4  Z ??` N  ` 5   ` 6  3 r1?? ` 60.01 7  Z ?? `N ` 8  ` 9  3 r$1??` 60.01 :  Z ??`N `B ;  `B <  3 r1??`B 61.21 =  Z ??`B N  >   ?  3 r1?? o Recursive CPU!0  @  Z ??N  A