jump to navigation

PL/SQL bug with DBMS_RANDOM? October 8, 2015

Posted by mwidlake in bug, PL/SQL, SQL.
Tags: , , ,
7 comments

I think I’ve found an (admittedly obscure) bug with DBMS_RANDOM, group functions, PL/SQL and/or SQL.

Have a look and see if you also think this is odd – or have I missed the totally obvious?

(This is all on 12.1.0.2)

{Update – my conclusion is, and thanks to Joel and Sayan for their comments, that this is not a “bug”. Oracle do not promise us how PL/SQL functions are executed due to the way SQL can be re-written by the parser. I think most of us stumbling over something like this would treat it as a bug though. You have to look at the column projection, again see the comments, to see how Oracle is deciding to get the columns derived by a naked call to DBMS_RANDOM.VALUE (by naked I mean no inclusion of parameters passed in and, significantly, no reference to columns). It’s just the way it is}

Without going into the details (we would be here for hours if I did) I’m looking into the overhead of context switching between PL/SQL and SQL. It it fairly common knowledge that when you call a PL/SQL function from SQL there is a context switch when the SQL engine hands over control to the PL/SQL engine. I’ve been doing some work into how much the overhead is and that it is incurred for each distinct PL/SQL function (plus loads of other considerations around it).

In doing so I saw something unexpected (to me, anyway) which I have simplified down to this:

select /* mdw_z1 */ avg(dbms_random.value) avg_dbrav1,avg(dbms_random.value) avg_dbrav2
      ,max(created) max_cre
from all_objects
where rownum <50000

AVG_DBRAV1 AVG_DBRAV2 MAX_CRE
---------- ---------- -----------------
.502234063 .502234063 11-SEP-2014 09:31
Elapsed: 00:00:00.89

Note that the two averages of DBMS_RANDOM.VALUE are exactly the same. It is so improbably as to be pretty much impossible that over all those rows, the different random values generated for each column add up to exactly the same. They are getting the same values for each row. I’m very, very dubious of any “identical seeding” issue (ie they both get the same seed and from then provide identical values) as even if DBMS_RANDOM is basing it’s output on something like initial seed, SCN of statement and number of iterations, it is still being referenced twice for each row.

Some further evidence is that when I increase the number of calls to DBMS_RANDOM the elapsed time is almost identical and the statement CPU and PLSQL_EXEC_TIME (pulled from V$SQL) do not increase in any significant way (PLSQL_EXEC_TIME actually goes down):

select /* mdw_z2 */ avg(dbms_random.value) avg_dbrav1,avg(dbms_random.value) avg_dbrav2
       ,avg(dbms_random.value) avg_dbrav3,avg(dbms_random.value) avg_dbrav4
       ,avg(dbms_random.value) avg_dbrav5,avg(dbms_random.value) avg_dbrav6
      ,max(created) max_cre
from all_objects
where rownum <50000

AVG_DBRAV1 AVG_DBRAV2 AVG_DBRAV3 AVG_DBRAV4 AVG_DBRAV5 AVG_DBRAV6 MAX_CRE
---------- ---------- ---------- ---------- ---------- ---------- -----------------
.500367568 .500367568 .500367568 .500367568 .500367568 .500367568 11-SEP-2014 09:31
Elapsed: 00:00:00.84 -- (cf .89 before)

-- information about the two SQL statements from v$SQL, identified by my comments
SQL_ID        PLAN_HASHV  PRSE  EXCS     BUFFS DISCS     CPU_T PLSQL_EXEC    RWS
------------- ---------- ----- ----- --------- ----- --------- ---------- ------
SQL_TXT
--------------------------------------------------------------------------------
4y4jsj7uy12t3 1587414607     1     1     41481     0    843750     312691      1
select /* mdw_z2 */ avg(dbms_random.value) avg_dbrav1,avg(dbms_random.value) avg
gpdga3qars8p2 1587414607     1     1     41481     0    828125     316648      1
select /* mdw_z1 */ avg(dbms_random.value) avg_dbrav1,avg(dbms_random.value) avg

