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

[Jack C. Mahaffey]

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'

********************************************************************************

[Ryan Kogelheide · Accepted solution]

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]

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]

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]

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]

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

jack...

[Alwyn Santos]

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]

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]

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]

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...

[Volker Borowski]

Hi Jack,

another idea, as 7.x might not be able to use the index with ">" and "<"

SELECT ... WHERE var BETWEEN low: and high: ;

Should take the index even in Oracle 7.x.

What the heck do they want with so many rows ?
If this table is queuelike (insert/delete) and you ave some GB to be read, consider to reorganize it, because it might be fragmented.
Select bytes from dba_segments, calculate an average row_length and do a select count(*). Multiply count(*) with average row-length and compare to bytes from dba_segments. If this shows a big diffrence (bytes significantly bigger), go for a reorg.

If you do not need all columns, but only a,b,c consider to create the index as

mx_timestamp,a,b,c because the range youe have for mx_timestamp apears not to be so small, an INDEX_FAST_FULLSCAN might reduce the IO, ...(although I do not remember, if Oracle is capable of fast_fullscans in 7.3).

In addition, I'd like to see the diffrent explains as well.

Volker

[Jack C. Mahaffey]

I'm getting real good at tracing active SQL on a HP-UX server. Does anyone have any guidance for finding the heavy hitters on a Windows NT, XP, 2000 server?

Can any performance counter be used to find the corresponding spid in v$process?

Note that we don't have the performance pack installed.

jack...

[Alwyn Santos]

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

Should actually be...

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

* index_name should be changed to the index you want to use.


Also, to find poorly performing queries on NT or any oracle db...

select disk_reads,buffer_gets,executions,sql_text
from v$sqlarea
where disk_reads > 10000
or buffer_gets > 100000
order by disk_reads,buffer_gets
/

Concentrate on statements that have high disk read/execution ratio.