Страницы

Показаны сообщения с ярлыком 11g. Показать все сообщения
Показаны сообщения с ярлыком 11g. Показать все сообщения

понедельник, 30 января 2017 г.

DBMS_METADATA.GET_SXML_DDL may produce incorrect DDL for trigger in EBR environment

I have recently discovered a case when DBMS_METADATA.GET_SXML_DDL returns incorrect DDL for the trigger in an EBR environment.
Here is a test case to reproduce the issue that is present in 12.1.0.2.170117 and 11.2.0.4.161018:
SQL> grant connect, create table, create view, create trigger to tc identified by tc;

Grant succeeded.

SQL> 
SQL> alter user tc enable editions for view,trigger;

User altered.

SQL> 
SQL> conn tc/tc
Connected.
SQL> 
SQL> create table t (
  2    x int)
  3  /

Table created.

SQL> 
SQL> create or replace editioning view ev
  2  as
  3  select *
  4    from t
  5  /

View created.

SQL> 
SQL> create or replace trigger trg
  2  before update of x on ev
  3  declare
  4  begin
  5    null;
  6  end;
  7  /

Trigger created.
Let us look at the DDL of the trigger returning by DBMS_METADATA.GET_DDL and DBMS_METADATA.GET_SXML_DDL functions.
SQL> select dbms_metadata.get_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------

  CREATE OR REPLACE EDITIONABLE TRIGGER "TC"."TRG"
before update of x on ev
declare
begin
  null;
end;
ALTER TRIGGER "TC"."TRG" ENABLE


SQL> select dbms_metadata.get_sxml_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_SXML_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------
  CREATE OR REPLACE TRIGGER "TC"."TRG"
  BEFORE UPDATE OF X ON "TC"."EV"
  declare
begin
  null;
end;
They are pretty much the same. Now I change the status of my trigger. Please note the highlighted lines showing the differences:
SQL> alter trigger trg enable;

Trigger altered.

SQL> 
SQL> select dbms_metadata.get_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------

  CREATE OR REPLACE EDITIONABLE TRIGGER "TC"."TRG"
before update of x on ev
declare
begin
  null;
end;
ALTER TRIGGER "TC"."TRG" ENABLE


SQL> select dbms_metadata.get_sxml_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_SXML_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------
  CREATE OR REPLACE TRIGGER "TC"."TRG"
  BEFORE UPDATE OF X, X ON "TC"."EV"
  declare
begin
  null;
end;
I have ended up with two X columns in the output of DBMS_METADATA.GET_SXML_DDL, which is, in fact, a non-working DDL statement.
I played more with this issue and I have eventually obtained four X columns and it is not a limit:
SQL> alter trigger trg disable;

Trigger altered.

SQL> 
SQL> select dbms_metadata.get_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------

  CREATE OR REPLACE EDITIONABLE TRIGGER "TC"."TRG"
before update of x on ev
declare
begin
  null;
end;
ALTER TRIGGER "TC"."TRG" DISABLE


SQL> select dbms_metadata.get_sxml_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_SXML_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------
  CREATE OR REPLACE TRIGGER "TC"."TRG"
  BEFORE UPDATE OF X, X, X ON "TC"."EV"
  declare
begin
  null;
end;
  ALTER TRIGGER "TC"."TRG" DISABLE


SQL> 
SQL> alter trigger trg enable;

Trigger altered.

SQL> 
SQL> select dbms_metadata.get_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------

  CREATE OR REPLACE EDITIONABLE TRIGGER "TC"."TRG"
before update of x on ev
declare
begin
  null;
end;
ALTER TRIGGER "TC"."TRG" ENABLE


SQL> select dbms_metadata.get_sxml_ddl( 'TRIGGER', 'TRG') from dual;

DBMS_METADATA.GET_SXML_DDL('TRIGGER','TRG')
--------------------------------------------------------------------------------
  CREATE OR REPLACE TRIGGER "TC"."TRG"
  BEFORE UPDATE OF X, X, X, X ON "TC"."EV"
  declare
begin
  null;
end;
The DBMS_METADATA.GET_SXML_DDL procedure uses a SELECT statement similar to the above to obtain the DDL:
SELECT /*+all_rows*/ 
       SYS_XMLGEN(
         VALUE(KU$), 
         XMLFORMAT.createFormat2('TRIGGER_T', '7')), 
       KU$.OBJ_NUM 
  FROM SYS.KU$_TRIGGER_VIEW KU$ 
 WHERE NOT (KU$.BASE_OBJ IS NOT NULL AND BITAND(KU$.BASE_OBJ.FLAGS,128)!=0) 
   AND KU$.SCHEMA_OBJ.NAME = 'TRG' 
   AND KU$.SCHEMA_OBJ.OWNER_NAME = 'TC';
