Страницы

четверг, 18 июня 2015 г.

Function-Based index changed its definition after a rebuild

One of our developers have discovered a problem when index column data type changed after index had been rebuild.
They asked me for help with that issue. Here's a demo script:
SQL> create table t(
  2    x int,
  3    y int);

Table created.

SQL> create index t_i on t(
  2    decode(x, 1, to_number(null), y));

Index created.

SQL> exec dbms_stats.gather_table_stats( '', 't')

PL/SQL procedure successfully completed.
I create a function-based index with one column.
The index column is defined to show "Y" column (with type int) if the "X" column isn't equal to 1 (or null).
According to a documentation:
http://docs.oracle.com/database/121/SQLRF/functions056.htm#SQLRF00631
Oracle automatically converts the return value to the same data type as the first result.
If the first result has the data type CHAR or if the first result is null, 
then Oracle converts the return value to the data type VARCHAR2.
Notice that index column data type is a NUMBER:
SQL> select column_name
  2    from user_ind_columns
  3   where index_name = 'T_I';

COLUMN_NAME
------------------------------
SYS_NC00003$

SQL> select data_type
  2    from user_tab_cols
  3   where table_name = 'T'
  4     and column_name = 'SYS_NC00003$';

DATA_TYPE
------------------------------
NUMBER
The developer have found that his query doesn't use the index:
SQL> explain plan for
  2  select *
  3    from t
  4   where decode(x, 1, to_number(null), y) = to_number(:1);

Explained.

SQL> 
SQL> @?/rdbms/admin/utlxpls

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
Plan hash value: 2153619298

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |    26 |     2   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T    |     1 |    26 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------

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

   1 - filter(DECODE("X",1,TO_NUMBER(NULL),"Y")=TO_NUMBER(:1))
Index will be used when he changed his query to following:
SQL> explain plan for
  2  select *
  3    from t
  4   where decode(x, 1, null, y) = to_number(:1);

Explained.

SQL> 
SQL> @?/rdbms/admin/utlxpls

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
Plan hash value: 2858887366

--------------------------------------------------------------------------------------------
| Id  | Operation                           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |      |     1 |    39 |     1   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| T    |     1 |    39 |     1   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | T_I  |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

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

   2 - access(DECODE("X",1,NULL,TO_CHAR("Y"))=TO_NUMBER(:1))
Why is this?
The index expression is not what I passed in the CREATE INDEX statement:
SQL> select column_expression
  2    from user_ind_expressions
  3   where index_name = 'T_I';

COLUMN_EXPRESSION
------------------------------
DECODE("X",1,NULL,"Y")
It looks like Oracle is "clever enough" to change our index expression from:
DECODE(X, 1, TO_NUMBER(NULL), Y)
to:
DECODE("X", 1, NULL, "Y")
This leads to unexpected results when index was rebuild:
alter index t_i rebuild;
The index column data type is VARCHAR2 after that!
SQL> select data_type
  2    from user_tab_cols
  3   where table_name = 'T'
  4     and column_name = 'SYS_NC00003$';

DATA_TYPE
------------------------------
VARCHAR2
Our query now suddenly has started using FTS where previously it was using an index:
SQL> explain plan for
  2  select *
  3    from t
  4   where decode(x, 1, null, y) = to_number(:1);

Explained.

SQL> 
SQL> @?/rdbms/admin/utlxpls

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------
Plan hash value: 2153619298

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |    48 |     2   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T    |     1 |    48 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------

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

   1 - filter(TO_NUMBER(DECODE("X",1,NULL,TO_CHAR("Y")))=TO_NUMBER(:1))

Index hint did not help either:
SQL> explain plan for
  2  select /*+ index(t t_i)*/*
  3    from t
  4   where decode(x, 1, null, y) = to_number(:1);

Explained.

SQL> 
SQL> @?/rdbms/admin/utlxpls

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
Plan hash value: 2153619298

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |    48 |     2   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T    |     1 |    48 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------

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

   1 - filter(TO_NUMBER(DECODE("X",1,NULL,TO_CHAR("Y")))=TO_NUMBER(:1))
