Viewing detail event statistics
There is another level of trace data available for a detail trace. It shows all traced events for a thread in chronological sequence.
To see the detail event statistics
On STRAC, on the EXPAND line, navigate to the DETAIL option and press Enter.You can follow the sequence of events during thread processing using the DTRAC (Detail Trace Entry) display.
BMC Software -------------- DETAIL TRACE ENTRY --------------PERFORMANCE MGMT
SERV ==> DTRAC INPUT 10:21:48 INTVL=> 3 LOG=> N TGT==> DB2G
PARM ==> TEST3,SEQ=000017,LEVEL=2 ROW 1 OF 35 SCROLL=> CSR
EXPAND: LINESEL(DETAIL), HISTORY
START: 09:17:11 AUTH: JEK1 PLAN: DSNTIB21 CORR: DB221REQ CONN: BATCH
==============================================================================
EVENT AT ELAPSED CPU DETAIL
-------------- -------- -------- -------- -----------------------------------
CREATE-THD 0.000 45 ms 4,492 us
PLAN-ALLOC 0.045 ISOLATION=CS ACQ=USE REL=COMMIT
PKG-ALLOC 0.065 *DSNESPCS ISO=CS ACQ=USE REL=COMIT
PREPARE 350 0.069 1,361 ms 26 ms *RC( 0) C=DT D/X PS( 10)
SQL-TEXT 0.070 *TYPE=DYNAMIC TEXT=SELECT * FROM DS+
EXPLAIN 0.078 *PLAN=DSN8IC22 COST(4.6)
EDM-REQ 1.302 123 ms 3,964 us DB=00000258
OPEN 524 1.489 204 us 202 us *RC( 0) C=DT
FETCH 532 1.489 2,058 ms 6,247 us *RC( 0) C=DT D/X PS( 2)
OPEN-TS 2.235 DB=DSN8D21A TS=DSN8S21D
OPEN-TS 3.352 DB=DSN8D21A TS=XDEPT3
FETCH 532 3.549 35 ms 441 us *RC( 0) C=DT D/X
FETCH 532 3.615 354 us 353 us *RC( 0) C=DT D/X
FETCH 532 3.616 335 us 335 us *RC( 0) C=DT D/X
FETCH 532 3.620 354 us 353 us *RC( 0) C=DT D/X
FETCH 532 3.621 386 us 387 us *RC( 0) C=DT D/X
FETCH 532 3.672 386 us 387 us *RC( 0) C=DT D/X
FETCH 532 3.673 337 us 337 us *RC( 0) C=DT D/XThe number and type of events shown depend on how much you decided to trace (more events, more overhead). The simplest detail trace captures only the major events and exceptions in the life of the thread. This trace also has SQL, SCANS, and IO.
Subordinate events are indented in the display. Whenever possible, nesting at different levels is provided, although this nesting is somewhat dependent on the sequence in which the IFCIDs are received.
Look at the first event, CREATE-THD.
Events like this example, with start and end trace records, are matched and displayed on one line with relative start time, elapsed, and CPU times. Events that occur within another event (like I/O for a scan) are indented.
Look at the PARM field.
The SEQ number is the same as that shown on the Summary display (STRAC). But now there is a new parameter of LEVEL=2. With this parameter you can widen or narrow your view of the traced events. Level 2 shows you the major events (for example, the first event you see is probably PLAN-ALLOCation) and SQL.
To see only the SQL statements, change the level to 1.PARM ==> traceid ,SEQ= nnnnnn , LEVEL=1
Browse through the SQL statements to find one you want to know more about.
- Move to that statement and press F7 to scroll it to the top (SCROLL => CSR).
To see SCANS and I/O, change the level to 3 .PARM ==> traceid ,SEQ= nnnnnn , LEVEL=3
The events always remain in chronological sequence, and the event at the top of the screen remains there. Now you can see all of the events that occurred in processing the SQL statement–index scans, data scans, table space opens, sorts, dynamic SQL text and EXPLAIN data, I/O, and so on.
Move the cursor to an SQL statement and press Enter.The statistics for the single SQL statement are available in a pop-up display whenever you need them, but are out of the way when browsing the events.
BMC SOFTWARE -------------- DETAIL TRACE ENTRY -----------PERFORMANCE MGMT
SERV ==> DTRAC INPUT 13:16:40 INTVL=> 3 LOG=> N TGT==> WTNDEEO
PARM ==> TEST,SEQ=2,LEVEL=2 ROW 1 OF 33 SCROLL=> CSR
EXPAND: EXPLAIN
START: 12:57:19 AUTH: BOLWTN1 PLAN: DSNESPRR CORR: BOLWTN1 CONN: TSO
===============================================================================
EVENT AT ELAPSED CPU DETAIL
-------------- -------- -------- -------- -------------------------------------
OPEN 264 0.151 214 ms 25 ms *RC( 0) C=C1 D/X PS(4006)
===============================================================================
CURSOR: C1
LOCATION: DEEO
COLLECTION: DSNESPRR
PACKAGE: DSNESM68
SQL EXPANSION RSN: N/A
CURSOR SCROLLABILITY: NO SENSITIVITY: UNSPECIFIED RESULT TYPE: UNSPECIFIED
INDEX SEQ-DATA
-------- --------
ROWS PROCESSED ALL TYPES 2,000 2,001
ROWS PROCESSED CORRECT TYPE 1,999 1
ROWS QUALIFIED BY DM (STAGE 1) 0 2,001
ROWS QUALIFIED BY RDS (STAGE 2) 0 1,001
ROWS INSERTED 0 0
ROWS UPDATED 0 0
ROWS DELETED 0 0
PAGES SCANNED 2,004 2,002
REFERENTIAL INTEGRITY PROCESSING:
PAGES SCANNED 0 0
ROWS DELETED/SET NULL 0 0
LOB - PAGES SCANNED 0 0
- PAGES UPDATED 0 0
ROWS SKIPPED - INCOMPATIBLE LOCKAny event that has an asterisk at the beginning of the DETAIL column has a pop-up display. The detail column shows the most important data, but many trace records have more information available. This data varies by event type. For example, for an SQL statement, you see the return code, cursor, indicators about data access (Data/Index/Work = D/X/W), and pages scanned.
You have already seen the SQL pop-up display; the same row/page statistics are available per scan. Some other important pop-up displays are:
Pop-up display
Description
BIND-TEXT
For DB2 Version 7.1 and earlier, text of dynamic SQL (also static SQL if BIND traced)
EXPLAIN
EXPLAIN data for dynamic SQL (also from BIND)
LOCK-SUMMARY
Summary of locks held per page set
TIMEOUT/ DEADLOCK
Lock contention events that cause a SQL statement or thread to fail
RIDLIST
Statistics on RID list processing, success, or failure
SQL-TEXT
Text of dynamic SQL (also static SQL if BIND traced)
- Press F3 until you return to the LTRAC list of thread entries.
Related topic