| TKPROF showing wrong totals for non-recursive statements [message #683660] |
Thu, 11 February 2021 06:19 |
Andrey_R
Messages: 441
Registered: January 2012
Location: Israel
|
Senior Member |
|
|
Hi all,
I have traced a session and produced a trace file, which I tkprof'ed with
C:\...myuser>tkprof D:\SOMEPATH...\MYDB_ora_26950.trc D:\SOMEPATH...\MYDB_ora_26950.tkprf sort=exeela,fchela,prsela
TKPROF: Release 12.1.0.2.0 - Development on Thu Feb 11 11:16:34 2021
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
C:\...myuser>
TKPROF: Release 12.1.0.2.0 - Development on Thu Feb 11 11:16:16 2021
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
Trace file: D:\*MYPATH*\*MYDB*_ora_19983.trc
Sort options: exeela fchela prsela
********************************************************************************
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
********************************************************************************
SQL ID: 7c55t2dag19y3 Plan Hash: 2537333851
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 1.33 1.33 0 36042 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 1.33 1.33 0 36042 0 2
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 317 (recursive depth: 1)
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 VIEW (cr=18021 pr=0 pw=0 time=666679 us cost=4517 size=31 card=1)
1 1 1 SORT AGGREGATE (cr=18021 pr=0 pw=0 time=666677 us)
4306578 4306578 4306578 INDEX RANGE SCAN *SOMEOBJ* (cr=18021 pr=0 pw=0 time=534595 us cost=4517 size=57370 card=5737)(object id 576435)
********************************************************************************
SQL ID: 56fpu993a68yj Plan Hash: 4278094301
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.51 0.51 0 152 0 0
Fetch 1 0.12 0.73 946 8819 0 224
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.64 1.24 946 8971 0 224
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 317
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
224 224 224 VIEW (cr=8819 pr=946 pw=0 time=391022 us cost=546 size=47476 card=143)
224 224 224 UNION-ALL (cr=8819 pr=946 pw=0 time=391021 us)
*CONTENT OF EXEC PLAN*
0 0 0 INDEX RANGE SCAN *SOMEOBJ* (cr=0 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 575806)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
Disk file operations I/O 21 0.00 0.00
db file sequential read 946 0.01 0.64
SQL*Net message from client 1 0.00 0.00
********************************************************************************
SQL ID: 6tzqywcvs09sj Plan Hash: 2113245666
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 1.20 1.20 0 40824 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 1.20 1.20 0 40824 0 2
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 317 (recursive depth: 1)
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 VIEW (cr=20412 pr=0 pw=0 time=600303 us cost=5149 size=31 card=1)
1 1 1 SORT AGGREGATE (cr=20412 pr=0 pw=0 time=600302 us)
4306578 4306578 4306578 INDEX RANGE SCAN *SOMEOBJ* (cr=20412 pr=0 pw=0 time=446345 us cost=5149 size=74581 card=5737)(object id 575862)
********************************************************************************
SQL ID: 9juhy6x564z57 Plan Hash: 877077697
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 1.15 1.15 0 34852 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 1.15 1.15 0 34852 0 2
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 317 (recursive depth: 1)
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 VIEW (cr=17426 pr=0 pw=0 time=576656 us cost=4370 size=31 card=1)
1 1 1 SORT AGGREGATE (cr=17426 pr=0 pw=0 time=576654 us)
4306578 4306578 4306578 INDEX RANGE SCAN *SOMEOBJ* (cr=17426 pr=0 pw=0 time=438414 us cost=4370 size=57370 card=5737)(object id 575860)
********************************************************************************
SQL ID: 0z8dg5mqnz3a8 Plan Hash: 30659628
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.88 0.88 0 14404 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.88 0.88 0 14404 0 1
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 317 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 VIEW (cr=14404 pr=0 pw=0 time=887849 us cost=3 size=31 card=1)
1 1 1 SORT AGGREGATE (cr=14404 pr=0 pw=0 time=887847 us)
54037 54037 54037 INDEX RANGE SCAN *SOMEOBJ* (cr=14404 pr=0 pw=0 time=904198 us cost=3 size=126214 card=5737)(object id 575863)
********************************************************************************
SQL ID: bkv7kdkgwfw3k Plan Hash: 3257521680
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 19 0.00 0.00 0 0 0 0
Fetch 19 0.61 0.62 0 82228 0 19
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 39 0.61 0.62 0 82228 0 19
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 317
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 VIEW (cr=4569 pr=0 pw=0 time=49867 us cost=2 size=53 card=1)
1 1 1 WINDOW SORT PUSHED RANK (cr=4569 pr=0 pw=0 time=49864 us cost=2 size=108 card=6)
54946 54946 54946 TABLE ACCESS BY INDEX ROWID BATCHED *SOMETAB* (cr=4569 pr=0 pw=0 time=50627 us cost=1 size=108 card=6)
54946 54946 54946 INDEX RANGE SCAN *SOMEOBJ* (cr=101 pr=0 pw=0 time=7046 us cost=1 size=0 card=2)(object id 575797)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 19 0.00 0.00
SQL*Net message from client 19 0.00 0.00
********************************************************************************
SQL ID: 7tscgm3prc7rz Plan Hash: 398800517
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.50 0.50 0 152 0 0
Fetch 1 0.02 0.02 0 9869 0 91
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.53 0.53 0 10021 0 91
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: FIRST_ROWS
Parsing user id: 317
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net more data to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
SQL ID: 6uyta32x4pps3 Plan Hash: 3448338493
*SELECT STUFF
FROM
PLACES... *
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.31 0.31 0 1832 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.31 0.31 0 1832 0 2
Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 317 (recursive depth: 1)
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT GROUP BY (cr=916 pr=0 pw=0 time=155759 us)
7463 7463 7463 TABLE ACCESS SAMPLE *SOMETAB* (cr=916 pr=0 pw=0 time=8791 us cost=135 size=1382576 card=4784)
********************************************************************************
SQL ID: 01d5n1nm17r2h Plan Hash: 285348934
*SELECT STUFF
FROM
PLACES... *
End of the same tkprof files:
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 33 0.00 0.00 0 0 0 0
Execute 523 1.04 1.06 0 304 0 0
Fetch 523 0.79 1.48 1045 104232 0 494
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1079 1.84 2.55 1045 104536 0 494
Misses in library cache during parse: 2
Misses in library cache during execute: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 524 0.00 0.00
SQL*Net message from client 524 39.04 39.50
Disk file operations I/O 21 0.00 0.00
db file sequential read 1045 0.01 0.72
SQL*Net more data to client 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 691 0.01 0.01 0 0 0 0
Execute 3176 0.10 0.10 0 0 0 0
Fetch 3176 10.44 10.44 0 338931 0 2958
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7043 10.56 10.56 0 338931 0 2958
Misses in library cache during parse: 0
354 user SQL statements in session.
29 internal SQL statements in session.
383 SQL statements in session.
********************************************************************************
Trace file: D:\*SOMEPATH*\*MYDB*_ora_19983.trc
Trace file compatibility: 11.1.0.7
Sort options: exeela fchela prsela
1 session in tracefile.
354 user SQL statements in trace file.
29 internal SQL statements in trace file.
383 SQL statements in trace file.
206 unique SQL statements in trace file.
41157 lines in trace file.
13 elapsed seconds in trace file.
However, looking at the worst statements on top - these make some 7+ seconds alone ( and there are some 350 more, small ones that add to quite a few more seconds, in the rest of the file I didn't post here )
How can it be that the sum of execution time for non-recursive SQLs in the summary is less by many times than the number of seconds we get if we add each statements exec time ?
I see no significant wait times that can explain it. The statements I specified are masked but I can guarantee each is an application driven query,
So from what I understand it counts as a NON-RECURSIVE query. In the totals it says the NON-RECURSIVE is 3 seconds overall.
However it means that...
1.33 + 1.24 [0.64 of which is sequential read, fine, we don't have to count it..] + 1.20 + 1.15 + 0.88 + 0.62 + 0.53 + 0.31 > 3s
What am I missing here? Am I doing the math wrong ? Misinterpreting what I think I see ? Why don't the numbers add up 
Many thanks in advance,
Andrey
[Updated on: Thu, 11 February 2021 17:11] Report message to a moderator |
|
|
|
] 
Blog
Search
Help
Members
Register
Login
Home
