THE Q U A D R O BLOG

Latch: row cache objects, session_cached_cursors and a database link

noreply@blogger.com (Alex Fatkulin) — Thu, 02 Feb 2012 01:08:00 +0000

What could possibly be common about the above things?

Sometime ago I was involved in tuning a large scale production system which experienced quite a lot of latch contention. In fact the contention was bad enough as to render the entire system unusable during peak hours.

A typical AWR report during times with moderate workload looked like this:

Event                      Waits           Time(s) Avg wait (ms)   % DB time  Wait Class
DB CPU                     21,805          36.95  
latch: row cache objects   14,524,462      11,552  1               19.57      Concurrency
db file sequential read    2,697,778       8,988   3               15.23      User I/O
gc current block 3-way     4,202,356       3,599   1               6.10       Cluster
gc current block 2-way     3,670,293       2,330   1               3.95       Cluster

(in reality it was a 7-node RAC cluster but it is not really relevant to our subject).

It is not hard to spot latch: row cache objects on a second place consuming almost 20% of DB time. This event was rapidly escalating whether load increased quickly bringing the entire cluster into unusable state as far as any front-end application were concerned. The total number of gets during an hour (the interval with which this particular AWR report had been made) totaled 1,281,167,103 which averages a whopping 355,879 gets per second!

The first step was to take a look at the Dictionary Cache statistics and see if there were any obvious deviations:

Cache                   Get Requests    Pct Miss
dc_awr_control          72              9.72
dc_database_links       124,452         0.05
dc_files                46,900          17.14
dc_global_oids          555,599         0.07
dc_histogram_data       8,962,576       1.01
dc_histogram_defs       412,885,094     0.02
dc_object_grants        52,475          1.13
dc_objects              2,860,222       0.64
dc_profiles             61,189          0.01
dc_rollback_segments    392,885         0.00
dc_segments             657,653         7.72
dc_sequences            1,324           67.67
dc_table_scns           3,206           3.31
dc_tablespaces          1,253,322       0.06
dc_users                5,475,824       0.02
global database name    65,092          0.01
kqlsubheap_object       10,910          0.46
outstanding_alerts      721             95.98

dc_histogram_defs really stands out but so far provides no direct clues. Though the entire dictionary cache seems to be quite busy. Let's take a look at instance activity statistics:

                  Per Second   Per Transaction  Per Exec        Per Call
DB Time(s):       16.4         0.5              0.00            0.00
DB CPU(s):        6.1          0.2              0.00            0.00
Redo size:        87,543.5     2,398.6
Logical reads:    336,555.7    9,221.2
Block changes:    449.3        12.3
Physical reads:   1,018.3      27.9
Physical writes:  36.8         1.0
User calls:       41,250.4     1,130.2
Parses:           6,264.4      171.6
Hard parses:      27.1         0.7
W/A MB processed: 33,769,202.4 925,233.0
Logons:           18.3         0.5
Executes:         14,230.5     389.9
Rollbacks:        3.4          0.1
Transactions:     36.5

A couple of things to notice:

The number of executions is not that high (at least for an IBM box with 56 CPU cores, that is).
Execute to Parse ratio is not particularly good nor bad (6,264.4 parses per second compared to 14,230.5 executions).
None of the above seems to be enough to justify 355,879 latch: row cache objects gets per second, even when you consider 27.1 hard parses/sec.

There had to be more going on. Looking at the SQL ordered by Parse Calls section of the report revealed that all the top parsing queries were coming from a database link. Which prompted me to ask additional questions...

It turned out that the system had a somewhat weird architecture. A 7-node RAC cluster served as a back end to a numerous front-end Oracle databases which were essentially acting as PL/SQL-engines, accessing all the data through the database link while dong all the processing. The architectural feasibility of such solution is debatable (to say the least) but let's not steer away from the main topic of our discussion.

I geared to find out whether there was some special case which could cause latch: row cache objects to shoot through the roof when we deal with a lot of queries executed through a database link. After a number of experiments I eventually found a cause which explains the title of this blog post.

Take a look at the following example:

SQL> declare
  2   l_gets number;
  3  begin
  4   select gets into l_gets from v$latch@dblink where name='row cache objects';
  5  
  6   for i in 1 .. 1000
  7   loop
  8    for cur in (select null from dual@dblink) loop null; end loop;
  9   end loop;
 10  
 11   select sum(gets)-l_gets into l_gets from v$latch@dblink where name='row cache objects';
 12   dbms_output.put_line(to_char(l_gets));
 13  end;
 14  /
 
79
 
PL/SQL procedure successfully completed

Accessing a remote table 1000 times through a database link only caused 79 row cache objects gets on the destination database. However, exactly the same example can produce quite a different result:

SQL> alter session set session_cached_cursors=0;
 
Session altered
 
SQL> 
SQL> declare
  2   l_gets number;
  3  begin
  4   select gets into l_gets from v$latch@dblink where name='row cache objects';
  5  
  6   for i in 1 .. 1000
  7   loop
  8    for cur in (select null from dual@dblink) loop null; end loop;
  9   end loop;
 10  
 11   select sum(gets)-l_gets into l_gets from v$latch@dblink where name='row cache objects';
 12   dbms_output.put_line(to_char(l_gets));
 13  end;
 14  /
 
3082
 
PL/SQL procedure successfully completed

Now we jumped from 79 gets to 3082 which is a 39x increase! What's really astonishing is the fact that it's a cursor cache miss on the source which wreaks havoc on the destination. Evidently, the solution to the problem had nothing to do with the database where the problem was observed. The "PL/SQL-databases" had an insufficient setting for session_cached_cursors and once that was corrected the issue disappeared.

It is somewhat ironic that that problem would have never appears had the data and PL/SQL be allowed to be kept in the same database (where they belong).

Oracle GoldenGate and undocumented OCI redo log APIs

noreply@blogger.com (Alex Fatkulin) — Wed, 06 Apr 2011 00:23:00 +0000

Last time I did some quick write up on the new APIs appeared in Oracle GoldenGate 11G which can be used against Oracle 10.2.0.5 and 11.2.0.2 to improve how GG handles redo on ASM.

Some of the items still required follow up, namely:

What are the names of these new API functions?
What kind of security privileges do you need to call these?

I was especially interested in the last item since the ability to read Oracle's redo log gives you extremely powerful access to database information.

New OCI APIs

Discovering these is pretty straightforward, all we need to do is a stack dump on a running GG Extract process:

[oracle@quadro.com ~]$ pstack 4390
...
#10 0x00002acc23443ef0 in knxOGGRedoLogRead () from /u01/app/oracle/ggs_11g/libclntsh.so.11.1
#11 0x00002acc232a9b3b in OCIPOGGRedoLogRead () from /u01/app/oracle/ggs_11g/libclntsh.so.11.1
#12 0x00000000008fa92c in ASMReader2::readFile(unsigned int, unsigned int, unsigned int*, char*, char*) ()
...

Once we know the name of the read function (OCIPOGGRedoLogRead) we can find the rest of them:

[oracle@quadro.com ~]$ nm /u01/app/oracle/ggs_11g/libclntsh.so.11.1 | grep OCIPOGG
00000000010e3954 T OCIPOGGRedoLogClose
00000000010e3c90 T OCIPOGGRedoLogOpen
00000000010e3a2a T OCIPOGGRedoLogRead

As you can see, these functions are indeed exposed directly through libclntsh library. We can even see the Extract process "in action" calling these functions with the help of Linux's gdb:

[oracle@quadro.com ~]$ ps -aef | grep extract
oracle    4390  4386  0 19:36 ?        00:00:00 /u01/app/oracle/ggs_11g/extract PARAMFILE /u01/app/oracle/ggs_11g/dirprm/11g_ext.prm REPORTFILE /u01/app/oracle/ggs_11g/dirrpt/11G_EXT.rpt PROCESSID 11G_EXT USESUBDIRS
oracle    4985  4114  0 19:51 pts/2    00:00:00 grep extract
[oracle@quadro.com ~]$ gdb /u01/app/oracle/ggs_11g/extract -p 4390
...
(gdb) break OCIPOGGRedoLogClose
Breakpoint 1 at 0x2acc232a9958
(gdb) break OCIPOGGRedoLogOpen
Breakpoint 2 at 0x2acc232a9c94
(gdb) break OCIPOGGRedoLogRead
Breakpoint 3 at 0x2acc232a9a2e
(gdb) info break
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x00002acc232a9958 
2       breakpoint     keep y   0x00002acc232a9c94 
3       breakpoint     keep y   0x00002acc232a9a2e

After we've sat up our breakpoints we can let the Extract run and hit one of these:

(gdb) continue
Continuing.

Breakpoint 3, 0x00002acc232a9a2e in OCIPOGGRedoLogRead ()
   from /u01/app/oracle/ggs_11g/libclntsh.so.11.1

(gdb) bt
#0  0x00002acc232a9a2e in OCIPOGGRedoLogRead ()
   from /u01/app/oracle/ggs_11g/libclntsh.so.11.1
#1  0x00000000008fa92c in ASMReader2::readFile (this=0xa408100,
    offset=, bytes_to_read=1024000,
    bytes_read=0x7fffb8c73ad4, buffer=0xabc0000 "\001\"", errtext=0xc457c0 "")
    at /home/ecloud/workspace/Build_FBO_OpenSys_r11.1.1.0.0_078_[34086]/perforce/src/app/er/redo/oracle/asm.c:798
...

On top of the stack we can see GoldenGate making a call to OCIPOGGRedoLogRead. We can also get a sense of parameters by looking at the calling function (ASMReader2::readFile). The function specifies how many bytes it would like to read (bytes_to_read=1024000), a pointer to a variable which will hold the actual amount read (bytes_read=0x7fffb8c73ad4), a pointer to a buffer to store the returned redo data (buffer=0xabc0000) and the error text, if any (errtext=0xc457c0).

Now it is time to see the other two functions usage. What I did is switched the redo logs in my database, disabled breakpoint number 3 (the one which points to OCIPOGGRedoLogRead) and let the Extract process continue:

(gdb) disable 3

(gdb) continue
Continuing.

Breakpoint 2, 0x00002acc232a9c94 in OCIPOGGRedoLogOpen ()
   from /u01/app/oracle/ggs_11g/libclntsh.so.11.1
(gdb) bt
#0  0x00002acc232a9c94 in OCIPOGGRedoLogOpen ()
   from /u01/app/oracle/ggs_11g/libclntsh.so.11.1
#1  0x00000000008fa859 in ASMReader2::openFile (this=0xa408100,
    filename=0xa408350 "+DATA/ora11gr2/onlinelog/group_3.258.743164441",
    lblksize=, blksize=0x0, tot_blks=0x0,
    filetype=, errtext=0xc457c0 "")
    at /home/ecloud/workspace/Build_FBO_OpenSys_r11.1.1.0.0_078_[34086]/perforce/src/app/er/redo/oracle/asm.c:762
...

Interestingly enough we never made a call to OCIPOGGRedoLogClose. Maybe I should open an Oracle SR and complain :)

As before, we can get a glimpse of parameters which include redo log file name as well as bunch of output parameters specifying the block size and so on (which looks somewhat similar to what you get from dbms_diskgroup.open call).

Security

Looking at how all this stuff is being exposed through OCI, I became even more eager to find out what kind of privileges do you require on the database side in order to be able to use these. The first step was to try and run the Extract process with stripped out privileges which thankfully resulted in the following error:

2011-04-05 20:10:36  ERROR   OGG-00446  Opening ASM file +DATA/ora11gr2/onlinelog/group_3.258.743164441 in DBLOGREADER mode: (1031) ORA-01031: insufficient privilegesNot able to establish initial position for sequence 398, rba 1040.

At least there is something but what exactly is it? GoldenGate's documentation (should I add "as usual?") doesn't mention anything in that regards so I had to figure that one out on my own.

After some back and forth I was able to eventually discover the privilege which makes it all possible -- it's select any transaction. Alas it is not documented to play this role but now you know anyway.

Oracle GoldenGate, ASM and DBLOGREADER option

noreply@blogger.com (Alex Fatkulin) — Sat, 05 Mar 2011 18:21:00 +0000

Some time ago I did a write up detailing how Oracle GoldenGate interacts with Oracle ASM. The technology stack where the Extract process establishes a connection with the ASM instance and then reads file contents using dbms_diskgroup package is quite cumbersome to say the least. When compared to how GG reads redo from a filesystem (detailed here), the way GG has to deal with ASM is quite inefficient to say the least. In fact, as part of my original article, the recommendation was to use a bequeath connection when possible to cut on the amount of overhead. Nowadays the use of bequeath connection became an official recommendation from Oracle outlined in Oracle GG 11G Release Notes.

DBLOGREADER

I was quite excited to see that Oracle made some progress in it's newer release of GoldenGate (11.1). Here is what the documentation says about the new option:

A new DBLOGREADER option was added to TRANLOGOPTIONS to enable Extract to use a
newer API for capturing from an Oracle ASM instance. This feature is available as of Oracle
10.2.0.5.

This was indeed promising, however, what exactly has changed remained to be discovered.

The first change you're going to notice when using DBLOGREADER is that the Extract process establishes a connection with the RDBMS instance (not an ASM instance). If you trace the relevant server side process then you'll observer the following event being emitted each time it reads from the redo:

WAIT #0: nam='log file sequential read' ela= 3 log#=0 block#=102653 blocks=2000 obj#=-1 tim=1299345636565911

One of the advantages of the new option is the ability to use a much larger buffer (the old mechanism was limited to something around 28K which is abysmal for any system with even moderate redo generation rate). As we can see from the above, we had 2000x512=1000K worth of data read in one shot so at least that part works as advertised. But how is it done?

A stack dump reveals the following:

[oracle@ora11gr2 ggs_11g]$ pstack 4740
#1  0x00000000090bae87 in sskgpwwait ()
#2  0x00000000090b9f9a in skgpwwait ()
#3  0x0000000008d29f93 in ksliwat ()
#4  0x0000000008d29541 in kslwaitctx ()
#5  0x0000000008d269ab in kslwait ()
#6  0x00000000071f8566 in knloggRedoRead ()
#7  0x00000000071f9e05 in knloggmain ()
#8  0x0000000008eae67a in opiodr ()
#9  0x00000000090467f9 in ttcpip ()
#10 0x0000000001722f86 in opitsk ()
#11 0x0000000001727c26 in opiino ()
#12 0x0000000008eae67a in opiodr ()
#13 0x000000000171eedc in opidrv ()
#14 0x0000000001d95f5f in sou2o ()
#15 0x0000000000a07935 in opimai_real ()
#16 0x0000000001d9b408 in ssthrdmain ()
#17 0x0000000000a078a1 in main ()

Look at the functions in line #6 and #7 (knloggmain() and knloggRedoRead()). These functions follow right after OPI (Oracle Program Interface) layer which makes this code path look rather efficient. No need to deal with compilation (KK) and execution (KX) layers. Just a direct and straightforward call to the functions we need. Indeed, when I did some quick and dirty tests (using 11.2.0.2), the new code path was able to archive about 90% performance compared to just reading your redo from ext3 filesystem.

