Oracle 11g’s Query Result Cache — Introducing the RC Enqueue

Aug 27, 2007 / By Alex Fatkulin

Tags: ,

Way before 11G made its way to production, I joked that this new feature called Query Result Cache will just implicitly create a materialized view, protecting dependent objects with some new enqueue while doing so. Now we all can start the new release — at least on Linux x86 — so naturally, I was curious to see whether I was just throwing sparks without having a fire. Query Result Cache was the first new feature that I put to the test, only to discover that you can spend more than two minutes waiting on… guess what.

There is how it supposed to work:

SQL> create table t as select * from all_objects;

Table created.

SQL> set autot traceonly stat
SQL> select /*+ result_cache */ owner, count(*) from t group by owner;

18 rows selected.

Statistics
----------------------------------------------------------
         48  recursive calls
          0  db block gets
        986  consistent gets
        906  physical reads
          0  redo size
        780  bytes sent via SQL*Net to client
        403  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         18  rows processed

SQL> select /*+ result_cache */ owner, count(*) from t group by owner;

18 rows selected.

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

Notice zero LIO count for a second execution. That’s pretty much the same effect you can observe while accessing fast dual. Since Result Cache is subject to read-only access, it should be backed up by lighter-weight serialization stuff than the traditional buffer cache. But more on that next time.

Okay, what about the fun part, you ask? The fun part is that it took me roughly 30 seconds to realize the presence of a new enqueue. Let’s go…

SQL> set autot off
SQL> drop table t;

Table dropped.

SQL> create table t as select level n from dual connect by level <=2;

Table created.

SQL> select * from t;

         N
----------
         1
         2

I’m going with the simplest example I could think of. You are free to apply that to any real-world situation you can imagine.

Now I need to declare a refcursor:

SQL> variable rc refcursor;
SQL> exec open :rc for select /*+ result_cache */ n from t;

PL/SQL procedure successfully completed.

I also need a procedure to fetch a single row from that refcursor:

SQL> create or replace procedure rc_fetch(
  2    p_rc in sys_refcursor
  3   ) is
  4   l_n number;
  5  begin
  6   fetch p_rc into l_n;
  7   dbms_output.put_line(to_char(l_n));
  8  end;
  9  /

Procedure created.

Let’s go ahead and do a fetch.

SQL> set serveroutput on
SQL> exec rc_fetch(:rc);
1

PL/SQL procedure successfully completed.

Now open a second session and try to do the same.

SQL> variable rc refcursor;
SQL> exec open :rc for select /*+ result_cache */ n from t;

PL/SQL procedure successfully completed.

SQL> exec dbms_monitor.session_trace_enable(waits => true, binds => false);

PL/SQL procedure successfully completed.

SQL> set serveroutput on
SQL> set timing on
SQL> exec rc_fetch(:rc);
1

PL/SQL procedure successfully completed.

Elapsed: 00:02:17.17

How’s that? More than two minutes to fetch a single record with this new all-around-EE feature? What does tkprof have to say?

SELECT /*+ result_cache */ N 
FROM                                                                                                                                                                        
 T

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        1      0.00     137.17          0          3          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00     137.17          0          3          0           1

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

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  enq: RC - Result Cache: Contention              6       87.15        137.17

Relevant raw trace data:

*** 2007-08-26 13:35:58.918
WAIT #4: nam='enq: RC - Result Cache: Contention' ela= 10003413 name|mode=1380122628 chunkNo=1 blockNo=1 obj#=12448 tim=1188149758918762

*** 2007-08-26 13:36:08.923
WAIT #4: nam='enq: RC - Result Cache: Contention' ela= 10004415 name|mode=1380122628 chunkNo=1 blockNo=1 obj#=12448 tim=1188149768923387

*** 2007-08-26 13:36:18.928
WAIT #4: nam='enq: RC - Result Cache: Contention' ela= 10004434 name|mode=1380122628 chunkNo=1 blockNo=1 obj#=12448 tim=1188149778927982

*** 2007-08-26 13:36:28.931
WAIT #4: nam='enq: RC - Result Cache: Contention' ela= 10003340 name|mode=1380122628 chunkNo=1 blockNo=1 obj#=12448 tim=1188149788931595

*** 2007-08-26 13:36:38.935
WAIT #4: nam='enq: RC - Result Cache: Contention' ela= 10003460 name|mode=1380122628 chunkNo=1 blockNo=1 obj#=12448 tim=1188149798935215

*** 2007-08-26 13:38:06.086
WAIT #4: nam='enq: RC - Result Cache: Contention' ela= 87151350 name|mode=1380122628 chunkNo=1 blockNo=1 obj#=12448 tim=1188149886086834

Introduce yourself to the enq: RC - Result Cache: Contention wait. Cache can be like that sometimes.

Let’s go back to the first session:

SQL> select sid, type, id1, id2, lmode
  2   from v$lock
  3   where sid=sys_context('userenv', 'sid');

       SID TY        ID1        ID2      LMODE
---------- -- ---------- ---------- ----------
       135 AE         99          0          4
       135 RC          1          1          6

It’s a pity that no one bothered to add those enqueues here (probably in the desperate belief that no one will notice their presence). You can discover that any user session connected to a database is holding AE enqueue in shared mode. The purpose of that enqueue is unknown to me for now. RC stands for Result Cache.

So you see, our first session is holding the RC enqueue in exclusive mode. The second session was trying to acquire this enqueue in shared mode until a certain amount of timeouts (six, according to our trace). The good news is that subsequent executions in any other session (including our second session) will not try to acquire RC enqueue again. The bad news is that they will not use Result Cache. As long as our first session has fetched all rows from a refcursor all other sessions will suddenly start to use Result Cache without incrementing the total_req# stat for RC enqueue in the v$enqueue_stat view.

So there should be some other mechanism in place. But more on that in my next blog post.

6 Responses to “Oracle 11g’s Query Result Cache — Introducing the RC Enqueue”

Leave a Reply

  • (will not be published)

XHTML: You can use these tags: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>