Страницы

четверг, 21 мая 2015 г.

session cursor cache count statistics incorrect with parallel queries

Recently I investigated a issue with high 'session cursor cache count' statistics in one of database version 11.2.0.4. I found that some of the sessions have extremely high values of this statistics:
SQL> select s.sid, ss.value, s.logon_time, s.service_name, s.program
  2    from v$session s,
  3         v$statname sn,
  4         v$sesstat ss
  5   where sn.name='session cursor cache count'
  6     and ss.statistic#=sn.statistic#
  7     and ss.value > 100
  8     and s.sid=ss.sid;

       SID      VALUE LOGON_TIME          SERVICE_NAME PROGRAM
---------- ---------- ------------------- ------------ ----------------
       485        255 19.05.2015 02:47:52 dp_task      JDBC Thin Client
       705      12774 19.05.2015 02:47:51 dp_task      JDBC Thin Client
       800        267 19.05.2015 02:47:51 dp_task      JDBC Thin Client
session_cached_cursors parameter has default value of 50. My first thought was that sessions changed session_cached_cursors parameter. To confirm my hypothesis, I executed below oradebug command:
oradebug dump modified_parameters 1
Looking into trace file:
Received ORADEBUG command (#1) 'dump modified_parameters 1' from process 'Unix process pid: 13761, image: <none>'
DYNAMICALLY MODIFIED PARAMETERS:
  nls_language             = AMERICAN
  nls_territory            = AMERICA
  log_archive_dest_state_3 = ENABLE
  service_names            = drep_dp_stat, drep_dp_task, drep_ora_at, drep_dp_core

*** 2015-05-14 10:44:20.744
Finished processing ORADEBUG command (#1) 'dump modified_parameters 1'
So session_cached_cursors parameter wasn't changed by session. At the next step I decided to dump all cursors cached by session:
oradebug dump cursordump 1
Here is a relevant portion of trace file:
----- Session Cached Cursor Dump -----
----- Generic Session Cached Cursor Dump -----
-----------------------------------------------------------
-------------- Generic Session Cached Cursors Dump --------
-----------------------------------------------------------
hash table=ffffffff79d34228 cnt=50 LRU=ffffffff79d245f0 cnt=49 hit=64510 max=50 NumberOfTypes=6
From the above, there was no doubt that 'session cursor cache count' statistic is lying. I opened SR with Oracle and support engineer pointed to a Bug 5713223 : 'SESSION CURSOR CACHE COUNT' OF V$SYSSTAT IS NOT CURRENT VALUE
This bug was opened in 2006 for 10.2 version and still not resolved yet.
I have couple of SR with Oracle in which I waiting for resolution of such long-lived bugs. So, I decided to further diagnose this issue and provide additional information to the Oracle Support. All of the sessions are using dp_task database service. I created this service for reporting application that executes bunch of heavy SQL.
I wrote a simple job that takes a snapshots of v$session, v$sesstat on periodic interval. On a next day I check generated data and find couple of suspicious SQL for further investigation.
Most of them are used some of combination: PARALLEL hint, pipelined table functions, MATERIALIZE hint. Deeping into this further, I found that a incorrect statistics are due to PARALLEL hint.
I created a simple test case that was used to reproduce this issue.
create table t as select * from dba_objects;

sho parameter session_cached_cursors

select s.value 
  from v$statname n, 
       v$mystat s 
 where n.name = 'session cursor cache count' 
   and s.statistic#=n.statistic#;

select /*+ parallel(4)*/count(distinct owner) from t;

select s.value 
  from v$statname n, 
       v$mystat s 
 where n.name = 'session cursor cache count' 
   and s.statistic#=n.statistic#;

select /*+ parallel(4)*/count(distinct owner) from t;
    
Below is a SQL*Plus output of the script execution.
SQL> sho parameter session_cached_cursors

NAME                                 TYPE                              VALUE
------------------------------------ --------------------------------- ------------------------------
session_cached_cursors               integer                           50
SQL> 
SQL> select s.value
  2    from v$statname n,
  3         v$mystat s
  4   where n.name = 'session cursor cache count'
  5     and s.statistic#=n.statistic#;

     VALUE
----------
        49

SQL> 
SQL> select /*+ parallel(4)*/count(distinct owner) from t;

COUNT(DISTINCTOWNER)
--------------------
                  59

SQL> 
SQL> select s.value
  2    from v$statname n,
  3         v$mystat s
  4   where n.name = 'session cursor cache count'
  5     and s.statistic#=n.statistic#;

     VALUE
----------
        58
Notice that 'session cursor cache count' statistic is 49 before parallel query and 58 after. After I executed parallel query multiple times and checked a statistics at each step, I found that each query execution leads to increase of 'session cursor cache count' statistics by 2*(parallel_degree).
SQL> select /*+ parallel(4)*/count(distinct owner) from t;

COUNT(DISTINCTOWNER)
--------------------
                  59
SQL> 
SQL> select s.value
  2    from v$statname n,
  3         v$mystat s
  4   where n.name = 'session cursor cache count'
  5     and s.statistic#=n.statistic#;

     VALUE
----------
        98
SQL> 
SQL> select /*+ parallel(8)*/count(distinct owner) from t;

COUNT(DISTINCTOWNER)
--------------------
                  59

SQL> 
SQL> select s.value
  2    from v$statname n,
  3         v$mystat s
  4   where n.name = 'session cursor cache count'
  5     and s.statistic#=n.statistic#;

     VALUE
----------
       114
SQL> 
Good news: issue is not reproduced in 12.1.0.2. I hope that Oracle support resolve this issue in 11.2.0.4.

Update 17.06.2015: Oracle has released the patch 21135007: SESSION CURSOR CACHE COUNT STATISTICS IS INCORRECT
I applied it to 11.2.0.4 environment and it works as expected.
Now the 'session cursor cache count' statistics is correct.