UKOUG Tech16 Conference

Friday, July 15, 2016

Complete Refresh of Materialized Views: Atomic, Non-Atomic and Out-of-Place

Recently, and more than once, I have found myself explaining exactly how an Oracle database performs a complete refresh of a materialized view, and what are the implications.  So I thought I would set it out in a blog post.
I am only looking at the case where it is not possible to incrementally refresh using on a materialized view log because the materialized view joins tables together, groups data, or breaches one of the other restrictions (see General Restrictions on Fast Refresh).

Behaviour of DBMS_MVIEW.REFRESH

Materialized views are managed by the delivered DBMS_MVIEW package.  The REFRESH procedure can refresh one or more materialized views.  I want to discuss at the effect of the ATOMIC_REFRESH parameter.  This parameter has been present since at least Oracle 8i when materialized views were called snapshots, so none of this is new.
DBMS_MVIEW.REFRESH (
   { list                 IN     VARCHAR2,
   | tab                  IN     DBMS_UTILITY.UNCL_ARRAY,}
…
   atomic_refresh         IN     BOOLEAN        := true,
…
);
This is what the Oracle 12c documentation says:
"If this parameter is set to true, then the list of materialized views is refreshed in a single transaction. All of the refreshed materialized views are updated to a single point in time. If the refresh fails for any of the materialized views, none of the materialized views are updated.
If this parameter is set to false, then each of the materialized views is refreshed non-atomically in separate transactions.
As part of complete refresh, if truncate is used (non-atomic refresh), unique index rebuild is executed. INDEX REBUILD automatically computes statistics. Thus, statistics are updated for truncated tables."
It is possible to see the behaviour of the refresh procedure by using SQL trace.  My tests were run on a 12c database.  I have cut a lot out of the traces to make them easier to read.

Trace of Atomic Refresh

  • All constraints are deferred to the end of the transaction which is not until all the specified materialized views are refreshed.
  • For each materialized view, all rows are deleted
  • Then the complete content is reinserted.
  • If more than one materialised view is refreshed in a refresh group, or by specifying them in a single execution of refresh, they are refreshed in a single transaction.
Trace file /home/oracle/app/oracle/diag/rdbms/cdb1/cdb1/trace/cdb1_ora_27100_ATOMIC.trc
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options
System name: Linux
Node name: localhost.localdomain
Release: 3.8.13-68.1.3.el7uek.x86_64
Version: #2 SMP Wed Apr 22 11:51:54 PDT 2015
Machine: x86_64
=====================
PARSING IN CURSOR #140647220341720 len=73 dep=0 uid=156 oct=47 lid=156 tim=2204121046481 hv=3058798929 ad='c86e9600' sqlid='1rz3cakv534aj'
BEGIN DBMS_MVIEW.REFRESH('MY_EXAMPLE2','C', atomic_refresh=>TRUE); END;
END OF STMT
PARSE #140647220341720:c=0,e=139,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=2204121046475
=====================
PARSING IN CURSOR #140647220211192 len=28 dep=1 uid=156 oct=90 lid=156 tim=2204121059425 hv=3879155062 ad='c88f49d0' sqlid='231qv0rmmfdbq'
SET CONSTRAINTS ALL DEFERRED
END OF STMT
PARSE #140647220211192:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=2204121059418
EXEC #140647220211192:c=0,e=72,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=2204121059610
CLOSE #140647220211192:c=0,e=9,dep=1,type=0,tim=2204121059737
=====================
PARSING IN CURSOR #140647218302768 len=34 dep=1 uid=156 oct=7 lid=156 tim=2204121175365 hv=812824424 ad='c86e1658' sqlid='46t32c0s75dv8'
 delete from "SCOTT"."MY_EXAMPLE2"
END OF STMT
PARSE #140647218302768:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2149302637,tim=2204121175360
EXEC #140647218302768:c=0,e=303,p=0,cr=3,cu=2,mis=0,r=1,dep=1,og=1,plh=2149302637,tim=2204121175801
pw=0 time=93 us cost=2 size=0 card=1)'
=====================
PARSING IN CURSOR #140647218302768 len=177 dep=1 uid=156 oct=2 lid=156 tim=2204121185717 hv=1441390243 ad='c86d91c8' sqlid='9ctg639aymrp3'
INSERT /*+ BYPASS_RECURSIVE_CHECK */ INTO "SCOTT"."MY_EXAMPLE2" SELECT 2 id
,      sysdate my_system_date
,      count(*) X
from kill_cpu
connect by n > prior n
start with n = 1
END OF STMT
PARSE #140647218302768:c=9000,e=8028,p=0,cr=8,cu=0,mis=1,r=0,dep=1,og=1,plh=2203518424,tim=2204121185711
*** 2016-07-11 14:44:24.152
EXEC #140647218302768:c=11189000,e=11191474,p=0,cr=4,cu=3,mis=0,r=1,dep=1,og=1,plh=2203518424,tim=2204132377380
CLOSE #140647218302768:c=0,e=18,dep=1,type=0,tim=2204132377809

Trace of Non-Atomic Refresh

  • Again, all constraints are deferred to the end of the transaction, which this time is only as far as the truncate statement.
  • An exclusive lock is obtained on the materialized view to ensure that there are no in-flight transactions on it.
  • The materialized view is then truncated.  The purge materialized view log option is specified in case another materialized view is based on this materialized view
  • The materialized view is repopulated, but in direct path mode because the APPEND hint is specified.
  • Stats are automatically collected on a 12c database (note this statement is one level deeper).
Trace file /home/oracle/app/oracle/diag/rdbms/cdb1/cdb1/trace/cdb1_ora_27100_NOTATOMIC.trc
=====================
PARSING IN CURSOR #140647224204240 len=74 dep=0 uid=156 oct=47 lid=156 tim=2204109695504 hv=2544739527 ad='c8c758b8' sqlid='fm9xzbfbuv967'
BEGIN DBMS_MVIEW.REFRESH('MY_EXAMPLE1','C', atomic_refresh=>FALSE); END;
END OF STMT
PARSE #140647224204240:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=2204109695500
=====================
PARSING IN CURSOR #140647223494264 len=28 dep=1 uid=156 oct=90 lid=156 tim=2204109716722 hv=3879155062 ad='c88f49d0' sqlid='231qv0rmmfdbq'
SET CONSTRAINTS ALL DEFERRED
END OF STMT
PARSE #140647223494264:c=0,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=2204109716718
EXEC #140647223494264:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=2204109716836
CLOSE #140647223494264:c=0,e=15,dep=1,type=0,tim=2204109717294 
=====================
PARSING IN CURSOR #140647218294296 len=59 dep=2 uid=156 oct=26 lid=156 tim=2204109881174 hv=846098398 ad='c8831a50' sqlid='8td4wj8t6wvyy'
LOCK TABLE "SCOTT"."MY_EXAMPLE1" IN EXCLUSIVE MODE  NOWAIT 
END OF STMT
PARSE #140647218294296:c=1000,e=759,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=1,plh=0,tim=2204109881168
EXEC #140647218294296:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=0,tim=2204109881317
CLOSE #140647218294296:c=0,e=11,dep=2,type=0,tim=2204109881369
=====================
PARSING IN CURSOR #140647218302768 len=56 dep=1 uid=156 oct=85 lid=156 tim=2204109882394 hv=4078491682 ad='c8838320' sqlid='1hkq5cgtjjq12'
 truncate table "SCOTT"."MY_EXAMPLE1" purge snapshot log
END OF STMT
PARSE #140647218302768:c=3000,e=3255,p=0,cr=6,cu=1,mis=1,r=0,dep=1,og=1,plh=1592878302,tim=2204109882390
=====================
PARSING IN CURSOR #140647218302768 len=185 dep=1 uid=156 oct=2 lid=156 tim=2204109979170 hv=3331603390 ad='c8824c90' sqlid='bag14pr398fxy'
INSERT /*+ BYPASS_RECURSIVE_CHECK APPEND  */ INTO "SCOTT"."MY_EXAMPLE1" SELECT 1 id
,      sysdate my_system_date
,      count(*) X
from kill_cpu
connect by n > prior n
start with n = 1
END OF STMT
PARSE #140647218302768:c=58000,e=58028,p=0,cr=178,cu=0,mis=1,r=0,dep=1,og=1,plh=1420092967,tim=2204109979166
CLOSE #140647224167168:c=1000,e=608,dep=2,type=1,tim=2204120957626
=====================
PARSING IN CURSOR #140647224532056 len=124 dep=2 uid=0 oct=47 lid=0 tim=2204120958103 hv=1731287439 ad='d54ed0e0' sqlid='827tjqdmm2qcg'
BEGIN    dbms_stats.postprocess_stats(:owner, :tabname, :partname,      :subpartname, 2, :rawstats, :selmap, :clist);  END; 
END OF STMT
PARSE #140647224532056:c=0,e=128,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=0,tim=2204120958098

