Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> High performance hit when tracing a session

High performance hit when tracing a session

From: Dymynix <no_at_anon>
Date: Tue, 23 Apr 2002 16:26:59 +0100
Message-ID: <1019575514.13461.0.nnrp-12.c2d92da9@news.demon.co.uk>


Oracle 8.1.7.0.0 running on Windows 2000 Server.

Trying to find why a particular report is running slow, and have added code to log
start and end times to a database table for each SQL statement executed.

Results are like below:

Identifer                                        SubFunction
Start        End                            Duration (s)
01/15012002/15012002/140 22 - REDUCT_TOTAL 15:37:33 15:37:33 0
01/15012002/15012002/140 23 - PROFIT_ALL 15:37:33 15:37:33 0
01/15012002/15012002/140 24 - Adjustments 15:37:33 15:37:33 0
01/15012002/15012002/140 25 - IssuesAtList 15:37:33 15:37:52 19
01/15012002/15012002/140 26 - ClosingRetains 15:37:52 15:37:52 0
01/15012002/15012002/140    27 - CashSales                 15:37:52 15:37:52
0
01/15012002/15012002/140    28 - Var: PaidIn               15:37:52 15:37:52
0
01/15012002/15012002/140    29 - Var: Banked              15:37:52 15:37:53
1
01/15012002/15012002/140    30 - CashPaidIn                15:37:53 15:37:53
0

Duration is calculated by end - start * 86400.

I can see that IssuesAtList is slow compared to other SQL.

I decided to use tkprof to see the explain for this SQL so turned tracing on ONLY for this session via code.

Ran the report again and the following time were reported.

01/15012002/15012002/140 22 - REDUCT_TOTAL 16:09:51 16:09:51 0

01/15012002/15012002/140       23 - PROFIT_ALL                16:09:51
16:09:52                         1
01/15012002/15012002/140       24 - Adjustments                   16:09:52
16:09:53                         1
01/15012002/15012002/140       25 - IssuesAtList                   16:09:53
16:14:18                       265
01/15012002/15012002/140       26 - ClosingRetains              16:14:20
16:14:26                         6
01/15012002/15012002/140       27 - CashSales                      16:14:28
16:14:35                         7
01/15012002/15012002/140       28 - Var: PaidIn                    16:14:37
16:14:45                         8
01/15012002/15012002/140       29 - Var: Banked                  16:14:47
16:14:51                         4
01/15012002/15012002/140       30 - CashPaidIn                   16:14:52
16:14:53                         1

Now I know tracing a session will have an impact but an order of 10 impact seems way over the top.

Anyway got the explain plan for IssuesAtList and it is doing a full scan on a products table.

However when I run the SQL from SQL*Plus the products table is accessed via an index which is what I expect.

Any Ideas? Received on Tue Apr 23 2002 - 10:26:59 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US