Running a query with profile information collected
In TOAD, use this template to run your query:
alter session set sql_trace=true ;
alter session set tracefile_identifier='my_name_here';
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
/* your query here */
alter session set sql_trace=false ;
You can find the latest version of it here: https://svn.fastenal.com/svn/logistics/trunk/LogisticsMobile/Support/queries/trace.sql. Add your query to the middle of that file where the comment indicates. Where it says my_name_here put in a useful identifier to make it easy to find your file. For example jdm_bg is what I used when working on a blue global query. Underscore (_) is allowed here but dash (-) is not. I don't know about other special characters. You must end your query with a semicolon (;). You can have more than one query if you want.
Run the query as a script. This is F5 in TOAD. You could also run it in sql*plus.
Extracting Profile Information
Connect to racnode5 using Putty or some other terminal program. Login with your usual username and password.
First time setup:
|
You should set up your profile so that you have the following command line functions available. Add the following code to your .bashrc file wmst() { source /oracle/env_file/env_WMST.sh wmsd() { source /oracle/env_file/env_WMSD.sh The commands wmst and wmsd will be available for your future logins. To enable them on this login type the following command. source .bashrc |
Type wmsd or wmst depending on what system you are testing on. This will set you up for the rest of your session. You should not need to do this again on this session unless you are changing between WMSD and WMST.
First you need to locate the trace file. Type the following command (if you are on WMSD then change the WMST to WMSD):
ls -ltr /oracleTrace/WMST/udump/
Near the end of the list you should see a file with a name similar to what you had in the query. For example when my name was set to jdm_gl2, I saw this line in the listing:
-rw-r--r-- 1 oracle dba 1379013 Jul 1 09:21 wmsd3_ora_6674_jdm_gl2.trc
Type the following command (using your filename)
tkprof /oracleTrace/WMSD/udump/wmsd3_ora_6674_jdm_gl2.trc ~/jdm print=15 explain=tms/tms sort=(prsela,exeela,fchela)
· tkprof starts the profile program.
· /oracleTrace/WMSD/udump/wmsd3_ora_6674_jdm_gl2.trc is the file name that you need to replace with what you found with the ls command.
· ~/jdm makes the output file jdm.prf in my home directory. The ~/ is your home directory. You can change the jdm to anything you want. The ~/ is not really needed if you are in your home directory when you run the command.
· print=15 will limit the output to showing the first 15 queries. Most of the queries that you see profiled are behind-the-scenes queries issued automatically by TOAD or other tools.
· explain=tms/tms gives the login information so that your output file can show the same Explain Plan that you can see in TOAD. If you don't have access to the underlying tables with tms/tms then you won't have it here either. However the explain plan is just one section; there will be useful information in other sections.
· sort=(prsela,exeela,fchela) specifies the order in which the queries are displayed in your file. This makes it so that your most expensive queries are listed first.
Shortcut:
|
You can skip the ls step if you have a unique name. For the jdm_gl2 example the command would be. tkprof /oracleTrace/WMSD/udump/*jdm_gl2.trc ~/jdm print=15 explain=tms/tms sort=(prsela,exeela,fchela) |
After the command is run, you can view the file (in this case jdm.prf) with a unix file view like view or less or you can mail it to yourself with a command like this one.
mail -s "new profile" jmarter@fastenal.com <~/jdm.prf
Interpreting the Profile
Here is a sample output of a larger query
TKPROF: Release 10.2.0.3.0 - Production on Mon Jul 14 07:29:45 2008
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: /oracle/app/oracle/admin/WMSD/udump/wmsd2_ora_26188_jdm_bg.trc
Sort options: prsela exeela fchela
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************
error connecting to database using: tms/tms
EXPLAIN PLAN option disabled.
********************************************************************************
WITH offset AS
(SELECT DECODE (TO_CHAR (SYSDATE, 'DY'), 'MON', 2, 0) days
FROM DUAL),
basic_bol AS
(SELECT /*+ materialize */
destination_bu, TRUNC (intf_dt - .25) bol_dt, load_bu , weight, carrier_cd,
item_id, location_id, truck_route_id, gl_sequence_number gl_sequence_no
FROM wms.wms_intf_trailer_content, offset
WHERE TRUNC (intf_dt - .25) BETWEEN TRUNC (SYSDATE) - 1 - days
AND TRUNC (SYSDATE) - 1
AND load_bu <> 'pack'
AND TRUNC (intf_dt - .25) > SYSDATE - 5
AND carrier_cd IN ('FTRK', 'BGEX')) ,
truck_route AS
(SELECT DISTINCT origin_campus_id, truck_route_id
FROM wms_truck_route_vw),
bu_mast AS
(SELECT /*+ materialize */
business_unit, LOWER (fas_bu_4char) branch4, ibu_group,
fas_campus_id
FROM ps_bus_unit_tbl_in
WHERE business_unit_gl IN ('FCUSA', 'FCCAN')
AND ibu_group IN ('BRANCH', 'DIST_CNTR')),
hubs AS
(SELECT fas_campus_id, business_unit, branch4
FROM bu_mast
WHERE ibu_group = 'DIST_CNTR'),
stores AS
(SELECT branch4, business_unit
FROM bu_mast
WHERE ibu_group = 'BRANCH'),
filtered_bol AS
(SELECT destination_bu, bol_dt, load_bu, weight, carrier_cd, item_id, location_id,
s.business_unit, h.business_unit hub_business_unit,
t.truck_route_id, gl_sequence_no
FROM basic_bol b, hubs h, truck_route t, stores s
WHERE b.load_bu = h.business_unit
AND h.fas_campus_id = t.origin_campus_id
AND MOD (b.truck_route_id, 1000) = t.truck_route_id(+)
AND b.destination_bu = s.business_unit),
csp_program AS
(SELECT /*+ materialize */
business_unit, fas_freight_number
FROM tms_frgt_bu_mvw),
csp_list AS
(SELECT DISTINCT business_unit, inv_item_id
FROM csp_program p, tms_frgt_itm_mvw c
WHERE p.fas_freight_number = c.fas_freight_number),
ship AS
(SELECT destination_bu, bol_dt, load_bu, SUM (weight) weight,
SUM (DECODE (c.inv_item_id, NULL, 0, weight)) loose_csp_wt,
carrier_cd, b.business_unit, truck_route_id, gl_sequence_no
FROM filtered_bol b, csp_list c
WHERE b.item_id = c.inv_item_id(+) AND b.business_unit = c.business_unit(+)
GROUP BY destination_bu,
load_bu,
bol_dt,
carrier_cd,
b.business_unit,
truck_route_id,
gl_sequence_no
HAVING SUM (weight) > 0),
removed AS
(SELECT b.destination_bu, bol_dt, load_bu, SUM (f.weight) weight, b.carrier_cd
FROM filtered_bol b, csp_list c, wms_intf_sr_freight f
WHERE f.item_id = c.inv_item_id
AND b.business_unit = c.business_unit
AND f.business_unit_dest = b.business_unit
AND f.business_unit = b.hub_business_unit
AND b.location_id = f.pallet_container_id
AND f.intf_dt > bol_dt - 7
GROUP BY b.destination_bu, load_bu, bol_dt, b.carrier_cd
HAVING SUM (f.weight) > 0),
gl AS
(SELECT /*x+ materialize */
fas_branch5 deptid, ship_date, seq_nbr, fas_blue_globl_amt,
currency_cd, descr30,
DECODE (ACCOUNT,
6706, 'FTRK',
6707, 'BGEX',
6708, 'BGND'
) carrier
FROM ps_fas_gl_blugbl,
offset,
(SELECT /*+ materialize */
deptid, fas_branch5
FROM ps_fas_opuntall_vw) bu7
WHERE ship_date BETWEEN TRUNC (SYSDATE) - 1 - offset.days
AND TRUNC (SYSDATE) - 1
AND ps_fas_gl_blugbl.deptid = bu7.deptid),
exempts AS
(SELECT DISTINCT bol_dt, b.destination_bu
FROM filtered_bol b, tms.tms_charge_exclusion x, bu_mast m
WHERE m.branch4=x.branch4
and m.business_unit = b.destination_bu
AND b.bol_dt BETWEEN x.start_dt AND x.end_dt)
SELECT NVL (shipments.ship_date, gl.ship_date) ship_date, load_bu, destination_bu,
NVL (business_unit, deptid) bu,
NVL (carrier_code, carrier) carrier_code, truck_route_id route,
tot_weight, csp_weight, tot_weight - csp_weight charged_weight,
is_exempt, fas_blue_globl_amt, currency_cd, descr30,
gl.seq_nbr gl_sequence_no
FROM (SELECT ship.business_unit, ship.bol_dt ship_date, ship.load_bu,
DECODE (rf.business_unit,
NULL, ship.carrier_cd,
'FTRK'
) carrier_code,
ship.weight tot_weight, gl_sequence_no,
NVL (removed.weight, 0) + ship.loose_csp_wt csp_weight,
ship.destination_bu, truck_route_id,
DECODE (e.bol_dt, NULL, 'N', 'Y') is_exempt
FROM ship, removed, tms_reduced_freight_store rf, exempts e
WHERE ship.business_unit = rf.business_unit(+)
AND ship.destination_bu = removed.destination_bu(+)
AND ship.load_bu = removed.load_bu(+)
AND ship.carrier_cd = removed.carrier_cd(+)
AND ship.bol_dt = removed.bol_dt(+)
AND ship.destination_bu = e.destination_bu(+)
AND ship.bol_dt = e.bol_dt(+)) shipments
FULL OUTER JOIN
gl ON shipments.gl_sequence_no = gl.seq_nbr
ORDER BY tot_weight - csp_weight, fas_blue_globl_amt
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.31 0 0 9 0
Execute 1 47.63 79.93 58206 9951 54244 0
Fetch 1 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 47.71 80.24 58206 9951 54253 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 85
Rows Row Source Operation
------- ---------------------------------------------------
0 TEMP TABLE TRANSFORMATION (cr=9951 pr=58206 pw=108665 time=79932330 us)
1 LOAD AS SELECT (cr=128 pr=0 pw=1 time=22256 us)
6 NESTED LOOPS (cr=128 pr=0 pw=0 time=5394 us)
6 TABLE ACCESS FULL WMS_INTF_TRAILER_CONTENT (cr=128 pr=0 pw=0 time=5157 us)
6 VIEW (cr=0 pr=0 pw=0 time=192 us)
6 FILTER (cr=0 pr=0 pw=0 time=133 us)
6 FAST DUAL (cr=0 pr=0 pw=0 time=27 us)
1 LOAD AS SELECT (cr=0 pr=0 pw=10 time=29866 us)
2375 REMOTE PS_BUS_UNIT_TBL_IN (cr=0 pr=0 pw=0 time=209416 us)
0 LOAD AS SELECT (cr=284 pr=11 pw=0 time=56354 us)
0 HASH JOIN (cr=284 pr=11 pw=0 time=54323 us)
6 HASH JOIN (cr=31 pr=11 pw=0 time=38855 us)
44764 MERGE JOIN CARTESIAN (cr=26 pr=10 pw=0 time=137051 us)
19 VIEW (cr=14 pr=10 pw=0 time=1339 us)
19 VIEW (cr=14 pr=10 pw=0 time=1280 us)
2375 TABLE ACCESS FULL SYS_TEMP_0FD9FC88A_FB8DDAA6 (cr=14 pr=10 pw=0 time=3444 us)
44764 BUFFER SORT (cr=12 pr=0 pw=0 time=46465 us)
2356 VIEW (cr=12 pr=0 pw=0 time=7129 us)
2356 VIEW (cr=12 pr=0 pw=0 time=2414 us)
2375 TABLE ACCESS FULL SYS_TEMP_0FD9FC88A_FB8DDAA6 (cr=12 pr=0 pw=0 time=2423 us)
6 VIEW (cr=5 pr=1 pw=0 time=973 us)
6 TABLE ACCESS FULL SYS_TEMP_0FD9FC889_FB8DDAA6 (cr=5 pr=1 pw=0 time=956 us)
581 VIEW (cr=253 pr=0 pw=0 time=16177 us)
581 SORT UNIQUE (cr=253 pr=0 pw=0 time=15012 us)
14428 VIEW WMS_TRUCK_ROUTE_VW (cr=253 pr=0 pw=0 time=43779 us)
14428 MAT_VIEW ACCESS FULL WMS_TRUCK_ROUTE_MV (cr=253 pr=0 pw=0 time=14921 us)
1 LOAD AS SELECT (cr=6373 pr=0 pw=2905 time=868463 us)
1308135 MAT_VIEW ACCESS FULL TMS_FRGT_BU_MVW (cr=6373 pr=0 pw=0 time=1308180 us)
1 LOAD AS SELECT (cr=3166 pr=58195 pw=105749 time=75272784 us)
19304924 HASH UNIQUE (cr=3166 pr=58195 pw=55290 time=37574033 us)
19696095 HASH JOIN (cr=3166 pr=2905 pw=0 time=19742390 us)
46336 INDEX FAST FULL SCAN TMS_FRGT_ITM_MVW_IDX (cr=254 pr=0 pw=0 time=46439 us)(object id 9820365)
1308135 VIEW (cr=2912 pr=2905 pw=0 time=3926126 us)
1308135 TABLE ACCESS FULL SYS_TEMP_0FD9FC88C_FB8DDAA6 (cr=2912 pr=2905 pw=0 time=1309848 us)
0 LOAD AS SELECT (cr=0 pr=0 pw=0 time=22482 us)
0 FILTER (cr=0 pr=0 pw=0 time=248 us)
0 HASH GROUP BY (cr=0 pr=0 pw=0 time=243 us)
0 HASH JOIN OUTER (cr=0 pr=0 pw=0 time=144 us)
0 VIEW (cr=0 pr=0 pw=0 time=19 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88B_FB8DDAA6 (cr=0 pr=0 pw=0 time=14 us)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88D_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 LOAD AS SELECT (cr=0 pr=0 pw=0 time=1927 us)
0 FILTER (cr=0 pr=0 pw=0 time=183 us)
0 HASH GROUP BY (cr=0 pr=0 pw=0 time=179 us)
0 HASH JOIN (cr=0 pr=0 pw=0 time=130 us)
0 TABLE ACCESS BY INDEX ROWID WMS_INTF_SR_FREIGHT (cr=0 pr=0 pw=0 time=41 us)
1 NESTED LOOPS (cr=0 pr=0 pw=0 time=20 us)
0 VIEW (cr=0 pr=0 pw=0 time=13 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88B_FB8DDAA6 (cr=0 pr=0 pw=0 time=8 us)
0 INDEX RANGE SCAN WMS_INTF_SR_FREIGHT_IDX4 (cr=0 pr=0 pw=0 time=0 us)(object id 6850893)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88D_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 LOAD AS SELECT (cr=0 pr=0 pw=0 time=3652786 us)
0 HASH JOIN (cr=0 pr=0 pw=0 time=3650914 us)
2414 VIEW (cr=0 pr=0 pw=0 time=3853988 us)
2414 REMOTE PS_FAS_OPUNTALL_VW (cr=0 pr=0 pw=0 time=3849155 us)
0 NESTED LOOPS (cr=0 pr=0 pw=0 time=3465797 us)
1 VIEW (cr=0 pr=0 pw=0 time=62 us)
1 FILTER (cr=0 pr=0 pw=0 time=52 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=4 us)
0 REMOTE PS_FAS_GL_BLUGBL (cr=0 pr=0 pw=0 time=3465728 us)
0 LOAD AS SELECT (cr=0 pr=0 pw=0 time=2956 us)
0 HASH UNIQUE (cr=0 pr=0 pw=0 time=333 us)
0 HASH JOIN (cr=0 pr=0 pw=0 time=197 us)
0 NESTED LOOPS (cr=0 pr=0 pw=0 time=30 us)
0 VIEW (cr=0 pr=0 pw=0 time=24 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88B_FB8DDAA6 (cr=0 pr=0 pw=0 time=18 us)
0 TABLE ACCESS FULL TMS_CHARGE_EXCLUSION (cr=0 pr=0 pw=0 time=0 us)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88A_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 SORT ORDER BY (cr=0 pr=0 pw=0 time=1059 us)
0 VIEW (cr=0 pr=0 pw=0 time=1021 us)
0 UNION-ALL (cr=0 pr=0 pw=0 time=1012 us)
0 HASH JOIN OUTER (cr=0 pr=0 pw=0 time=623 us)
0 NESTED LOOPS OUTER (cr=0 pr=0 pw=0 time=381 us)
0 HASH JOIN OUTER (cr=0 pr=0 pw=0 time=374 us)
0 HASH JOIN OUTER (cr=0 pr=0 pw=0 time=212 us)
0 VIEW (cr=0 pr=0 pw=0 time=18 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88E_FB8DDAA6 (cr=0 pr=0 pw=0 time=10 us)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88F_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC891_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 INDEX UNIQUE SCAN PK_TMS_REDUCED_FREIGHT_STORE (cr=0 pr=0 pw=0 time=0 us)(object id 3377747)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC890_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 HASH JOIN RIGHT ANTI (cr=0 pr=0 pw=0 time=361 us)
0 VIEW VW_SQ_1 (cr=0 pr=0 pw=0 time=237 us)
0 NESTED LOOPS OUTER (cr=0 pr=0 pw=0 time=232 us)
0 HASH JOIN OUTER (cr=0 pr=0 pw=0 time=226 us)
0 HASH JOIN OUTER (cr=0 pr=0 pw=0 time=118 us)
0 VIEW (cr=0 pr=0 pw=0 time=20 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88E_FB8DDAA6 (cr=0 pr=0 pw=0 time=12 us)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC88F_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 VIEW (cr=0 pr=0 pw=0 time=0 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC891_FB8DDAA6 (cr=0 pr=0 pw=0 time=0 us)
0 INDEX UNIQUE SCAN PK_TMS_REDUCED_FREIGHT_STORE (cr=0 pr=0 pw=0 time=0 us)(object id 3377747)
0 VIEW (cr=0 pr=0 pw=0 time=12 us)
0 TABLE ACCESS FULL SYS_TEMP_0FD9FC890_FB8DDAA6 (cr=0 pr=0 pw=0 time=6 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
control file sequential read 36 0.01 0.03
gc cr multi block request 34 0.00 0.00
gc cr block 2-way 19 0.00 0.00
enq: TO - contention 2 0.00 0.00
direct path write temp 3692 0.01 2.78
SQL*Net message to dblink 5 0.00 0.00
SQL*Net message from dblink 5 3.46 3.53
SQL*Net more data from dblink 47 0.03 0.12
db file scattered read 183 0.00 0.21
db file sequential read 1 0.00 0.00
direct path read temp 3686 0.16 26.45
SQL*Net message to client 2 0.00 0.00
log file sync 1 0.02 0.02
SQL*Net message from client 2 0.11 0.12
********************************************************************************
I have color coded the first three temporary table accesses to illustrate how to map the actual run time statistics to your query. Each temporary table is created in order and I highlighted the two bytes to focus in on, 89, 8A, and 8B in the example above. These are the first three temporary table names in this query and they correspond to the first three LOAD statements. In the load statements you can see the tables that are being accessed. As you work through this example, you can see that it helps to be familiar with the source of all of your tables in order to see how it maps to your query. For example wms_truck_route_vw in the truck_route WITH clause called from the filtered_bol WITH clause is actually WMS_TRUCK_ROUTE_MV in the actual plan.
The lesson of this plan is that most of the time is spent joining the CSP related materialized views tms_frgt_bu_mvw and tms_frgt_itm_mvw together. Note that the tms_frgt_itm_mvw table is identified from the index that was used, TMS_FRGT_ITM_MVW_IDX. The total runtime was 80.24 seconds, 75.2 of which were spent on this join. Although this joined view gets used twice, building it in memory is a bad idea because it is very large and the result is not indexed. A better approach would be to join in these two tables where the csp_list WITH clause is used so that just the rows of interest on the first materialized view are accessed and then the corresponding rows for the second materialized view.