Comparison

While there are lots of advantages to non-atomic refresh, but perhaps the most significant disadvantage for developers is that the data disappears during refresh.  I think it is this that leads to widespread use of atomic refresh, but in the next section I show how this can be overcome.

Atomic Refresh Non-Atomic Refresh
Delete, Insert, Commit Truncate, Insert /*+APPEND*/
Space occupied by deleted rows not available to be reused until the delete is committed, which is not until after the insert. High water marks reset by truncate. All space in table released immediately. Table likely to be about half size of atomically refreshed materialized view.
Significant undo (and therefore also redo on undo) overhead. Minimal undo overhead.
Delete and Insert performed row-by-row. Indexes are maintained during DML. Insert performed in direct path mode. Faster. Indexes rebuilt when insert committed.
Table can be compressed by explicitly rebuilding after refresh, or requires Advanced Compression Licence. Table data can be compressed using basic compression without needing Advanced Compression Licence.
This would also work well with Hybrid Columnar Compression (HCC) on Exadata.
Statistics are not collected. It may be necessary to collect them manually. In 12c, table statistics will automatically be updated.
Content of materialized view always available due to read consistency. Materialized view will appear to be empty while refresh process is running.
Refresh of multiple materialized views can occur in a single transaction so that they remain consistent. Each materialized view refreshed independently.

Non-Atomic Refresh Without Temporarily Losing the Data

In this section I want to explain how to evade the problem of the data disappearing from the materialized view during non-atomic refresh.  Like all the best conjuring tricks, you require two materialized views!  First, I will describe a workaround for use with Oracle 11g or earlier, then I will look at a new feature in Oracle 12c.
I want to create a simple stand-alone demonstration.  I need a materialized view that will take several seconds to refresh so I can check whether the data is still available during that process.  So, I need a long running query, for which I am using Jonathan Lewis's kill_cpu script.  On my database, it runs for around 10 seconds.
set timi on
DROP TABLE kill_cpu PURGE
/
create table kill_cpu(n primary key) organization index as 
select rownum from dual connect by level <=1
/
--this is Jonathan Lewis' killcpu query - duration doubles for every row in kill_cpu table - so the MVs take time to refresh
select count(*) X 
from kill_cpu 
connect by n > prior n 
start with n = 1 
/
I am going to create two identical materialized views based on (almost) the same query.
--create 2 identical MVs.  this time they will be fast to build
DROP MATERIALIZED VIEW my_example1;
DROP MATERIALIZED VIEW my_example2;

CREATE MATERIALIZED VIEW my_example1
COMPRESS PCTFREE 0
BUILD IMMEDIATE
AS 
SELECT 1 id
,      sysdate my_system_date
,      count(*) X 
from kill_cpu 
connect by n > prior n 
start with n = 1 
/

CREATE MATERIALIZED VIEW my_example2
COMPRESS PCTFREE 0
BUILD IMMEDIATE
AS 
SELECT 2 id
,      sysdate my_system_date
,      count(*) X 
from kill_cpu 
connect by n > prior n 
start with n = 1 
/
--this makes the query in the MVs slow to execute
TRUNCATE TABLE kill_cpu;
INSERT INTO kill_cpu
SELECT rownum FROM dual CONNECT BY LEVEL <=24
/
commit
/
I can see my materialized views and when they were last refreshed
alter session set nls_date_Format = 'hh24:mi:ss dd.mm.yyyy';
--list MVs and last refresh dates
column mview_name format a20
select mview_name, last_refresh_date, last_refresh_end_time
from user_mviews
order by last_refresh_date
/

MVIEW_NAME           LAST_REFRESH_DATE   LAST_REFRESH_END_TI
-------------------- ------------------- -------------------
MY_EXAMPLE1          14:44:01 11.07.2016 14:44:12 11.07.2016
MY_EXAMPLE2          14:44:12 11.07.2016 14:44:23 11.07.2016
The following PL/SQL block
  • refreshes the older version of the two materialized views
  • It then recreates a view on the freshly refreshed materialized view.
    • The application should reference this view, and so it will always point to the most up-to-date materialized view.
    • The view will refer to the older materialized until the refresh is complete so the data will never disappear.
    • Complex view merging means that any query will seamlessly reference the underlying table and the performance will be as if the application had referred to the materialized view.
    • In-flight queries will not be affected by the view being rebuilt. They will continue to run against the now older materialized view.
--refresh MVs, collect stats, rebuild view, 
set serveroutput on timi on
DECLARE
  l_module VARCHAR2(64);
  l_action VARCHAR2(64);
  l_mview_owner VARCHAR2(128) := 'SCOTT';
  l_mview_name  VARCHAR2(128);
  l_sql CLOB;
BEGIN
  dbms_application_info.read_module(module_name=>l_module, action_name=>l_action);
  dbms_application_info.set_module(module_name=>'MV_EXAMPLE', action_name=>'Initialise');
  WITH x AS (
    SELECT ROW_NUMBER() OVER (ORDER BY last_refresh_date) as ranking
    ,      mview_name, last_refresh_date  
    FROM   user_mviews
    WHERE  owner = l_mview_owner
    AND    mview_name IN('MY_EXAMPLE1','MY_EXAMPLE2')
  ) 
  SELECT mview_name
  INTO   l_mview_name
  FROM   x
  WHERE  ranking = 1;

  dbms_application_info.set_action(action_name=>'Refresh '||l_mview_name);  
  dbms_output.put_line('About to refresh mview '||l_mview_name);
  DBMS_MVIEW.REFRESH(l_mview_name,'C', atomic_refresh=>FALSE);

  --add stats collection here – not necessary in 12c
  --dbms_application_info.set_action(action_name=>'Collect Stats '||l_mview_name);  
  --dbms_stats.gather_Table_stats(ownname=>l_mview_owner, tabname=>l_mview_name, cascade=>TRUE);

  --rebuild view to point to MV just refreshed  
  dbms_application_info.set_action(action_name=>'Rebuild view MY_EXAMPLE');  
  l_sql:= 'CREATE OR REPLACE VIEW my_example AS SELECT * FROM '||l_mview_name;
  dbms_output.put_line('SQL:'||l_sql);
  EXECUTE IMMEDIATE l_sql;

  --reinstate initial settings for module and action
  dbms_application_info.set_module(module_name=>l_module, action_name=>l_action);
END;
/
select mview_name, last_refresh_date, last_refresh_end_time
from user_mviews
order by last_refresh_date
/
The first time I ran the script MY_EXAMPLE1 was refreshed and the view was rebuilt to point to it.
About to refresh mview MY_EXAMPLE1
SQL:CREATE OR REPLACE VIEW my_example AS SELECT * FROM MY_EXAMPLE1

MVIEW_NAME           LAST_REFRESH_DATE   LAST_REFRESH_END_TI
-------------------- ------------------- -------------------
MY_EXAMPLE2          14:44:12 11.07.2016 14:44:23 11.07.2016
MY_EXAMPLE1          10:39:57 12.07.2016 10:40:06 12.07.2016
The next time I ran the script MY_EXAMPLE2 was refreshed and the view was again rebuilt.
About to refresh mview MY_EXAMPLE2
SQL:CREATE OR REPLACE VIEW my_example AS SELECT * FROM MY_EXAMPLE2

MVIEW_NAME           LAST_REFRESH_DATE   LAST_REFRESH_END_TI
-------------------- ------------------- -------------------
MY_EXAMPLE1          10:39:57 12.07.2016 10:40:06 12.07.2016
MY_EXAMPLE2          10:40:50 12.07.2016 10:40:59 12.07.2016

Summary 

