Oracle query is slower the second time

oracleoracle-11g-r2performancequery-performance

I have a general question about something I'm seeing in performance tuning in Oracle. I have a query that I'm testing. It's too big and complex for me to provide a simple example, sorry! (I tried lowering it down, but lost the symptom)

The first time I run the query, it's 2 seconds. Subsequent times it's 3, 4, or even 5 seconds. This happens consistently – if I change the spacing, I get 2 seconds again, then it goes back up.

This is the opposite of what I would expect – after the first time, the database doesn't need to parse the query, and blocks should be in read into the buffer cache. The only thing I can think of is that it is writing temp data somewhere, in such a way that it is faster to write and read it than it is to just read it. But that of course makes no sense.

Does anyone know why this is happening? Or any red flags in the execution plan that would cause something like this?

FYI, this is a SELECT, with multiple joins, aggregation, and views. No internal PL/SQL.

Thank you

@Colin It's unlikely another process could be affecting this Dev machine, at least so consistently. Not sure what dynamic sampling is. Same thing as cardinality feedback?

@druzin No bind variables, but no predicate changes either – same hash.

@mustaccio Good idea, although I suspect it's something to do with implicit temp tables or caching. I'll give it a try.

Best Answer

Cases like this can usually be solved for certain by enabling trace events 10046 (if you have authority to do so), and run tkprof on the resulting trace files:

alter session set events '10046 trace name context forever, level 8';
select /* try one */ -- add your SQL here and invoke it;
select /* try two */ -- add your same SQL here and invoke it;
show parameter user_dump_destination

Invoke it a few times, and then turn tracing off, log off to ensure the trace files get closed:

alter session set events '10046 trace name context off';
exit;

Then find your trace file, and run tkprof on it, assuming your trace file name is ${ORACLE_SID}_ora_39110.trc:

cd $ORACLE_BASE/diag/rdbms/$ORACLE_SID/$ORACLE_SID/trace
tkprof ${ORACLE_SID}_ora_39110.trc ${ORACLE_SID}_ora_39110.trc.txt
vi ${ORACLE_SID}_ora_39110.trc.txt

The output of tkprof will show you execution statistics (logical reads, physical reads, etc). And you can look at the actual trace file if the tkprof output doesn't help.

If that doesn't help, you can enable 10053 event, and enjoy wading through thousands of lines of output; but sometimes you need to do that.

But first things (well easier things) first; do as others suggested; see if table statistics are up to date, optimizer settings, etc. If you are using the exact same criteria each execution, could be the optimizer is "on the border" on plans. I would ensure you have collected system statistics; see the documentation on dbms_stats.gather_system_stats pl/sql package.

Related Question