Time Model Bug

Tasks that are performed via jobs in the database will be double accounted in the system time model that has been introduced with Oracle 10g.

So if you execute significant workload via DBMS_JOB or DBMS_SCHEDULER any system time model related statistic like DB Time, DB CPU etc. that gets recorded for that workload gets double accounted.

This bug is not particularly relevant since your top workloads will still be the same top workloads, because all other statistics (like Elapsed Time, CPU, Buffer Gets etc.) are not affected by the bug.

I mention it only here since the bug (see below for details) as of the time of writing can't yet be found on My Oracle Support in the bug database but I recently came across several AWR reports where the majority of workload was generated via job processes and therefore the time model statistics were effectively doubled.

It might help as a viable explanation if you sometimes wonder why an AWR or Statspack report only captures 50% or less of the recorded total DB Time or DB CPU and where this unaccounted time has gone. If a significant part of the workload during the reporting period has been performed by sessions controlled via DBMS_JOB or DBMS_SCHEDULER then probably most of the unaccounted time is actually not unaccounted but the time model statistics are wrong.

So if you have such an otherwise unexplainable unaccounted DB Time / DB CPU etc. you might want to check if significant workload during the reporting period was executed via the job system. Note that I don't say that this is the only possible explanation of such unaccounted time - there might be other reasons like uninstrumented waits, other bugs etc.

Of course all the percentages that are shown in the AWR / ADDM / Statspack reports that refer to "Percentage of DB Time" or "Percentage of DB CPU" will be too small in such cases.

If the majority of workload during the reporting period has been generated by jobs then you can safely assume that the time model statistics have to be divided by 2 (and the percentages have to be doubled). If you have a mixture of jobs and regular foreground sessions then it will be harder to derive the correct time model statistics.

Note that the "Active Session History" (ASH) is not affected by the bug - the ASH reports always were consistent in my tests regarding the DB Time (respectively the number of samples) and CPU time information.

The following simple test case can be used to reproduce the issue at will. Ideally you should have exclusive access to the test system since any other concurrent activity will affect the test results.

You might want to check the 1000000000 iterations of the simple PL/SQL loop on your particular CPU - on my test system this takes approx. 46 seconds to complete.

The first version assumes that a PERFSTAT user with an installed STATSPACK is present in the database since STATSPACK doesn't require an additional license. An AWR variant follows below.

alter session set nls_language = american nls_territory = america;

store set .settings replace

set echo on timing on define on

define iter="1000000000"

variable snap1 number

exec :snap1 := statspack.snap

declare
n_cnt binary_integer;
begin
n_cnt := 0;
for i in 1..&iter loop
n_cnt := n_cnt + 1;
end loop;
end;
/

variable snap2 number

exec :snap2 := statspack.snap

/* Uncomment this if you want to test via DBMS_JOB
variable job_id number

begin
dbms_job.submit(:job_id, '
declare
n_cnt binary_integer;
n_status integer;
begin
n_cnt := 0;
for i in 1..&iter loop
n_cnt := n_cnt + 1;
end loop;
n_status := dbms_pipe.send_message(''bg_job_complete'');
end;
');
end;
/

commit;
*/