I’ve verified that adding other PL/SQL calls adds about 0.4 seconds to the execution time per extra (simple) PL/SQL function and you see the CPU Time and PLSQL_EXEC_TIME increase.

It is as if Oracle realises the call to DBMS_RANDOM is the same and so does it once per row and puts the results into each column. It does this for other deterministic PL/SQL functions but I would (a) be worried if DBMS_RANDOM was being treated as deterministic (as it’s purpose is to NOT be deterministic) and (b) I know I have used DBMS_RANDOM to generate test data many times, often for several columns in my generating SQL SELECT statement, and I never noticed this before. So, I decided to check that it was only returning 1 value per row to populate the results for each column derived from DBMS_RANDOM.VALUE:


select dbms_random.value drv1, dbms_random.value drv2,created
from all_objects where rownum < 6

      DRV1       DRV2 CREATED
---------- ---------- -----------------
.341919389 .020497964 11-SEP-2014 08:40
.569447631 .727672346 11-SEP-2014 08:40
.019986319 .709239586 11-SEP-2014 08:40
.286970852 .144263004 11-SEP-2014 08:40
 .14440676 .538196808 11-SEP-2014 08:40

Huh? That rather damages my theory and actually works the way I expected, hoped for and thought I remembered. And you can just look at the two columns and you know they are not going to add up to exactly the same! (the last digit adds up to 21 for DRV1 , 28 for DRV2) {How many of you checked that and got 27 for DRV1?}.

So I wrote some code that should be logically identical to my original SQL statement but does the data collection “manually”:

with source as
(select /*+ materialize */
        dbms_random.value  dbrav1    ,dbms_random.value dbrav2
       ,created
from all_objects
where rownum <50000
)
select/* mdw_z3 */ avg(dbrav1)  avg_dbrav1     ,avg(dbrav2)  avg_dbrav2
      ,max(created)  max_cre
from source

AVG_DBRAV1 AVG_DBRAV2 MAX_CRE
---------- ---------- -----------------
.497954489 .497633494 11-SEP-2014 09:31

Elapsed: 00:00:00.96

As you can see, all I do is force the data to be collected into an internal temporary table using the WITH clause and hint it to stop oracle merging the code together and then average the columns. And now I get two different values for the two DBMS_RANDOM.VALUE derived columns.

This version of the code also accrues more runtime and statement CPU/PLSQL_EXEC_TIME, as I mentioned above, when I add more PL/SQL calls. In the below the extended list of “columns” version takes 1.78 seconds, CPU time increases from 843,750 microseconds to 1,703,125 and PLSQL_EXEC_TIME increases from 316,589 microseconds to 917,208

with source /*2 */ as
(select /*+ materialize */
        dbms_random.value  dbrav1    ,dbms_random.value dbrav2
       ,dbms_random.value  dbrav3    ,dbms_random.value dbrav4
       ,dbms_random.value  dbrav5    ,dbms_random.value dbrav6
       ,created
from all_objects
where rownum <50000
)
select/* mdw_z4 */ avg(dbrav1)  avg_dbrav1     ,avg(dbrav2)  avg_dbrav2
      ,avg(dbrav3)  avg_dbrav3     ,avg(dbrav4)  avg_dbrav4
      ,avg(dbrav5)  avg_dbrav5     ,avg(dbrav6)  avg_dbrav6
      ,max(created)  max_cre
from source

AVG_DBRAV1 AVG_DBRAV2 AVG_DBRAV3 AVG_DBRAV4 AVG_DBRAV5 AVG_DBRAV6 MAX_CRE
---------- ---------- ---------- ---------- ---------- ---------- -----------------
.499007362 .501985119 .498591643  .50252316  .49939127  .49804233 11-SEP-2014 09:31

Elapsed: 00:00:01.78