There is a trade-off to this approach, but I suggest that the advantages of this approach to using non-atomic refresh outweigh the additional complexities.
Advantages Disadvantanges
Data is always available during materialized view refresh. The refresh and view rebuild process is more complex, though it could be encapsulated into a PL/SQL procedure.
Each materialized view will be half the size of the atomically refresh materialized view because space is freed by the delete is only available after the commit. So the overall space requirement is about the same as atomic refresh. Two copies of the materialized view and its indexes are required.
Refresh will be faster because indexes are not maintained during the insert, but are rebuilt afterwards.
Queries no longer run on view being refreshed, so database does not have to do consistent reads of data blocks. This should prevent query performance being degraded during refresh.
Basic table compression (or HCC on Exadata) could make it considerably smaller. This should also improve query performance by reducing I/O.
I have not reserved any free space in the table in my demonstration because I know the table will never be updated. Further saving space and reducing I/O.

Out-of-Place Refresh in Oracle 12c

Out-of-place refresh is a new option on DBMS_MVIEW.REFRESH in Oracle 12c.  The complete refresh process builds a new table which seamlessly becomes the materialized view, the old table is dropped.  It only works in conjunction with non-atomic refresh.  It also works with incremental (or fast) refresh.
As with my 11g workaround described above, two copies of the data are used. The refresh process creates and populates a new table with indexes, exchanges the new with the old, and drops the old table. For this example, I have enabled the recycle bin so we can see the dropped table.
exec DBMS_MVIEW.REFRESH('MY_EXAMPLE1','C', atomic_refresh=>FALSE, out_of_place=>TRUE);
select object_id, object_type, object_name, last_ddl_time
from user_objects
where object_name LIKE 'MY_EXAMPLE1'
order by 1
/
select original_name, createtime, droptime, dropscn, base_object, purge_object
from user_recyclebin
order by dropscn
/
Each time I refresh the materialized view, the table gets a new object ID, and a new object appears in the recycle bin.
 OBJECT_ID OBJECT_TYPE             OBJECT_NAME     LAST_DDL_TIME
---------- ----------------------- --------------- -------------------
    112366 MATERIALIZED VIEW       MY_EXAMPLE1     09:50:06 14.07.2016
    112382 TABLE                   MY_EXAMPLE1     08:40:34 14.07.2016

ORIGINAL_NAME   CREATETIME          DROPTIME               DROPSCN BASE_OBJECT
--------------- ------------------- ------------------- ---------- -----------
RV$1B6FD        2016-07-14:09:43:43 2016-07-14:09:50:05   68878082      112381
The object ID of the new entry is the previous object ID of the materialized view. A new table was created and the old table was dropped. The intermediate table name is RV$ followed by the object ID in hexadecimal.
 OBJECT_ID OBJECT_TYPE             OBJECT_NAME     LAST_DDL_TIME
---------- ----------------------- --------------- -------------------
    112366 MATERIALIZED VIEW       MY_EXAMPLE1     09:51:41 14.07.2016
    112383 TABLE                   MY_EXAMPLE1     08:40:34 14.07.2016