Notice TO_NUMBER conversion at line 1:
   1 - filter(TO_NUMBER(DECODE("X",1,NULL,TO_CHAR("Y")))=TO_NUMBER(:1))
We should rewrite our query as follows:
SQL> explain plan for
  2  select *
  3    from t
  4   where decode(x, 1, null, y) = to_char(:1);

Explained.

SQL> 
SQL> @?/rdbms/admin/utlxpls

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
Plan hash value: 2858887366

--------------------------------------------------------------------------------------------
| Id  | Operation                           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |      |     1 |    48 |     1   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID BATCHED| T    |     1 |    48 |     1   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN                  | T_I  |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

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

   2 - access(DECODE("X",1,NULL,TO_CHAR("Y"))=:1)
To workaround this issue, we could use an index on virtual columns.
We could prevent TO_NUMBER(NULL) to NULL conversion by changing TO_NUMBER(NULL) to CAST(NULL as NUMBER), or other such expression.
I have opened the SR with Oracle and they told me that this's due to:
Bug 17871767: FUNCTION BASE INDEX DEFINITION CHANGED ON 11.2, ADDED A TO_CHAR FUNCTION This bug is still under work and hasn't been resolved yet.
Actually, this issue with function-based indexes has been present for a long time.
I have reproduced it on 9.2.0.6 at least.

четверг, 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.

среда, 11 февраля 2015 г.

Join elimination not performed in the presence of virtual columns on parent table