The only question I have about all this is a security paradigm behind knloggmain() calls. This function appears to be directly exposed through the OPI layer and, while this helps archive greater efficiency, how does it control who can who can not calls it? You may not necessarily want somebody connect to your database and start reading your redo stream as you may get all kinds of sensitive information right there. I haven't spent any time figuring that one out yet though.

Oracle GoldenGate Trail File Size

noreply@blogger.com (Alex Fatkulin) — Sun, 19 Dec 2010 19:54:00 +0000

When it comes to estimating how big your trail files will be, Oracle documentation suggests to use the following formula:

[log volume in one hour] x [number of hours downtime] x .4 = trail disk space

It is also described as being a conservative estimate so you are likely to archive a better mileage. What I found is that there are some corner cases which can produce some "anomaly" results.

Test Case

I'll start with a specially crafted schema and table names as well as data:

create user uuuuuuuuuuuuuuuuuuuuuuuuuuuuuu identified by "u";

User created.

SQL> grant resource to uuuuuuuuuuuuuuuuuuuuuuuuuuuuuu;

Grant succeeded.

SQL> create table uuuuuuuuuuuuuuuuuuuuuuuuuuuuuu.tttttttttttttttttttttttttttttt
  2  (
  3     n number primary key
  4  );

Table created.

SQL> alter table uuuuuuuuuuuuuuuuuuuuuuuuuuuuuu.tttttttttttttttttttttttttttttt
  2 add supplemental log data (primary key) columns;

Table altered.

I've just created a new trail file which is currently 974 bytes in size:

[oracle@gg1 dirdat]$ ls -l aa000000
-rw-rw-rw- 1 oracle oinstall 974 Dec 19 11:50 aa000000

What I'm going to do is insert some data into a table and then measure how much redo as well as trail data were generated:

SQL> set autot traceonly stat
SQL> insert into uuuuuuuuuuuuuuuuuuuuuuuuuuuuuu.tttttttttttttttttttttttttttttt
      select power(10,10)+(level-1)*power(10,10)
        from dual
        connect by level <= 10000;  2    3    4

10000 rows created.


Statistics
----------------------------------------------------------
        0  recursive calls
      329  db block gets
       31  consistent gets
        0  physical reads
     364612  redo size
      821  bytes sent via SQL*Net to client
      917  bytes received via SQL*Net from client
        3  SQL*Net roundtrips to/from client
        2  sorts (memory)
        0  sorts (disk)
      10000  rows processed

SQL> commit;

Commit complete.

Let's take a look at the trail file size:

[oracle@gg1 dirdat]$ ls -l aa000000
-rw-rw-rw- 1 oracle oinstall 1619890 Dec 19 13:40 aa000000

That is roughly 4.4 times bigger than our redo size and 11 times bigger than Oracle's "conservative" estimate. Your storage provisioning might be in for a surprise.

Trail File

To understand the key factors which resulted in our trail file to be of such outrageous size let's use logdump and take a look inside:

Logdump 11 >open ./dirdat/aa000000
Current LogTrail is /u01/app/oracle/ggs/dirdat/aa000000
Logdump 12 >ghdr on
Logdump 13 >next 2

2010/12/19 13:39:16.632.818 FileHeader           Len   966 RBA 0
Name: *FileHeader*
 3000 01b6 3000 0008 4747 0d0a 544c 0a0d 3100 0002 | 0...0...GG..TL..1...
 0002 3200 0004 2000 0000 3300 0008 02f1 bdfb 2d3e | ..2... ...3.......->
 74f2 3400 0028 0026 7572 693a 6767 313a 7175 6164 | t.4..(.&uri:gg1:quad
 726f 3a63 6f6d 3a3a 7530 313a 6170 703a 6f72 6163 | ro:com::u01:app:orac
 6c65 3a67 6773 3600 0025 0023 2f75 3031 2f61 7070 | le:ggs6..%.#/u01/app
 2f6f 7261 636c 652f 6767 732f 6469 7264 6174 2f61 | /oracle/ggs/dirdat/a
 6130 3030 3030 3037 0000 0101 3800 0004 0000 0000 | a0000007....8.......

___________________________________________________________________
Hdr-Ind    :     E  (x45)     Partition  :     .  (x04)
UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41)
RecLength  :    19  (x0013)   IO Time    : 2010/12/19 13:40:32.000.000
IOType     :     5  (x05)     OrigNode   :   255  (xff)
TransInd   :     .  (x00)     FormatType :     R  (x52)
SyskeyLen  :     0  (x00)     Incomplete :     .  (x00)
AuditRBA   :         45       AuditPos   : 37458516
Continued  :     N  (x00)     RecCount   :     1  (x01)

2010/12/19 13:40:32.000.000 Insert               Len    19 RBA 974
Name: UUUUUUUUUUUUUUUUUUUUUUUUUUUUUU.TTTTTTTTTTTTTTTTTTTTTTTTTTTTTT
After  Image:                                             Partition 4   G  b
 0000 000f 0000 000b 3130 3030 3030 3030 3030 30   | ........10000000000

The first record is a standard trail file header and is of little interest to us. We're going to take look at the second record. First of all, as you can see, we've got a fully qualified table name stored in there. We can see the inserted value as well. Now if all that stuff got stored in plain text that could explain it... let's check it out:

[oracle@gg1 dirdat]$ grep --binary-files=text -o -i \
> uuuuuuuuuuuuuuuuuuuuuuuuuuuuuu.tttttttttttttttttttttttttttttt \
> aa000000 \
> | wc -l
10000

Indeed, we've got a fully qualified table name appearing 10 thousand times on our trail file! The longer your schema and/or your table names are the bigger your trail file will be. The main reason Oracle Streams are using object identifiers (as well as Oracle's redo) is to avoid getting into exactly this kind of trouble. This makes GoldenGate configuration easier as it doesn't have to store the mapping information on the target database but you also have to pay the price with every row modification which gets captured.

The story doesn't end there, however. Let's take a look at the inserted data. How do you think that got stored?

[oracle@gg1 dirdat]$ grep --binary-files=text -o -i \
> 0000000000 \
> aa000000 \
> | wc -l
10000

That's right - all numbers got stored in plain text. The fundamental problem here is that trail file does not store data types. Everything just gets converted to strings. This helps dealing with heterogeneous data sources but also makes the storage for certain data types to be very inefficient. Again, you have to pay the price somewhere. If you gzip the above trail file you'll get a whopping 25x compression ratio.

You may ask yourself how column names are being stored? The answer is there are no column names in the trail file, just column positions. That's why GoldenGate requires column order to match between source and target databases, otherwise you'll get your data mapped to a wrong column. Add a lack of data types and you might be in for a very interesting results. If column order doesn't match then you'll have to use defgen to get your data across properly.

In a nutshell, watch out for tables/schemas with long names and lots of numeric data.

ASM Mirroring and Disk Partnership

noreply@blogger.com (Alex Fatkulin) — Tue, 20 Jul 2010 02:32:00 +0000

Let's say you have a RAID10 disk array with 50 disks. I'm offering you to play the following game. You'll spin a wheel of fortune divided into 50 equal slots with numbers ranging from 1 to 50. After you spun the wheel for the first time you'll write the resulted number down. After that I'll offer you to spin the second wheel of fortune equally divided into 49 slots where the number you've just pulled is missing (so you can't pull the same number twice).

After that you'll end up with two (mutually exclusive) random numbers in a range from 1 to 50. What I'm going to ask you do next is pull the disks with corresponding numbers out of your RAID10 array. What are the odds of your entire array going down?

In a classical RAID10 setup where every drive is being mirrored by a single other drive you can calculate the probability in a straightforward fashion. After you've pulled the first drive out (doesn't matter which one) there is only one specific disk out of 49 which you have to pull in order for the entire array to go bust. So your odds of taking the entire array down will be 1/49 or roughly 2%.

Now let's say that instead of a regular RAID10 array you've got a normal redundancy ASM disk group with two failure groups (25 disks each). What are the odds now?

ASM Mirroring

Before we're going to answer the above question we need to realize that ASM does not mirror disks the same way traditional RAID10 does. In fact it doesn't mirror disks at all. It mirrors extents instead. For all you know is that the extents from the disk you've just pulled out won't be mirrored in the same failure group. So that leaves us with 24 disks as safe. But what about the other 25 disks from the other failure group? How much of these disks are unsafe and will result in your normal redundancy disk group going south?

Disk Partnership