ORIGINAL_NAME   CREATETIME          DROPTIME               DROPSCN BASE_OBJECT
--------------- ------------------- ------------------- ---------- -----------
RV$1B6FD        2016-07-14:09:43:43 2016-07-14:09:50:05   68878082      112381
RV$1B6FE        2016-07-14:09:50:03 2016-07-14:09:51:40   68878546      112382
A trace of the refresh process shows the data being inserted into another table. However, note that it is a conventional insert, not a direct-path insert. So statistics will not be collected automatically. The DDL statements at create and drop interim tables are truncated in the trace, but can be reinstated with event 10979, level 1 (see Jonathan Lewis's 12c MView refresh blog).  This event also causes additional progress information about the refresh process to be written to the trace file.
PARSING IN CURSOR #139759670421744 len=178 dep=1 uid=156 oct=2 lid=156 tim=2412454493901 hv=3909484904 ad='d56b62a8' sqlid='0k8chjrnhc0b8'
/* MV_REFRESH (ITB) */INSERT INTO "SCOTT"."RV$1B6E0"  SELECT 1 id
,      sysdate my_system_date
,      n
--,      count(*) X
from kill_cpu
connect by n > prior n
start with n = 1
END OF STMT

Summary

Out-of-Place refresh has some advantages and disadvantages over my 11g method.
AdvantagesDisadvantanges
The entire refresh process is encapsulated within the DBMS_MVIEW.REFRESH procedure.
Physical tablespace is still required to hold two copies of the table, but now only during the refresh. The original table is dropped after the new one is built.  If the recycle bin is enabled, every out-of-place refresh will preserve another copy of the table and any indexes. I recommend disabling the recycle bin.
The data is always available while the materialized view is being refreshed. Long running queries running across the out-of-place refresh will continue to run correctly, at least until the data blocks used to hold the dropped table are overwritten, when an "ORA_08103: object no longer exists" error will be raised (again, see Jonathan Lewis's 12c MView refresh blog).
The table is populated in conventional rather than direct path mode. Although the indexes are built after population. This has a number of consequences.
  • The performance of the conventional insert will not be as good as direct-path insert.
  • Simple table compression will not have any effect. HCC is probably not an option.
  • Table statistics are not automatically collected by On-Line Statistics Gathering, but the indexes will have statistics computed as they are rebuilt during each refresh.

Thursday, June 16, 2016

Diagnosing Non-Intuitive Errors with Errorstack

This is a story about how to diagnose a problem where the error message did not seem to make sense, nor have any apparent relation to what I thought was happening.

The Problem 

During a PeopleSoft on Exadata Proof-of-concept test, running on Oracle 11.2.0.4, we got this error in a COBOL process in PeopleSoft North American Payroll.
Application Program Failed
 Action Type     : SQL SELECT
 In Pgm Section  : SQLRT: EXECUTE-STMT
 With Return Code: 31011
 Error Message   : ORA-31011: XML parsing failed ORA-19202: Error occurred in XML processing LPX-00210: expected '<' instead of '�' Error at line 1
 Stored Stmt     : PSPEBUPD_S_BENF_NO
 SQL Statement   : SELECT A.BENEFIT_RCD_NBR FROM PS_PAY_EARNINGS A WHERE A.COMP
                   ANY=:1 AND A.PAYGROUP=:2 AND A.PAY_END_DT=:3 AND A.OFF_CYCLE
                   =:4 AND A.EMPLID=:5 AND A.EMPL_RCD=:6�
There is no XML processing anywhere near this process. The table only has character, date and numeric columns. No CLOBs or XML data types.  The error didn't make any sense to me at the time.

Initial Attempts at Diagnosis 

So, I generated both PeopleSoft and Oracle session traces for the process. This is from an Oracle session trace – I don’t see any bind variables in the trace for this statement, but I do for other statements in the same session. The ORA-31011 error definitely occurs during the SQL parse.
…
=====================
PARSING IN CURSOR #140203930927312 len=157 dep=0 uid=139 oct=3 lid=139 tim=1466008802922936 hv=3840857025 ad='345a5f148' sqlid='4q8nzfzkfxny1'
SELECT A.BENEFIT_RCD_NBR FROM PS_PAY_EARNINGS A WHERE A.COMPANY=:1 AND A.PAYGROUP=:2 AND A.PAY_END_DT=:3 AND A.OFF_CYCLE=:4 AND A.EMPLID=:5 AND A.EMPL_RCD=:6
END OF STMT
PARSE #140203930927312:c=0,e=178,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1466008802922936
WAIT #140203930927312: nam='library cache lock' ela= 89 handle address=13956911600 lock address=14075795680 100*mode+namespace=955359640485890 obj#=229711 tim=1466008802923114
WAIT #140203930927312: nam='library cache pin' ela= 82 handle address=13956911600 pin address=14075795424 100*mode+namespace=955359640485890 obj#=229711 tim=1466008802923249
=====================
PARSE ERROR #140203930927312:len=158 dep=0 uid=139 oct=3 lid=139 tim=1466008802924036 err=31011
SELECT A.BENEFIT_RCD_NBR FROM PS_PAY_EARNINGS A WHERE A.COMPANY=:1 AND A.PAYGROUP=:2 AND A.PAY_END_DT=:3 AND A.OFF_CYCLE=:4 AND A.EMPLID=:5 AND A.EMPL_RCD=:6
…
I found I could reproduce it in SQL*Plus. I tried an explain plan in SQL*Plus so it would just parse the statement
SQL> explain plan for
  2  SELECT A.BENEFIT_RCD_NBR
  3  FROM PS_PAY_EARNINGS A
  4  WHERE A.COMPANY=:1 AND A.PAYGROUP=:2 AND A.PAY_END_DT=:3
  5  AND A.OFF_CYCLE=:4 AND A.EMPLID=:5 AND A.EMPL_RCD=:6
  6  /
FROM PS_PAY_EARNINGS A
     *
ERROR at line 3:
ORA-31011: XML parsing failed
ORA-19202: Error occurred in XML processing
LPX-00210: expected '<' instead of '┐'
Error at line 1
It produced a perfectly innocuous execution plan
Plan hash value: 1063404702
------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |     1 |    79 |     4   (0)| 00:00:01 |
|*  1 |  INDEX RANGE SCAN| PSAPAY_EARNINGS |     1 |    79 |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
   1 - SEL$1 / A@SEL$1

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      INDEX(@"SEL$1" "A"@"SEL$1" ("PS_PAY_EARNINGS"."COMPANY"
              "PS_PAY_EARNINGS"."PAYGROUP" "PS_PAY_EARNINGS"."PAY_END_DT"
              "PS_PAY_EARNINGS"."OFF_CYCLE" "PS_PAY_EARNINGS"."PAGE_NUM"
              "PS_PAY_EARNINGS"."LINE_NUM" "PS_PAY_EARNINGS"."SEPCHK"
              "PS_PAY_EARNINGS"."ADDL_NBR" "PS_PAY_EARNINGS"."PAY_LINE_STATUS"
              "PS_PAY_EARNINGS"."OK_TO_PAY" "PS_PAY_EARNINGS"."SINGLE_CHECK_USE"
              "PS_PAY_EARNINGS"."EMPLID" "PS_PAY_EARNINGS"."EMPL_RCD"
              "PS_PAY_EARNINGS"."BENEFIT_RCD_NBR"))
      OUTLINE_LEAF(@"SEL$1")
      ALL_ROWS
      DB_VERSION('11.2.0.4')
      OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
      IGNORE_OPTIM_EMBEDDED_HINTS
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("A"."COMPANY"=:1 AND "A"."PAYGROUP"=:2 AND
              "A"."PAY_END_DT"=:3 AND "A"."OFF_CYCLE"=:4 AND "A"."EMPLID"=:5 AND
              "A"."EMPL_RCD"=TO_NUMBER(:6))
       filter("A"."EMPLID"=:5 AND "A"."EMPL_RCD"=TO_NUMBER(:6))
But then if I used different bind variable names so I could specify variables in SQL*Plus and assign values the statement no longer produced the error.
SQL> explain plan for
  2  SELECT A.BENEFIT_RCD_NBR FROM PS_PAY_EARNINGS A
  3  WHERE A.COMPANY=:b1 AND A.PAYGROUP=:b2 AND A.PAY_END_DT=:b3
  4  AND A.OFF_CYCLE=:b4 AND A.EMPLID=:b5 AND A.EMPL_RCD=:b6
  5  /

Explained.
Or, if I tried a different numeric column, again no error.
SQL> explain plan for
  2  SELECT A.SHIFT_RT
  3  FROM PS_PAY_EARNINGS A
  4  WHERE A.COMPANY=:1 AND A.PAYGROUP=:2 AND A.PAY_END_DT=:3
  5  AND A.OFF_CYCLE=:4 AND A.EMPLID=:5 AND A.EMPL_RCD=:6
  6  /

Explained.
I wondered if the table was corrupt in some way and tried rebuilding it, but that didn't make any difference.
I couldn't decide if this error means the bind variables haven’t been set up properly in COBOL (I had already worked through other COBOL issues), or whether there really is a problem in the database.
I will also say that I had changed the character set on this database from WE8MSWIN1252 to AL32UTF8.
In fact there is a clue to what was actually going on in what I have already described, but I had got too close to the problem to see it. At this point I asked some colleagues to take a look and two very good suggestions were made. One was to generate an error stack to investigate the error. I will tell you about the other one later.

Error Stack 

I enabled, at session level, an event to generate an error stack on the error. I also added an identifier to the trace file name to make it easier to find the file.
alter session set tracefile_identifier=ERRORSTACK;
alter session set events '31011 trace name errorstack level 3';
I reproduced the error and got this trace file. It has the standard trace header information.
Trace file /u01/app/oracle/diag/rdbms/xxxxxx/XXXXXX1/trace/XXXXXX1_ora_16657_ERRORSTACK.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0.4/dbhome_1
System name: Linux
Node name: xxxxxxxxx.enkitec.local
Release: 2.6.39-400.250.4.el6uek.x86_64
Version: #1 SMP Tue Jun 2 14:50:33 PDT 2015
Machine: x86_64
Instance name: XXXXXX1
Redo thread mounted by this instance: 1
Oracle process number: 57
Unix process pid: 16657, image: oracle@xxxxxxxx.enkitec.local

*** 2016-06-16 03:46:31.677
*** SESSION ID:(56.4425) 2016-06-16 03:46:31.677
*** CLIENT ID:() 2016-06-16 03:46:31.677
*** SERVICE NAME:(XXXXXX) 2016-06-16 03:46:31.677
*** MODULE NAME:(SQL*Plus) 2016-06-16 03:46:31.677
*** ACTION NAME:() 2016-06-16 03:46:31.677
Then we get the error message and problem SQL statement
*** 2016-06-16 03:46:31.677
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=3, mask=0x0)
----- Error Stack Dump -----
ORA-31011: XML parsing failed
ORA-19202: Error occurred in XML processing
LPX-00210: expected '<' instead of '¯'
Error at line 1
----- Current SQL Statement for this session (sql_id=0vzbgvwh3mr4v) -----
explain plan for
SELECT A.BENEFIT_RCD_NBR
FROM PS_PAY_EARNINGS A
WHERE A.COMPANY=:1 AND A.PAYGROUP=:2 AND A.PAY_END_DT=:3
AND A.OFF_CYCLE=:4 AND A.EMPLID=:5 AND A.EMPL_RCD=:6
Next comes the stack trace. The list of C functions in the Oracle kernel that have been called when the error occurs. The stack trace starts with the most deeply nested function and works up towards the main() function.
We have an XML error, so let's see if there is anything in the stack about XML. I have marked them in bold to make it easier.

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
skdstdst()+41        call     kgdsdst()            000000000 ? 000000000 ?
                                                   7FFFF4C2BA00 ? 7FFFF4C2BAD8 ?
                                                   7FFFF4C30580 ? 000000002 ?
ksedst1()+103        call     skdstdst()           000000000 ? 000000000 ?
                                                   7FFFF4C2BA00 ? 7FFFF4C2BAD8 ?
                                                   7FFFF4C30580 ? 000000002 ?
ksedst()+39          call     ksedst1()            000000000 ? 000000001 ?
                                                   7FFFF4C2BA00 ? 7FFFF4C2BAD8 ?
                                                   7FFFF4C30580 ? 000000002 ?
dbkedDefDump()+2746  call     ksedst()             000000000 ? 000000001 ?
                                                   7FFFF4C2BA00 ? 7FFFF4C2BAD8 ?
                                                   7FFFF4C30580 ? 000000002 ?
ksedmp()+41          call     dbkedDefDump()       000000003 ? 000000000 ?
                                                   7FFFF4C2BA00 ? 7FFFF4C2BAD8 ?
                                                   7FFFF4C30580 ? 000000002 ?
dbkdaKsdActDriver()  call     ksedmp()             000000003 ? 000000000 ?
+1960                                              7FFFF4C2BA00 ? 7FFFF4C2BAD8 ?
                                                   7FFFF4C30580 ? 000000002 ?
dbgdaExecuteAction(  call     dbkdaKsdActDriver()  7FE43E28E730 ? 7FFFF4C32C80 ?
)+1065                                             7FFFF4C2BA00 ? 7FFFF4C2BAD8 ?
                                                   7FFFF4C30580 ? 000000002 ?
dbgdaRunAction()+81  call     dbgdaExecuteAction(  7FE43E28E730 ? 00A600760 ?
5                             )                    0020C0003 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
dbgdRunActions()+64  call     dbgdaRunAction()     7FE43E28E730 ? 000000005 ?
                                                   0020C0003 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
dbgdProcessEventAct  call     dbgdRunActions()     7FE43E28E730 ? 000000005 ?
ions()+656                                         0020C0003 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
dbgdChkEventKgErr()  call     dbgdProcessEventAct  7FE43E28E730 ? 00C0CC9E0 ?
+1658                         ions()               7FE43A453998 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
dbkdChkEventRdbmsEr  call     dbgdChkEventKgErr()  7FE43E28E730 ? 00C0CC9E0 ?
r()+61                                             7FE43A453998 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
ksfpec()+66          call     dbkdChkEventRdbmsEr  7FE43E28E730 ? 00C0CC9E0 ?
                              r()                  7FE43A453998 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
dbgePostErrorKGE()+  call     ksfpec()             7FE43E28E730 ? 00C0CC9E0 ?
1137                                               7FE43A453998 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
dbkePostKGE_kgsf()+  call     dbgePostErrorKGE()   00C0CC9E0 ? 7FE43B3B4920 ?
71                                                 000007923 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
kgeselv()+276        call     dbkePostKGE_kgsf()   00C0CC9E0 ? 7FE43B3B4920 ?
                                                   000007923 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000002 ?
kgesecl0()+139       call     kgeselv()            00C0CC9E0 ? 7FE43B3B4920 ?
                                                   000007923 ? 7FFFF4C32C80 ?
                                                   000000001 ? 000000000 ?
qmxErrHandler()+860  call     kgesecl0()           00C0CC9E0 ? 7FE43B3B4920 ?
                                                   000007923 ? 7FFFF4C32C80 ?
                                                   000000001 ? 00000000A ?
XmlErrOut()+61       call     qmxErrHandler()      7FFFF4C36DE0 ? 7FE43B3B4920 ?
                                                   000007923 ? 7FFFF4C32C80 ?
                                                   000000001 ? 00000000A ?
LpxErrMsg()+223      call     XmlErrOut()          7FE43A7BFBF8 ? 7FE43B3B4920 ?
                                                   7FFFF4C343E0 ? 7FFFF4C32C80 ?
                                                   000000001 ? 00000000A ?
LpxFSMParseProlog()  call     LpxErrMsg()          7FE43A7BFBF8 ? 7FE43B3B4920 ?
+12252                                             00000003C ? 000E3B1AF ?
                                                   000000000 ? 0000000E3 ?
LpxFSMParseDocument  call     LpxFSMParseProlog()  00287CB91 ? 7FE4219243E0 ?
()+296                                             00000003C ? 000E3B1AF ?
                                                   000000000 ? 0000000E3 ?
LpxParse()+2304      call     LpxFSMParseDocument  7FE43B275BC8 ? 7FE4219243E0 ?
                              ()                   00000003C ? 000E3B1AF ?
                                                   000000000 ? 0000000E3 ?
LpxBufferParse()+49  call     LpxParse()           7FE43B275BC8 ? 000000003 ?
                                                   7FE4219248F0 ? 00000047D ?
                                                   000000000 ? 7FE43B3DFD78 ?
qmxuParseXobDoc_int  call     LpxBufferParse()     7FE43B275BC8 ? 000000003 ?
()+2968                                            7FE4219248F0 ? 00000047D ?
                                                   000000000 ? 7FE43B3DFD78 ?
qmxManifest0()+1871  call     qmxuParseXobDoc_int  00C0CC9E0 ? 2DBE2A518 ?
                              ()                   7FE4219248F0 ? 00000047D ?
                                                   000000000 ? 7FE43B3DFD78 ?
qmxManifest()+95     call     qmxManifest0()       00C0CC9E0 ? 2DBE2A518 ?
                                                   000000000 ? 000000000 ?
                                                   000000001 ? 000000000 ?
qmxIterInit()+183    call     qmxManifest()        00C0CC9E0 ? 2DBE2A518 ?
                                                   000000000 ? 000000000 ?
                                                   000000001 ? 000000000 ?
qmxGetNodeByNameCS(  call     qmxIterInit()        00C0CC9E0 ? 7FFFF4C38538 ?
)+191                                              2DBE2A518 ? 00000001E ?
                                                   000000001 ? 000000000 ?
qolTextXmlStringToH  call     qmxGetNodeByNameCS(  00C0CC9E0 ? 2DBE2A518 ?
intList()+140                 )                    2DBE2A518 ? 00000001E ?
                                                   000000000 ? 00C0CC9E0 ?
qsmoGetSqlProfHints  call     qolTextXmlStringToH  2DB891498 ? 7FE4219248F0 ?
()+402                        intList()            00000047D ? 00000001E ?
                                                   000000000 ? 00C0CC9E0 ?
opiSem()+17280       call     qsmoGetSqlProfHints  2DB891498 ? 7FE4219248F0 ?
                              ()                   00000047D ? 00000001E ?
                                                   000000000 ? 00C0CC9E0 ?
opiDeferredSem()+40  call     opiSem()             7FFFF4C3B1A0 ? 345825198 ?
0                                                  0000000AF ? 00000001E ?
                                                   000000000 ? 00C0CC9E0 ?
opitca()+250         call     opiDeferredSem()     7FFFF4C3B1A0 ? 000000000 ?
                                                   0000000AF ? 00000001E ?
                                                   000000000 ? 00C0CC9E0 ?
kksFullTypeCheck()+  call     opitca()             7FE43AF06BD8 ? 2DB8915E8 ?
69                                                 7FFFF4C3D7C0 ? 00000001E ?
                                                   000000000 ? 00C0CC9E0 ?
rpiswu2()+1776       call     kksFullTypeCheck()   7FFFF4C3C8C0 ? 2DB8915E8 ?
                                                   7FFFF4C3D7C0 ? 00000001E ?
                                                   000000000 ? 00C0CC9E0 ?
kksSetBindType()+21  call     rpiswu2()            34C302480 ? 00000008B ?
92                                                 302E454AC ? 000000025 ?
                                                   000000000 ? 00C0CC9E0 ?
kksfbc()+11135       call     kksSetBindType()     7FFFF4C3D7C0 ? 7FE43AF06BD8 ?
                                                   7FFFF4C3D850 ? 000000102 ?
                                                   000000014 ? 000000000 ?
opiexe()+2330        call     kksfbc()             7FE43AF06BD8 ? 000000003 ?
                                                   000000102 ? 000000000 ?
                                                   000000000 ? 000000000 ?
kpoal8()+2118        call     opiexe()             000000049 ? 000000003 ?
                                                   000000102 ? 000000000 ?
                                                   000000000 ? 000000000 ?
opiodr()+917         call     kpoal8()             00000005E ? 000000003 ?
                                                   000000102 ? 000000000 ?
                                                   000000000 ? 000000000 ?
ttcpip()+2183        call     opiodr()             00000005E ? 00000001C ?
                                                   7FFFF4C41FD0 ? 000000000 ?
                                                   000000000 ? 000000000 ?
opitsk()+1710        call     ttcpip()             00C0EA630 ? 00999BB10 ?
                                                   7FFFF4C41FD0 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
opiino()+969         call     opitsk()             00C0EA638 ? 000000000 ?
                                                   7FFFF4C41FD0 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
opiodr()+917         call     opiino()             00000003C ? 000000004 ?
                                                   7FFFF4C437C8 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
opidrv()+570         call     opiodr()             00000003C ? 000000004 ?
                                                   7FFFF4C437C8 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
sou2o()+103          call     opidrv()             00000003C ? 000000004 ?
                                                   7FFFF4C437C8 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
opimai_real()+133    call     sou2o()              7FFFF4C437A0 ? 00000003C ?
                                                   000000004 ? 7FFFF4C437C8 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
ssthrdmain()+265     call     opimai_real()        000000002 ? 7FFFF4C43990 ?
                                                   000000004 ? 7FFFF4C437C8 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
main()+201           call     ssthrdmain()         000000002 ? 7FFFF4C43990 ?
                                                   000000001 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
__libc_start_main()  call     main()               000000002 ? 7FFFF4C43B38 ?
+253                                               000000001 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
_start()+41          call     __libc_start_main()  000A29134 ? 000000002 ?
                                                   7FFFF4C43B28 ? 000000000 ?
                                                   7FFFF4C41A28 ? 7FFFF4C41FCC ?
There is a call to a function called qsmoGetSqlProfHints(). So do we have SQL Profiles?
The other suggestion made by independently by two colleagues was to look at whether there was a SQL Profile in place. A search on Oracle Support produced the following:
In short, the character set conversion has corrupted the SQL Profiles, and that is causing the error.

Fixing the Profiles 

I checked and we did have profiles. So I moved them to a different category.
BEGIN
 FOR i IN (select * from dba_sql_profiles WHERE category = 'DEFAULT') LOOP
  dbms_sqltune.ALTER_SQL_PROFILE(name=>i.name, attribute_name => 'CATEGORY', value=>'CORRUPT');
 END LOOP;
END;
/
The error ceased, but I could reproduce it if I set
ALTER SESSION SET SQLTUNE_CATEGORY = 'CORRUPT';
So, there is no question but that the profiles have been corrupted in some way.  When I changed the SQL statement in the explain command, it did not error because the profile did not match.
So, I disabled the profiles to make certain they can't be used.
BEGIN
 FOR i IN (select * from dba_sql_profiles WHERE category = 'CORRUPT') LOOP
  dbms_sqltune.ALTER_SQL_PROFILE(name=>i.name, attribute_name => 'STATUS', value=>'DISABLED');
 END LOOP;
END;
/
However, we need the profiles from the original system to maintain the performance assured by the profiles, so I renamed the corrupt profiles and migrated the correct profiles per Doc ID 457531.1: How to Move SQL Profiles from One Database to Another (Including to Higher Versions).
Now, when I produce an execution plan for the problem statement I can see there is a SQL*Profile referenced in the note at the bottom of the execution plan
Plan hash value: 1063404702
------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |     1 |    79 |     4   (0)| 00:00:01 |
|*  1 |  INDEX RANGE SCAN| PSAPAY_EARNINGS |     1 |    79 |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
   1 - SEL$1 / A@SEL$1

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      INDEX(@"SEL$1" "A"@"SEL$1" ("PS_PAY_EARNINGS"."COMPANY"
              "PS_PAY_EARNINGS"."PAYGROUP" "PS_PAY_EARNINGS"."PAY_END_DT"
              "PS_PAY_EARNINGS"."OFF_CYCLE" "PS_PAY_EARNINGS"."PAGE_NUM"
              "PS_PAY_EARNINGS"."LINE_NUM" "PS_PAY_EARNINGS"."SEPCHK"
              "PS_PAY_EARNINGS"."ADDL_NBR" "PS_PAY_EARNINGS"."PAY_LINE_STATUS"
              "PS_PAY_EARNINGS"."OK_TO_PAY" "PS_PAY_EARNINGS"."SINGLE_CHECK_USE"
              "PS_PAY_EARNINGS"."EMPLID" "PS_PAY_EARNINGS"."EMPL_RCD"
              "PS_PAY_EARNINGS"."BENEFIT_RCD_NBR"))
      OUTLINE_LEAF(@"SEL$1")
      ALL_ROWS
      DB_VERSION('11.2.0.4')
      OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
      IGNORE_OPTIM_EMBEDDED_HINTS
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("A"."COMPANY"=:1 AND "A"."PAYGROUP"=:2 AND
              "A"."PAY_END_DT"=:3 AND "A"."OFF_CYCLE"=:4 AND "A"."EMPLID"=:5 AND
              "A"."EMPL_RCD"=TO_NUMBER(:6))
       filter("A"."EMPLID"=:5 AND "A"."EMPL_RCD"=TO_NUMBER(:6))

Note
-----
   - SQL profile "SYS_SQLPROF_014b572bf5550000" used for this statement

Footnote

If I flushed the shared pool and reproduced the error with session trace running, then the trace file did show some recursive SQL associated with reading SQL Profiles from the data dictionary, but this SQL was parsed and cached when the error occurred in a COBOL process emitting trace.

Conclusions

  • Don't suffer in silence. Describe your problem properly to your colleagues/a list server/Oracle support as appropriate. Often, just describing it to someone else can help you to see it more clearly. 
  • The error stack may shed light where other techniques leave you stumped. Session trace, so often the rightly instinctive for choice for such analyses, did not reveal anything in this case. My thanks to Frits Hoogland for suggesting this approach. 
  • This was not the first problem we experienced in this database due to changing from a single-byte character set to Unicode (AL32UTF8). Perhaps we should have gone back and recreated the database as a Unicode database and reimported the data.

Saturday, November 14, 2015

Disappearing Histograms

In general once you have a histogram on a column you keep it.  However, this is not because DBMS_STATS simply maintains it because it is there, but because it is still appropriate to have it based on the column workload usage.
Since Oracle 10g, the default method for collecting histograms is AUTO, which means that Oracle determines whether to collect a histogram based on data distribution and the workload of the column.
What is less well known (including to me until recently), is that histograms can be removed if there is no column workload to justify them.

This can be an issue when for some reason you have imported statistics on a freshly rebuilt table with no column usage.  I think the first two scenarios are the most likely:
  1. Export statistics.  Reorganize table by recreation.  Import statistics.  
  2. On a test database, import cut down data set and but full volume production statistics.
  3. Column usage is deleted.
In all cases, the histograms will removed by the maintenance window statistics job if column usage has not built up again.  This can lead to changes in execution plan and performance problems.  When this happens in a production system, it is often a transient problem until the column usage builds up and the histograms are usually reinstated when statistics are next collected.
In the third scenario you have the potential to refer back to any statistics history (see Mauro Pagano's blog Histograms Come Histograms Go), but that will not be the case where the original table has been dropped.

Demonstration

I will create a table and populate it.  The data in columns A, B and C is perfectly uniform, only column SKEW is skewed.
drop table t purge
/
create table t
(a number
,b number
,c number
,skew number
)
/
insert into t 
with x as (
select rownum n from dual connect by level <= 10
)
select a.n, b.n, c.n, a.n*b.n*c.n 
from x a, x b, x c
/
Note that I have collected statistics with SKEWONLY. So statistics will be collected if the data distribution is skewed irrespective of the usage of the column.
REM collect stats and histograms on everything
begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT' ,tabname=>'T' ,method_opt=>'FOR ALL COLUMNS SIZE SKEWONLY'
 );
end;
/
REM check for histogram
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from   dba_tab_col_statistics
where  owner = 'SCOTT'
and    table_name = 'T'
/
Now I have histograms on all columns, even though the data in columns A, B and C is not skewed at all but is perfectly uniform,  This shows the value of the column usage feature it limiting excessive collection of histograms.
Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------                                                 
T     A            10     0 FREQUENCY      10    1000
T     B            10     0 FREQUENCY      10    1000
T     C            10     0 FREQUENCY      10    1000
T     SKEW        120     0 FREQUENCY     120    1000
At this point there is no column usage. So when I collect statistics the histogram will all disappear.
REM check no column usage
select *
from   sys.col_usage$ u
where  obj# IN(select object_id 
               from  dba_objects 
               WHERE owner = 'SCOTT'
               AND   object_name = 'T'
               AND   object_Type = 'TABLE')