--
--
SQL_ID        PLAN_HASHV  PRSE  EXCS     BUFFS DISCS     CPU_T PLSQL_EXEC    RWS
------------- ---------- ----- ----- --------- ----- --------- ---------- ------
SQL_TXT
--------------------------------------------------------------------------------
49zjaaj41dg00 3034557986     1     1     43465   962   1703125     917208      1
with source /*2 */ as (select /*+ materialize */         dbms_random.value  dbra
0rtbx97f14b0k 3034557986     1     1     42294   382    843750     316586      1
with source as (select /*+ materialize */         dbms_random.value  dbrav1    ,

I did have the execution plans in here too but the post is already quite long. They are identical though, as is shown by the same value of 3034557986 for the PLAN_HASH_VALUE for both statements

So in Summary, the below two versions of the (logically identical as far as I can see) code give different results. The difference is that one is allowing Oracle to do the averaging natively and in the other I am forcing the data to be collected into an internal temporary table and then averaged:

select /* mdw_z1 */ avg(dbms_random.value) avg_dbrav1,avg(dbms_random.value) avg_dbrav2
      ,max(created) max_cre
from all_objects
where rownum <50000

AVG_DBRAV1 AVG_DBRAV2 MAX_CRE
---------- ---------- -----------------
.502234063 .502234063 11-SEP-2014 09:31

with source as
(select /*+ materialize */
        dbms_random.value  dbrav1    ,dbms_random.value dbrav2
       ,created
from all_objects
where rownum <50000
)
select/* mdw_z3 */ avg(dbrav1)  avg_dbrav1     ,avg(dbrav2)  avg_dbrav2
      ,max(created)  max_cre
from source

AVG_DBRAV1 AVG_DBRAV2 MAX_CRE
---------- ---------- -----------------
.497954489 .497633494 11-SEP-2014 09:31

If no one can explain what I am missing, I suppose I should raise a bug with Oracle. Which could be tricky seeing as my access to MyOracleSupport is a bit tenuous…

In case you want to play, this is my whole test script, which does everything but query V$SQL for the statement stats at the end. I am sure you can manage that yourselves…

-- the two columns from dbms_random get the same result - which I did not expect
select /* mdw_z1 */ avg(dbms_random.value) avg_dbrav1,avg(dbms_random.value) avg_dbrav2
      ,max(created) max_cre
from all_objects
where rownum <50000
/

select /* mdw_z2 */ avg(dbms_random.value) avg_dbrav1,avg(dbms_random.value) avg_dbrav2
       ,avg(dbms_random.value) avg_dbrav3,avg(dbms_random.value) avg_dbrav4
       ,avg(dbms_random.value) avg_dbrav5,avg(dbms_random.value) avg_dbrav6
      ,max(created) max_cre
from all_objects
where rownum <50000
/
--
-- The below forces oracle to gather the data into an internal temporary table first.
-- and then I average that
with source as
(select /*+ materialize */
        dbms_random.value  dbrav1    ,dbms_random.value dbrav2
       ,created
from all_objects
where rownum <50000
)
select/* mdw_z3 */ avg(dbrav1)  avg_dbrav1     ,avg(dbrav2)  avg_dbrav2
      ,max(created)  max_cre
from source
/
-- and now I make it do more executions against dbms_random, to see if makes a difference
-- which will lend support to my idea it is doing more contect switching.
with source /*2 */ as
(select /*+ materialize */
        dbms_random.value  dbrav1    ,dbms_random.value dbrav2
       ,dbms_random.value  dbrav3    ,dbms_random.value dbrav4
       ,dbms_random.value  dbrav5    ,dbms_random.value dbrav6
       ,created
from all_objects
where rownum <50000
)
select/* mdw_z4 */ avg(dbrav1)  avg_dbrav1     ,avg(dbrav2)  avg_dbrav2
      ,avg(dbrav3)  avg_dbrav3     ,avg(dbrav4)  avg_dbrav4
      ,avg(dbrav5)  avg_dbrav5     ,avg(dbrav6)  avg_dbrav6
      ,max(created)  max_cre
from source
/

Skipped Initial Sequence Value on Oracle 11.2 November 17, 2011

Posted by mwidlake in bug, Testing.
Tags: , ,
4 comments

I’m seeing an oddity with newly created sequences skipping the initial value. ie I create the sequence and the first use of it returns the value 2, not 1.

{update, see the post comments and this post by Niall – this is a side effect of delayed segment creation – the first insert silently fails, but gets the sequence, and is repeated behind the scenes once the segment is there. It is fixed in 11.2.0.3, my db is at 11.2.0.1 as I got sick of the download of the latest version failing on my poor broadband connection and got it off a mate – turns out it is not the latest version.
Thanks for the enlightenment Niall.}

This is on Oracle 11.2.0.1 on Windows (XP, Vista and now Windows 7 64 bit). I am sure I did not see this on Oracle 10.1 and 10.2 on linux, Tru64 and windows.

I create a set of test tables for when I run courses or just want to test some things, a few tables holding people, names, addresses, phone calls and monthly call summaries. I do this with a bunch of pretty crude scripts that create the data in steps. Only on Oracle 11.2 it all stopped working. I tracked down the problem to the skipping of the first value for the first sequence I create and use. I’ve just confirmed this on a new server I have created.

I’ve boiled it down to the following test case. I ensure my test table and two sequences are not there, create them and then insert 10 records for men and 10 for women. For the women the records are numbered 1 to 10. For the men they are numbered 2 to 11!!!

My code:

-- seq_oddity.sql
-- BUG ON 11.2.0.1 ??
-- though I create both sequences afresh, the first use of seq_m is getting 2, yes two!
-- cannot work out why, so fixed by setting the row with forn_id of 130 to 1.
set timi off
spool seq_oddity.lst
--
drop table test_fn purge;
drop sequence seq_m;
drop sequence seq_f;
create table test_fn
(forn_id number(5) not null
,forname varchar2(30) not null
,sex_ind char(1) not null)
tablespace users
/
create sequence seq_m;
create sequence seq_f;
insert into test_fn values (seq_m.nextval,'ALAN','M');
exec dbms_output.put_line ('I have just created male name number '||seq_m.currval);
insert into test_fn values (seq_m.nextval,'BARRY','M');
insert into test_fn values (seq_m.nextval,'CHRIS','M');
insert into test_fn values (seq_m.nextval,'DAVID','M');
insert into test_fn values (seq_m.nextval,'EDWARD','M');
insert into test_fn values (seq_m.nextval,'JANG','M');
insert into test_fn values (seq_m.nextval,'GARY','M');
insert into test_fn values (seq_m.nextval,'HARRY','M');
insert into test_fn values (seq_m.nextval,'IAN','M');
insert into test_fn values (seq_m.nextval,'JAMES','M');
exec dbms_output.put_line ('I created 10 men and last value was '||seq_m.currval);
--
--
--
insert into test_fn values (seq_f.nextval,'ALISON','F');
exec dbms_output.put_line ('I have just created female name number '||seq_f.currval);
insert into test_fn values (seq_f.nextval,'BARBARA','F');
insert into test_fn values (seq_f.nextval,'CHERYL','F');
insert into test_fn values (seq_f.nextval,'DAWN','F');
insert into test_fn values (seq_f.nextval,'ELAINE','F');
insert into test_fn values (seq_f.nextval,'FRANCIS','F');
insert into test_fn values (seq_f.nextval,'GILLIAN','F');
insert into test_fn values (seq_f.nextval,'CHERRY','F');
insert into test_fn values (seq_f.nextval,'INGRID','F');
insert into test_fn values (seq_f.nextval,'JANET','F');
exec dbms_output.put_line ('I created 10 women and last value was '||seq_f.currval);
--
select sex_ind,min(forn_id),max(forn_id)
from test_fn
group by sex_ind/
--
spool off

The results are:

mdw11> @seq_oddity
drop table test_fn purge
           *
ERROR at line 1:
ORA-00942: table or view does not exist

drop sequence seq_m
              *
ERROR at line 1:
ORA-02289: sequence does not exist

drop sequence seq_f
              *
ERROR at line 1:
ORA-02289: sequence does not exist

Table created.

Sequence created.

Sequence created.

1 row created.

I have just created male name number 2

1 row created.
1 row created.
...
1 row created.

I created 10 men and last value was 11


1 row created.

I have just created female name number 1

1 row created.
1 row created.
...
1 row created.
I created 10 women and last value was 10


S MIN(FORN_ID) MAX(FORN_ID)
- ------------ ------------
M            2           11
F            1           10
2 rows selected.

mdw11>

I suppose I should trace this and check for known oracle bugs but I wondered if anyone else had seen it.

Missing SQL in AWR/ASH February 23, 2010

Posted by mwidlake in AWR, performance.
Tags: , , ,
3 comments

I’ve been working on some demonstrations of AWR/ASH within OEM for a client and I’ve come across a situation where you can be missing the SQL (and thus a lot of the useful information) for code run via DBMS_JOB or DBMS_SCHEDULER.

This is due to bugs 5928612.8 for DBMS_JOB and 5140631.8 for DBMS_SCHEDULER. If you can’t access metalink, then check out the end of this webpage. The SQL_ID/SQL_HASH_VALUE is not populated in V$SESSION for those jobs running under DBMS_JOB or DBMS_SCHEDULER. I am presuming from the fact that V$SESSION is not updated with these values, it is not available to V$ACTIVE_SESSION_HISTORY.

I did check that the SQL_ID was null in V$ACTIVE_SESSION_HISTORY for the records that connected to the USER_ID I was using, except for the handful of entries for when I was testing my code manually before running it via DBMS_JOB. The SQL_ID was captured fine for these interactive sessions (and the code executed was identical).

The bugs appear in 10.1.0.2 and both are fixed in 10.2.0.4 and 11. Both have patches available.
I am using 10.2.0.3

As soon as I mentioned my woes about not being able to see the SQL for code I was running via DBMS_JOB I knew of the existence of the bugs, as colleagues mentioned being aware of them as the patches have been applied to a couple of the other systems. However, I could find no trace of them on Metalink or Google.These bugs are listed as against v$session, not AWR or ASH, which is why I could not find them via searches for “missing sql awr” or missing sql ash” etc. So hopefully this posting will allow the connection to be made.

I find it very vexing when you know there is a fix for an oracle problem but you can’t find it in metalink (which seems even more true with the new, all-singing all-dancing all-fancy-graphics little help metalink). Sometimes it is because the bug number is not being made publically available and in other cases, such as this one, it is because no one has made the connection between the initial problem and other things it could impact. I guess it is asking a lot of Oracle Corp to do this for us and it would be unreasonable of us to hold it against them – But they are supposed to be a blooming data, information and knowledge expertise company! Tsch.

As an example of what I see in AWR with my workload, generated via DBMS_JOB {and I’m sorry it is so small, you should be able to click on it and get a full-size version}:

Notice that the top five jobs are via user MDW_2. I know that none of the top SQL on the left is from my workload (you will have to just take my work, but it is, in fact, all the “OEM/AWR code:-) ). Also, the top code shown is heave on green for CPU, but you can see most of the workload in the Top Activity and the Top Sessions is blue, for User IO.

If I pick out the top session, 545, and click on it I get the below screen:

Note the entry for SQL_ID is blank and SQL Command is “UNKNOWN”. I can see what it is doing (db_file_scattered read and some CPU) but not what on or why.😦

Follow

Get every new post delivered to your Inbox.

Join 221 other followers