When mirroring extents ASM uses a concept called Disk Partnership. Every disk in a normal redundancy disk group has one or more partners which are used to mirror primary extents from that disk. This also means that the loss of any of the partner disks is fatal to the disk group as you'll nuke both the primary extent and it's mirror copy (keep in mind that we're talking about pulling both disks out before the disk group would be able to rebalance). At least now we know what we need next in order to solve the puzzle. We need to find out how many partners each of the disks in our array have.

Disk Partners

Let's say that the first disk we've pulled out was disk number 0. The following query can be used to find all partners for the disk number 0 in a first disk group:

SQL> select p.number_kfdpartner, d.FAILGROUP
        from x$kfdpartner p, v$asm_disk d
        where p.disk=0
                and p.grp=1
                and p.grp=group_number
                and p.number_kfdpartner=d.disk_number;  2    3    4    5    6

NUMBER_KFDPARTNER FAILGROUP
----------------- ------------------------------
               25 FG2
               26 FG2
               27 FG2
               29 FG2
               38 FG2
               46 FG2
               48 FG2
               49 FG2

8 rows selected.

Pulling any of the above disks out at the same time with the disk number 0 will be fatal for our normal redundancy disk group. In other words, once we pull the first disk out, there are other 8 disks out of 49 which are unsafe. That will bring our odds up (or down, depending in which outcome you're interested :) to 8/49 or a little bit more than 16%.

You can confirm that every disk has exactly 8 partners by running the following query:

SQL> select min(cnt), max(cnt) from (
select number_kfdpartner disk_number, count(*) cnt
        from x$kfdpartner
        where grp=1
        group by number_kfdpartner);  2    3    4    5

  MIN(CNT)   MAX(CNT)
---------- ----------
         8          8

Partner Disk Count

Is there any way to control the number of partner disks which ASM uses for extents mirroring? Turns out that there is. Note that it's a completely non supported operation so you shouldn't be playing with it.

The parameter which controls the maximum number of partner disks is called _asm_partner_target_disk_part. In 11GR2 that parameter has a default value of 8. I didn't have a chance to check it in a previous versions but supposedly it's default value there is 10(1). So at least we know that Oracle itself sometimes changes it between different releases.

All you need to do after changing this parameter is to rebalance the disk group:

SQL> alter system set "_asm_partner_target_disk_part"=2;

System altered.

SQL> alter diskgroup data rebalance;

Diskgroup altered.

SQL> select p.number_kfdpartner, d.FAILGROUP
        from x$kfdpartner p, v$asm_disk d
        where p.disk=0
                and p.grp=1
                and p.grp=group_number
                and p.number_kfdpartner=d.disk_number;  2    3    4    5    6
NUMBER_KFDPARTNER FAILGROUP
----------------- ------------------------------
               25 FG2
               38 FG2

So here it goes!

References

Oracle Automatic Storage Management: Under-the-Hood & Practical Deployment Guide
ASM Metadata and Internals

All test were performed with Oracle Grid Infrastructure 11.2.0.1

11GR2 Result Cache Scalability

noreply@blogger.com (Alex Fatkulin) — Wed, 09 Jun 2010 02:00:00 +0000

Result Cache in 11GR1

Two years ago I wrote a series of posts where I explained some of the dynamics around Result Cache latch. To recap, the result cache memory in 11GR1 is backed up by a single RC latch. That in itself wouldn't be so much of an issue (at least relatively to what we've got in reality) had the latch allowed for shared mode gets in case all you have to do is read from the result cache memory.

Alas, the latch turned out to be without shared mode gets. It is going almost without saying that, as concurrency levels increased, that single latch was behaving more and more like to a hand brake (link to a test I've done back then on a 8-way Itanium 2).

Back to the future

When 11GR2 has been released I knew that at some point in time I'll need to go back and revisit this subject. What I did is a couple of quick and dirty runs which came back confirming the same single latch and no shared mode gets so it didn't look like something has really changed. At this point I've decided to revisit it a bit later. This a "bit later" happened just recently.

How bad can it get?

What I wanted to do is get an UltraSPARC T2 and face it against Core i7 980X on a different concurrency levels in order to see how bad it can get. T2 will require quite a lot of parallelism in order to keep up even with a single i7 core. But since all we've got is a single RC latch, I've expected T2 to choke on it quite fast as not only there will be a lot of processes competing for the same latch, the slow single-threaded performance will cause the latch to be held for a much longer periods of time. Performance degradation will be dare.

Result Cache in 11GR2

I used the same test described here as it is targeted at exploiting RC latch weakness and gives me the ability to compare with the old results. I've used 250K lookup iterations. The performance was measured as a total number of lookups performed per second and RC latch statistics were captured for analysis.

Since 980X has 6 cores and 12 threads, the tests were done with 1 to 12 processes running at the same time which also gave an opportunity to see how well HT will scale. Note that I plan to do some further testing on T2 with up to 64 threads but for now I've tested up to 12 threads only as I couldn't get a test window big enough.

UltraSPARC T2 Results

# of processes	Buffer Cache	% linear	Result Cache	% linear
1	4426	100	4555	100
2	8930	100.88	9124	100.15
3	13465	101.41	13731	100.48
4	17886	101.03	18179	99.77
5	22290	100.72	22715	99.74
6	26615	100.22	27012	98.84
7	30659	98.96	30804	96.61
8	34347	97	34910	95.8
9	38389	96.37	39029	95.2
10	42772	96.64	43126	94.68
11	46840	96.21	46936	93.68
12	50667	95.4	50590	92.55

When I saw these numbers for the first time I was quite surprised just how good these results are! UlstraSPARC T2 end up being far from choking and, as a matter of fact, the only position where Result Cache had to give up is the last one. If you reference the results I've obtained on 8-way Itanium 2 in 11GR1 you'll see that Result Cache gave up much earlier and scaled a lot worse.

This certainly looks promising so let's take a look at the RC latch statistic:

# of processes	Gets	Misses	Sleeps	Wait Time
1	500001	0	0	0
2	1000002	40253	1	0
3	1500003	50404	0	0
4	2000004	165116	9	464
5	2500005	211559	5	182
6	3000006	437898	8	6877
7	3500007	805752	52	16556
8	4000008	1214762	20	2980
9	4500009	1775372	188	3140
10	5000010	2244964	491	29568
11	5500011	2552323	664	28011
12	6000012	3019903	1226	60005

There is one astonishing fact about the above number. Let's get some efficiency metrics in place for comparison between these numbers and the ones I've got in 11GR1. I'll use a data point with eight parallel processes as it's the highest reference point I can get across both data sets.

First of all, the number of gets per execution remained the same and equals two gets per exec. If we were going to calculate % miss per get we'll get 28.62% in 11GR1 and 50.33% in 11GR2. In other words, roughly every second get request has resulted in a miss in 11GR2 and every third in 11GR1. It may appear as if this got worse but it's really a consequence from something else.

If we calculate % sleep per miss we'll get 31.36% in 11GR1 but only 0.04% in 11GR2! In other words, the amount of times a process had to go to sleep has drastically decreased. In almost all of the cases the process was able to acquire a latch during a spin without going into a sleep. This also explains why % miss per get in 11GR2 went up and shows that a lowering in efficiency for a single metric does not necessarily indicates a problem, it might happen because some other correlated metric has in fact improved.

There is certainly a sign of a great improvement but what is it? Most likely the improvement is related to the optimization of how long the latch is required to be held. The time required to hold the latch became so small that, in most of the cases, the process is able to acquire it during spinning before being required to go to sleep (i.e. less than _spin_count iterations).

Core i7 980X Results

# of processes	Buffer Cache	% linear	Result Cache	% linear
1	40064	100	43554	100
2	78989	98.58	84602	97.12
3	121753	101.3	127768	97.79
4	159490	99.52	166667	95.67
5	194704	97.2	204583	93.94
6	229709	95.56	240770	92.13
7	231788	82.65	244755	80.28
8	233918	72.98	246305	70.69
9	250836	69.57	260718	66.51
10	267094	66.67	275330	63.22
11	280326	63.61	290084	60.55
12	290416	60.41	293830	56.22

Here Result Cache won across all the positions. We need about 10 processes running on UltraSPARC T2 in order to beat a single process running on i7 980X. Performance gains declined rapidly once we got over six concurrent processes but still we were able to realize some additional performance with 12 threads being about 22% faster than 6 threads.

Latch statistics:

# of processes	Gets	Misses	Sleeps	Wait Time
1	500001	0	0	0
2	1000002	40456	0	0
3	1500003	117893	5	71
4	2000004	209399	0	0
5	2500005	381160	0	0
6	3000006	517745	11	179
7	3500007	913125	20	555
8	4000008	1355226	26	11914
9	4500009	1834112	13	1017
10	5000010	2602801	42	1607
11	5500011	3196415	145	3451
12	6000012	3730467	184	123954

Essentially we're looking at the same phenomena with the amount of sleeps being significantly lower compared to what we observed in 11GR1. With six concurrent processes % miss per get is 17.26% and % sleep per miss is 0.002%! This allowed Result Cache to stay ahead with up to (and including) 12 concurrent processes running.

UltraSPARC T2 vs i7 980X

We'll wrap up with a nice graph showing result cache performance on both UltraSPARC T2 and Core i7 980X:

i7 980X starts almost where 12 UltraSPARC T2 processes ends. Would T2 be able to narrow the gap with more parallel threads? I'll certainly find out.

Conclusion

There is an enormous improvement when it comes to Result Cache scalability in 11GR2. Still it's slower than if we had shared mode gets (or multiple child latches or, even better, both) but it gets very, very close.

Row cache objects latch contention

noreply@blogger.com (Alex Fatkulin) — Mon, 07 Jun 2010 21:47:00 +0000

A data loading process was running on UltraSPARC T2 CPU. To take advantage of the platform architecture (or, I'd rather say, to avoid it's limitations) the loading process has been design to run with a massive amount of parallel query slaves in order to extract the maximum output from CMT architecture.

Every time this data loading process executed, it experienced strange slowdowns on seemingly random points in time. Performance drops were quite substantial, which prompted to do an additional investigation. Upon a closer examination of ASH data, it turned out that all slowdowns were due to latch: row cache objects contention.

Row cache objects latch protects the dictionary cache. The first thing was to figure out whether most of the contention was contributed by a particular row cache objects child latch:

SQL> select latch#, child#, sleeps
  2   from v$latch_children
  3   where name='row cache objects'
  4    and sleeps > 0
  5   order by sleeps desc;
 
    LATCH#     CHILD#     SLEEPS
---------- ---------- ----------
       270          1   24241645
       270          5        523
       270          4         52

The first child certainly doesn't look good when we take the amount of sleeps experienced by it, compared to all the other child latches. Once we have the troublesome child latch identified, we can move on and see which type of dictionary cache it protects:

SQL> select distinct s.kqrstcln latch#,r.cache#,r.parameter name,r.type,r.subordinate#
from v$rowcache r,x$kqrst s
where r.cache#=s.kqrstcid
order by 1,4,5;  2    3    4

 LATCH# CACHE# NAME                              TYPE        SUBORDINATE#
------- ------ --------------------------------- ----------- ------------
      1      3 dc_rollback_segments              PARENT
      2      1 dc_free_extents                   PARENT
      3      4 dc_used_extents                   PARENT
      4      2 dc_segments                       PARENT
      5      0 dc_tablespaces                    PARENT
      6      5 dc_tablespace_quotas              PARENT
      7      6 dc_files                          PARENT
      8     10 dc_users                          PARENT
      8      7 dc_users                          SUBORDINATE            0
      8      7 dc_users                          SUBORDINATE            1
      8      7 dc_users                          SUBORDINATE            2
      9      8 dc_objects                        PARENT
      9      8 dc_object_grants                  SUBORDINATE            0
     10     17 dc_global_oids                    PARENT
     11     12 dc_constraints                    PARENT
     12     13 dc_sequences                      PARENT
     13     16 dc_histogram_defs                 PARENT
     13     16 dc_histogram_data                 SUBORDINATE            0
     13     16 dc_histogram_data                 SUBORDINATE            1
     14     32 kqlsubheap_object                 PARENT
     15     19 dc_table_scns                     PARENT
     15     19 dc_partition_scns                 SUBORDINATE            0
     16     18 dc_outlines                       PARENT
     17     14 dc_profiles                       PARENT
     18     47 realm cache                       PARENT
     18     47 realm auth                        SUBORDINATE            0
     19     48 Command rule cache                PARENT
     20     49 Realm Object cache                PARENT
     20     49 Realm Subordinate Cache           SUBORDINATE            0
     21     46 Rule Set Cache                    PARENT
     22     34 extensible security user and rol  PARENT
     23     35 extensible security principal pa  PARENT
     24     37 extensible security UID to princ  PARENT
     25     36 extensible security principal na  PARENT
     26     33 extensible security principal ne  PARENT
     27     38 XS security class privilege       PARENT
     28     39 extensible security midtier cach  PARENT
     29     44 event map                         PARENT
     30     45 format                            PARENT
     31     43 audit collector                   PARENT
     32     15 global database name              PARENT
     33     20 rule_info                         PARENT
     34     21 rule_or_piece                     PARENT
     34     21 rule_fast_operators               SUBORDINATE            0
     35     23 dc_qmc_ldap_cache_entries         PARENT
     36     52 qmc_app_cache_entries             PARENT
     37     53 qmc_app_cache_entries             PARENT
     38     27 qmtmrcin_cache_entries            PARENT
     39     28 qmtmrctn_cache_entries            PARENT
     40     29 qmtmrcip_cache_entries            PARENT
     41     30 qmtmrctp_cache_entries            PARENT
     42     31 qmtmrciq_cache_entries            PARENT
     43     26 qmtmrctq_cache_entries            PARENT
     44      9 qmrc_cache_entries                PARENT
     45     50 qmemod_cache_entries              PARENT
     46     24 outstanding_alerts                PARENT
     47     22 dc_awr_control                    PARENT
     48     25 SMO rowcache                      PARENT
     49     40 sch_lj_objs                       PARENT
     50     41 sch_lj_oids                       PARENT

60 rows selected.

The first child protects dc_rollback_segments. We can confirm it by referencing data in v$rowcache:

SQL> select parameter, gets
  2   from v$rowcache
  3   order by gets desc;
 
PARAMETER                              GETS
-------------------------------- ----------
dc_rollback_segments              310995555
dc_tablespaces                     76251831
dc_segments                         3912096
dc_users                            2307601
dc_objects                          1460725
dc_users                             608659
dc_histogram_defs                    250666
global database name                  67475
dc_histogram_data                     43098
dc_histogram_data                     14364
dc_global_oids                        14320
outstanding_alerts                     2956
dc_profiles                            2555
dc_awr_control                         1925
dc_object_grants                        745
dc_files                                532
dc_constraints                          201
sch_lj_oids                             158
dc_sequences                            156
dc_table_scns                            20
sch_lj_objs                              18
dc_qmc_ldap_cache_entries                 0
qmc_app_cache_entries                     0
qmc_app_cache_entries                     0
qmtmrcin_cache_entries                    0
qmtmrctn_cache_entries                    0
qmtmrcip_cache_entries                    0
qmtmrctp_cache_entries                    0
qmtmrciq_cache_entries                    0
qmtmrctq_cache_entries                    0
qmrc_cache_entries                        0
qmemod_cache_entries                      0
SMO rowcache                              0
dc_users                                  0
dc_partition_scns                         0
dc_users                                  0
realm auth                                0
Realm Subordinate Cache                   0
rule_or_piece                             0
rule_info                                 0
audit collector                           0
format                                    0
event map                                 0
extensible security midtier cach          0
XS security class privilege               0
extensible security principal ne          0
extensible security principal na          0
extensible security UID to princ          0
extensible security principal pa          0
extensible security user and rol          0
Rule Set Cache                            0
Realm Object cache                        0
Command rule cache                        0
realm cache                               0
dc_outlines                               0
kqlsubheap_object                         0
dc_tablespace_quotas                      0
dc_used_extents                           0
rule_fast_operators                       0
dc_free_extents                           0
 
60 rows selected

The next step is to see whether latch miss source can give us some more hints regarding the issue:

SQL> select "WHERE", sleep_count, location
  2   from v$latch_misses
  3   where parent_name='row cache objects'
  4    and sleep_count > 0;
 
WHERE               SLEEP_COUNT LOCATION
------------------- ----------- ------------------------------
kqrpre: find obj       20612167 kqrpre: find obj
kqrpup                        7 kqrpup
kqrcmt: while loop            1 kqrcmt: while loop
kqrcmt: clear flag            1 kqrcmt: clear flag
kqreqd                  1026837 kqreqd
kqreqd: reget           2602576 kqreqd: reget
 
6 rows selected

Now if you take kqrpre: find obj and plug it into a search on My Oracle Support you'll quickly yield Bug 5749075 High Requests on dc_rollback_segments. Among other things, this note points out at the unusually high number of undo segments being created due to cleanup not able to work properly...

SQL> select count(*) from dba_rollback_segs;
 
  COUNT(*)
----------
     14838

...and this seems to be the case. The only difference is that the issue has been observed on 11GR2 and the bug has been filled against the older versions. Though it was still worth checking in case we were seeing a regression. Indeed, after getting rid of that many undo segments by simply recreating the undo tablespace, the issue, thought not completely vanished, manifested itself a lot less making it's impact relatively insignificant to the process throughput.

The case of a slow lookup

noreply@blogger.com (Alex Fatkulin) — Wed, 12 May 2010 23:36:00 +0000

Take a look at the runtime difference for the same anonymous PL/SQL block between 11GR1 and 11GR2:

Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> set timing on
SQL> begin
        for i in 1 .. 1000000
        loop
                for cur in (select n from z_t where n=mod(i,10000)+1)
                loop
                        null;
                end loop;
        end loop;
end;  2    3    4    5    6    7    8    9
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:31.03

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> set timing on
SQL> begin
        for i in 1 .. 1000000
        loop
                for cur in (select n from z_t where n=mod(i,10000)+1)
                loop
                        null;
                end loop;
        end loop;
end;  2    3    4    5    6    7    8    9
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:46.23

11GR2 end up being about 50% slower.

A little background

I've been running some tests and the numbers I was getting back just weren't making any sense. I've been using 11GR2 but all I was getting were marginally better results compared to the tests I've done a couple of years ago using 11GR1 on a much less powerful hardware. Something definitely didn't look right so I geared up to find out what it is. The above test case is something I arrived at, which is simple but demonstrates the issue. This test case was run using the same hardware so the only difference was release of Oracle database being used.

tkprof results

To see whether there are any low hanging fruits I've traced the same loop with 250K iterations (to cut a bit on a trace file size):

11GR1

SQL ID: 85f6s9ndbynfc
Plan Hash: 3532178995
SELECT N
FROM
 Z_T WHERE N=MOD(:B1 ,10000)+1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 249995      2.51       2.24          0          0          0           0
Fetch   249995      1.54       1.68          0     499990          0      249995
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   499991      4.06       3.92          0     499990          0      249995

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 54     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  INDEX UNIQUE SCAN PK_Z_T (cr=2 pr=0 pw=0 time=0 us cost=1 size=13 card=1)(object id 61973)

11GR2

SQL ID: 85f6s9ndbynfc
Plan Hash: 3532178995
SELECT N
FROM
 Z_T WHERE N=MOD(:B1 ,10000)+1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 249999      4.07       4.06          0          0          0           0
Fetch   249999      2.62       2.67          0     499998          0      249999
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   499999      6.69       6.74          0     499998          0      249999

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 57     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  INDEX UNIQUE SCAN PK_Z_T (cr=2 pr=0 pw=0 time=0 us cost=1 size=13 card=1)(object id 69265)

These statistics looks almost identical but with one big difference. 11GR2 is about 70% slower.

What's going on?

Certainly you wouldn't expect the newest release of Oracle database to be so much slower compared to the previous version. As a first step I've traced both loops which resulted in discovering some timing improvements which I've blogged about just recently. But the additional overhead introduced by times syscalls was not even remotely enough to justify the difference. As a next step I've compared session statistics between 11GR1 and 11GR2 which lead to session cached cursors overflow issue discovery. Apart from that the only difference was significantly greater amount of CPU time consumed by 11GR2 (as evident by the trace file as well).

Now what?

Certainly some more diagnostic were required. What I did is a couple of stack dumps while the loop was running to see whether there will be something unusual... and there were something indeed:

[oracle@ora11gr2 trace]$ pstack 1052
#0  0x0000003b83c99247 in times () from /lib64/libc.so.6
#1  0x00000000085556c7 in sltrgatime64 ()
#2  0x0000000005521a44 in auddft ()
#3  0x0000000008438ee3 in audStatement ()
#4  0x00000000083fc299 in opiexe ()
#5  0x0000000008405f57 in opipls ()
#6  0x00000000083f78b9 in opiodr ()
#7  0x00000000084892af in __PGOSF141_rpidrus ()
#8  0x00000000085ee820 in skgmstack ()
#9  0x000000000848a759 in rpiswu2 ()
#10 0x0000000008489e9d in rpidrv ()
#11 0x0000000008476438 in psddr0 ()
#12 0x0000000008476048 in psdnal ()
#13 0x000000000288b3aa in pevm_BFTCHC ()
#14 0x000000000287ab84 in pfrinstr_BFTCHC ()
#15 0x0000000008645105 in pfrrun_no_tool ()
#16 0x00000000086439ea in pfrrun ()
#17 0x000000000864a7d6 in plsql_run ()
#18 0x0000000002870d07 in peicnt ()
#19 0x0000000002867649 in kkxexe ()
#20 0x00000000083fe337 in opiexe ()
#21 0x00000000019da690 in kpoal8 ()
#22 0x00000000083f78b9 in opiodr ()
#23 0x0000000008583187 in ttcpip ()
#24 0x0000000001702661 in opitsk ()
#25 0x0000000001707282 in opiino ()
#26 0x00000000083f78b9 in opiodr ()
#27 0x00000000016fe708 in opidrv ()
#28 0x0000000001b7183f in sou2o ()
#29 0x00000000009d3f05 in opimai_real ()
#30 0x0000000001b76ace in ssthrdmain ()
#31 0x00000000009d3e71 in main ()

Look at the lines #2 and #3. Are these some auditing functions getting in the way? I verified audit_trail parameter which turned out to be sat to DB:

SQL> show parameter audit_trail

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
audit_trail                          string      DB

Though I didn't have any auditing enabled for any of the statements let alone the table I was selecting from. But after I've confirmed that audit_trail was set to NONE on 11GR1 database, disabling audit completely looked like something worth trying.

After I've repeated the test with audit_trail sat to NONE, I end up getting virtually identical results compared to 11GR1:

Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> set timing on
SQL> begin
        for i in 1 .. 1000000
        loop
                for cur in (select n from z_t where n=mod(i,10000)+1)
                loop
                        null;
                end loop;
        end loop;
end;  2    3    4    5    6    7    8    9
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:32.42

...and two audit functions has disappeared from the stack dump as well.

It looks like the impact of having auditing enabled end up being high enough to draw some attention in this particular case even though it wasn't sat to capture anything about our test. On a side note this can be considered an invitation to instrument some auditing functionality as well.

Timing improvements in Oracle 11GR2 trace

noreply@blogger.com (Alex Fatkulin) — Tue, 11 May 2010 23:35:00 +0000

I've been doing some research recently (I might blog about it a bit later if something worthwhile comes out of it) which resulted in a byproduct I found interesting to blog about.

In a nutshell, in one of the steps I've run the following PL/SQL block to trace the results of a very tight loop:

begin
 dbms_monitor.session_trace_enable(waits => false, binds => false);
 for i in 1 .. 100000
 loop
  for cur in (select null from dual)
  loop
   null;
  end loop;
 end loop;
 dbms_monitor.session_trace_disable;
end;

While comparing raw trace files between 11.1.0.7 and 11.2.0.1 I've noticed something interesting. Here is an excerpt from 11.1.0.7 raw trace:

PARSING IN CURSOR #2 len=21 dep=1 uid=54 oct=3 lid=54 tim=1273621434711518
 hv=2339989301 ad='86044a88' sqlid='bg2ng0u5rkttp'
SELECT NULL FROM DUAL
END OF STMT
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1273621434711518
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1273621434711518
CLOSE #2:c=0,e=0,dep=1,type=3,tim=1273621434711518

Notice how tim= values are the same across parse, exec, fetch and close; and e= values are zero for fetch, close and execute.

Now take a look at a similar excerpt from 11GR2:

PARSING IN CURSOR #3 len=21 dep=1 uid=57 oct=3 lid=57 tim=1273621440328909
 hv=2339989301 ad='844d5a20' sqlid='bg2ng0u5rkttp'
SELECT NULL FROM DUAL
END OF STMT
EXEC #3:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1273621440328908
FETCH #3:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1273621440328947
CLOSE #3:c=0,e=1,dep=1,type=3,tim=1273621440328968

Notice how tim= value changes from line to line and e= has a corresponding value associated with it.

Before we move on you may ask how 11.1.0.7 calculates the time if all the values appear to be zero? The answer is that every so often you'll see a line like that:

FEXEC #5:c=1000,e=20960,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1273621434873334

Sure we didn't spent that much time fetching a single row. This value comes from the fact that we've just dumped all the time associated with multiple executions in this single line.

Now for 11GR2 to calculate the time with that additional precision will require a heck more times syscalls. To confirm this I've ran strace for processes in both 11GR1 and 11GR2 and here is what I came up with:

11GR1

[oracle@ora11gr1 tmp]$ grep -c times 4279.out
116

11GR2

[oracle@ora11gr2 tmp]$ grep -c times 5318.out
200149

Indeed, 11GR2 end up calling times twice per iteration while 11GR1 was doing one call per about thousand iterations. In total 11GR2 end up doing roughly 200K more syscalls. Next I became curious about how much overhead all these additional syscalls introduce and in order to find out I've run a small program:

[oracle@ora11gr2 tmp]$ cat do_times.c
#include 

int main()
{
        int i;
        struct tms t;
        clock_t c;
        for (i=1;i<=200000;i++)
        {
                c=times(&t);
        }

        return 0;
}
[oracle@ora11gr2 tmp]$ gcc do_times.c
[oracle@ora11gr2 tmp]$ time ./a.out

real    0m0.096s
user    0m0.037s
sys     0m0.059s

We're talking about 0.01 second for 200K times syscalls, in other words - not much.

It's definitely nice to see all these small improvements being done.

How to install Oracle Grid Control Agents on a Windows failover cluster with no downtime

noreply@blogger.com (Alex Fatkulin) — Thu, 06 Aug 2009 23:20:00 +0000

Metalink Note:464191.1 describes steps required to configure Oracle Grid Control agent in Windows failover cluster environment. Unfortunately, as part of the configuration, the cluster disk containing virtual agent's state information have to be moved to the node where the agent is being deployed.

The agent state directory has to "follow" virtual agent when a failover occurs, hence the requirement for it to be on a cluster disk resource. And since the cluster disk resource is visible on the active node only, you can not deploy virtual agent on any of the passive nodes without moving the group containing disk with state information first.

The above is not a big deal when you're doing install on a brand new or development system but what if you have to deal with a production cluster where any potential downtime that might be associated with moving the group across the nodes would better be avoided?

Let's say you have an Oracle FailSafe configuration and you intend to use Oracle Grid Control to monitor your Oracle database. In this case your virtual agent will be a part of the same cluster group where your Oracle database is. Failing over your database across all the nodes for the sake of deploying a virtual agent may not necessarily be what you want to do.

Of course, the easy workaround is to add another disk (LUN) to a cluster, use it to deploy the agents and, once the deployment has been done, add it to the same group where your database is. But what if you do not have any spare disks and have to share the same cluster disk with your Oracle database?

I gave this problem a bit of research and, as it turned out, there is a really simple workaround which may come in handy in case you'll be faced with the same problem.

I'll use the following configuration as an example:

ORA01A -- first (active) node.
ORA01B -- second (passive) node.
ORA01V -- Oracle Database VIP.
c:\oracle\product\10.2.0\agent10g -- Oracle Grid Control agent home.

Let's say that each system has a local drive C: and the deployment will be done on a cluster drive D:.

Deploy virtual agent on the active node

This is where you follow exactly what Metalink note says you to do:

C:\>emctl deploy agent -n OracleAgentORA01V d:\agent10g ORA01V:1830 ORA01A:1830
Creating shared install...
Source location: C:\oracle\product\10.2.0\agent10g
Destination (shared install) : d:\agent10g
DeployMode : agent

Creating directories...
Creating targets.xml...
Creating emctl control program...
Creating emtgtctl control program...
Setting log and trace files locations for Agent ...
Secure agent found. New agent should be configured for secure mode

Source Agent operating in secure mode.
Run "d:\agent10g/bin/emctl secure agent" to secure agent
Service "OracleAgentORA01V" create SUCCESS

The above will create a virtual agent service named OracleAgentORA01V which will be "bound" to ORA01V virtual IP and use d:\agent10g as a location for virtual agent's state files. Note that I'm using port 1830 since port 3872 is used by a "real" agent. You can specify AgentListenOnAllNICs=FALSE in your emd.properties file (for all agents in the cluster) if you want virtual and real agents share the same port as this will stop agents from trying to listen on all network adapters on the node.

Secure the agent in case your OMS is running in the secure mode:

C:\>d:\agent10g/bin/emctl secure agent
Oracle Enterprise Manager 10g Release 5 Grid Control 10.2.0.5.0.
Copyright (c) 1996, 2009 Oracle Corporation.  All rights reserved.
Agent is already stopped...   Done.
Securing agent...   Started.
Enter Agent Registration Password :
Securing agent...   Successful.

Deploy virtual agent on the passive node

The same deployment command won't work on a passive node simply because drive D: is not there. As a workaround which will allow us to create a virtual agent service on the passive node we will use a local drive C: for initial deployment:

C:\>emctl deploy agent -n OracleAgentORA01V c:\agent10g ORA01V:1830 ORA01B:1830
Creating shared install...
Source location: C:\oracle\product\10.2.0\agent10g
Destination (shared install) : c:\agent10g
DeployMode : agent

Creating directories...
Creating targets.xml...
Creating emctl control program...
Creating emtgtctl control program...
Setting log and trace files locations for Agent ...
Secure agent found. New agent should be configured for secure mode

Source Agent operating in secure mode.
Run "c:\agent10g/bin/emctl secure agent" to secure agent
Service "OracleAgentORA01V" create SUCCESS

However, this is not what we want as all virtual agents should be sharing the same cluster drive D: instead. To fix the location of the agent state directory, launch regedit.exe and navigate to

HKLM\SOFTWARE\ORACLE\SYSMAN\OracleAgentORA01V

registry key. Under that key you'll find EMSTATE field with c:\agent10g as its value. Modify this value to be d:\agent10g instead. You can remove original folder as well.

Done! I found that this virtual agent will be fully operational once the group failovers to the passive node (don't forget to create a cluster resource for a virtual agent) and will be using shared state directory.

Consistent gets from cache (fastpath) 2

noreply@blogger.com (Alex Fatkulin) — Sun, 08 Feb 2009 04:40:00 +0000

Not so long time ago I wrote an article about interesting optimization in 11G which appears as consistent gets from cache (fastpath). One thing I've pointed there is that this optimization can operate only if we're accessing the same block over and over again. This may bring us to some interesting observations how certain type of queries are behaving in 11G.

HASH GROUP BY vs SORT GROUP BY

Consider the following example:

SQL> create table dept
  2  (
  3   dept_id  number primary key,
  4   dept_name varchar2(100)
  5  ) organization index;
 
Table created
 
SQL> insert /*+ append */ into dept
  2   select level, dbms_random.string('x', 100)
  3    from dual
  4    connect by level <= 10000;
 
10000 rows inserted
 
SQL> create table emp
  2  (
  3   emp_id  number primary key,
  4   dept_id  references dept (dept_id),
  5   emp_name varchar2(100)
  6  );
 
Table created
 
SQL> insert /*+ append */ into emp
  2   select level, trunc(dbms_random.value(1, 10000)), dbms_random.string('x', 100)
  3    from dual
  4    connect by level <= 100000;
 
100000 rows inserted
 
SQL> commit;
 
Commit complete

SQL> exec dbms_stats.gather_table_stats(user, 'dept');
 
PL/SQL procedure successfully completed
 
SQL> exec dbms_stats.gather_table_stats(user, 'emp');
 
PL/SQL procedure successfully completed

Let's say we want to output department names along with how many employees are there:

SQL> select /*+ gather_plan_statistics */ count(*)
  2  from (
  3   select /*+ no_merge */ d.dept_name, count(*) cnt
  4    from emp e, dept d
  5    where e.dept_id=d.dept_id
  6    group by d.dept_name
  7  );

  COUNT(*)
----------
      9999

SQL> select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
SQL_ID  djysxbcmwwxj3, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from (  select /*+
no_merge */ d.dept_name, count(*) cnt   from emp e, dept d   where
e.dept_id=d.dept_id   group by d.dept_name )

Plan hash value: 1432452646

----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation               | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |                   |      1 |        |      1 |00:00:00.08 |   11636 |       |       |          |
|   1 |  SORT AGGREGATE         |                   |      1 |      1 |      1 |00:00:00.08 |   11636 |       |       |          |
|   2 |   VIEW                  |                   |      1 |   9999 |   9999 |00:00:00.06 |   11636 |       |       |          |
|   3 |    HASH GROUP BY        |                   |      1 |   9999 |   9999 |00:00:00.06 |   11636 |  2058K|   999K| 2497K (0)|
|   4 |     NESTED LOOPS        |                   |      1 |   9999 |   9999 |00:00:00.02 |   11636 |       |       |          |
|   5 |      VIEW               | VW_GBC_10         |      1 |   9999 |   9999 |00:00:00.02 |    1635 |       |       |          |
|   6 |       HASH GROUP BY     |                   |      1 |   9999 |   9999 |00:00:00.02 |    1635 |  1207K|  1207K| 2496K (0)|
|   7 |        TABLE ACCESS FULL| EMP               |      1 |    100K|    100K|00:00:00.01 |    1635 |       |       |          |
|*  8 |      INDEX UNIQUE SCAN  | SYS_IOT_TOP_15648 |   9999 |      1 |   9999 |00:00:00.01 |   10001 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------


PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------

   8 - access("ITEM_1"="D"."DEPT_ID")


27 rows selected.

Note that 11G did "Group by Placement" automatically (Jonathan Lewis wrote an article about it) and our query performed 11636 consistent gets.

Now, take a look at what happens if we rewrite the query to use a sort group by instead:

SQL> select /*+ gather_plan_statistics */ count(*)
  2  from (
  3   with e as
  4   (
  5    select dept_id, count(*) cnt
  6     from emp e
  7     group by dept_id
  8     order by dept_id
  9   )
 10   select /*+ no_merge */ d.dept_name, e.cnt
 11    from e, dept d
 12    where e.dept_id=d.dept_id
 13  );

  COUNT(*)
----------
      9999

SQL> select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------------------------------------
SQL_ID  2utq5vammnwa4, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from (  with e as  (
select dept_id, count(*) cnt    from emp e    group by dept_id    order
by dept_id  )  select /*+ no_merge */ d.dept_name, e.cnt   from e, dept
d   where e.dept_id=d.dept_id )

Plan hash value: 2732217545

---------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |                   |      1 |        |      1 |00:00:00.10 |    2624 |       |       |          |
|   1 |  SORT AGGREGATE        |                   |      1 |      1 |      1 |00:00:00.10 |    2624 |       |       |          |
|   2 |   VIEW                 |                   |      1 |   9999 |   9999 |00:00:00.08 |    2624 |       |       |          |
|   3 |    NESTED LOOPS        |                   |      1 |   9999 |   9999 |00:00:00.08 |    2624 |       |       |          |
|   4 |     VIEW               |                   |      1 |   9999 |   9999 |00:00:00.08 |    1635 |       |       |          |
|   5 |      SORT GROUP BY     |                   |      1 |   9999 |   9999 |00:00:00.08 |    1635 |   549K|   549K|  487K (0)|
|   6 |       TABLE ACCESS FULL| EMP               |      1 |    100K|    100K|00:00:00.01 |    1635 |       |       |          |
|*  7 |     INDEX UNIQUE SCAN  | SYS_IOT_TOP_15648 |   9999 |      1 |   9999 |00:00:00.01 |     989 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------


PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------

   7 - access("E"."DEPT_ID"="D"."DEPT_ID")


27 rows selected.

What I did there is performed the same transformation myself but replaced hash group by with a sort group by. Note more than 4 times decrease in the amount of consistent gets. By looking at the plan statistics, you can tell why. Although both group by's performed the same amount of consistent gets (1635), it is a nested loops join with dep which produced all the difference -- 10001 for hash group by versus only 989 for a sort group by.

Unless you've heard about consistent gets from cache (fastpath) optimization, the above results may produce quite a bit of surprise for you. Note that due to a sorting, which has to be performed by our second query, the first query still performs better. However, in the environments which are wreaking havoc on CBC latches, the additional savings on number of consistent gets may have a potential to alleviate additional sorting expenses. In other words, the lesser are expenses for outer resultset sorting, the more appealing this could be.

Of course, before you even consider this as an optimization opportunity, keep in mind that you're relying on a specific feature which may narrow you down to a specific dot releases (or even patches) as it may change (or even completely disappear) in the next versions.

AE enqueue

noreply@blogger.com (Alex Fatkulin) — Sun, 01 Feb 2009 20:18:00 +0000

Just a quick follow up from my previous post.

The relation of AE enqueue to editions was mentioned a couple of times around the internet already. Any user session connected to a database holds AE enqueue in a shared mode...

SQL> select type, id1, lmode, sys_context('userenv', 'current_edition_id') edition_id
  2   from v$lock
  3   where type='AE'
  4    and sid=sys_context('userenv', 'sid');
 
TYPE        ID1      LMODE EDITION_ID
---- ---------- ---------- --------------------------------------------------------------------------------
AE          100          4 100

...and the first argument seems to be session's current_edition_id. I guess the lock mode will require an upgrade to exclusive mode during edition alterations.

Here is another interesting thing -- it looks like installing 11.1.0.7 patchset increments the current_edition_id. The value in 11.1.0.6 seems to be 99, but 11.1.0.7 changes it to 100 (you can observe it in sys.editon$ table as well). Does that mean that Oracle has any plans in doing patchset installation through edition-based redefinition (install the patchset online, short downtime is required only during switch to an upgraded edition) or is it simply a way to represent version change?

Updated the same day: it looks like in case your database was upgraded from a previous release, edition_id for ORA$BASE will be some other number as it represents ORA$BASE's object_id. This also means that my initial assumption about patchset installation changing edition_id is not correct as it is just whatever object_id is being available at the time. Before ORA$BASE edition is being created, 11.1.0.7 creates one more object (compared to 11.1.0.6), index I_SYN2, which explains advance in edition_id.

However, the idea seems to be interesting anyway...

Edition-based redifinition (a speculation)

noreply@blogger.com (Alex Fatkulin) — Sat, 31 Jan 2009 22:44:00 +0000

As you can see from this link, there is a feature called Edition-based redefinition mentioned in the 11GR1 documentation. Unfortunately, all it says is that this feature is unavailable as of now so there is really not much you can tell about it.

A speculation

I'm usually not a great fun of doing any sort of a guesswork, however, in this case it might be an interesting exercise to observe some bits and pieces presented in the current release of 11GR1 in order to see whether it can give us some clues as to what expect from this new feature as well as what the potential underpinning might look like. As well as prepare yourself for some implications...

SYS.OBJ$

Perhaps this will be the first thing what you'll notice as soon as 11G's data dictionary is concerned. For example, this is how dba_synonyms view is defined in 10GR2:

create or replace view dba_synonyms
(owner, synonym_name, table_owner, table_name, db_link)
as
select u.name, o.name, s.owner, s.name, s.node
from sys.user$ u, sys.syn$ s, sys.obj$ o
where o.obj# = s.obj#
  and o.type# = 5
  and o.owner# = u.user#;

Now, take a look at the same view's definition in 11GR1:

create or replace view dba_synonyms
(owner, synonym_name, table_owner, table_name, db_link)
as
select u.name, o.name, s.owner, s.name, s.node
from sys.user$ u, sys.syn$ s, sys."_CURRENT_EDITION_OBJ" o
where o.obj# = s.obj#
  and o.type# = 5
  and o.owner# = u.user#;

For you see, the reference to SYS.OBJ$ was replaced with SYS."_CURRENT_EDITION_OBJ". This replacement occurs all around the place in the data dictionary which alone makes it interesting enough to attract a bit of attention.

SYS._CURRENT_EDITION_OBJ

What is _CURRENT_EDITION_OBJ? It's a view:

SQL> select object_type
  2   from dba_objects
  3   where object_name='_CURRENT_EDITION_OBJ';
 
OBJECT_TYPE
-------------------
VIEW

Let's take a look at this view's definition (I've omitted fields list for the sake of clarity):

select ...
from obj$ o, user$ u
where o.owner# = u.user#
  and (   /* non-versionable object */
          (   o.type# not in (4,5,7,8,9,10,11,12,13,14,22,87,88)
           or bitand(u.spare1, 16) = 0)
          /* versionable object visible in current edition */
       or (    o.type# in (4,5,7,8,9,10,11,12,13,14,22,87)
           and (   (u.type# <> 2 and
                    sys_context('userenv', 'current_edition_name') = 'ORA$BASE')
                or (u.type# = 2 and
                    u.spare2 = sys_context('userenv', 'current_edition_id'))
                or exists (select 1 from obj$ o2, user$ u2
                           where o2.type# = 88
                             and o2.dataobj# = o.obj#
                             and o2.owner# = u2.user#
                             and u2.type#  = 2
                             and u2.spare2 =
                                  sys_context('userenv', 'current_edition_id'))
               )
          )
      );

First of all, it mentions about (A) versionable objects and (B) current edition which is referenced through session's context sys_context('userenv', 'current_edition_id').

Versionable objects

Only the objects of the following types seems to be versionable:

VIEW
SYNONYM
PROCEDURE
FUNCTION
PACKAGE
PACKAGE BODY
TRIGGER
TYPE
TYPE BODY
LIBRARY
ASSEMBLY

Object type# = 88 seems to be something special as I couldn't find what it is from sql.bsq (nor dba_objects) and it is being referenced using somewhat special way: if obj# matches dataobj# of some entry with type# = 88 and this entry is part if the current edition, the object is considered to be a part of the current edition as well. Note that the join itself permits this special object to exist in some other schema, though I don't know whether this has any practical meaning or not.

New userenv attributes

There are two (at least) new userenv context attributes:

SQL> select sys_context('userenv', 'current_edition_name')
  2   current_edition_name from dual;
 
CURRENT_EDITION_NAME
--------------------------------------------------------------------------------
ORA$BASE
SQL> select sys_context('userenv', 'current_edition_id')
  2   current_edition_id from dual;
 
CURRENT_EDITION_ID
--------------------------------------------------------------------------------
100

Changing these will change data returned by _CURRENT_EDITION_OBJ view as well and, given that that view is referenced instead of obj$, it looks like these contexts will be the primary mechanism responsible for referencing one version (edition) of the object or the other.

New user type

Again, by looking at the view definition, we may spot that versionable objects are being concerned as far as user$.type# = 2. To remind you, 0 is a role and 1 is a regular user, so there will be something new, perhaps this new feature could be enabled on a per-user level and/or versioned objects will be owned by some other "ghost" schema (my comment about object with type 88 seems to be allowing this, at least technically).

Some interesting clues might be get from _CURRENT_EDITION_OBJ's field definition itself:

when (u.type# = 2) then
 (select eo.name from obj$ eo where eo.obj# = u.spare2)
else
 'ORA$BASE'
end

The objects which are owned by this new user type will have editition_id as their object_id and will be named after edition name. That also means that object_id is no longer unique:

create unique index i_obj1 on obj$(obj#, owner#, type#) (11GR1)
create unique index i_obj1 on obj$(obj#) (10GR2)
(from sql.bsq)

I wander whether this have some chances to break legacy code which references sys.obj$ by obj# and expect one row to be returned at most...

Does all that, again, points out that object versions will be kept under this special user and will be linked back using data_object_id? Is this also a reason why objects which do have "proper" data_object_id are not versionable?

A speculation (again)

Pleases note that everything said in this post is based on some (random) observations of preliminary data available in the current release (11.1.0.7). There are chances that some (if not all) of this data may became altered or even completely invalid when this feature will be officially announced.

However, one thing seems to be clear -- in order to support this new feature, some serious alterations of the data dictionary are taking place and you should keep yourself alerted...

Create database or who wants some DMT?

noreply@blogger.com (Alex Fatkulin) — Sat, 31 Jan 2009 21:59:00 +0000

Simpler than ever

Starting from Oracle 10G, creating the database can be as simple as this:

SQL> create database;

Database created.

It's not a surprise that this feature was somewhat advertised here and there. However, what was missing in these advertisements is this:

SQL> select name, decode(bitmapped, 0, 'DMT', 'LMT')
      from ts$
      order by name;  2    3

NAME                           DEC
------------------------------ ---
SYSAUX                         LMT
SYSTEM                         DMT
SYS_UNDOTS                     LMT

For you see, create database will make your SYSTEM tablespace to be dictionary managed by default. I don't really know if there are any reasons for this and since everything else will default to LMT, this should not be a big deal for most of you anyway. Just don't forget that SYSTEM hosts objects like AUD$ (audit log), FGA_LOG$ (fine-grained audit log) or NCOMP_DLL$ (natively compiled objects) which could grow to a fairly large number of extents.

I was a bit surprised watching this relic appear even when you do this in 11.1.0.7...

Moving a datafile

noreply@blogger.com (Alex Fatkulin) — Sat, 31 Jan 2009 03:27:00 +0000

Sometimes you need to move a datafile into a different mount point or ASM diskgroup. This could make you wandering what technique you can use in order to minimize downtime. I'll show you one of my favorite methods which works well under certain circumstances.

Let's say you want to move the following datafile...

SQL> select file_id, file_name
  2     from dba_data_files
  3     where tablespace_name='USERS';

FILE_ID FILE_NAME
------- --------------------------------------------------------
      4 /u01/oradata/ORA11GR1/datafile/o1_mf_users_4q759m64_.dbf

...into mount point /u02.

Backup as copy

The first thing we need to do is backup this datafile as copy using RMAN:

[oracle@ora11gr1a ~]$ rman

Recovery Manager: Release 11.1.0.7.0 - Production on Thu Jan 29 17:29:59 2009

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

RMAN> connect target;

connected to target database: ORA11GR1 (DBID=3707369966)

RMAN> backup as copy datafile 4
2>      format '/u02/oradata/ORA11GR1/datafile/users01.dbf';

Starting backup at 29-JAN-09
using channel ORA_DISK_1
channel ORA_DISK_1: starting datafile copy
input datafile file number=00004 name=/u01/oradata/ORA11GR1/datafile/o1_mf_users
_4q759m64_.dbf
output file name=/u02/oradata/ORA11GR1/datafile/users01.dbf tag=TAG20090129T1825
32 RECID=14 STAMP=677442334
channel ORA_DISK_1: datafile copy complete, elapsed time: 00:00:03
Finished backup at 29-JAN-09

Rollforward image copy

Since switching to datafile copy will require datafile recover, it might be a good idea to rollforward this image copy first, in order to bring it up to date...

RMAN> list copy of datafile 4;

List of Datafile Copies
=======================

Key     File S Completion Time Ckp SCN    Ckp Time
------- ---- - --------------- ---------- ---------------
14      4    A 29-JAN-09       2033489    29-JAN-09
        Name: /u02/oradata/ORA11GR1/datafile/users01.dbf
        Tag: TAG20090129T182532

RMAN> backup incremental from scn 2033489 datafile 4 format '/u02/oradata/ORA11G
R1/datafile/%U';

Starting backup at 29-JAN-09

using channel ORA_DISK_1
backup will be obsolete on date 05-FEB-09
archived logs will not be kept or backed up
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00004 name=/u01/oradata/ORA11GR1/datafile/o1_mf_users
_4q759m64_.dbf
channel ORA_DISK_1: starting piece 1 at 29-JAN-09
channel ORA_DISK_1: finished piece 1 at 29-JAN-09
piece handle=/u02/oradata/ORA11GR1/datafile/1nk61t1d_1_1 tag=TAG20090129T183004
comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01

using channel ORA_DISK_1
backup will be obsolete on date 05-FEB-09
archived logs will not be kept or backed up
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
including current control file in backup set
channel ORA_DISK_1: starting piece 1 at 29-JAN-09
channel ORA_DISK_1: finished piece 1 at 29-JAN-09
piece handle=/u02/oradata/ORA11GR1/datafile/1ok61t1e_1_1 tag=TAG20090129T183004
comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 29-JAN-09

RMAN> recover copy of datafile 4;

Starting recover at 29-JAN-09
using channel ORA_DISK_1
channel ORA_DISK_1: starting incremental datafile backup set restore
channel ORA_DISK_1: specifying datafile copies to recover
recovering datafile copy file number=00004 name=/u02/oradata/ORA11GR1/datafile/u
sers01.dbf
channel ORA_DISK_1: reading from backup piece /u02/oradata/ORA11GR1/datafile/1nk
61t1d_1_1
channel ORA_DISK_1: piece handle=/u02/oradata/ORA11GR1/datafile/1nk61t1d_1_1 tag
=TAG20090129T183004
channel ORA_DISK_1: restored backup piece 1
channel ORA_DISK_1: restore complete, elapsed time: 00:00:01
Finished recover at 29-JAN-09

RMAN> list copy of datafile 4;

List of Datafile Copies
=======================

Key     File S Completion Time Ckp SCN    Ckp Time
------- ---- - --------------- ---------- ---------------
15      4    A 29-JAN-09       2033633    29-JAN-09
        Name: /u02/oradata/ORA11GR1/datafile/users01.dbf
        Tag: TAG20090129T182532

Note that image copy's checkpoint SCN has moved forward. Keep in mind that this step generally makes sense only if you have block change tracking enabled and/or there is a huge amount of archivelogs to apply, as it will be a trade-off between creating and applying the incremental backup compared to directly applying all necessarily archivelogs. This step can be done starting from Oracle 10G.

Switch datafile

All we have to do now is execute small RMAN block...

RMAN> run
2> {
3>      sql 'alter database datafile 4 offline';
4>      switch datafile 4 to datafilecopy '/u02/oradata/ORA11GR1/datafile/users0
1.dbf';
5>      recover datafile 4;
6>      sql 'alter database datafile 4 online';
7> }

sql statement: alter database datafile 4 offline

datafile 4 switched to datafile copy
input datafile copy RECID=15 STAMP=677442659 file name=/u02/oradata/ORA11GR1/dat
afile/users01.dbf

Starting recover at 29-JAN-09
using channel ORA_DISK_1

starting media recovery
media recovery complete, elapsed time: 00:00:00

Finished recover at 29-JAN-09

sql statement: alter database datafile 4 online

This is where you'll have some downtime. The amount of downtime depends on how long it will take to recover the datafile which will generally be a function of how many archivelogs needs to be applied which, in turn, can be reduced by using incremental backup. The point is that this step can be really fast.

Don't forget to watch against nologging operations!

Update and rownum oddity

noreply@blogger.com (Alex Fatkulin) — Sun, 25 Jan 2009 13:27:00 +0000

Take a look at the following table:

SQL> create table codes
  2  (
  3     code varchar2(10),
  4     used number,
  5     constraint pk_codes primary key (used, code)
  6  ) organization index;

Table created.

SSQL> insert into codes
  2     select  dbms_random.string('x', 10),
  3             case when level <= 5000 then 1 else 0 end
  4             from dual
  5             connect by level <= 100000;

100000 rows created.

SQL> commit;

Commit complete.

SQL> exec dbms_stats.gather_table_stats(user, 'codes');

PL/SQL procedure successfully completed.

This table contains a set of codes with used column representing whether the code was already used (1) or not (0). We need to return one (random) unused code from the above table and mark this code as used. This is very easy to archive using the following update statement:

SQL> variable code varchar2(10);
SQL> set autot traceonly
SQL> update codes set used=1
  2     where used=0 and rownum=1
  3     returning code into :code;

1 row updated.


Execution Plan
----------------------------------------------------------
Plan hash value: 1169687698

-----------------------------------------------------------------------------------
| Id  | Operation              | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT       |          |     1 |    13 |   117   (1)| 00:00:02 |
|   1 |  UPDATE                | CODES    |       |       |            |          |
|*  2 |   COUNT STOPKEY        |          |       |       |            |          |
|*  3 |    INDEX FAST FULL SCAN| PK_CODES | 50000 |   634K|   117   (1)| 00:00:02 |
-----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(ROWNUM=1)
   3 - filter("USED"=0)


Statistics
----------------------------------------------------------
          1  recursive calls
          5  db block gets
         12  consistent gets
          0  physical reads
        124  redo size
        913  bytes sent via SQL*Net to client
        874  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)

However, the plan is not exactly what I would expect (I'm running this on 11.1.0.7)... Why do IFFS when we can do IRS to get only one row? This is exactly what regular select does, after all:

SQL> select *
  2     from codes
  3     where used=0 and rownum=1;


Execution Plan
----------------------------------------------------------
Plan hash value: 802332609

------------------------------------------------------------------------------
| Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |          |     1 |    13 |     2   (0)| 00:00:01 |
|*  1 |  COUNT STOPKEY    |          |       |       |            |          |
|*  2 |   INDEX RANGE SCAN| PK_CODES |     1 |    13 |     2   (0)| 00:00:01 |
------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(ROWNUM=1)
   2 - access("USED"=0)


Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
          2  consistent gets
          0  physical reads
          0  redo size
        590  bytes sent via SQL*Net to client
        520  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

10053 trace

Let's take a look at 10053 trace output for both select and update statements. I'm picking up relevant sections.

UPDATE:

***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: CODES  Alias: CODES
    #Rows: 100000  #Blks:  423  AvgRowLen:  13.00
Index Stats::
  Index: PK_CODES  Col#: 2 1
    LVLS: 1  #LB: 423  #DK: 100000  LB/K: 1.00  DB/K: 1.00  CLUF: 0.00
Access path analysis for CODES
***************************************
SINGLE TABLE ACCESS PATH 
  Single Table Cardinality Estimation for CODES[CODES] 
  Table: CODES  Alias: CODES
    Card: Original: 100000.000000  Rounded: 50000  Computed: 50000.00  Non Adjusted: 50000.00
  Access Path: index (index (FFS))
    Index: PK_CODES
    resc_io: 116.00  resc_cpu: 20012369
    ix_sel: 0.000000  ix_sel_with_filters: 1.000000 
  Access Path: index (FFS)
    Cost:  116.81  Resp: 116.81  Degree: 1
      Cost_io: 116.00  Cost_cpu: 20012369
      Resp_io: 116.00  Resp_cpu: 20012369
OPTIMIZER PERCENT INDEX CACHING = 0


  Access Path: index (IndexOnly)
    Index: PK_CODES
    resc_io: 213.00  resc_cpu: 11516867
    ix_sel: 0.500000  ix_sel_with_filters: 0.500000 
    Cost: 213.47  Resp: 213.47  Degree: 1
  Best:: AccessPath: IndexFFS
  Index: PK_CODES
         Cost: 116.81  Degree: 1  Resp: 116.81  Card: 50000.00  Bytes: 0

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

Nothing else is being tried and this is what optimizer selects as the best execution plan. Note how cardinalities are being reported (highlighted in red).

SELECT:

In addition to the above, has one more section:

***************************************
SINGLE TABLE ACCESS PATH (First K Rows)
  Single Table Cardinality Estimation for CODES[CODES] 
  Table: CODES  Alias: CODES
    Card: Original: 2.000000  Rounded: 1  Computed: 1.00  Non Adjusted: 1.00
  Access Path: index (index (FFS))
    Index: PK_CODES
    resc_io: 2.00  resc_cpu: 7461
    ix_sel: 0.000000  ix_sel_with_filters: 1.000000 
  Access Path: index (FFS)
    Cost:  2.00  Resp: 2.00  Degree: 1
      Cost_io: 2.00  Cost_cpu: 7461
      Resp_io: 2.00  Resp_cpu: 7461
OPTIMIZER PERCENT INDEX CACHING = 0


  Access Path: index (IndexOnly)
    Index: PK_CODES
    resc_io: 2.00  resc_cpu: 14443
    ix_sel: 0.500000  ix_sel_with_filters: 0.500000 
    Cost: 2.00  Resp: 2.00  Degree: 1
  Best:: AccessPath: IndexRange
  Index: PK_CODES
         Cost: 2.00  Degree: 1  Resp: 2.00  Card: 1.00  Bytes: 13

First K Rows: unchanged join prefix len = 1
Join order[1]:  CODES[CODES]#0
***********************

Note how cardinalities has changed (highlighted in green) this time. What happened is rownum = 1 predicate resulted in fist_rows(1) mode (highlighted in blue), affecting how cardinalities were calculated.

We know that first_rows(n) hint is being ignored in update and delete statements, thus our update statement always goes in all_rows mode.

You can confirm that select behaves exactly the same way when in all_rows mode:

SQL> select /*+ all_rows */ *
  2     from codes
  3     where used=0 and rownum=1;


Execution Plan
----------------------------------------------------------
Plan hash value: 2682988822

----------------------------------------------------------------------------------
| Id  | Operation             | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |          |     1 |    13 |   117   (1)| 00:00:02 |
|*  1 |  COUNT STOPKEY        |          |       |       |            |          |
|*  2 |   INDEX FAST FULL SCAN| PK_CODES | 50000 |   634K|   117   (1)| 00:00:02 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(ROWNUM=1)
   2 - filter("USED"=0)


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         12  consistent gets
          0  physical reads
          0  redo size
        590  bytes sent via SQL*Net to client
        520  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

Well, I guess here goes my next wish for CBO improvement regarding how update and delete statements are handled with predicates involving rownum...

11G Managed Recovery Process

noreply@blogger.com (Alex Fatkulin) — Fri, 23 Jan 2009 21:29:00 +0000

MRP process is commonly referenced throughout the web as the process which performs redo apply to your managed standby database. MRP may can in a team with PQ slave (or prnn in 11G) processes in case you start managed recovery in parallel.

Unfortunately, the term performs redo apply seems to be causing some confusion along the way as well. I found it very common that people believes that it's MRP process which performs both reads from the redo streams as well as writes changes into datafiles. For example, sometimes they try to battle slow log apply by increasing managed recovery parallelism without realizing that there is in fact a bit more to the puzzle.

Some details

I'm going to use my 11G DataGuard setup to demonstrate a couple of key points. My setup is operating using real time apply (no parallel), which makes the entire example a bit simpler to demonstrate.

Let's update a row on the source DB:

SQL> update t set n=n;

1 row updated.

SQL>  commit;

Commit complete.

Now, take a look at MRP strace output which was produced as a result of the above change:

[oracle@ora11gr1b fd]$ ps -fp 6364
UID        PID  PPID  C STIME TTY          TIME CMD
oracle    6364     1  0 19:59 ?        00:00:00 ora_mrp0_ora11gr1
[oracle@ora11gr1b fd]$ strace -e pread,pwrite -p 6364
Process 6364 attached - interrupt to quit
pread(32,..., 512, 45568) = 512
pread(32,..., 1024, 46080) = 1024
pread(30,..., 8192, 2228224) = 8192
pread(30,..., 8192, 259858432) = 8192
pread(31,..., 8192, 9461760) = 8192

I've set filesystemio_options=none so we can observe pread/pwrite syscalls which are easier to follow compared to asynch io_submit/io_getvents system calls (and we don't care about O_DIRECT flag either).

Let's check what are these file descriptors:

[oracle@ora11gr1b fd]$ cd /proc/6364/fd
[oracle@ora11gr1b fd]$ file 30
30: symbolic link to `/u01/oradata/ORA11GR1B/datafile/o1_mf_undotbs1_0fk5fp2c_.dbf'
[oracle@ora11gr1b fd]$ file 31
31: symbolic link to `/u01/oradata/ORA11GR1B/datafile/o1_mf_users_0ik5fp4u_.dbf'
[oracle@ora11gr1b fd]$ file 32
32: symbolic link to `/u01/oradata/ORA11GR1B/onlinelog/o1_mf_9_4qn2rkhk_.log'

In other words, the process read from standby logfile, undo and users (this is where our table is) tablespaces. However, as you might notice, all these calls were reads, we didn't write anything.

From time to time MRP gets a bit more interesting, for example during logfile switches:

...
pwrite(27,..., 16384, 16384) = 16384
pread(27,..., 16384, 16384) = 16384
pread(28,..., 8192, 8192) = 8192
pread(29,..., 8192, 8192) = 8192
pread(30,..., 8192, 8192) = 8192
pread(31,..., 8192, 8192) = 8192
pread(27,..., 16384, 393216) = 16384
pwrite(28,..., 8192, 8192) = 8192
pwrite(29,..., 8192, 8192) = 8192
pwrite(30,..., 8192, 8192) = 8192
pwrite(31,..., 8192, 8192) = 8192
...

Here we actually wrote (27 is a controlfile, 28 and 29 are system and sysaux tablespaces respectively) something. However, from the offset (fourth parameter) you can realize that we are writing to the second block in these datafiles. There is no (can't be) any user data there.

Who is writing the data then?

The first thing you might want to check is, of course, the database writer process:

[oracle@ora11gr1b ~]$ ps -fp 6303
UID        PID  PPID  C STIME TTY          TIME CMD
oracle    6303     1  0 19:55 ?        00:00:00 ora_dbw0_ora11gr1
[oracle@ora11gr1b ~]$ strace -e pread,pwrite -p 6303
Process 6303 attached - interrupt to quit
pwrite(23,..., 8192, 2097152) = 8192
pwrite(23,..., 8192, 35987456) = 8192
pwrite(24,..., 8192, 9461760) = 8192

This is the output produced by standby's dbwr right after we updated our table on the source. We wrote two undo blocks (23) and one block in users tablespace (24). By looking at the offset for file descriptor 24 we can confirm that we wrote the table itself:

SQL> select segment_name
 2   from dba_extents
 3   where tablespace_name='USERS'
 4    and 9461760/8192 between block_id and block_id + blocks-1;

SEGMENT_NAME
--------------------------
T

From the above you can confirm that it is DBWR process which wrote the changes for us and it plays crucial role during your standby database operations.

MRP's workload consists mostly from reading the redo stream, datafiles, controlfiles and occasional writes into the controlfile and datafiles header.

If your standby is suffering from the redo apply performance, you may want to pay attention to both MRP and DBWR processes.

Latch waits in 11G: queuing

noreply@blogger.com (Alex Fatkulin) — Tue, 20 Jan 2009 11:10:00 +0000

Following up on my previous post about 11G latch waits using semaphore post-wait with a latch holder...

What I was curious to confirm is whether latch holder posts only the first waiter in the list or all of them?

The results

Here are the results I've got using three sessions:

Session 1: gets RC latch
Session 2: misses the latch, begins to sleep
semop(753664, 0x7fbfffa348, 1)
Session 3: misses the latch, begins to sleep
semop(753664, 0x7fbfff5f58, 1)
Session 1: completes, posts session 2
semctl(753664, 28, SETVAL, 0x1)
Session 2: completes, posts session 3
semctl(753664, 31, SETVAL, 0x1)

Note that though we used the same semaphore set (753664), sessions 1 and 2 posted different semaphores within that set (28 and 31 respectively) and waiters were wakened up by their respective holders according to the order they begun to wait.

sleeps + spin_gets = misses ?

That's an ideal case, of course, as just awakened process might at least have to compete for the same latch with a previous holder if that holder decided to get the same latch again. If awakened process doesn't manage to get the latch during the spin, it'll have to sleep again (thus breaking the above formula). However, the proximity to the above equation might be useful as one of the indicators whether latch is a potential subject to the "new" algorithm or not (this new wait model should tend to produce less sleeps, hence spins, per miss, otherwise there were not much points about it).

SQL> select misses, sleeps, spin_gets, sleeps+spin_gets
  2   from v$latch
  3   where name='Result Cache: Latch';
 
    MISSES     SLEEPS  SPIN_GETS SLEEPS+SPIN_GETS
---------- ---------- ---------- ----------------
      8208        275       7946             8221

The numbers are pretty close indeed. All this made me a bit more curios and I've decided to take a bit closer look at what happens in the strace then waiter has to sleep more than once in a row.

I've ran two parallel sessions executing a loop which selects from result cache...

begin
 for i in 1 .. 1000000
 loop
  for cur in (select /*+ result_cache */ * from t where n=1)
  loop
   null;
  end loop;
 end loop;
end;

...made sure the above formula became distorted further and took a look at strace cutput for one of the sessions which led me to an interesting discovery:

[oracle@ora11gr1a ~]$ strace -e semop,semctl,semtimedop -p 7591
Process 7591 attached - interrupt to quit
...
semctl(1015808, 30, SETVAL, 0x1)        = 0
semctl(1015808, 30, SETVAL, 0x1)        = 0
semtimedop(1015808, 0x7fbfff42b8, 1, {0, 10000000}) = 0
semtimedop(1015808, 0x7fbfff42b8, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable)
semop(1015808, 0x7fbfff5f58, 1)         = 0
...

What we see there is traditional time-based sleep using semtimedop syscall. Does that means that Oracle still can choose between algorithms dynamically? The answer, according to extended SQL trace, seems to be no, as I wasn't able to match these semtimedop syscalls with latch waits in SQL trace (so these syscalls were used for something else).

P.S. It looks like 11G has invalidated all that pseudo code you may find around about latch acquisition algorithm Oracle uses.

"LONGHOLD" latch waits on Linux

noreply@blogger.com (Alex Fatkulin) — Mon, 19 Jan 2009 23:05:00 +0000

Take a look at the figure from my previous blog post:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch     5001      0.53      53.71          0          0          0      500000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     5003      0.53      53.71          0          0          0      500000

...

Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch free                                      1       53.20         53.20

What's unusual about it is a single latch wait for 53 seconds without consuming any CPU time. This is something different from a usual

get -> miss -> spin -> sleep

latch acquisition algorithm we generally used to.

Sequence of events

To remind you, the sequence of events goes like this:

First session: do select /*+ result_cache */ * from t which places a single big result into Result Cache memory.
First session: do select count(*) from v$result_cache_memory which grabs Result Cache latch for a long amount of time.
Second session: do select /*+ result_cache */ * from t which forces us to wait until Result Cache latch will be freed up by our first session.

Latch statistics

Let's take a look at v$latch right after we execute the above three steps:

SQL> select gets, misses, sleeps
  2   from v$latch
  3   where name='Result Cache: Latch';
 
      GETS     MISSES     SLEEPS
---------- ---------- ----------
     53494          1          1

As we can see, the session indeed went into a sleep after a single miss. The first thing which may come into your mind is that I'm running this on a single CPU box where we don't spin if we miss a latch (due to _spin_count=1 being default on a single CPU boxes). This is not the case:

SQL> show parameter cpu_count

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
cpu_count                            integer     2

And my DB's _spin_count has a default value of 2000 as well.

Let's look a bit further:

SQL> select location, sleep_count, wtr_slp_count, longhold_count
  2   from v$latch_misses
  3   where parent_name='Result Cache: Latch'
  4    and sleep_count+wtr_slp_count+longhold_count > 0;
 
LOCATION                       SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT
------------------------------ ----------- ------------- --------------
Result Cache: Serialization12            0             1              0
Result Cache: Serialization16            1             0              1

Note LONGHOLD_COUNT column equals 1 for Result Cache: Serialization16. That means that we've holded a latch for the entire duration of someone else's sleep which, again, conforms to our observation. But what is the underlying mechanism for this?

Under the hood

Here is an excerpt from our second session's strace output:

...
getrusage(RUSAGE_SELF, {ru_utime={0, 728889}, ru_stime={1, 317799}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 728889}, ru_stime={1, 317799}, ...}) = 0
semop(98304, 0x7fbfff5f58, 1)           = 0 -- enters the sleep here
times({tms_utime=72, tms_stime=131, tms_cutime=0, tms_cstime=0}) = 429496789
getrusage(RUSAGE_SELF, {ru_utime={0, 729889}, ru_stime={1, 317799}, ...}) = 0
...

And the first session:

...
mmap(0x2a972e7000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 9, 0) = 0x2a972e7000
mmap(0x2a972f7000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 9, 0) = 0x2a972f7000
semctl(98304, 31, SETVAL, 0x7f00000001) = 0 -- issues upon completion
getrusage(RUSAGE_SELF, {ru_utime={206, 80670}, ru_stime={2, 686591}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={206, 81670}, ru_stime={2, 686591}, ...}) = 0
...

In other words:

Second session: upon discovering that the latch is busy, it begins to sleep by issuing
semop(98304, 0x7fbfff5f58, 1) command.
First session: upon completion issues
semctl(98304, 31, SETVAL, 0x7f00000001) which wakes our second session up.

The first argument is a semid which means that both sessions are operating on the same semaphore. Both semaphore syscalls are not presented if we execute each of the above sessions separately.

Though we do sleep under normal latch acquisition algorithm as well, the sleep is based on time, not the latch holder posting us.

Which algorithm?

The interesting question to answer is how the waiter determines which algorithm to use. It could be (A) a special "longhold" mode get for a latch or (B) the waiter might check for how long the latch was already held. Thus far I tend to think that it is more close to (A) (a special get mode or a separate flag somewhere) because if we execute above two sessions concurrently we always get an enormously unusual number of sleeps even if we place only one single-row result into Result Cache memory (thus making sure there are no significant delays selecting from v$result_cache_memory).

Maybe some of you could share other ideas as well.

v$result_cache_memory or what is the newest method to hang stuff up?

noreply@blogger.com (Alex Fatkulin) — Sun, 18 Jan 2009 11:14:00 +0000

Sometimes I get quite amused by the "side effects" you can discover while playing with features.

Prerequisites

First, we need to place something relatively big into result cache memory. The easiest way to archive this is start like this:

SQL> alter system set result_cache_max_size=64m;

System altered.

SQL> alter system set result_cache_max_result=100;

System altered.

The first parameter controls how much memory out of your shared pool Oracle can dedicate for result cache. The second parameter tells how much memory, in percent, can be dedicated for a single resultset. Default value is 5 and I've set it to 100 so we don't have to dedicate a lot of memory to demonstrate my point.

All we have to do now is populate the result cache memory:

SQL> create table t as
  2   select level n, rpad('*', 100, '*') v
  3    from dual
  4    connect by level <= 500000;
 
Table created
 
SQL> begin
  2   for cur in (select /*+ result_cache*/ * from t)
  3   loop
  4    null;
  5   end loop;
  6  end;
  7  /
 
PL/SQL procedure successfully completed

What's next?

Let's check how much result cache memory is allocated:

SQL> set timing on
SQL> select count(*) from v$result_cache_memory;
 
  COUNT(*)
----------
     65536
 
Executed in 55.984 seconds

That's almost a minute to get the results, yes.

So what?

There are (nasty) consequences.

It's time to buy Core i7

Let's start by taking a look at the trace file of our session:

SQL ID: 0zudkuq64dkwx
Plan Hash: 600544352
select count(*)
from
 v$result_cache_memory


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1     54.65      56.96          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3     54.65      56.96          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 38

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=0 pr=0 pw=0 time=0 us)
  65536   FIXED TABLE FULL X$QESRCMEM (cr=0 pr=0 pw=0 time=0 us cost=0 size=13 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.01

First of all, all the time was spent actively consuming CPU. Selecting from X$QESRCMEM became a pretty expensive thing (in fact, at first I confused such a huge delay with a session being simply hang while spinning on the CPU).

Can't use result cache

Any session which attempts to use result cache will be forced to wait until our first session completes:

SQL ID: bzf4nvdav1m2j
Plan Hash: 1601196873
SELECT /*+ result_cache*/ *
FROM
 T


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch     5001      0.53      53.71          0          0          0      500000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     5003      0.53      53.71          0          0          0      500000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 38     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
 500000  RESULT CACHE  49yjv3h37cjhz39gkd90p4413p (cr=0 pr=0 pw=0 time=0 us)
      0   TABLE ACCESS FULL T (cr=0 pr=0 pw=0 time=0 us cost=2127 size=30436770 card=468258)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  latch free                                      1       53.20         53.20

And the latch name is...

WAIT #2: nam='latch free' ela= 53205337 address=1610838648 number=377 tries=0 obj#=-1 tim=1232316789354155

SQL> select name from v$latch where latch#=377;
 
NAME
----------------------------------------------------------------
Result Cache: Latch

Surprised? I'm not. Don't expect me to start complaining about the absence of shared mode gets again.

The Real Deal or result_cache_mode = force

Things gets really nasty if you set result_cache_mode = force which has a potential outcome of rendering your entire system unusable for some extended period of time. Because even the simplest queries like select * from dual will hang, escalating situation to a point where your normal users will be unable to even connect to a database, let alone executing the queries. For example, trying to connect with SQL*Plus results in the following:

SQL ID: d6vwqbw6r2ffk
Plan Hash: 1388734953
SELECT USER
FROM
 DUAL


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00      43.40          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01      43.41          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 38

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  RESULT CACHE  4c48ztv5ztq25dkd78360h2uxb (cr=0 pr=0 pw=0 time=0 us)
      1   FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  latch free                                      1       43.39         43.39
  SQL*Net message from client                     2        0.00          0.00

I don't have to mention the latch name again.

Real World?

What are the chances of meeting the above situation on some real system? First of all, having a system with more than a 100GB SGA is not uncommon these day. The thing gets worse the more memory is being occupied by a single result. Having a lot of small results seems to be not a problem. If we take 5% as a default threshold to be eligible to be placed into result cache memory, facing the above situation will require 1280M for result cache memory. That looks like quite a big number, however, on the scale of hundred gigs SGA it's no longer seems to be improbable. Aggregating a multi gigabytes of data into 64MB result doesn't sound insane either (at least not to me, you may have a different opinion here).

Plus it takes someone to query v$result_cache_memory. So just don't do it. There are other views (like v$result_cache_objects) which you can use to at least get a part of that info, alas at lower granularity.

Environment

The above tests were verified on Oracle 11GR1 running on Windows XP x64 (native) and Linux x86-64 under VMware (with XP x64 acting as a host OS).

insert /+ append / into ... values (...)

noreply@blogger.com (Alex Fatkulin) — Fri, 16 Jan 2009 23:20:00 +0000

Alex Egorov has left a very fascinating comment to my post about 11G adaptive direct path reads which I thought definitely deserves mentioning.

What we are talking about here is a serious behavior change how statements like...

insert /*+ append */ into t values (1)

...are handled in 11G.

Saving yourself from yourself... not anymore

In previous Oracle versions, the append hint in the cases like above was simply ignored for some good reasons. The hint is being obeyed in 11G.

To better elaborate what that means, let's take the following example:

begin
 for i in 1 .. 1000
 loop
  insert /*+ append */ into t values (i);
  commit;
 end loop;
end;

...and compare how behavior will change in 11G.

First of all, I've seen legacy code like the above in many places where developers were putting append hint everywhere they could because they heard it is like fast=true thing.

After you upgrade, you might expect the following:

If you don't do commit after each row -- the code will break itself with ORA-12838: cannot read/modify an object after modifying it in parallel.
If you do commit (as in my example) -- you have all chances to grow the table beyond the skies as each direct path insert writes beyond the HWM (in 11G, the above code will grow the table by 1000 blocks each time it is executed).
Serious locking issues as each direct path insert has to obtain an exclusive lock on the table first.

The above might produce quite an unpleasant surprises for some of you...

Hot backup mode and a little known fact

noreply@blogger.com (Alex Fatkulin) — Thu, 15 Jan 2009 21:27:00 +0000

Most people are aware of the implication hot backup puts on your redo stream. They'll tell you that on first modification Oracle will dump the entire block image into a redo stream and subsequent writes of the block will go as usual.

This is only half of the story.

The example

Let's start by creating a simple table I'll use as an example:

SQL> create table t pctfree 99 pctused 1 as
  2     select level n
  3             from dual
  4             connect by level <= 100;

Table created.

Now, let's measure the amount of redo generated if I'm going to update all rows in the table:

SQL> set autot traceonly stat
SQL> update t set n=n;

100 rows updated.


Statistics
----------------------------------------------------------
         30  recursive calls
         20  db block gets
         44  consistent gets
         18  physical reads
      12152  redo size
        826  bytes sent via SQL*Net to client
        769  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
        100  rows processed

That's almost 12K of redo. Let's see what happens if I put tablespace into a hot backup mode:

SQL> alter tablespace users begin backup;

Tablespace altered.

SQL> update t set n=n;

100 rows updated.


Statistics
----------------------------------------------------------
          0  recursive calls
         20  db block gets
         20  consistent gets
          0  physical reads
     152708  redo size
        830  bytes sent via SQL*Net to client
        769  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
        100  rows processed

The amount of redo grew up to almost 150K. Oracle has to dump the entire block image into a redo stream due to fractured blocks problem. If we do the same update second time:

SQL> update t set n=n;

100 rows updated.


Statistics
----------------------------------------------------------
          0  recursive calls
         17  db block gets
         20  consistent gets
          0  physical reads
      11980  redo size
        830  bytes sent via SQL*Net to client
        769  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
        100  rows processed

It goes as usual. In fact, and this is kind of amazing, this is what most of the sources available on the internet will tell you about the behavior: the full image of the block gets written only on first modification in order to prevent fractured blocks problem and subsequent modifications will go as usuals.

Only half of the story

Let me continue with my example:

SQL> alter system flush buffer_cache;

System altered.

SQL> update t set n=n;

100 rows updated.


Statistics
----------------------------------------------------------
          0  recursive calls
         20  db block gets
         20  consistent gets
         20  physical reads
     151916  redo size
        831  bytes sent via SQL*Net to client
        769  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
        100  rows processed

What you see here is the entire image of the blocks written into a redo stream again.

The true story

Corrected 27-Jan-2009: initially I thought that it is a write to disk what matters, however, thanks to Jonathan Lewis for correcting me -- it's a read from disk to buffer. Please see his first comment.

Don't confuse correlation with causation.

Consistent gets from cache (fastpath)

noreply@blogger.com (Alex Fatkulin) — Thu, 15 Jan 2009 02:44:00 +0000

There is an intresting optimization introduced in 11G regarding the way blocks are accessed in the buffer cache.

Let's start with a simple example to demonstrate my point.

10GR2 example

SQL> create table t (
 2   n number,
 3   v varchar2(100),
 4   constraint pk_n primary key (n)
 5  );

Table created

SQL>
SQL> insert into t
 2   select level, rpad('*', 100, '*')
 3    from dual
 4    connect by level <= 1000;

1000 rows inserted

SQL> commit;

Commit complete

I'm going to create the procedure to return number of consistent gets in my session:

SQL> create or replace procedure get_cg(
 2   p_cg out number
 3  ) is
 4  begin
 5   select ms.value end into p_cg
 6    from v$mystat ms, v$statname sn
 7    where ms.STATISTIC#=sn.STATISTIC#
 8     and sn.NAME='consistent gets';
 9  end get_cg;
10  /

Procedure created

Let's execute a simple select and measure the number of consistent gets:

SQL> declare
 2   l_cg_b  number;
 3   l_cg_a  number;
 4  begin
 5   get_cg(l_cg_b);
 6   for cur in (select n from (select mod(level, 1000)+1 l from dual connect by
 level <= 100000) l, t where t.n=l.l)
 7   loop
 8    null;   
 9   end loop;
 10   get_cg(l_cg_a);
 11   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 12  end;
 13  /

consistent gets: 100012

PL/SQL procedure successfully completed

This is somewhat expected number, we did an index lookup (a unique scan) for all 100K rows returned from our connect by query.

11GR1 example

Let's do the same example in 11G. I've slightly modified the procedure to return two statistics -- consistent gets and consistent gets from cache (fastpath):

SQL> create or replace procedure get_cg(
 2   p_cg out number,
 3   p_cgfp out number
 4  ) is
 5  begin
 6   select max(case sn.NAME when 'consistent gets' then ms.value end),
 7     max(case sn.NAME when 'consistent gets from cache (fastpath)'
 then ms.value end)
 8     into p_cg, p_cgfp
 9    from v$mystat ms, v$statname sn
10    where ms.STATISTIC#=sn.STATISTIC#
11     and sn.NAME in ('consistent gets', 'consistent gets from 
cache (fastpath)');
12  end get_cg;
13  /

Procedure created

SQL> declare
 2   l_cg_b  number;
 3   l_cgfp_b number;
 4   l_cg_a  number;
 5   l_cgfp_a number;
 6  begin
 7   get_cg(l_cg_b, l_cgfp_b);
 8   for cur in (select n from (select mod(level, 1000)+1 l from dual connect by 
level <= 100000) l, t where t.n=l.l)
 9   loop
 10    null;
 11   end loop;
 12   get_cg(l_cg_a, l_cgfp_a);
 13   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 14   dbms_output.put_line('consistent gets (fastpath): '||to_char(l_cgfp_a-l_cgfp_b));
 15  end;
 16 
/
consistent gets: 2602
consistent gets (fastpath): 1400

PL/SQL procedure successfully completed

That's quite a difference! 2602 consistent gets for 11GR1 versus ~100K for 10GR2. Note a new consistent gets (fastpath) statistic appearing in this test case.

A slightly different example

To make you a bit more curious, here is a slightly different example executed on 11GR1:

SQL> declare
 2   l_cg_b  number;
 3   l_cgfp_b number;
 4   l_cg_a  number;
 5   l_cgfp_a number;
 6  begin
 7   get_cg(l_cg_b, l_cgfp_b);
 8   for cur in (select n from (select trunc(dbms_random.value(1, 1000)) l from 
dual connect by level <= 100000) l, t where t.n=l.l)
 9   loop
 10    null;
 11   end loop;
 12   get_cg(l_cg_a, l_cgfp_a);
 13   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 14   dbms_output.put_line('consistent gets (fastpath): '||to_char(l_cgfp_a-l_cgfp_b));
 15  end;
 16  /
consistent gets: 101998
consistent gets (fastpath): 2934

PL/SQL procedure successfully completed

As soon as we've started reading index blocks in a random fashion, the effect, well, disappeared. Thus far optimization seems to be kicking in only if we repeaditly accessing the same block over and over again.

Another slightly different example

10GR2:

SQL> declare
 2   l_cg_b  number;
 3   l_cg_a  number;
 4  begin
 5   get_cg(l_cg_b);
 6   for cur in (select v from (select mod(level, 1000)+1 l from dual connect by 
level <= 100000) l, t where t.n=l.l)
 7   loop
 8    null;
 9   end loop;
 10   get_cg(l_cg_a);
 11   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 12  end;
 13  /
consistent gets: 201001

PL/SQL procedure successfully completed

What we are doing here is reading the data from a table itself (not only from index). Again, that's expected number. We had to do an index unique scan followed by table access by rowid, resulting in two LIOs per returned row. Now, take a look what happens in 11GR1:

SQL> declare
 2   l_cg_b  number;
 3   l_cgfp_b number;
 4   l_cg_a  number;
 5   l_cgfp_a number;
 6  begin
 7   get_cg(l_cg_b, l_cgfp_b);
 8   for cur in (select v from (select mod(level, 1000)+1 l from dual connect by 
level <= 100000) l, t where t.n=l.l)
 9   loop
 10    null;
 11   end loop;
 12   get_cg(l_cg_a, l_cgfp_a);
 13   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 14   dbms_output.put_line('consistent gets (fastpath): '||to_char(l_cgfp_a-
l_cgfp_b));
 15  end;
 16  /
consistent gets: 102602
consistent gets (fastpath): 1400

PL/SQL procedure successfully completed

In other words, index blocks were "neutralized", but table blocks were not. Another point is that optimization still works for index blocks even though we accessing table blocks in between.

Works only for index blocks?

That's really simple to verify using the following example:

SQL> declare
 2   l_cg_b  number;
 3   l_cgfp_b number;
 4   l_cg_a  number;
 5   l_cgfp_a number;
 6  begin
 7   get_cg(l_cg_b, l_cgfp_b);
 8   for cur in (select v from (select case mod(level, 2) when 0 then 
'AAADq1AAEAAAAJHAAA' else 'AAADq1AAEAAAAJHAAB' end l from dual connect by level <= 
100000) l, t where t.rowid=l.l)
 9   loop
 10    null;
 11   end loop;
 12   get_cg(l_cg_a, l_cgfp_a);
 13   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 14   dbms_output.put_line('consistent gets (fastpath): '||to_char(l_cgfp_a-
l_cgfp_b));
 15  end;
 16  /
consistent gets: 1000
consistent gets (fastpath): 1000

PL/SQL procedure successfully completed

The same example in 10GR2, of course, produces ~100K LIOs, so the optimization seems to be kicking in for table blocks as well. Further, the behavior in the previous example can not be explained by table blocks being randomly distributed since the clustering factor is perfect:

SQL> select sum(bn_diff)
 2   from (
 3    select case when bn!=lag(bn, 1, bn) over (order by n)then 1 else 0 
end bn_diff
 4     from (select n, dbms_rowid.rowid_block_number(rowid) bn from 
t)
 5   );

SUM(BN_DIFF)
------------
         15

SQL> select count (distinct dbms_rowid.rowid_block_number(rowid)) from t;

COUNT(DISTINCTDBMS_ROWID.ROWID
------------------------------
                           16

Perhaps, there is some overhead associated with fastpath and the logic assumes a bad clustering factor by default (which works for majority of cases) thus doesn't tries to do a fastpath for table blocks in our previous example.

Moving further

Take a look at this:

SQL> declare
 2   l_cg_b  number;
 3   l_cgfp_b number;
 4   l_cg_a  number;
 5   l_cgfp_a number;
 6  begin
 7   get_cg(l_cg_b, l_cgfp_b);
 8   for cur in (select t1.n n1, t2.n n2 from (select mod(level, 1000)+1 l from 
dual connect by level <= 100000) l, t t1, t t2 where t1.n=l.l and t2.n=l.l)
 9   loop
 10    null;
 11   end loop;
 12   get_cg(l_cg_a, l_cgfp_a);
 13   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 14   dbms_output.put_line('consistent gets (fastpath): '||to_char(l_cgfp_a-
l_cgfp_b));
 15  end;
 16  /
consistent gets: 5204
consistent gets (fastpath): 2800

PL/SQL procedure successfully completed

I've simply added the same table into a join twice. Though we were accessing exactly the same blocks from the same table, the optimization didn't span both tables.

Doesn't work across fetches

SQL> declare
 2   l_cg_b  number;
 3   l_cgfp_b number;
 4   l_cg_a  number;
 5   l_cgfp_a number;
 6  begin
 7   get_cg(l_cg_b, l_cgfp_b);
 8   for cur in (select n from (select 1 l from dual connect by level <= 100000) 
l, t where t.n=l.l)
 9   loop
 10    null;
 11   end loop;
 12   get_cg(l_cg_a, l_cgfp_a);
 13   dbms_output.put_line('consistent gets: '||to_char(l_cg_a-l_cg_b));
 14   dbms_output.put_line('consistent gets (fastpath): '||to_char(l_cgfp_a-
l_cgfp_b));
 15  end;
 16  /
consistent gets: 1008
consistent gets (fastpath): 1001

PL/SQL procedure successfully completed

While we were accessing the same row (hence, the block), we got 1K LIOs. It is explained by 11G doing implicit array fetches by 100 rows at a time and also points out at the fact that consistent gets (fastpath) can not operate across fetches (though the same rule applies for "regular" consistent gets as well).

In a nutshell

Overall, this looks like a nice feature. The downside, of course, is less predictability. 11G seems to have introduces these little tricks and features all over the place, which can really help you under certain circumstances but can also make your head spin while trying to figure out for "magical" performance differences...

Added 16-Jan-2009: Take a look at Concurrency post by Jonathan Lewis for some more details.

Airlines...

noreply@blogger.com (Alex Fatkulin) — Mon, 12 Jan 2009 06:21:00 +0000

Reliability considered to be a table stake in the airlines industry. Something you have to have if you want to play the planes game at all.

I had a flight to Toronto a couple of days ago which I can describe as very fascinating and enlightening.

My flight was scheduled at 8AM and I arrived to Ottawa International airport around 7:10AM. After checking in and passing required security checks I was waiting to board my plane. Almost immediately after I begun to wait, airport intercom said:

- If there is anyone willing to board an earlier flight to Toronto, you can do so.

Well, fine. It is better to be in Pearson earlier than waiting in Ottawa. So I boarded a flight which was supposed to take off 25 minutes earlier.

As soon as everyone has boarded, they closed the doors and started to move the plane. When, suddenly, boom! I'm observing a lot of smoke coming from a back of the plane. The plane stops very hard, almost instantly. I can smell partially burned jet fuel. A minute later a fire extinguisher machine comes and stops a few meters from us doing nothing. I'm watching people becoming more and more curious (is the plane on fire? is it time to jump off the plane to avoid being cooked?). The pilot says:

- It seems that we've got some electronics snag here, let me try to reboot the on-board computer to see if that fixes the problem.

Now, that's cool. Ummm... Windows embedded or what? A couple of minutes later pilot comes again:

- It looks like our problem still persist, so I'm going to power off the entire plane and then put the power back on, let's hope it will fix our problem, because usually it does.

If there is a moment when you start thinking whether you should be sitting on the plane at all, it seems to be it. Some people has already stood up and clearly wandering how they can get off the plane. This is really a time when stewardess can help everyone:

- We were trying to figure out if there is a possibility to board the other plane but, unfortunately, all morning flights are extremely busy.

What a perfect argument to keep the plane's doors closed. The plane backs to life as pilots recycled the power...

- It looks like our problem was solved, so we are going to proceed for takeoff...

Why do I have that strange feeling that it would better be not solved so we can board off? Anyway, they are starting to move us again... When, suddenly, boom! I'm observing a lot of smoke coming from a back of the plane. Here we go again, a fire extinguisher machine comes. That's enough, who can show me the exit? The pilot:

- It appears that our problem reoccurred again, the brakes applied without anything telling them to apply.

Let me think what would happen had the brakes applied on a runway itself... not a rocket since.

- We are going to call the maintenance to see if they can fix the problem, it should take around 25-30 minutes...

Right, while they are calling the maintenance, I'm watching my flight taking off... Some guy comes in and disappears under the plane.

- It looks like maintenance fixed the problem and after they'll be done with a paperwork, we can proceed for takeoff...

Read the book, as Gordon says, if you don't do scheduled maintenance then the plane will schedule one for you. Trying to save costs? I have no doubts you can make service to be so cheap that no one wants to use it. Well, at least they gonna miss one of their KPIs, arrival on time, so there is a hope someone is going to do something about it...

Using DBMS_RULE_ADM to evaluate dynamic predicates

noreply@blogger.com (Alex Fatkulin) — Sun, 11 Jan 2009 04:45:00 +0000

The best comments are the ones which inspire you to try and learn something new. I received one of these to my recent blog post about Scaling dynamic SQL. Stas, one of my good friends, asked whether I have tried DBMS_RULE_ADM package for this task. Well, now I did. Stas, you should be careful what you ask next time, you might get it :)

The first thing we need to do is create an evaluation context:

SQL> declare
  2   l_vtl sys.re$variable_type_list;
  3  begin
  4   l_vtl:=sys.re$variable_type_list(
  5    sys.re$variable_type('age', 'number', null, null),
  6    sys.re$variable_type('balance', 'number', null, null),
  7    sys.re$variable_type('birthdate', 'date', null, null),
  8    sys.re$variable_type('today', 'date', null, null)
  9   );
 10  
 11   dbms_rule_adm.create_evaluation_context(
 12    evaluation_context_name => 'adverts_ctx',
 13    variable_types => l_vtl
 14   );
 15  end;
 16  /
 
PL/SQL procedure successfully completed

We can create the rules itself now:

SQL> declare
  2   l_rules dbms_sql.Varchar2_Table;
  3  begin
  4   dbms_rule_adm.create_rule_set(
  5    rule_set_name => 'adverts'
  6   );
  7  
  8   l_rules(1):=':age between 16 and 18';
  9   l_rules(2):=':birthdate = :today or :balance > 1000';
 10   l_rules(3):=':balance between 100 and 200 and :age > 18';
 11  
 12   for i in 1 .. 3
 13   loop
 14    dbms_rule_adm.create_rule(
 15     rule_name => 'rule_'||to_char(i),
 16     condition => l_rules(i),
 17     evaluation_context => 'adverts_ctx'
 18    );
 19  
 20    dbms_rule_adm.add_rule(
 21     rule_name => 'rule_'||to_char(i),
 22     rule_set_name => 'adverts'
 23    );
 24   end loop;
 25  end;
 26  /
 
PL/SQL procedure successfully completed

Since there will be no SQL executed, I've decided to simply measure wall clock time, given that we can obtain latch wait information from the extended SQL trace:

SQL> create table results
  2  (
  3   sid number,
  4   cs number
  5  );
 
Table created

Here is the test procedure itself:

SQL> create or replace procedure test_dra(
  2   p_i in number
  3  ) is
  4   l_age  sys.re$variable_value;
  5   l_balance sys.re$variable_value;
  6   l_birthdate sys.re$variable_value;
  7   l_today  sys.re$variable_value;
  8   l_vvl  sys.re$variable_value_list;
  9   l_true  sys.re$rule_hit_list;
 10   l_maybe  sys.re$rule_hit_list;
 11   l_time  number;
 12  begin
 13   l_age:=sys.re$variable_value('age', anydata.convertnumber(16));
 14   l_balance:=sys.re$variable_value('balance', anydata.convertnumber(1500));
 15   l_birthdate:=sys.re$variable_value('birthdate', anydata.convertdate(to_date('20090101', 'yyyymmdd')));
 16   l_today:=sys.re$variable_value('today', anydata.convertdate(trunc(sysdate)));
 17  
 18   l_vvl:=sys.re$variable_value_list(l_age, l_balance, l_birthdate, l_today);
 19  
 20   l_true:=sys.re$rule_hit_list();
 21   l_maybe:=sys.re$rule_hit_list();
 22  
 23   l_time:=dbms_utility.get_time;
 24   dbms_monitor.session_trace_enable(waits => true, binds => false);
 25  
 26   for i in 1 .. p_i
 27   loop
 28    dbms_rule.evaluate(
 29     rule_set_name => 'adverts',
 30     evaluation_context => 'adverts_ctx',
 31     variable_values => l_vvl,
 32     stop_on_first_hit => false,
 33     true_rules => l_true,
 34     maybe_rules => l_maybe
 35    );
 36   end loop;
 37  
 38   dbms_monitor.session_trace_disable;
 39   insert into results values (sys_context('userenv', 'sid'), dbms_utility.get_time-l_time);
 40  end test_dra;
 41  /
 
Procedure created

As before, I've used four parallel jobs with 100000 iterations each. Here are the results I've got:

SQL> select * from results;
 
       SID         CS
---------- ----------
       134       3472
       131       3412
       133       3205
       132       3358

And tkprof of one of the jobs:

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  library cache: mutex X                        769        0.00          0.04
  latch free                                     39        0.00          0.00

Which is, well, about 6.5 times slower given wall clock time compared to the cached results using package from my previous blog post:

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute 300000      4.85       4.97          0          0          0      300000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   300003      4.85       4.97          0          0          0      300000

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  library cache: mutex X                        209        0.00          0.00
  cursor: pin S wait on X                        98        0.01          1.04
  cursor: pin S                                 360        0.00          0.00

The interesting thing to note here is that DBMS_RULE_ADM seems to have a better scalability, however, I can't really say at what point it could be justified (if at all) given a pretty hefty wall clock time difference.