Skip to Main Content
  • Questions
  • tkprof sort option to find most expensive query

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, amey.

Asked: March 19, 2016 - 3:52 pm UTC

Last updated: April 21, 2021 - 3:41 am UTC

Version: 12c

Viewed 10K+ times! This question is

You Asked

Hi,
I saw various sort options in tkprof.

sort=(prsela,exeela,fchela)
sort=PRSDSK, EXEDSK, FCHDSK
sort=EXECPU,FCHCPU
sort=(exeela,fchela)

I really want to get poorly performing queries on the top. and then i want to print 10 top most poorly written queries from trace file.
PRINT = 10

tkprof a.trc limited_data sys=no explain=apps/ABC@DB sort=(prsela,exeela,fchela) print=10

Hence what is a right sorting option?

And is one option is helpful for both Select & DML ( insert/update/delete) statements or need to use two sort options.
Please can you provide some light.

Thank
Amey

and Connor said...

For me, my two areas of focus are:

- total elapsed time (simply because that's what customers judge you on).
- total cpu time (because if you're running out of server resources, that's the next thing to tackle).

As per the docs (emphasis mine)

"the output is sorted in descending order by the *sum* of the values specified in the sort options"

So consider perhaps as first options:

sort=(prsela,exeela,fchela)
sort=(prscpu,execpu,fchela)

then tailor from there (eg, if your storage admin barks at you about disk overload, then focus on disk io etc).


Rating

  (3 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

TkProd - Elapsed time for procedure call

Narendra, April 15, 2021 - 3:12 pm UTC

Hello Connor/Chris,

I am having to look at TkProf to diagnose a performance issue and It has been a long time since I last used TkProf so apologies if my question sounds silly.
How to get the elapsed time for a stored procedure call from TkProf, either formatted or raw trace file?

Reason for asking this question is, I have a trace for 2 executions of a stored procedure with one execution taking about 900 milliseconds and other one taking about 4.2 seconds.
However, the (formatted) TkProf is reporting below stats.

SQL ID: fs222j2tx1kqw Plan Hash: 0

<Stored Procedure>


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.35       0.46          0          0          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.35       0.46          0          0          0           2


Is this expected behaviour/limitation of TkProf output?
Connor McDonald
April 19, 2021 - 5:46 am UTC

We're trying not to double count so we'll typically separate out the child SQL timings.

For example:

SQL> create or replace
  2  procedure SLOW_PROC is
  3    x int;
  4  begin
  5    select count(edition_name)
  6    into   x
  7    from   dba_objects,dba_tables
  8    where object_id > 10;
  9  end;
 10  /

Procedure created.

SQL> exec slow_proc

PL/SQL procedure successfully completed.


ran for ~1min on my laptop. But the trace shows this:

BEGIN slow_proc; END;


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           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1




Because the time was not spent "in" the proc by the SQL it called:

SELECT COUNT(EDITION_NAME) 
FROM
 DBA_OBJECTS,DBA_TABLES WHERE OBJECT_ID > 10


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.15       0.16          0         20          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1     63.60      63.63          0      36693          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3     63.76      63.79          0      36713          0           1



That saves us from reporting at the end of the trace file that we ran for "2 mins" instead of 1.

Re: TkProd - Elapsed time for procedure call

Narendra, April 15, 2021 - 3:19 pm UTC

If it helps, the EXEC lines from the raw trace file for the 2 executions (of the store procedure) are as below

EXEC #150290611325248:c=884332,e=975850,p=1,cr=10695,cu=211,mis=0,r=1,dep=0,og=1,plh=0,tim=1504727735622

EXEC #150290611325248:c=3547827,e=4212025,p=1,cr=58053,cu=349,mis=0,r=1,dep=0,og=1,plh=0,tim=1504746711788

Re: TkProd - Elapsed time for procedure call

Narendra, April 19, 2021 - 8:48 am UTC

Hello Connor,

Appreciate your response and can understand the logic behind avoiding double-counting.
However, the question still remains...
How to derive the execution time for a stored procedure, irrespective of the number of sqls it has....from the 10046 trace files?

Would appreciate if you can provide any pointers.
The case I am working on, ends up producing rather large size of trace file and my SQL Developer struggles to present the "Statistics View" tab.
Connor McDonald
April 21, 2021 - 3:41 am UTC

Look at download sql trace analyzer MOS note 224270.1.

Do a global search/replace in all files for:

VARCHAR2(30)

and change to

VARCHAR2(128)

and then run it as per the instructions. It does some hierarchical totalling.