Pythian Blog: Technical Track

Oracle 11g's Query Result Cache -- Introducing the RC Enqueue

by Pythian Marketing on Aug 27, 2007 12:00:00 AM

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.
Topics: Oracle Technical Track

No Comments Yet

Let us know what you think

See all

See all

Subscribe by email
Follow us
Love Your Data
Pythian Logo

© 2024 All rights reserved.