/
REM collect the stats with default col usage
begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT',tabname=>'T');
end;
/
REM check for histogram - should have gone with no col usage
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from   dba_tab_col_statistics
where  owner = 'SCOTT'
and    table_name = 'T'
/

Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------
T     A            10     0 NONE            1    1000
T     B            10     0 NONE            1    1000
T     C            10     0 NONE            1    1000
T     SKEW        120     0 NONE            1    1000
Sure enough, there are now no histograms on the columns, and there is just a single bucket on each column. So now I will generate some column usage, I will do some equality queries on the column SKEW, and I will flush the monitoring information to the data dictionary.
set serveroutput off
declare
 z NUMBER;
begin
 for a in 1..10 loop
  for b in 1..10 loop
   for c in 1..10 loop
    EXECUTE IMMEDIATE 'SELECT '||'/*'||(a*b*c)||'*/'||' count(*) FROM t where skew = '||(a*b*c) INTO z;
   end loop;
  end loop;
 end loop;
end;
/
exec dbms_stats.flush_database_monitoring_info;
select *
from sys.col_usage$ u
where obj# IN(select object_id 
 from  dba_objects 
 WHERE owner = 'SCOTT'
  AND   object_name = 'T'
 AND   object_Type = 'TABLE')
/
      OBJ#    INTCOL# EQUALITY_PREDS EQUIJOIN_PREDS NONEQUIJOIN_PREDS RANGE_PREDS LIKE_PREDS NULL_PREDS TIMESTAMP