Today I observed poorly written SQL that performed unnecessary join between PARENT/CHILD tables:
SQL> select * from table(dbms_xplan.display_cursor( '23hbmd0xxv7p0'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID  23hbmd0xxv7p0, child number 0
-------------------------------------
SELECT P.ID FROM PARENT P, CHILD C WHERE P.ID = :B1 AND P.ID = C.PARENT_ID

Plan hash value: 3267741206

----------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name                | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                     |       |       |     5 (100)|          |
|   1 |  NESTED LOOPS                |                     |     2 |    36 |     5   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN          | PARENT_ID_PK        |     1 |     6 |     2   (0)| 00:00:01 |
|   3 |   TABLE ACCESS BY INDEX ROWID| CHILD               |     2 |    24 |     3   (0)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN          | CHILD_PARENT_FK_IDX |     2 |       |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

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

   2 - access("P"."ID"=:B1)
   4 - access("C"."PARENT_ID"=:B1)
PARENT table has primary key enabled and validated.
CHILD table with foreign key (enabled and validated) that references PARENT.
Without obvious reason JOIN ELIMINATION is not done when expected.
We are using Oracle database version 11.2.0.3.11 (PSU 11 applied).
I investigated this issue further and found that this's due to presence of virtual columns on PARENT table.
Below is a simple test case used to reproduce this issue (I copied this test case with little modification from Excellent Christian Antognini site):
SQL> CREATE TABLE t1 (
  2    id NUMBER NOT NULL,
  3    n NUMBER,
  4    pad VARCHAR2(4000),
  5    pad_virt varchar2(4000) generated always as (substr(pad,1,10)) virtual,
  6    CONSTRAINT t1_pk PRIMARY KEY(id)
  7  );
SQL> 
SQL> CREATE TABLE t2 (
  2    id NUMBER NOT NULL,
  3    t1_id NUMBER NOT NULL,
  4    n NUMBER,
  5    pad VARCHAR2(4000),
  6    CONSTRAINT t2_pk PRIMARY KEY(id),
  7    CONSTRAINT t2_t1_fk FOREIGN KEY (t1_id) REFERENCES t1
  8  );
SQL> 
SQL> CREATE OR REPLACE VIEW v AS
  2  SELECT t1.id AS t1_id, t1.n AS t1_n, t2.id AS t2_id, t2.n AS t2_n
  3    FROM t1, t2
  4   WHERE t1.id = t2.t1_id;
Lets select a rows only from child table:
SQL> EXPLAIN PLAN FOR SELECT t2_id, t2_n FROM v;
SQL> 
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------
Plan hash value: 733458710

----------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |     1 |    52 |     2   (0)| 00:00:01 |
|   1 |  NESTED LOOPS      |       |     1 |    52 |     2   (0)| 00:00:01 |
|   2 |   TABLE ACCESS FULL| T2    |     1 |    39 |     2   (0)| 00:00:01 |
|*  3 |   INDEX UNIQUE SCAN| T1_PK |     1 |    13 |     0   (0)| 00:00:01 |
----------------------------------------------------------------------------

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

   3 - access("T1"."ID"="T2"."T1_ID")
Join is not eliminated. Join is eliminated when I dropped virtual column:
SQL> ALTER TABLE t1 DROP COLUMN pad_virt;
SQL> 
SQL> EXPLAIN PLAN FOR SELECT t2_id, t2_n FROM v;
SQL> 
SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------
Plan hash value: 2904382265

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |    39 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS FULL| T2   |     1 |    39 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------
Could not find any obvious reason for this in 10053 trace file. But it looks like a problem is known since 2011: Bug 12739252 : JOIN ELIMINATION IS NOT DONE WHEN JOINING TABLE HAVE VIRTUAL COLUMN
Good news: problem is not reproduced in 11.2.0.4.4.

понедельник, 9 февраля 2015 г.

Suspending a users session on specific enqueue

Recently I faced a strange issue with EBR (Edition-Based Redefinition). In order to understand how things work internally I decided to use DTrace.
I wanted to suspend specific user session when session acquired AE lock. There are similar enq_trace.sh script that written by Tanel Poder. Tanel's script could be extended to accommodate to my specific requirements if needed.
My enq_suspend.d script is below:
#!/usr/sbin/dtrace -s

# pragma D option quiet
# pragma D option destructive

struct ksqrs_t {
  long     addr;
  char     b1[72];
  uint32_t id1;
  uint32_t id2;
  char     b2[4];
  char     idt[2];/*92=offset of X$KSQRS.KSQRSIDT column from x$kqfco*/
  char     b3[18];
};

struct ksqrs_t ksqrs;

pid$target:oracle:ksqgtl*:entry 
{ 
  ksqeq_lkadr = arg0; /* X$KSQEQ.KSQLKADR*/
  mode = arg1;
  timeout = arg3;
  lock_indx = arg4; /*X$KSIRESTYP.INDX*/
  flags = arg7;
} 

pid$target:oracle:ksqgtl*:return 
{
  ksqeq_lkres = *(long *)copyin(ksqeq_lkadr+8,8);
  ksqrs = *(struct ksqrs_t *)copyin(ksqeq_lkres,112);
  ksqrs.addr = ksqeq_lkres;
  printf("%d [%Y] %s: *** %s-%08x-%08x mode=%d flags=0x%x timeout=%d\n",
    timestamp,
    walltimestamp,
    probefunc,
    ksqrs.idt,
    ksqrs.id1,
    ksqrs.id2,
    mode, 
    flags, 
    timeout
  );
}

pid$target:oracle:ksqrcl*:entry 
{ 
  enqrs_addr = *(long *)copyin(arg0+8,8); /*X$KSQRS.ADDR enQueue Resource*/
  ksqrs = *(struct ksqrs_t *)copyin(enqrs_addr, 112);
  ksqrs.addr = enqrs_addr;
  printf("%d [%Y] %s: *** %s-%08x-%08x x$ksqrs.addr=0x%016x\n",
    timestamp,
    walltimestamp,
    probefunc,
    ksqrs.idt,
    ksqrs.id1,
    ksqrs.id2,
    ksqrs.addr
  );
} 

pid$target:oracle:ksqrcl*:entry 
/ksqrs.idt==$$1/
{
  printf("%d [%Y] %s.%s: lock_type=%s suspending execution\n", timestamp, walltimestamp, probefunc, probename, ksqrs.idt);
  stop();
}

pid$target:oracle:ksqrcl*:return {}
A brief description of the script.
  • # pragma D option quiet
    # pragma D option destructive
        
    Minimize output, allow destructive actions. We will use "stop()" call further.
  • struct ksqrs_t
    struct ksqrs_t {
      long     addr;
      char     b1[72];/*unknown not needed*/
      uint32_t id1;/*lock ID1*/
      uint32_t id2;/*lock ID2*/
      char     b2[4];/*unknown not needed*/
      char     idt[2];/*lock type, 92=offset of X$KSQRS.KSQRSIDT column from x$kqfco*/
      char     b3[18];/*unknown not needed*/
    };
        
    The above structure describes X$KSQRS entry (Kernel Services enQueue ReSource):
    SQL> select c.kqfconam column_name,
      2         c.kqfcodty datatype,
      3         c.kqfcosiz size_byte,
      4         c.kqfcooff offset
      5    from x$kqfta t,
      6         x$kqfco c
      7   where t.kqftanam = 'X$KSQRS'
      8     and c.kqfcotab = t.indx
      9   order by c.indx
     10  /
    
    COLUMN_NAME   DATATYPE  SIZE_BYTE     OFFSET
    ----------- ---------- ---------- ----------
    ADDR                23          8          0
    INDX                 2          4          0
    INST_ID              2          4          0
    KSQRSID1             2          4         80
    KSQRSID2             2          4         84
    KSQRSIDT             1          2         92
    KSQRSFLG             2          1        111
    
    ID1,ID2,IDT columns maps to relevant GV$LOCK columns, this can be obtained from V$FIXED_VIEW_DEFINITION:
    select s.inst_id, 
           l.laddr,
           l.kaddr,
           s.ksusenum,
           r.ksqrsidt,
           r.ksqrsid1, 
           r.ksqrsid2,
           l.lmode,
           l.request,
           l.ctime,
           decode(l.lmode,0,0,l.block)  
      from v$_lock l, 
           x$ksuse s, 
           x$ksqrs r  
     where l.saddr=s.addr 
       and concat(USERENV('Instance'),l.raddr)=concat(r.inst_id,r.addr)
    
  • ksqgtl.entry - get lock function, entry point
    pid$target:oracle:ksqgtl*:entry 
    { 
      ksqeq_lkadr = arg0; /* X$KSQEQ.KSQLKADR*/
      mode = arg1;
      timeout = arg3;
      lock_indx = arg4; /*X$KSIRESTYP.INDX*/
      flags = arg7;
    } 
    
    Interesting ksqgtl function arguments saved for further usage. In particularly, arg0 - is X$KSQEQ.KSQLKADR (lock address?).
  • ksqgtl.return - get lock function, return
    pid$target:oracle:ksqgtl*:return 
    {
      ksqeq_lkres = *(long *)copyin(ksqeq_lkadr+8,8);
      ksqrs = *(struct ksqrs_t *)copyin(ksqeq_lkres,112);
      ksqrs.addr = ksqeq_lkres;
      printf("%d [%Y] %s: *** %s-%08x-%08x mode=%d flags=0x%x timeout=%d\n",
        timestamp,
        walltimestamp,
        probefunc,
        ksqrs.idt,
        ksqrs.id1,
        ksqrs.id2,
        mode, 
        flags, 
        timeout
      );
    }
    
    We will interesting in "ID1", "ID2", "TYPE" lock attributes. We can fully decode them from X$KSQRS fixed table.
    But ksqgtl called with X$KSQEQ.KSQLKADR. X$KSQEQ.KSQLKRES maps to X$KSQRS.ADDR.
    SQL> select c.kqfconam column_name,
      2         c.kqfcodty datatype,
      3         c.kqfcosiz size_byte,
      4         c.kqfcooff offset
      5    from x$kqfta t,
      6         x$kqfco c
      7   where t.kqftanam = 'X$KSQEQ'
      8     and c.kqfcotab = t.indx
      9   order by c.indx
     10  /
    
    COLUMN_NAME   DATATYPE  SIZE_BYTE     OFFSET
    ----------- ---------- ---------- ----------
    ADDR                23          8          0
    INDX                 2          4          0
    INST_ID              2          4          0
    KSSOBFLG             2          4          0
    KSSOBOWN            23          8          0
    KSQLKADR            23          8         88
    KSQLKRES            23          8         96
    KSQLKMOD             2          1        176
    KSQLKREQ             2          1        177
    KSQLKMXH             2          2        178
    KSQLKSES            23          8          0
    KSQLKCTIM            2          4          0
    KSQLKLBLK            2          4          0
    
    We will print debug output similar to Tanel Poder script and 10704 event format.
  • pid$target:oracle:ksqrcl*:entry 
    { 
      enqrs_addr = *(long *)copyin(arg0+8,8); /*X$KSQRS.ADDR enQueue Resource*/
      ksqrs = *(struct ksqrs_t *)copyin(enqrs_addr, 112);
      ksqrs.addr = enqrs_addr;
      printf("%d [%Y] %s: *** %s-%08x-%08x x$ksqrs.addr=0x%016x\n",
        timestamp,
        walltimestamp,
        probefunc,
        ksqrs.idt,
        ksqrs.id1,
        ksqrs.id2,
        ksqrs.addr
      );
    } 
    
  • ksqrcl function (release lock) entry point:
    pid$target:oracle:ksqrcl*:entry 
    { 
      enqrs_addr = *(long *)copyin(arg0+8,8); /*X$KSQRS.ADDR enQueue Resource*/
      ksqrs = *(struct ksqrs_t *)copyin(enqrs_addr, 112);
      ksqrs.addr = enqrs_addr;
      printf("%d [%Y] %s: *** %s-%08x-%08x x$ksqrs.addr=0x%016x\n",
        timestamp,
        walltimestamp,
        probefunc,
        ksqrs.idt,
        ksqrs.id1,
        ksqrs.id2,
        ksqrs.addr
      );
    } 
    
    We will populate a ksqrs struct again.
  • If lock type equals to parameter passed to script, we will suspend process execution:
    pid$target:oracle:ksqrcl*:entry 
    /ksqrs.idt==$$1/
    {
      printf("%d [%Y] %s.%s: lock_type=%s suspending execution\n", timestamp, walltimestamp, probefunc, probename, ksqrs.idt);
      stop();
    }
    
Short demonstration how this works.
Suppose I will want suspend server process when session acquires TM lock. 1. I opened new session to the DB and determine server process ID and tracefile location:
SQL> select p.spid,
  2         p.tracefile
  3    from v$session s,
  4         v$process p
  5   where s.sid = sys_context( 'userenv', 'sid')
  6     and p.addr = s.paddr
  7  /

SPID  TRACEFILE
----- ----------------------------------------------------------------------------------------------------
1968  /pub/home/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_1968.trc
2. I created test table:
SQL> create table t (x int);

Table created.
SQL> select object_id,
  2         to_char(object_id, 'fm0xxxxxxx') object_id_hex
  3    from obj
  4   where object_name='T';

 OBJECT_ID OBJECT_ID_HEX
---------- ---------------------------
    349673 000555e9
3. Now I enable additional diagnostics: event 10704 to trace enqueues:
SQL> alter session set events '10704 level 2';

Session altered.
4. Next I will run DTrace script enq_suspend.d passing server process ID as parameter:
oracle@localhost dtrace$ ./enq_suspend.d -p 1968 TM
5. Trying to truncate table T:

Session suspending.
6. Observed output into console with DTrace script:
oracle@localhost dtrace$ ./enq_suspend.d -p 1968 TM
33969273235645237 [2015 Feb  9 12:42:21] ksqgtlctx: *** TM-000555e9-00000000 mode=6 flags=0x401 timeout=0
33969273240887878 [2015 Feb  9 12:42:21] ksqgtlctx: *** TX-0004001b-0000f92e mode=6 flags=0x401 timeout=0
33969273245689382 [2015 Feb  9 12:42:21] ksqrcl: *** TX-0004001b-0000f92e x$ksqrs.addr=0x000000041cda5c90
33969273245764458 [2015 Feb  9 12:42:21] ksqrcli: *** TX-0004001b-0000f92e x$ksqrs.addr=0x000000041cda5c90
33969273246279405 [2015 Feb  9 12:42:21] ksqrcl: *** TM-000555e9-00000000 x$ksqrs.addr=0x000000041cda25d0
33969273246301204 [2015 Feb  9 12:42:21] ksqrcl.entry: lock_type=TM suspending execution
You can see that when calling ksqrcl with TM-000555e9-00000000 (our object id) execution is suspending. We can gather any required diagnostic data at this step. 7. 10704 event data in the trace file:
*** 2015-02-09 12:42:21.102
ksqgtl *** TM-000555e9-00000000 mode=6 flags=0x401 timeout=0 ***
ksqgtl: xcb=0x419a6f068, ktcdix=2147483647, topxcb=0x419a6f068
        ktcipt(topxcb)=0x0
ksucti: init txn DID from session DID 
ksqgtl:
        ksqlkdid: 0001-0019-00000142
*** ksudidTrace: ksqgtl
        ktcmydid(): 0001-0019-00000142
        ksusesdi:   0001-0019-00000143
        ksusetxn:   0001-0019-00000142
ksqgtl: RETURNS 0
ksqgtl *** TX-0004001b-0000f92e mode=6 flags=0x401 timeout=0 ***
ksqgtl: xcb=0x419a6f068, ktcdix=2147483647, topxcb=0x419a6f068
        ktcipt(topxcb)=0x0
ksucti: init session DID from txn DID: 
ksqgtl:
        ksqlkdid: 0001-0019-00000142
*** ksudidTrace: ksqgtl
        ktcmydid(): 0001-0019-00000142
        ksusesdi:   0001-0019-00000143
        ksusetxn:   0001-0019-00000142
ksqgtl: RETURNS 0
ksqrcl: TX,4001b,f92e
ksqrcl: returns 0
enq_suspend.d script can be further extending for more complex conditions: such as stop when session acquires TM lock with particular object_id and mode, and so on. Script verified in my environment: Oracle Database version 11.2.0.3 on Solaris 10 SPARC64.

понедельник, 22 декабря 2014 г.

c3p0 PROBABLYNOT connection test query

I am participating in the project, which uses Play framework version 1.x.
Business logic at the application level, data stored in the Oracle database.
An SQL query below caught my attention:
--sql_id=az33m61ym46y4
SELECT NULL AS table_cat,
       o.owner AS table_schem,
       o.object_name AS table_name,
       o.object_type AS table_type,
       NULL AS remarks
  FROM all_objects o
  WHERE o.owner LIKE :1 ESCAPE '/'
    AND o.object_name LIKE :2 ESCAPE '/'
    AND o.object_type IN ('xxx', 'TABLE')
  ORDER BY table_type, table_schem, table_name
This query was executed 100K times per hour.
I enable SQL trace for a short time period to help diagnose this issue further:
alter system set events 'sql_trace[sql:az33m61ym46y4] bind=true';
"Bad" query was executed by different users but has same bind variable data:
BINDS #18446744071469205160:
Bind#0
  oacdty=01 mxl=32(04) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=873 siz=160 off=0
  kxsbbbfp=ffffffff7a760438  bln=32  avl=01  flg=05
  value="%"
Bind#1
  oacdty=01 mxl=128(44) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=873 siz=0 off=32
  kxsbbbfp=ffffffff7a760458  bln=128  avl=11  flg=01
  value="PROBABLYNOT"
Looks like we are faced with a c3p0 default connection test query.
Play framework uses the popular c3p0 for its connection pool. This query could be changed for something lightweight, such as:
select 'x' from dual
I sent that information to Java programmers and they promised to fix this issue.

вторник, 16 сентября 2014 г.

Bug 4991675 - Diagnostic event improve diagnosability of data dictionary invalidation issues

In recent MOS HOT Topics email I found a note: Bug 4991675 - Diagnostic event improve diagnosability of data dictionary invalidation issues (Doc ID 4991675.8) Many DBAs faced with "sporadic" invalidation issues in their work. Finding a root cause for such issues is not always easy. In many cases we investigate audit records, process redo logs with LogMiner and so on. You are out of problem when there are no DDL in database. Unfortunately, such goal not always reachable. In patch readme you can find next notes:
Note:Patch Post Install Steps:
This fix enhances the _trace_kqlidp parameter therefore please set this
parameter to true to enable this fix.
_trace_kqlidp was probably introduced in 11.1 but this patch enhances the parameter. I wrote a simple test case that can be used to demonstrate the effect of _trace_kqlidp parameter.
def tns_alias=orcl

conn /@&tns_alias.
drop user tc cascade;
grant connect to tc identified by tc;
grant alter session, create procedure, create table to tc;

conn tc/tc@&tns_alias.

create table t(x int) segment creation deferred;

create or replace procedure p
is
begin
  for t_rec in (
    select * from t)
  loop
    null;
  end loop;
end;
/

alter session set "_trace_kqlidp"=true;

select status from obj where object_name='P';
alter table t add y int;
select status from obj where object_name='P';
Latest alter table invalidates the procedure P. With parameter _trace_kqlidp set I see in trace file on 11.2.0.3:
ksedsts()+1296<-kqlidp0()+12068<-atbdrv()+26728<-opiexe()+20544<-opiosq0()+5576<-kpooprx()+212<-kpoal8()+536<-opiodr()+1164<-ttcpip()+1104<-opitsk()+1664<-opiino()+924<-opiodr()+1164<-opidrv()+1032<-sou2o()+88<-opimai_real()+504<-ssthrdmain()+316<-main()+316
<-_start()+380Fine-grain delta dump for unit TC.T
- Change bit vector 0:
  -23, -16, 
- Change bit vector 1:Empty
- Change bit vector 2:Empty
- Shift table:Empty 
kqlidp0: 964375 (CURSOR TC.T) (Parent:    0) [ROOT]
kqlidp0:. 964376 (PROCEDURE TC.P) (Parent:964375) [ADDED TO QUEUE]
kqlidp0:. 964376 (PROCEDURE TC.P) (Parent:964375) [INVALIDATE]
On 12.1.0.2:
INVALIDATION: Current SQL follows
alter table t add y int
ksedsts()+392<-kqlidp0()+11984<-atbdrv()+6728<-opiexe()+22596<-opiosq0()+3928<-kpooprx()+196<-kpoal8()+656<-opiodr()+1100<-ttcpip()+972<-opitsk()+1820<-opiino()+920<-opiodr()+1100<-opidrv()+932<-sou2o()+112<-opimai_real()+756<-ssthrdmain()+456<-main()+320<-_start()+300
Fine-grain delta dump for unit TC.T
- Change bit vector 0:
  -23, -16, 
- Change bit vector 1:Empty
- Change bit vector 2:Empty
- Shift table:Empty 
kqlidp0: 91877 (CURSOR TC.T) (Parent:    0) [ROOT]
kqlidp0:. 91878 (PROCEDURE TC.P) (Parent:91877) [ADDED TO QUEUE]
kqlidp0:. 91878 (PROCEDURE TC.P) (Parent:91877) [INVALIDATE]
We can see that patch 4991675 probably adds highlighted lines. "INVALIDATION" line helps in trace file identification. "Current SQL" line simplify root cause analysis. Update: alert.log also populated with "INVALIDATION" line.
Tue Sep 16 10:16:50 2014
INVALIDATION performed by ospid=21919. Please see tracefile.

суббота, 23 августа 2014 г.

event 10505

[oracle@oracle ~]$ oerr ora 10505
10505, 00000, "CBO enable dynamic sampling dump to table"
// *Cause:
// *Action:
Event 10505 can be used to dump dynamic sampling data to table. Same information can be obtained from event 10053 trace files. This event requires additional tables:
-- general table and dynamic sampling stats
create table kkedsamp_table(
  table_name varchar2(30),
  dyn_sampling_level number,
  c3 number, -- unknown
  c4 number, -- unknown
  c5 number, -- unknown
  c6 number, -- unknown
  c7 number, -- unknown
  single_table_dyn_sel_est number,
  dynamic_sampling_card number,
  sample_pct number,
  c11 number, -- unknown, partitioning
  c12 number, -- unknown, partitioning
  c13 number, -- unknown, partitioning
  c14 number, -- unknown
  actual_sample_size number,
  filtered_sample_card number,
  orig_card number,
  block_cnt_for_sampling_tabstat number,
  c19 number,
  max_sample_block_cnt number,
  sample_block_cnt number,
  min_sel_est number);
-- column stats
create table kkedsamp_column(
  column_name varchar2(30),
  table_name varchar2(30),
  c3 number, -- unknown
  num_distinct number,
  num_distinct_scaled number,
  num_nulls number,
  num_nulls_scaled number);
-- index stats
create table kkedsamp_index(
  index_name varchar2(30),
  table_name varchar2(30),
  c3 number, -- unknown
  index_selectity_est number,
  min_sel_est number, 
  c6 number, -- unknown
  num_blocks number);
Test case (run on 11.2.0.3):
SQL> create table t1 as select * from dba_objects;

Table created.
SQL> create table t2 as select * from dba_objects;

Table created.
SQL> create index t1_subobject_name_i on t1(subobject_name);

Index created.
SQL> exec dbms_stats.delete_index_stats( '', 'T1_SUBOBJECT_NAME_I')

PL/SQL procedure successfully completed.
SQL> alter session set events '10505';

Session altered.
SQL> select /*+ dynamic_sampling(4)*/
  2         count(*)
  3    from t1, t2
  4   where t1.owner='SYSTEM'
  5     and t2.subobject_name=t1.subobject_name
  6     and t2.object_type like 'TABLE%';

  COUNT(*)
----------
      3425
SQL> alter session set events '10505 off';

Session altered.
SQL> @pt "select * from kkedsamp_table"
TABLE_NAME                    : "T1"
DYN_SAMPLING_LEVEL            : 4
C3                            : 1
C4                            : 1
C5                            : 1
C6                            : 1
C7                            : 1
SINGLE_TABLE_DYN_SEL_EST      : .060506329113924
DYNAMIC_SAMPLING_CARD         : 12665.0793650794
SAMPLE_PCT                    : 31.1881188118812
C11                           : 1
C12                           : 1
C13                           : 1
C14                           : 1
ACTUAL_SAMPLE_SIZE            : 3950
FILTERED_SAMPLE_CARD          : 239
ORIG_CARD                     : 16500
BLOCK_CNT_FOR_SAMPLING_TABSTAT: 202
C19                           : 0
MAX_SAMPLE_BLOCK_CNT          : 64
SAMPLE_BLOCK_CNT              : 63
MIN_SEL_EST                   : .01
-----------------
TABLE_NAME                    : "T2"
DYN_SAMPLING_LEVEL            : 4
C3                            : 1
C4                            : 1
C5                            : 1
C6                            : 1
C7                            : 0
SINGLE_TABLE_DYN_SEL_EST      : .135717785399314
DYNAMIC_SAMPLING_CARD         : 13088.3174603175
SAMPLE_PCT                    : 31.1881188118812
C11                           : 1
C12                           : 1
C13                           : 1
C14                           : 1
ACTUAL_SAMPLE_SIZE            : 4082
FILTERED_SAMPLE_CARD          : 554
ORIG_CARD                     : 16500
BLOCK_CNT_FOR_SAMPLING_TABSTAT: 202
C19                           : 0
MAX_SAMPLE_BLOCK_CNT          : 64
SAMPLE_BLOCK_CNT              : 63
MIN_SEL_EST                   : .05
-----------------

PL/SQL procedure successfully completed.
SQL> @pt "select * from kkedsamp_column"
COLUMN_NAME                   : "T1"."SUBOBJECT_NAME"
TABLE_NAME                    : "T1"
C3                            : 3
NUM_DISTINCT                  : 160
NUM_DISTINCT_SCALED           : 161
NUM_NULLS                     : 3699
NUM_NULLS_SCALED              : 11860.2857142857
-----------------
COLUMN_NAME                   : "T2"."SUBOBJECT_NAME"
TABLE_NAME                    : "T2"
C3                            : 3
NUM_DISTINCT                  : 66
NUM_DISTINCT_SCALED           : 66
NUM_NULLS                     : 3997
NUM_NULLS_SCALED              : 12815.7777777778
-----------------

PL/SQL procedure successfully completed.
SQL> @pt "select * from kkedsamp_index"
INDEX_NAME                    : T1_SUBOBJECT_NAME_I
TABLE_NAME                    : "T1"
C3                            : 0
INDEX_SELECTITY_EST           : -1
MIN_SEL_EST                   : -1
C6                            : 1
NUM_BLOCKS                    : 8
-----------------
PL/SQL procedure successfully completed.