Home » RDBMS Server » Performance Tuning » TKPROF showing wrong totals for non-recursive statements (Oracle 12.1.0.2.0)
TKPROF showing wrong totals for non-recursive statements [message #683660] Thu, 11 February 2021 06:19
Andrey_R
Messages: 370
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>
In the beginning of the file:

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... *
*masked parts appear next to asterisks

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.

So I know that stuff like AWR and TKPROF are not guaranteed to be perfectly accurate, and it depends on many factors, fine.
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 Smile

Many thanks in advance,
Andrey

[Updated on: Thu, 11 February 2021 17:11]

Report message to a moderator

Previous Topic: ORA-12705: Cannot access NLS data files or invalid environment specified with jmeter test
Next Topic: Program is slower with Oracle12C compared to Oracle 11G
Goto Forum:
  


Current Time: Mon Jul 26 21:37:06 CDT 2021