---------- ---------- -------------- -------------- ----------------- ----------- ---------- ---------- ---------
     98167          4              1              0                 0           0          0          0 04-NOV-15
The column usage report tells us that there has been an equality predicate used on the column SKEW.
select dbms_stats.report_col_usage('SCOTT','T') from dual
/
DBMS_STATS.REPORT_COL_USAGE('SCOTT','T')
--------------------------------------------------------------------------------
LEGEND:                                                                                                                                 
.......                                                                                               
                                                
EQ         : Used in single table EQuality predicate
RANGE      : Used in single table RANGE predicate   
LIKE       : Used in single table LIKE predicate    
NULL       : Used in single table is (not) NULL predicate
EQ_JOIN    : Used in EQuality JOIN predicate             
NONEQ_JOIN : Used in NON EQuality JOIN predicate         
FILTER     : Used in single table FILTER predicate       
JOIN       : Used in JOIN predicate                      

DBMS_STATS.REPORT_COL_USAGE('SCOTT','T')                 
-------------------------------------------------------------------------------- 
GROUP_BY   : Used in GROUP BY expression
...............................................................................
###############################################################################
                       COLUMN USAGE REPORT FOR SCOTT.T                                                                       
................................
1. SKEW                                : EQ                                                           
###############################################################################
Now, when I collect statistics with the default METHOD_OPT, I will get a histogram on SKEW,
begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT',tabname=>'T');
end;
/
REM check for histogram - should have gone with no col usage
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from dba_tab_col_statistics
where owner = 'SCOTT'
and  table_name = 'T'
/

Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------
T     A            10     0 NONE            1    1000
T     B            10     0 NONE            1    1000
T     C            10     0 NONE            1    1000
T     SKEW        120     0 FREQUENCY     120    1000
Nest, I will delete the column usage and collect the statistics again
REM remove the column usage
exec dbms_stats.reset_col_usage('SCOTT','T');
begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT',tabname=>'T');
end;
/
REM check for histogram - should have gone with no col usage
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from dba_tab_col_statistics
where owner = 'SCOTT'
and  table_name = 'T'
/
And now the histogram has gone. QED.

Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------
T     A            10     0 NONE            1    1000
T     B            10     0 NONE            1    1000
T     C            10     0 NONE            1    1000
T     SKEW        120     0 NONE            1    1000