The column list for the trigger comes from this part of the SYS.KU$_TRIGGER_VIEW view:
          cast(multiset(select * from ku$_triggercol_view tv
                        where tv.obj_num=t.obj#
                      ) as ku$_triggercol_list_t
             ),
The code of the KU$_TRIGGERCOL_VIEW view is:
CREATE OR REPLACE FORCE NONEDITIONABLE VIEW "SYS"."KU$_TRIGGERCOL_VIEW" OF "SYS"."KU$_TRIGGERCOL_T"
  WITH OBJECT IDENTIFIER (obj_num,intcol_num,type_num) AS
  select '1','0',
         tc.obj#, tc.col#, tc.type#, tc.position#, tc.intcol#, c.name,
         (select a.name from attrcol$ a where
                        a.obj#=tc.obj# and a.intcol#=tc.intcol#)
  from col$ c, triggercol$ tc, trigger$ t
  where tc.obj#=t.obj#
    and c.obj#=t.baseobject
    and c.intcol#=tc.intcol#
And the final part of the puzzle is the TRIGGERCOL$ table:
SQL> select * from sys.triggercol$ where obj#=(select object_id from dba_objects where owner='TC' and object_name='TRG');

      OBJ#       COL#      TYPE#  POSITION#    INTCOL#
---------- ---------- ---------- ---------- ----------
    214352          1          0          0          1
    214352          1          0          0          1
    214352          1          0          0          1
    214352          1          0          0          1
    214352          1       1024          0          1
It gets one row each time I execute the "ALTER TRIGGER ENABLE/DISABLE" statement. I think Oracle Developers should filter the rows because there is only one row with TYPE#=1024.
DBMS_METADATA.GET_DDL returns correct DDL and it seems to be come from the DDL passed by a user.
Conversely, DBMS_METADATA.GET_SXML_DDL tries to reconstruct the user's DDL and it messes things up.

среда, 30 декабря 2015 г.

ORA-8102 on ALTER TABLE SHRINK SPACE with default column optimization

We have been using centralized AWR repository since 2013.
I developed some PL/SQL procedures for that using original awrextr.sql/awrload.sql scripts as a template.
That solution have some drawbacks, for example, an AWR retention for foreign databases always set to 40150 years after each load:
SQL> select dbid, retention from dba_hist_wr_control;

      DBID RETENTION
---------- --------------------
1110059808 +00366 00:00:00.0
1917063347 +40150 00:00:00.0
1996649024 +40150 00:00:00.0
We could change the retention but that would always be reset on the next AWR load.
To prevent the excessive AWR data growth, I executed DBMS_WORKLOAD_REPOSITORY.DROP_SNAPSHOT_RANGE procedure once a year.
The 2015 year was no exception.
I also executed ALTER TABLE SHRINK SPACE command after I had executed DBMS_WORKLOAD_REPOSITORY.DROP_SNAPSHOT_RANGE procedures.
Usually that command takes a while to execute, because the some of AWR tables are more than 50G in size, for example, WRH$_ACTIVE_SESSION_HISTORY.
It's a base table for DBA_HIST_ACTIVE_SESS_HISTORY view and contains an ASH data that's huge.
This year things went wrong:
SQL> alter table SYS.WRH$_ACTIVE_SESSION_HISTORY shrink space;
-- AFTER 4-8 hours
*
ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 635
Session ID: 281 Serial number: 54363
alert.log was not very helpful:
Mon Dec 21 14:37:31 2015
Process 0x3cd728e40 appears to be hung while dumping
Current time = 1689592362, process death time = 1689530965 interval = 60000
Called from location UNKNOWN:UNKNOWN
Attempting to kill process 0x3cd728e40 with OS pid = 17740
OSD kill succeeded for process 3cd728e40
Mon Dec 21 14:39:46 2015
Errors in file /oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_25447.trc:
But a relevant trace file (which was more than 4G in size) spotted a light on a problem:
*** ACTION NAME:() 2015-12-21 14:39:46.890
 
oer 8102.2 - obj# 1021709, rdba: 0x086ad43c(afn 33, blk# 2806844)
kdk key 8102.2:
  ncol: 6, len: 26
  key: (26): 
 06 c5 0c 0b 06 63 09 04 c3 08 0e 3e 02 c1 02 05 c4 62 46 05 3b 03 c2 02 3d
 ff
  mask: (4096): 
 81 90 20 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Well, string "oer 8102.2" it's a sign of famous ORA-8102 error:
[oracle@localhost ~]$ oerr ora 8102
08102, 00000, "index key not found, obj# %s, file %s, block %s (%s)"
// *Cause:  Internal error: possible inconsistency in index
// *Action:  Send trace file to your customer support representative, along
//      with information on reproducing the error
obj# 1021709 in the trace file easily shows to us where the problem is:
SQL> select xmltype(cursor(select * from dba_objects where object_id=1021709)) xml_rec from dual;

XML_REC
----------------------------------------------------------------------------------------------------------

<ROWSET>
  <ROW>
    <OWNER>SYS
    <OBJECT_NAME>WRH$_ACTIVE_SESSION_HISTORY_PK
    <SUBOBJECT_NAME>WRH$_ACTIVE_1110059808_66853
    <OBJECT_ID>1021709
    <DATA_OBJECT_ID>1080082
    <OBJECT_TYPE>INDEX PARTITION
    <CREATED>27.10.2015 01:28:05
    <LAST_DDL_TIME>22.12.2015 09:11:22
    <TIMESTAMP>2015-10-27:01:28:05
    <STATUS>VALID
    <TEMPORARY>N
    <GENERATED>N
    <SECONDARY>N
    <NAMESPACE>4
    <SHARING>NONE
    <ORACLE_MAINTAINED>Y
  </ROW>
</ROWSET>
The index WRH$_ACTIVE_SESSION_HISTORY_PK is local partitioned on next columns:
CREATE UNIQUE INDEX "SYS"."WRH$_ACTIVE_SESSION_HISTORY_PK" ON "SYS"."WRH$_ACTIVE_SESSION_HISTORY" ("DBID", "SNAP_ID", "INSTANCE_NUMBER", "SAMPLE_ID", "SESSION_ID", "CON_DBID")
The all of the above columns are numbers.
The index key:
  key: (26): 
 06 c5 0c 0b 06 63 09 04 c3 08 0e 3e 02 c1 02 05 c4 62 46 05 3b 03 c2 02 3d
 ff
can be decrypted easily:
SQL> with input as (
  2    -- index key
  3    select '06 c5 0c 0b 06 63 09 04 c3 08 0e 3e 02 c1 02 05 c4 62 46 05 3b 03 c2 02 3d ff' c from dual),
  4    t(pos, num,c) as (
  5    -- traverse the index key recursively
  6    select 0 pos, 0, replace(c, ' ') c from input union all
  7    select pos+1,
  8           utl_raw.cast_to_number(hextoraw(substr(c, 3, to_number(substr(c,1,2), 'xx')*2))),
  9           substr(c, (to_number(substr(c, 1, 2), 'xx')+1)*2+1)
 10      from t
 11     where c<>'ff')
 12  select pos, num
 13    from t
 14   where pos>0
 15   order by pos
 16  /

       POS        NUM
---------- ----------
         1 1110059808
         2      71361
         3          1
         4   97690458
         5        160
Ok, now we've known that: dbid=1110059808, snap_id=71361, instance_number=1, sample_id=97690458, session_id=160.
But the index was built on six columns when the problem key contains only five.
What is the CON_DBID for the problem key? That's where the trouble lies!
CON_DBID was introduced in Oracle 12.1 and added as a "DEFAULT NOT NULL" column, i.e. that column addition was a metadata-only operation without updating the table blocks (unless _add_col_optim_enabled was not set to FALSE).
SQL> select to_char(property, 'fm0xxxxxxx')
  2    from sys.col$
  3   where obj# = 22800
  4     and name = 'CON_DBID';

TO_CHAR(PROPERTY,'FM0XXXXXX
---------------------------
40000000
Notice that property was 0x40000000 - I speculated that such property was set to columns which were added with default column optimization.
Some MOS notes prove that, i.e. Table Columns Have Wrong Default Value After Transporting Tablespaces (Doc ID 1602994.1).
I dumped the relevant table block and found that CON_DBID column was not present in it.
The pieces of that puzzle started to fit together.
I had constructed a simple test case which reproduced an ORA-8102 error:
SQL> create table t(x int, pad varchar2(100)) enable row movement;
SQL> insert /*+ append*/
  2    into t
  3  select level, lpad('x', 100, 'x')
  4    from dual
  5    connect by level<=1e5;
SQL> commit;
SQL> 
SQL> alter table t add y int default 10 not null;
SQL> 
SQL> create index t_xy_i on t(x,y);
SQL> 
SQL> delete t where x<=1e5/2;
SQL> commit;
SQL> 
SQL> alter table t shrink space;
alter table t shrink space
*
ERROR at line 1:
ORA-08102: index key not found, obj# 91957, file 10, block 3990 (2)
The problem is present in Oracle 11.2.0.4 and more newest versions. I didn't test in earlier 11g patchsets.
Oracle Support raised a new bug: ORA-8102 ON ALTER TABLE SHRINK SPACE WITH ADD COL OPTIMIZATION (unpublished), which is still under investigation.
The tables suspected to an ORA-8102 error can be identified easily by bitand(col$.property, 1073741824)=1073741824 (0x40000000 in hex):
SQL> select o.object_name
  2    from sys.col$ c,
  3         dba_objects o
  4   where bitand(c.property, 1073741824)=1073741824
  5     and o.object_id=c.obj#
  6     and o.owner='SYS'
  7   order by o.object_name;
I restricted above query to SYS schema. Below is the output of that query in one of database which was upgraded from 11.2.0.4 to 12.1.0.2 in the 2015:
SQL> select o.object_name
  2    from sys.col$ c,
  3         dba_objects o
  4   where bitand(c.property, 1073741824)=1073741824
  5     and o.object_id=c.obj#
  6     and o.owner='SYS'
  7   order by o.object_name;

OBJECT_NAME
-------------------------------------------------------------------
CDB_LOCAL_ADMINAUTH$
HISTGRM$
PROFNAME$
WRH$_ACTIVE_SESSION_HISTORY
WRH$_BG_EVENT_SUMMARY
WRH$_BUFFERED_QUEUES
WRH$_BUFFERED_SUBSCRIBERS
WRH$_BUFFER_POOL_STATISTICS
WRH$_CLUSTER_INTERCON
WRH$_COMP_IOSTAT
WRH$_CR_BLOCK_SERVER
WRH$_CURRENT_BLOCK_SERVER
WRH$_DATAFILE
WRH$_DB_CACHE_ADVICE
WRH$_DISPATCHER
WRH$_DLM_MISC
WRH$_DYN_REMASTER_STATS
WRH$_DYN_REMASTER_STATS
WRH$_ENQUEUE_STAT
WRH$_EVENT_HISTOGRAM
WRH$_EVENT_NAME
WRH$_FILEMETRIC_HISTORY
WRH$_FILESTATXS
WRH$_IC_CLIENT_STATS
WRH$_IC_DEVICE_STATS
WRH$_INSTANCE_RECOVERY
WRH$_INST_CACHE_TRANSFER
WRH$_INTERCONNECT_PINGS
WRH$_IOSTAT_DETAIL
WRH$_IOSTAT_FILETYPE
WRH$_IOSTAT_FILETYPE_NAME
WRH$_IOSTAT_FUNCTION
WRH$_IOSTAT_FUNCTION_NAME
WRH$_JAVA_POOL_ADVICE
WRH$_LATCH
WRH$_LATCH_CHILDREN
WRH$_LATCH_MISSES_SUMMARY
WRH$_LATCH_NAME
WRH$_LATCH_PARENT
WRH$_LIBRARYCACHE
WRH$_LOG
WRH$_MEMORY_RESIZE_OPS
WRH$_MEMORY_TARGET_ADVICE
WRH$_MEM_DYNAMIC_COMP
WRH$_METRIC_NAME
WRH$_MTTR_TARGET_ADVICE
WRH$_MUTEX_SLEEP
WRH$_MVPARAMETER
WRH$_OPTIMIZER_ENV
WRH$_OSSTAT
WRH$_OSSTAT_NAME
WRH$_PARAMETER
WRH$_PARAMETER_NAME
WRH$_PERSISTENT_QMN_CACHE
WRH$_PERSISTENT_QUEUES
WRH$_PERSISTENT_SUBSCRIBERS
WRH$_PGASTAT
WRH$_PGA_TARGET_ADVICE
WRH$_PLAN_OPERATION_NAME
WRH$_PLAN_OPTION_NAME
WRH$_PROCESS_MEMORY_SUMMARY
WRH$_RESOURCE_LIMIT
WRH$_ROWCACHE_SUMMARY
WRH$_RSRC_CONSUMER_GROUP
WRH$_RSRC_PLAN
WRH$_RULE_SET
WRH$_SEG_STAT
WRH$_SEG_STAT_OBJ
WRH$_SERVICE_NAME
WRH$_SERVICE_STAT
WRH$_SERVICE_WAIT_CLASS
WRH$_SESSMETRIC_HISTORY
WRH$_SESS_TIME_STATS
WRH$_SESS_TIME_STATS
WRH$_SGA
WRH$_SGASTAT
WRH$_SGA_TARGET_ADVICE
WRH$_SHARED_POOL_ADVICE
WRH$_SHARED_SERVER_SUMMARY
WRH$_SQLCOMMAND_NAME
WRH$_SQLSTAT
WRH$_SQLTEXT
WRH$_SQL_BIND_METADATA
WRH$_SQL_PLAN
WRH$_SQL_SUMMARY
WRH$_SQL_WORKAREA_HISTOGRAM
WRH$_STAT_NAME
WRH$_STREAMS_APPLY_SUM
WRH$_STREAMS_APPLY_SUM
WRH$_STREAMS_CAPTURE
WRH$_STREAMS_CAPTURE
WRH$_STREAMS_POOL_ADVICE
WRH$_SYSMETRIC_HISTORY
WRH$_SYSMETRIC_SUMMARY
WRH$_SYSSTAT
WRH$_SYSTEM_EVENT
WRH$_SYS_TIME_MODEL
WRH$_TABLESPACE
WRH$_TABLESPACE_SPACE_USAGE
WRH$_TABLESPACE_STAT
WRH$_TEMPFILE
WRH$_TEMPSTATXS
WRH$_THREAD
WRH$_TOPLEVELCALL_NAME
WRH$_UNDOSTAT
WRH$_WAITCLASSMETRIC_HISTORY
WRH$_WAITSTAT
WRI$_ADV_SQLT_PLAN_HASH
WRI$_OPTSTAT_HISTGRM_HISTORY
WRI$_SQLSET_BINDS
WRI$_SQLSET_DEFINITIONS
WRI$_SQLSET_MASK
WRI$_SQLSET_PLANS
WRI$_SQLSET_PLAN_LINES
WRI$_SQLSET_STATEMENTS
WRI$_SQLSET_STATISTICS
WRI$_SQLTEXT_REFCOUNT

117 rows selected.
You could see that mostly AWR tables are affected (WRH$%, WRI%). The brand new 12c database's AWR tables won't have property set to 1073741824 (0x40000000), unless you wouldn't create some.
If you set the _add_col_optim_enabled parameter to FALSE, you will be safe.
If you will face a same issue one day, the possible workaround for the issue is to rebuild table in anyway to update the problem column (MOVE table, redefine table online, or set column value equals to self).

понедельник, 3 августа 2015 г.

Reclaim unused space from MLOG$ segments after MVIEW Refresh

We are using fast-refreshable MVIEWs in some of our database for reporting purposes.
They are works fine most of the time.
However, periodically MLOG size is increased due to different reasons.
Such as: bulk data loading, other abnormal application activities, or delays with MVIEW refresh.
After that, even if you refresh MVIEW, HWM doesn't reset.
You need to reset it manually, using commands such as ALTER TABLE SHRINK/MOVE and so on.
Without resetting the HWM MVIEW refresh performance can be poor.

Good news: there are Patch 11072728 available for some platforms that can reset the HWM without manual intervention.
This patch was described in MOS note Space Not Reclaimed from MLOG$ Segments After MVIEW Refresh (Doc ID 1941137.1)
According to the note, the fix for bug 11072728 will be provided in upcoming 12.2 release.
I have already requested that patch for Solaris SPARC64 on top of 11.2.0.4.4/11.2.0.4.6.

Today I have decided to look closer on Patch 11072728 in one of non-production database.
I want to be sure that patch didn't harm production instance.

Reading the bug readme, I have found that fix for bug is not enabled by default.
You need to set underscope parameter _bug11072728_mv_refresh_truncate_log to 1 to enable it.
Worth to be noted, is that we can change this parameter on the session and on the system level:
SQL> select isses_modifiable,
  2         issys_modifiable
  3    from v$parameter
  4   where name = '_bug11072728_mv_refresh_truncate_log';

ISSES_MODIFIABLE ISSYS_MODIFIABLE
---------------- ----------------
TRUE             IMMEDIATE
Next script I have used to setup test schema:
SQL> grant connect to tc identified by tc;

Grant succeeded.

SQL> grant alter session to tc;

Grant succeeded.

SQL> grant create materialized view to tc;

Grant succeeded.

SQL> grant create table to tc;

Grant succeeded.

SQL> grant unlimited tablespace to tc;

Grant succeeded.

SQL> 
SQL> conn tc/tc
Connected.
SQL> 
SQL> create table t
  2  as
  3  select *
  4    from all_users;

Table created.

SQL> 
SQL> alter table t add constraint t_pk primary key(username);

Table altered.

SQL> 
SQL> create materialized view log on t with primary key;

Materialized view log created.

SQL> 
SQL> create materialized view mv_t
  2  refresh fast
  3  as
  4  select *
  5    from t;

Materialized view created.
    
In the above script I have created table, mat view log on it, and materialized view.
We can see that mat view log is empty, segment has 8 blocks allocated:
SQL> select count(*) from mlog$_t;

  COUNT(*)
----------
         0

SQL> 
SQL> select blocks
  2    from user_segments
  3   where segment_name = 'MLOG$_T';

    BLOCKS
----------
         8
I update table in loop, 100 times in total:
SQL> begin
  2    for i in 1..100
  3    loop
  4      update t
  5         set created = created
  6       where username <> 'SYS';
  7      commit;
  8    end loop;
  9  end;
 10  /
Check that mat view log is not empty, segment was extended:
SQL> select count(*) from mlog$_t;

  COUNT(*)
----------
     19400

SQL> 
SQL> select blocks
  2    from user_segments
  3   where segment_name = 'MLOG$_T';

    BLOCKS
----------
       104
Let's refresh materialized view now:
SQL> exec dbms_mview.refresh( 'mv_t', method=>'f')

PL/SQL procedure successfully completed.
If the patch 11072728 was not applied or the parameter "_bug11072728_mv_refresh_truncate_log" not set to 1, then the HWM is not reset and the segment space allocated is the same:
SQL> select count(*) from mlog$_t;

  COUNT(*)
----------
         0

SQL> 
SQL> select blocks
  2    from user_segments
  3   where segment_name = 'MLOG$_T';

    BLOCKS
----------
       104
In the production system with a high DML activity materialized view logs can grows to a much higher size.
And the materialized view refresh performance degrades.
As I said previously, before the patch 11072728 you need to reset the HWM manually.
With the patch 11072829 you dont need to do it anymore.
Just the set parameter "_bug11072728_mv_refresh_truncate_log" to 1:
SQL> exec dbms_mview.refresh( 'mv_t', method=>'f')

PL/SQL procedure successfully completed.

SQL> 
SQL> select count(*) from mlog$_t;

  COUNT(*)
----------
         0

SQL> 
SQL> select blocks
  2    from user_segments
  3   where segment_name = 'MLOG$_T';

    BLOCKS
----------
         8
You can see that segment allocated space was decreased.
How does it works under the hood?
I have setup sql tracing and event 10704 (enqueue trace) to investigate it:
SQL> alter session set events 'sql_trace bind=true:10704 level 10';

Session altered.

SQL> 
SQL> exec dbms_mview.refresh( 'mv_t', method=>'f')

PL/SQL procedure successfully completed.
I used below command to filter the irrelevant lines from output:
egrep "ksqgtl \*|ksqrcl: [^r]|^truncate|select count\(\*\) from .*MLOG" orcl_ora_18632.trc
  • ksqgtl - get lock function
  • ksqrcl - release lock function
  • We want to show the truncate command and the select count(*) from MLOG.
Below is the output of egrep command, in which some lines was skipped for brevity:
select count(*) from "TC"."MLOG$_T"
ksqgtl *** TM-001854e4-00000000 mode=6 flags=0x401 timeout=0 ***
select count(*) from "TC"."MLOG$_T"
ksqgtl *** TM-001854e6-00000000 mode=6 flags=0x401 timeout=0 ***
truncate table "TC"."MLOG$_T"
These commands was executed when the materialized view update already done.
Looks like that new algorithm with MLOG truncate works in following way:
  1. execute old refresh code
  2. check count of rows in MLOG
  3. if zero, lock master table in exclusive mode nowait (TM lock with timeout=0)
  4. check count of rows in MLOG again (because there are can be DML between step 2 and 3)
  5. lock MLOG in exclusive mode nowait (TM lock with timeout=0)
  6. truncate MLOG
At least, an open transaction will prevent the truncation of MLOG.
And that indirectly confirms my assumptions about internal workings of new refresh algorithm. Let's update the 1 row in table in session 1:
SQL> -- session 1
SQL> update t
  2     set created=created
  3   where username='SYS';

1 row updated.
Now we will check space of MLOG before refresh, perform actual refresh and check the space again (in other session):
SQL> -- session 2
SQL> select blocks
  2    from user_segments
  3   where segment_name = 'MLOG$_T';

    BLOCKS
----------
       104

SQL> exec dbms_mview.refresh( 'mv_t', method=>'f')

PL/SQL procedure successfully completed.
SQL> 
SQL> select count(*) from mlog$_t;

  COUNT(*)
----------
         0

SQL> 
SQL> select blocks
  2    from user_segments
  3   where segment_name = 'MLOG$_T';

    BLOCKS
----------
       104
And the truncate of MLOG was not executed.
Looks like, it's safe to use a patch 11072728 in the production environment.
If I will face any issue with that patch in the production, I will update this blog post.

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

понедельник, 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.

воскресенье, 3 августа 2014 г.

JPPD bypassed View has non-standard group by

В одной из БД Hibernate сгенерировал новый запрос, который вызвал повышенную загрузку. Я исследовал этот запрос, оптимизируется он легко, но я выявил один интересный случай, когда JPPD (join-predicate push-down) не срабатывает для group by view. Test case (11.2.0.3):
drop table t1 cascade constraints purge;
drop table t2 cascade constraints purge;
create table t1(x,y) as select rownum, rownum from dual connect by level<=1e4;
alter table t1 modify x not null;
create index t1_y_i on t1(y);
create table t2(x,z) as select rownum, cast(dummy as char(20)) from dual connect by level<=1e5;
alter table t2 modify x not null;
create index t2_x_i on t2(x);
exec dbms_stats.gather_table_stats( '', 't1')
exec dbms_stats.gather_table_stats( '', 't2')
Hibernate генерировал следующий запрос:
select *
  from t1
 where y = :1
   and x not in (select x from t2 group by x);
С планом:
---------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |     1 |     8 |    85  (25)| 00:00:02 |
|*  1 |  FILTER                      |        |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |     1 |     8 |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | T1_Y_I |     1 |       |     1   (0)| 00:00:01 |
|*  4 |   FILTER                     |        |       |       |            |          |
|   5 |    HASH GROUP BY             |        |     1 |     5 |    83  (26)| 00:00:01 |
|   6 |     INDEX FAST FULL SCAN     | T2_X_I |   100K|   488K|    65   (5)| 00:00:01 |
---------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter( NOT EXISTS (SELECT 0 FROM "T2" "T2" GROUP BY "X" HAVING
              "X"=:B1))
   3 - access("Y"=TO_NUMBER(:1))
   4 - filter("X"=:B1)
Условие по T1 (Y=:1) - очень селективное. Как видно, subquery unnesting не срабатывает, а хотелось бы видеть анти-соединение, использующее INDEX RANGE SCAN индекса T2_X_I (индекс по T2(X)). Рассмотрим эквивалентный запрос:
select *
  from t1
 where y = :1
   and x not in (select x from t2);
Его план, который бы хотелось получить для исходного запроса:
---------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |     1 |    13 |     3   (0)| 00:00:01 |
|   1 |  NESTED LOOPS ANTI           |        |     1 |    13 |     3   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |     1 |     8 |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | T1_Y_I |     1 |       |     1   (0)| 00:00:01 |
|*  4 |   INDEX RANGE SCAN           | T2_X_I |   100K|   488K|     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("Y"=TO_NUMBER(:1))
   4 - access("X"="X")
Как еще можно переписать запрос? По логике, нужно выбрать строки из T1, которых нет в T2. Такой запрос с Oracle синтаксисом Join:
select t1.*
  from t1,
       (select x 
          from t2 
         group by x) t2
 where y = :1
   and t1.x = t2.x(+)
   and t2.x is null;
Имеет план:
-----------------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |     1 |    21 |       |   233   (4)| 00:00:03 |
|*  1 |  HASH JOIN ANTI              |        |     1 |    21 |       |   233   (4)| 00:00:03 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |     1 |     8 |       |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | T1_Y_I |     1 |       |       |     1   (0)| 00:00:01 |
|   4 |   VIEW                       |        |   100K|  1269K|       |   228   (3)| 00:00:03 |
|   5 |    HASH GROUP BY             |        |   100K|   488K|  1192K|   228   (3)| 00:00:03 |
|   6 |     INDEX FULL SCAN          | T2_X_I |   100K|   488K|       |   228   (3)| 00:00:03 |
-----------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."X"="T2"."X")
   3 - access("Y"=TO_NUMBER(:1))
Мы видим, что происходит HASH JOIN ANTI (анти-соединение) без JPPD. Т.е. предикат соединения T1.X=T2.X - не был протолкнут внутрь GROUP BY VIEW по T2. Выполнить проталкивание хинтами не получилось, что говорит о том, что такое VIEW для JPPD не подходит. Пришлось обратиться к трассировке CBO в поисках причин.
JPPD:     JPPD bypassed: View has non-standard group by.
JPPD: Applying transformation directives
JPPD: Checking validity of push-down in query block SEL$6D455ABB (#1)
JPPD:   No valid views found to push predicate into.
Вот это уже информация для анализа. Мы видим, что JPPD не сработал, т.к. View: "has non-standard group by". Подумав, я написал следующий запрос:
select t1.*
  from t1,
       (select x, 
               count(*)
          from t2 
         group by x) t2
 where y=:1
   and t1.x = t2.x(+)
   and t2.x is null;
Его план:
---------------------------------------------------------------------------------------
| Id  | Operation                    | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |        |     1 |    10 |     3   (0)| 00:00:01 |
|   1 |  NESTED LOOPS ANTI           |        |     1 |    10 |     3   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1     |     1 |     8 |     2   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | T1_Y_I |     1 |       |     1   (0)| 00:00:01 |
|   4 |   VIEW PUSHED PREDICATE      |        |     1 |     2 |     1   (0)| 00:00:01 |
|   5 |    SORT GROUP BY             |        |     1 |     5 |     1   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN         | T2_X_I |     1 |     5 |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("Y"=TO_NUMBER(:1))
   6 - access("X"="T1"."X")
По сути дела, мы запрос:
select t1.*
  from t1,
       (select x 
          from t2 
         group by x) t2
 where y = :1
   and t1.x = t2.x(+)
   and t2.x is null;
Переписали в эквивалентный:
select t1.*
  from t1,
       (select x, 
               count(*) 
          from t2 
         group by x) t2
 where y=:1
   and t1.x = t2.x(+)
   and t2.x is null;
И это позволило выполнить JPPD, что видно в плане и в трассе CBO:
***********************************
Cost-Based Join Predicate Push-down
***********************************
JPPD: Checking validity of push-down in query block SEL$6D455ABB (#1)
JPPD:   Checking validity of push-down from query block SEL$6D455ABB (#1) to query block SEL$2 (#2)
Check Basic Validity for Non-Union View for query block SEL$2 (#2)
JPPD:     Passed validity checks
JPPD: JPPD:   Pushdown from query block SEL$6D455ABB (#1) passed validity checks.
Join-Predicate push-down on query block SEL$6D455ABB (#1)
JPPD: Using search type: linear
JPPD: Considering join predicate push-down
JPPD: Starting iteration 1, state space = (2) : (0)
JPPD: Performing join predicate push-down (no transformation phase) from query block SEL$6D455ABB (#1) to query block SEL$2 (#2)
Пока это похоже на существующее ограничение CBO. Указанное поведение проверялось в 11.2.0.3 и 12.1.0.1.

понедельник, 21 июля 2014 г.

Bug 15931756 - ORA-4031 Queries against SYS_FBA_TRACKEDTABLES not shared (do not use binds)

В одной из промышленных БД версии 11.2.0.3.7 обнаружил большое количество системных SQL, не использующих литералы.
/*
Find queries that are not using bind variables
*/
select s.*, 
      (select sql_text from v$sqlarea where force_matching_signature=sig and rownum=1) sql_text
  from (
       select inst_id, to_char(force_matching_signature) sig,
              count(exact_matching_signature) cnt
         from (
              select inst_id, force_matching_signature, exact_matching_signature
                from gv$sql
               group by inst_id, force_matching_signature, exact_matching_signature
              )
        group by inst_id, force_matching_signature
       having count(exact_matching_signature) > 1
        order by cnt desc
       ) s
 where rownum <= 10
В выводе оказалось множество запросов вида:
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1865226
select count(FA#) from SYS_FBA_TRACKEDTABLES where OBJ# = 1864581 and bitand(FLAGS, 128)=0
С кол-вом подобных курсоров в кол-ве 501 и 399 соответственно.
SQL> select sql_text from v$sql where force_matching_signature=15893216616221909352 and rownum<=10;
SQL_TEXT
---------------------------------------------------------------------------------
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1865226
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1865182
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1865129
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1864747
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1864989
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1865069
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1864718
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1864786
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1864815
select FLAGS from SYS_FBA_TRACKEDTABLES where OBJ# = 1864679
Поиск на MOS по SYS_FBA_TRACKEDTABLES тут же выдает, что имеет место быть баг: Bug 15931756 - ORA-4031 / Queries against SYS_FBA_TRACKEDTABLES not shared (do not use binds) (Doc ID 15931756.8)