Operating System - HP-UX
1748087 Members
5032 Online
108758 Solutions
New Discussion юеВ

Oracle tkprof output understanding.... exec and fetch counts are the same.

 
SOLVED
Go to solution
Jack C. Mahaffey
Super Advisor

Oracle tkprof output understanding.... exec and fetch counts are the same.

Hi, I executed tkprof against a heavy hitter on my system.

I'm not sure I'm reading the output correct. Does the following tell me the statement executed 332 times and the code likely only used the first record each time the code executed? There are 332 fetches also. A one-to-one ratio for the executions.

I suspect the sql is executed, the row is deleted and then the sql is executed again with a new value of mx_timestamp.



select rowid rowid_cid199, invent_hist.*
FROM
invent_hist WHERE (mx_timestamp <> 0 and mx_timestamp < 962114678)


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 332 0.03 0.10 0 0 0 0
Fetch 332 1042.40 1702.53 7944425 7955798 664 332
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 664 1042.43 1702.63 7944425 7955798 664 332

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 21 (MSDUSR)

Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'INVENT_HIST'

********************************************************************************
13 REPLIES 13
Ryan Kogelheide
Frequent Advisor
Solution

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

What you say sounds right. I believe tkprof summarizes by looking at sql that uses the same sql area, so if the bind value changes, it's still the same statement. it may be that it does not print it as a bind if it is not explicitly bound (i.e. you're using cursor_sharing=force).

Volker Borowski
Honored Contributor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

Well,

the best info is

0 SELECT STATEMENT GOAL: CHOOSE
0 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'INVENT_HIST'

Create an index on column mx_timestamp, and it will fly like hell.

If it behaves the way you suspect, that would be bad application programming, but if you can not access the source ther will be no way to change that.
If you create the index, it will also be executed 332 times, but much quicker.

Hope this helps
Volker
Jack C. Mahaffey
Super Advisor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

There is an index on mx_timestamp. It's not used. I suspect the index is ignored because all the columns are being returned.

I also noticed that there isn't a unique primary key on the table.
Alwyn Santos
Advisor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

It's not using the index because of the <> (not equal will suppress and index)

If the column dosn't have negative numbers, change the query to

WHERE (mx_timestamp > 0 and mx_timestamp < 962114678)

Depending on the range of values, this should do an index range scan.
Jack C. Mahaffey
Super Advisor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

I've made the recommendation of removing the '<>' at first looking at the sql. The explain plan did not change...

jack...
Alwyn Santos
Advisor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

You may have to hint the index to get it to work.

select /*+ index(table_name index_name) */ rowid rowid_cid199, invent_hist.*
FROM invent_hist WHERE (mx_timestamp <> 0 and mx_timestamp < 962114678)

Bill Thorsteinson
Honored Contributor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

I would expect bind variables to
show up as :1 :2 etc.

It looks like the query is already
parsed in the SGA (parse count = 0).

The fetch is executed once for each
execution.

If they are looping on this statement
then you should consider using a cursor
and fetching each row and procesing it
in a loop.

If the table hasn't been analyzed
recently, then the statistics may
not be available to cause use of the
index.

Try a statement like

SELECT ROWID rowid_cid199,
invent_hist.*
FROM invent_hist
WHERE mx_timestamp = (
SELECT mx_timestamp
FROM invent_hist
WHERE mx_timestamp <> 0
AND mx_timestamp < :1)
Ryan Kogelheide
Frequent Advisor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

Jack,

There's no reason that the index should not be used with that query.

1) Are you sure the table and index statistics are up to date?

2) Are you using histograms? If so, try rebuilding the stats without them or with only one bucket.

3) What version of Oracle is it?

Also, what's the code of the calling program? It still looks like it's being executed 332 times, though perhaps that's a bug in tkprof.

May the force be with you...

Ryan
Jack C. Mahaffey
Super Advisor

Re: Oracle tkprof output understanding.... exec and fetch counts are the same.

Oracle 7.3.4 on HP-UX

Thanks for the SQL ideas. The explain plans look much better. I kinda like the idea of a short-term interim fix of having them change the statement to the following:

SELECT ROWID rowid_cid199,
invent_hist.*
FROM invent_hist
WHERE mx_timestamp = (
SELECT min(mx_timestamp)
FROM invent_hist
WHERE mx_timestamp > 0
AND mx_timestamp < 962289620)

This results in only a sql statement change.

I'm bugging the app developers about the performance.

Here's the latest performance of the cursosr for 53 minutes. Performance really sucks...

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 711 0.10 0.23 0 0 0 0
Fetch 711 2306.86 2852.25 17801524 17838125 1422 711
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1422 2306.96 2852.48 17801524 17838125 1422 711

2306 / 60 = 38.43 minutes of cpu overhead
2852 / 60 = 47.54 minutes of elapsed time
17801524 * 8192 bytes per block = 145,830,084,608 bytes read from disk io (146 gb)
17838125 * 8192 = 146,149,920,000 oracle blocks bytes read (146gb)
711 records processed

And yes the statistics are updated on a regular basis.

I'm also trying to find out why they are retrieving all the columns. I'm suggesting a longer term solution to not retrieve all the columns and use a cursor to drive the application to ensure an index is used and data is only retrieved if necessary.

jack...