Conclusion

As you add histograms to a table, the time taken to collect statistics and to parse statements increases.  I think having a mechanism to remove unwanted histograms is desirable.  However, it has the potential to cause problems, so just be aware of it.
If you are sure that you need histograms on a particular column, then I would suggest creating table preferences for METHOD_OPT, and managing those preferences along with the table DDL.

Monday, August 24, 2015

When Is An Idle Wait Not An Idle Wait?

 In general, performance tuning is quite straightforward. You work out how much time is spent doing what, and follow the numbers to the things that are taking the most time. If you are fortunate to the have the Diagnostics Pack on Enterprise Edition of Oracle you Active Session History will report the active database sessions. If you can measure the overall response time of a batch or application server you have merely to deduct the DB reported in ASH, and difference is client/middleware time.
While that is an over-simplification, it is substantially true. The rest of this blog is about an exception to the general rule.

A War Story 

I've been working with a system that makes extensive, and probably excessive, use of database links. There is a constellation of 3 Oracle databases and there are database links between them. There is also a soon-to-be legacy DB2 database, and one of the Oracle database uses Oracle Transparent Gateway to create Heterogeneous Database Links over which the application running on Oracle references data in the DB2 database.
During a load test, nearly all of the 64 application server processes are reported as busy handling requests, yet ASH reports than usually less than 2 database sessions are concurrently busy. You would expect to see 60 application server processes consuming CPU, but CPU does not appear to be as highly utilised as we should expect.
Application Server Activity
Database Activity
An application SQL trace reports that while the majority of the time is indeed spent on client CPU, about 20% is spent on a few SQL statements that reference synonyms that refer to tables or views in a DB2 database. Why didn't these show up in ASH?

A Simple Test Script 

I wrote a simple test script that just executes the SQL statements that refer to the DB2 objects, but it collects AWR snapshots at the beginning and end of the script, and it also enables Oracle session trace. 
set verify on head on timi on feedback on lines 200 trimspool on
spool otg_db2

variable b1 VARCHAR2(10)
variable b2 VARCHAR2(10)

BEGIN
 :b1 := '123456789';
 :b2 := '42';
END;

ALTER SESSION SET tracefile_identifier='OTG_DB2';
ALTER SESSION SET current_schema=APPSCHEMA;

EXEC dbms_workload_repository.create_snapshot;
EXEC dbms_application_info.set_action('OTG_DB2');
EXEC dbms_monitor.session_trace_enable;

SELECT …
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2
/
SELECT …
FROM db2_object2 a
WHERE a.field1 = :b1 AND a.field2 = :b2
/
…

exec dbms_application_info.set_action('NONE');
exec dbms_monitor.session_Trace_disable;
exec dbms_workload_repository.create_snapshot;

select sample_id, sample_time, sql_id, sql_plan_hash_value, sql_plan_line_id, sql_exec_id, event
from v$active_session_history
where action = 'OTG_DB2';

spool off
The first interesting output is that although some of the queries on DB2 objects took several seconds, I didn't get any rows in the query on ASH buffer for this session.
So, now let's look at the trace file. This is the output for the longest SQL statement having profiled it in TKPROF. We can see that nearly all the time is spent on an event called HS message to agent.
SELECT …
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.04          0          0          1           0
Fetch        1      0.00       2.73          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       2.77          0          0          1           0

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 35  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  DFS lock handle                                 1        0.00          0.00
  rdbms ipc reply                                 2        0.00          0.00
  HS message to agent                             5        2.73          2.77
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
And this is the corresponding section of the raw trace. The execution took just under 42ms, and then the fetch took 2.73 seconds.
PARSING IN CURSOR #4579254328 len=171 dep=0 uid=35 oct=3 lid=0 tim=14984112395546 hv=1291470523 ad='700010b2204a518' sqlid='xxxxxxxxxxxxx'
SELECT …
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2
END OF STMT
PARSE #4579254328:c=106,e=172,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=14984112395545
WAIT #4579254328: nam='Disk file operations I/O' ela= 23 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=14984112395633
WAIT #4579254328: nam='DFS lock handle' ela= 5205 type|mode=1146617861 id1=3569868743 id2=0 obj#=-1 tim=14984112401137
WAIT #4579254328: nam='rdbms ipc reply' ela= 75 from_process=46 timeout=900 p3=0 obj#=-1 tim=14984112401291
WAIT #4579254328: nam='rdbms ipc reply' ela= 710 from_process=46 timeout=900 p3=0 obj#=-1 tim=14984112402047
WAIT #4579254328: nam='HS message to agent' ela= 3464 p1=0 p2=0 p3=0 obj#=-1 tim=14984112405590
WAIT #4579254328: nam='HS message to agent' ela= 38459 p1=0 p2=0 p3=0 obj#=-1 tim=14984112444724
WAIT #4579254328: nam='HS message to agent' ela= 17 p1=0 p2=0 p3=0 obj#=-1 tim=14984112444791
EXEC #4579254328:c=932,e=49215,p=0,cr=0,cu=1,mis=1,r=0,dep=0,og=1,plh=0,tim=14984112444865
WAIT #4579254328: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=14984112444958
WAIT #4579254328: nam='HS message to agent' ela= 2730045 p1=0 p2=0 p3=0 obj#=-1 tim=14984115175093
WAIT #4579254328: nam='HS message to agent' ela= 8 p1=0 p2=0 p3=0 obj#=-1 tim=14984115175165
FETCH #4579254328:c=206,e=2730295,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=14984115175285
WAIT #4579254328: nam='SQL*Net message from client' ela= 895 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=14984115176264
CLOSE #4579254328:c=10,e=16,dep=0,type=0,tim=14984115176343
Across the whole of my test I have 29 waits on this event totalling 5.3s. Why I am not seeing this event in ASH?
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        9      0.00       0.00          0          0          0           0
Execute     10      0.00       0.21          0          0          1           3
Fetch        7      0.00       5.10          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       26      0.01       5.32          0          0          1           3

Misses in library cache during parse: 3
Misses in library cache during execute: 4

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       9        0.00          0.00
  SQL*Net message from client                     9        0.00          0.00
  Disk file operations I/O                        9        0.00          0.00
  DFS lock handle                                 1        0.00          0.00
  rdbms ipc reply                                 2        0.00          0.00
  HS message to agent                            29        2.73          5.30
  library cache pin                               2        0.00          0.00