/* Uncomment this if you want to test via DBMS_SCHEDULER */
begin
dbms_scheduler.create_job(
job_name => dbms_scheduler.generate_job_name
, job_type => 'PLSQL_BLOCK'
, job_action => '
declare
n_cnt binary_integer;
n_status integer;
begin
n_cnt := 0;
for i in 1..&iter loop
n_cnt := n_cnt + 1;
end loop;
n_status := dbms_pipe.send_message(''bg_job_complete'');
end;
' , enabled => true);
end;
/

declare
pipe_status integer;
begin
pipe_status := dbms_pipe.receive_message('bg_job_complete');
end;
/

declare
pipe_id integer;
begin
pipe_id := dbms_pipe.remove_pipe('bg_job_complete');
end;
/

variable snap3 number

exec :snap3 := statspack.snap

rem set heading off pagesize 0 feedback off linesize 500 trimspool on termout off echo off verify off

prompt Enter PERFSTAT password

connect perfstat

column dbid new_value dbid noprint

select dbid from v$database;

column instance_number new_value inst_num noprint

select instance_number from v$instance;

column b_id new_value begin_snap noprint
column e_id new_value end_snap noprint

select :snap1 as b_id, :snap2 as e_id from dual;
define report_name=sp_foreground.txt

@?/rdbms/admin/sprepins

column dbid new_value dbid noprint

select dbid from v$database;

column instance_number new_value inst_num noprint

select instance_number from v$instance;

column b_id new_value begin_snap noprint
column e_id new_value end_snap noprint

select :snap2 as b_id, :snap3 as e_id from dual;
define report_name=sp_background.txt

@?/rdbms/admin/sprepins

undefine iter

@.settings

set termout on

Here is the same test case but with AWR reports (requires additional diagnostic license)

alter session set nls_language = american nls_territory = america;

store set .settings replace

set echo on timing on define on

define iter="1000000000"

column snap1 new_value awr_snap1 noprint

select dbms_workload_repository.create_snapshot as snap1 from dual;

declare
n_cnt binary_integer;
begin
n_cnt := 0;
for i in 1..&iter loop
n_cnt := n_cnt + 1;
end loop;
end;
/

column snap2 new_value awr_snap2 noprint

select dbms_workload_repository.create_snapshot as snap2 from dual;

/* Uncomment this if you want to test via DBMS_JOB
variable job_id number

begin
dbms_job.submit(:job_id, '
declare
n_cnt binary_integer;
n_status integer;
begin
n_cnt := 0;
for i in 1..&iter loop
n_cnt := n_cnt + 1;
end loop;
n_status := dbms_pipe.send_message(''bg_job_complete'');
end;
');
end;
/

commit;
*/

/* Uncomment this if you want to test via DBMS_SCHEDULER */
begin
dbms_scheduler.create_job(
job_name => dbms_scheduler.generate_job_name
, job_type => 'PLSQL_BLOCK'
, job_action => '
declare
n_cnt binary_integer;
n_status integer;
begin
n_cnt := 0;
for i in 1..&iter loop
n_cnt := n_cnt + 1;
end loop;
n_status := dbms_pipe.send_message(''bg_job_complete'');
end;
' , enabled => true);
end;
/

declare
pipe_status integer;
begin
pipe_status := dbms_pipe.receive_message('bg_job_complete');
end;
/

declare
pipe_id integer;
begin
pipe_id := dbms_pipe.remove_pipe('bg_job_complete');
end;
/

column snap3 new_value awr_snap3 noprint

select dbms_workload_repository.create_snapshot as snap3 from dual;

set heading off pagesize 0 feedback off linesize 500 trimspool on termout off echo off verify off

spool awr_foreground.html

select
output
from
table(
sys.dbms_workload_repository.awr_report_html(
(select dbid from v$database)
, (select instance_number from v$instance)
, &awr_snap1
, &awr_snap2
)
);

spool off

spool awr_background.html

select
output
from
table(
sys.dbms_workload_repository.awr_report_html(
(select dbid from v$database)
, (select instance_number from v$instance)
, &awr_snap2
, &awr_snap3
)
);

spool off

spool awr_diff.html

select
output
from
table(
sys.dbms_workload_repository.awr_diff_report_html(
(select dbid from v$database)
, (select instance_number from v$instance)
, &awr_snap1
, &awr_snap2
, (select dbid from v$database)
, (select instance_number from v$instance)
, &awr_snap2
, &awr_snap3
)
);

spool off

undefine awr_snap1
undefine awr_snap2
undefine awr_snap3

undefine iter

column snap1 clear
column snap2 clear
column snap3 clear

@.settings

set termout on

And here is a sample snippet from a generated Statspack report on a single CPU system with nothing else running on the system:

Normal foreground execution:

STATSPACK report for

Database DB Id Instance Inst Num Startup Time Release RAC
~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
orcl112 1 05-Aug-10 08:21 11.2.0.1.0 NO

Host Name Platform CPUs Cores Sockets Memory (G)
~~~~ ---------------- ---------------------- ----- ----- ------- ------------
XXXX Microsoft Windows IA ( 1 0 0 2.0

Snapshot Snap Id Snap Time Sessions Curs/Sess Comment
~~~~~~~~ ---------- ------------------ -------- --------- ------------------
Begin Snap: 13 05-Aug-10 08:34:17 25 1.2
End Snap: 14 05-Aug-10 08:35:05 25 1.2
Elapsed: 0.80 (mins) Av Act Sess: 1.1
DB time: 0.87 (mins) DB CPU: 0.80 (mins)

Cache Sizes Begin End
~~~~~~~~~~~ ---------- ----------
Buffer Cache: 104M Std Block Size: 8K
Shared Pool: 128M Log Buffer: 6,076K

Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~ ------------------ ----------------- ----------- -----------
DB time(s): 1.1 2.4 0.09 3.99
DB CPU(s): 1.0 2.2 0.08 3.68

Execution via Job/Scheduler:

STATSPACK report for

Database DB Id Instance Inst Num Startup Time Release RAC
~~~~~~~~ ----------- ------------ -------- --------------- ----------- ---
orcl112 1 05-Aug-10 08:21 11.2.0.1.0 NO

Host Name Platform CPUs Cores Sockets Memory (G)
~~~~ ---------------- ---------------------- ----- ----- ------- ------------
XXXX Microsoft Windows IA ( 1 0 0 2.0

Snapshot Snap Id Snap Time Sessions Curs/Sess Comment
~~~~~~~~ ---------- ------------------ -------- --------- ------------------
Begin Snap: 14 05-Aug-10 08:35:05 25 1.2
End Snap: 15 05-Aug-10 08:35:53 24 1.3
Elapsed: 0.80 (mins) Av Act Sess: 1.9
DB time: 1.55 (mins) DB CPU: 1.54 (mins)

Cache Sizes Begin End
~~~~~~~~~~~ ---------- ----------
Buffer Cache: 104M Std Block Size: 8K
Shared Pool: 128M Log Buffer: 6,076K

Load Profile Per Second Per Transaction Per Exec Per Call
~~~~~~~~~~~~ ------------------ ----------------- ----------- -----------
DB time(s): 1.9 92.8 0.79 7.74
DB CPU(s): 1.9 92.1 0.78 7.68

As you might have guessed my single CPU test system has not been added a second CPU when performing the same task via DBMS_SCHEDULER / DBMS_JOB yet the time model reports (almost) 2 DB Time / DB CPU seconds and active sessions per second in that case.

I have reproduced the bug on versions 10.2.0.4, 11.1.0.7 and 11.2.0.1 but very likely all versions supporting the time model are affected.

A (non-public) bug "9882245 - DOUBLE ACCOUNTING OF SYS MODEL TIMINGS FOR WORKLOAD RUN THROUGH JOBS" has been filed for it, but the fix is not available yet therefore as far as I know it is not yet part of any available patch set / PSU.

Note that there seems to a different issue with the DB CPU time model component: If you have a system that reports more CPUs than sockets (for example a Power5, Power6 or Power7 based IBM server that reports 16 sockets / 32 CPUs) then the DB CPU component gets reduced by approximately 50%, which means it is divided by 2.

This means in combination with above bug that you end up with a doubled DB Time component for tasks executed via jobs, but the DB CPU time model component is in the right ballpark since the doubled DB CPU time gets divided by 2.

I don't know if the bug fix also covers this issue, so you might want to keep this in mind when checking any time model based information.

Double Trouble

One of my clients runs a Data Warehouse with several important data loading and transformation procedures.

One of those key procedures had to be executed in a kind of a loop since many of the transformations steps depend on each other's result.

So although each transformation step was executed in an rather efficient way using Oracle best-practices like parallel DML / exchange partition still the iterative approach meant that the underlying server wasn't used as efficiently as possible since many of those transformations steps also included smaller data sets that didn't use all of the resources available.

In order to address that they've recently introduced a more sophisticated version of that key procedure that uses some clever algorithm based on a dependency tree to determine which steps could be executed in parallel since they do not depend on each other.

Now as part of that optimization they've worked out that on their particular hardware they could run as much as 25 transformation steps in parallel and furthermore up to four of those 25 as parallel execution steps.

So you end up in principle with two queues - one is dequeued by four consumers processing "big" slices via parallel execution and a second queue is dequeued by approx. 20 consumers each processing "small" slices using serial execution (It is quite a big "iron" hardware).

This allowed them to increase the resource utilization of the available server hardware and resulted in a significant drop in overall runtime - actually they saved more than 50% of the original runtime which is quite a good result given that they have achieved that on exactly the same hardware!

So far, so very good - now they got an even "bigger" server with newer CPUs and ran the same database with the same configuration, the only change were the CPUs (which required also a newer version of the operating system, but that is a different story). Since most of the processes really use a lot of CPU (due to the design of the system and therefore running them in parallel makes good usage of all the available CPU power since I/O is not the only constraining factor) they expected a further drop in runtime but to their surprise the key procedure they tested took far longer than on the old hardware.

An analysis showed a really interesting case: It turned out that one of the "weak" points of the system which are rather inefficient user-defined PL/SQL functions that perform recursive SQL were going sideways in their performance and required almost hundred times longer per execution than before.

The explanation was rather stunning: Although no change to the database and in particular no code change to the user defined functions was introduced these recursive queries issued by the user-defined functions suddenly started to be executed in parallel using parallel query - which is a rather bad idea when getting executed 20 million times within an hour or so.

The interesting side effect was that on the operating system side it could be monitored that the kernel time increased to more than 50% of the available CPU time bringing the whole system more or less to a grinding halt.

Now the big question was: How could this have happened? This has never happened before on any of the previous systems but the same code / database on the new system showed this weird behaviour.

The first surprising finding was that the recursive queries showed a parallel execution plan when explaining a plan for them - simply due to the fact that the underlying tables and indexes were marked as parallel. This was an obvious bug in the code that seemed to be there from the beginning but hadn't surfaced yet.

So the question became more: Why had this not happened all the time in the past?

Looking further it turned out that the new CPUs resulted in a doubled CPU_COUNT reported by the operating system to Oracle - and they've used a DEFAULT parallel degree for their parallel executions.

This resulted obviously in a doubled degree of parallelism (DOP) of the parallel executions, but they still used the same instance configuration - in particular the same PARALLEL_MAX_SERVERS setting.

So what happened was that using the same approach as described above (using four consumers for the "big" queue) they simply ran out of parallel servers resulting in severe downgrades for some of the intended parallel executions - and some of them were even downgraded to serial.

And here these two issues together allowed the bug above to surface: Once the parallel execution was downgraded to serial the recursive query was eligible to be executed in parallel. Since the user-defined functions were marked with "PARALLEL_ENABLE" they usually were pushed into the parallel slaves and got executed there. Oracle recognizes this execution in the slaves and prevents a recursive parallel execution implicitly - you could call this a limitation or restriction, but in this case it prevented the bug from showing up.

So, in summary the following happened:

- In the past the old implementation ran at most one parallel execution at the same time, so due to the restrictions enforced via the Resource Manager for other sessions no serial downgrade was possible, so the recursive query was pushed into the slaves and executed serially there - no problems so far

- A new implementation was introduced that used a clever queuing approach. As part of that queuing multiple parallel executions happened simultaneously, but due to the carefully chosen settings these were not downgraded, at least not to serial and the recursive query ran as intended in the parallel slaves - still no problems

- A new hardware was introduced, doubling the CPU_COUNT and therefore doubling the default parallel degree, and bingo: Using the same carefully chosen settings parallel executions were downgraded to serial due to the doubled DOP, and the recursive query eventually started to be executed in parallel - the performance went south

After fixing the issue in the code by explicitly forcing serial execution of the recursive query even with the unadjusted settings causing serial downgrades the problem didn't show up anymore.

What can be taken away from this?

- Oracle treats things in parallel slaves differently from things executed in normal sessions

- Using a DEFAULT parallel degree can lead to interesting effects when modifying the underlying hardware / configuration

- Even if your code ran without problems for years it doesn't mean there isn't a bug waiting for you

Just for curiosity, here is a generic testcase that can be used to reproduce the issue at will:

-----------------------------
-- The complete testcase
-----------------------------

-- Tested with the following settings:
-- NO RAC
-- PARALLEL_MAX_SERVERS = 4
-- PARALLEL_ADAPTIVE_MULTI_USER = TRUE
-- PARALLEL_AUTOMATIC_TUNING = FALSE
-- If above parameters are different the setup needs to adjusted

-----------------------------
-- The setup
-----------------------------

alter system set parallel_max_servers = 4 parallel_adaptive_multi_user = true scope = memory;

drop package pkg_recursive_query;

drop table t_parallel_index purge;

drop table t_driver purge;

create table t_parallel_index (
id integer not null,
large_vc varchar2(200),
pkey integer not null
)
partition by range (pkey)
(
partition pkey_0 values less than (1),
partition pkey_1 values less than (2),
partition pkey_2 values less than (3)
);

create index t_parallel_index_idx on t_parallel_index (id) local parallel 2;

exec dbms_random.seed(0)

insert into t_parallel_index (
id
, large_vc
, pkey
)
select
rownum as id
, dbms_random.string('X', 100)
, 1
from
dual
connect by
level <= 10000;

commit;

insert into t_parallel_index (
id
, large_vc
, pkey
)
select
rownum as id
, dbms_random.string('X', 100)
, 2
from
dual
connect by
level <= 10000;

commit;

exec dbms_stats.gather_table_stats(null, 't_parallel_index')

explain plan for
select
large_vc
from
t_parallel_index
where
id = 2;

-- This is going to be a parallel index range scan by default
select * from table(dbms_xplan.display);

create table t_driver (
id integer not null,
pkey integer not null
);

alter table t_driver add constraint pk_t_driver primary key (id);

insert into t_driver (
id
, pkey
) values (
100
, 1
);

insert into t_driver (
id
, pkey
) values (
200
, 2
);

commit;

exec dbms_stats.gather_table_stats(null, 't_driver')

explain plan for
select /*+ opt_param('parallel_execution_enabled', 'true') */
f.large_vc
from
t_driver d
, t_parallel_index f
where
d.id = 100
and f.pkey = d.pkey
and f.id = 2;

-- This is again going to be a parallel index range scan by default
select * from table(dbms_xplan.display);

-- The user-defined function performing recursive SQL
create or replace package pkg_recursive_query
as
function get_value(p_f_id in integer, p_d_id in integer) return varchar2 parallel_enable;
end pkg_recursive_query;
/

create or replace package body pkg_recursive_query
as
function get_value(p_f_id in integer, p_d_id in integer) return varchar2 parallel_enable
as
s_value varchar2(200);
begin
select /*+ opt_param('parallel_execution_enabled', 'true') */
/* no_parallel_index(f) */
f.large_vc
into
s_value
from
t_driver d
, t_parallel_index f
where
d.id = p_d_id
and f.pkey = d.pkey
and f.id = p_f_id;

return 'SID: ' || sys_context('USERENV', 'SID') || '|' || s_value;
exception
when NO_DATA_FOUND then
s_value := 'SID: ' || sys_context('USERENV', 'SID') || '|<NO DATA FOUND>' ;
return s_value;
end get_value;
end pkg_recursive_query;
/

-----------------------------
-- The steps to perform
-----------------------------

-- First session
-- The main query is executed in parallel
-- Due to PARALLEL_ENABLE the recursive query is pushed into the parallel slaves
-- Being executed in the slaves forces serial execution of the recursive query
-- Keep the result set open to allocate the parallel slaves
set echo on pause on arraysize 1 pagesize 3 linesize 120

column result format a50 truncated

select /*+ parallel(t, 2) full(t) */
pkg_recursive_query.get_value(t.id, 100) as result
from
t_parallel_index t
where
id <= 50;

-- Second session
-- Simply allocate the second set of parallel slaves
-- Now all parallel slaves are allocated
-- Any further request for parallel execution will be downgraded to serial
set echo on

variable c refcursor

begin
open :c for '
select /*+ parallel(t, 2) full(t) */
*
from
t_parallel_index t
where
id <= 50
';
end;
/

-- Third session
-- The main query is now downgraded to serial
-- Now that the main query is serialized the recursive query potentially can get executed in parallel
-- But no parallel slaves are available so it shares the serial execution with the existing child cursor in the library cache
-- Keep the result set open
set echo on pause on arraysize 1 pagesize 3 linesize 120

column result format a50 truncated

select /*+ parallel(t, 2) full(t) */
pkg_recursive_query.get_value(t.id, 100) as result
from
t_parallel_index t
where
id <= 50;

-- Fourth session forces invalidation of child cursor for recursive query
alter table t_parallel_index truncate partition pkey_0;

-- Now close the second session to free parallel slaves
-- Further executions of the recursive subquery of session 3 will be performed in parallel
-- as long as parallel slaves are available otherwise it will be downgraded to serial