Execution time varies

I have a long process that usually takes 1 hour, but it sometimes takes 3 times longer.

We set up a VirtualMachine with Windows 2008 R2 and Oracle 11g Release 11.2.0.1. No other user has access to this VM. Before each test we delete and recreate the Oracle instance with the data. In theory every single execution should take the same time.

About 20% of the time, it takes 3 hours instead of 1. I decided to enable logging with "set sqltrace = true" and then monitor for differences with "tkprof".

The output of a fast (1 hour) and a slow (3 hours) execution are identical, except for the summary at the bottom of the trace.

Here is the trace summary of the fast execution:

Code:

---


        1 session in tracefile
  1711850 user SQL statements in trace file
    67495 internal SQL statements in trace file
  1779345 SQL statements in trace file
      4196 unique SQL statements in trace file
  13692028 lines in trace file

---

Here is the trace summary of the slow execution:

Code:

---


        3 sessions in tracefile
  5135559 SQL statements in trace file
    202506 internal SQL statements in trace file
  1779365 SQL statements in trace file
      4200 unique SQL statements in trace file
  13692482 lines in trace file

---

As you can see, with the same data processed, I see 3 sessions instead of one, and the total execution time is also 3 times longer. What does the "3 sessions" means, I was alone on the VM for every tests, there was no additionnal sessions running at the time.

It means three different sessions are in the trace.

Would you mind in showing us wait events session for each trace?

I am new to Oracle, so how do I monitor the "wait event sessions" ?

I am using a Oracle 11g standard (I don't have access to the Statpack or any optional monitoring tools).

I figured out how to get some wait statistics. Here is a table comparing a slow execution (3 hrs) vs a fast execution (1 hr). Keep in mind that all tests were done on the same server, alone, database was restored from a backup every time, and Oracle was shutdown and restarted between each tests. Usually the slow tests happens when the Oracle server was sitting idle for a few days (like a weekend):

Attachment 591

Look at this particular wait events and research what they mean...
jobq_slave_wait,
*parallel*,
db_file_sequential_read

My take is that "slow" process is doing parallelism while "fast" one isn't.

"slow" process is also doing a lot more of reads by index (db_file_sequential_read) than "fast" process does - Something is different, Oracle would not choose different execution plans just for the fun of it.

When you say... "database was restored from backup", is that a real datafile level backup or are you just imp or impdb the data?

We are deleting the database schema, then we recreate it with a script and we reload the data.

Quote:

---

Originally Posted by JacquesLebrun

We are deleting the database schema, then we recreate it with a script and we reload the data.

---

That sounds to me like the database is never "restored" but the data imported either via imp, impdp, sqlloader, external tables, a dblink or something like that, init? That means database is never the same in terms of how data is stored.

Not "the same" database then you can expect differences in execution time.

I double-checked with the guy that does the different tests, and he is using the data pump (impdp) to restore the database every time. I fail to see why the same data, loaded with the same Oracle tool, can sometimes make a program run 3 x longer (3 hours instead of 1 hour) ...

From what we observed, the long execution happens when the program when the Oracle database server was idle for a few days (usually after a weekend).

During the week, I can restore and run my program 10 times in a row, it will ALWAYS takes 1 hour to run. On mondays, or if I leave the Oracle database server idle for 2-3 days, my program ALWAYS takes 3 hours to run.

My program operates on a small amount of data. Even if the Oracle cache was completely empty when I started my program, this would not explain an additionnal 2 hours delay !!!

Answering the first question, impdp does not performs a restore but an import. A restore implies that the datafiles are physically indentical, impdp cannot offer that certainty.

In regards to the actual issue please do this. Before executing you process check the statistics of all involved tables, the data you want to catch is num_rows, sample_size and last_updated. If you see different values for any of these three attributes when slow and fast processes happens it means that a process is gathering statistics then causing Oracle to choose a different execution plan.