If I generate an ASH report on the two snapshots created in this test and look at the Foreground events I might start to see why. AWR reports 29 waits totalling 5 seconds, so that agrees. However, note that this is at the bottom of the report with 'SQL*Net message from client' and there is no '%DB Time'.
AWR Foreground Events

We (should) know that 'SQL*Net message from client' is an idle event. So we can understand that there are 806 seconds reported on this event in this AWR report because there were 151 sessions connect to the database, most of which were mostly idle for the 6 seconds between the AWR snapshots. That is perfectly normal.
However, HS message to agent is classed as an idle wait, although the user was not idle. During this event the application is not busy, it is waiting for the Oracle database to respond, which is in turn waiting for the remote non-Oracle database to respond.
 This is in contrast to Oracle-to-Oracle (homogeneous) database links which report time to 'SQL*Net message from dblink' which is not an idle wait, but is part of the 'Network' wait class. I think the difference is an anomaly.
The next question is how much time my application spent on this event. For that I must look at the AWR data, either by generating an AWR report that corresponds to the load test, or directly in dba_hist_system_event.

Waits from AWR snspshots

Conclusion

  1. I am not the first person to call this out, just the latest person to get caught by it. It may be an idle wait, but the user is waiting for the database to respond. 
    Database Link Wait Event Wait Class
    Heterogeneous HS message to agent Idle
    Homogeneous SQL*Net message from dblink Network
  2. I got as far as starting to write an e-mail to a colleague asking for help, but before sending it I realised that I could do more to find out what was happening. Perhaps just the act of try to explain the problem helped me to think more clearly about it.

Thursday, December 20, 2012

No DBA is an Island

Introduction

I gave an OakTalk at the UKOUG2012 conference. This article is based upon the notes for that talk. It is not a technical article, just an opinion piece.
I have always described myself as a DBA, although it has been many years since I had day-to-day responsibility for a production database.  My day job is about performance, helping people to get the best possible performance from their PeopleSoft systems.  That can involve anything from tuning a specific SQL statement, to changing how the database, middleware, or application has been configured, through to standing back and looking at the way the architecture has been put together.  Lots of people have to work together on any system, and I frequently work with people for whom the database is not their home
The concept of the division of labour is nothing new.  Plato suggested the ‘minimum state would consist of four or five men’.  Adam Smith (possibly inspired by Henri-Louis Duhamel du Monceau) famously took the manufacture of pins as his example.  Businesses must break tasks down into manageable units, and as they do each person’s job becomes progresively more specific and specialised. 
IT is no exception.  The modern IT department is broken down into teams of administrators.  We have desktop teams, network teams, application administrators, middleware teams, DBA, operating system admins, storage area network teams.  In some places, I have seen DBA teams broken down into a core database team and separate application DBA teams for each major application.  Every tier and technology has its team, each with specialist knowledge and skills. Such are the tribes of IT.
I have heard these groupings described as verticals, or stove-pipes, or silos.  The clue is in the name.  The problem that I perceive is that these groups are not always good at communicating with each other, and when something goes wrong, they are not always above blaming one another.

What is IT for? 

A modern company simply couldn’t function without IT.  The business systems that we, as IT professionals design, build and manage are fundamental to the companies in which we work.  There will be lots of different systems that do stuff.  Different companies will do slightly different stuff.  Absolute minimum, you need a PC that can connect to things.  There will always be e-mail. There will be a Finance system to track the money.  There will be some form of HR system to track employees.  There will be a payroll system to pay the employees.  If a company sells widgets, there will be some form stock control, and some form of logistics to manage its movement.  Those systems will communicate with each other. Lots of systems, and it doesn’t really matter what the system is.  The point is that every system will need the services provided by several of those IT silos. Each system is a chain of technology that is laid horizontally across those IT silos. At one end you have users, and at the other end you probably have physical spinning disks (for now).  Over time, those chains have come to exist of every more links.

The DBA’s view?

I described myself as a DBA, because that is the tribe I came from. However, I firmly believe, if I was still a day-to-day production DBA, that in order to do my job properly, I would occasionally need to look out from my silo and not just to look at the neighbouring silos along the chains of technology, but all the silos on the chains, and sometimes even outside IT department.
I believe that the DBA is well placed and appropriately skilled to asses most aspects of a system.  Let me illustrate this with 2 examples

Example 1: Two Temporary Tablespace

I have seen more than one HR system where the temporary tablespace has been allowed to grow hugely, sometimes hundreds of GB, in response to space errors. Each time, the root cause has been users running ad-hoc queries concurrently with critical batch processes. So, I have suggested that they use two temporary tablespaces.
•    One for regular processing – on-line transaction processing, regular and scheduled batch processes.
•    Another for ad-hoc queries whether submitted by ad-hoc database users or by the application’s ad-hoc query tool.
As a DBA, that seems like a straight forward technical decision.  It will protect the critical batches from out of space errors that occur when the temp space has been consumed by the ad-hoc queries.  It allows me to regulate bad queries by restricting their temporary tablespace consumption limiting their effect on the system while they run for hours on end while they copy data into the temporary tablespace (and before anybody asks, we are also thinking about Oracle resource manager).
But it isn’t as simple as that.  It requires a different relationship between the users and their application support team.  Now, when a query crashes with an out of space error we don’t just extended the temporary tablespace, we need to examine the query and consider how it can be improved. Meanwhile, the users have to understand that this approach is for the greater good of the system, and in time it will also improve their query performance.
It is no longer just a technical problem.  It has become political.  It needs to be sold to the users, and it needs a change in business process.  So the DBA needs to talk to people outside their silo, and sometimes even outside IT.

Example 2: Archiving

I work on an Time & Labor and Payroll system that has run for 4 years without any archiving.  We have 4 years of schedule data.  4 years of reported time.  4 years of payroll data. 4 years of audit data.  We now have a 4TB OLTP database. Archiving was de-scoped from the initial implementation.
How have we survived this long?  Many of the tables that hold this data have been partitioned, mostly on a time basis – that is to say that different periods of time are different partitions.  In many cases, but by no means all, the long tail of history is hidden by partition elimination.  Partitioning was introduced to improve performance, but the design of the partitioning always had an eye to future archiving.
With or without partitioning, keeping all the data for ever is not an option.  Quite apart from data security and performance, the size of the database is becoming a challenge.  Periodically, we have to copy the production database into various development and test environments.  We trim some history from some of those environments, but size is still a challenge.
So we had to look at archive and purge.  So the first step it to understand the application, and then work out with the business users at what point do they at least no longer need the data to operate their process, and at what point can we ultimately purge the data entirely from the database. 
We are about to deliver the first tranche of archiving into one functional area.  Conceptually our process is very simple.  Some data we can purge, often by dropping partitions.  Some data we have had to keep for ad-hoc query.  Where possible, we use partition exchange to exchange historical partitions into archive tables.  We have also been very successful in using table compression to further reduce the overall database size.
Archive and purge is going to be a regular, rolling process - at least monthly.  It is going to be done without any system outage, and it will as far as possible be automated.  Therefore, we have had to build some of these processes into the application not least so the application support team has visibility. The archive process is sensitive to system date and some application data. So it has had to involve developers.
We have created a meta-data driven PL/SQL package, effectively an API, to do all the partition handling and compression. The developers call that from their processes.
It takes someone who is, if not a DBA, then very database aware to design the concept (and you’ve probably guessed correctly that in this case that DBA is me). That person also needs to have some understanding of the application and how the application data fits together. I think it is also essential, at least for the largest and most critical systems, that the DBA understands how the business uses the application.  The DBA can’t do this hiding in their silo.

Conclusion

I have heard it said that some production DBAs think their job is to make sure nothing happens; by making sure that nothing happens. Business is not about maintaining status quo.  Businesses talk about bigger, better, cheaper, faster. You can track the pulse of a business by measuring its critical IT systems. A DBA’s job is not to hold the tide back, but to make sure that the systems we tend are fit for purpose, and continue so to be. We need to be proactive. Sometimes, we should go out and be consultants, look for improvements, initiate changes, and advise on developments.
Therefore, if you are a production DBA hiding in your silo, send not to know for whom the bell tolls, it tolls for thee.