HOWTO: Trace “ORA-19022: Unoptimized XML construct”

So you’re on 11.2.0.2.0 and you encountered in SQL*Plus this new feature “Unoptimized XML construct detected (enable XMLOptimizationCheck for more information)“. What can you do and how to get more info…?

I encountered this new feature in SQL*Plus a month or so ago via the executing the following:

 
SQL> SET autotrace ON
 
SQL> SELECT xt.nam, xt2.color
  2  FROM XMLTable(XMLNamespaces(DEFAULT 'abc.com/123',
  3                              'xyz.net/456' AS "b"),
  4                'employees/emp'
  5                PASSING XMLTYPE('<employees xmlns="abc.com/123" xmlns:b="xyz.net/456">
  6   <emp>
  7    <name>Scott</name>
  8    <b:favorites>
  9     <b:color>red</b:color>
 10      <b:color>orange</b:color>
 11     </b:favorites>
 12    </emp>
 13    <emp>
 14     <name>John</name>
 15     <b:favorites>
 16      <b:color>blue</b:color>
 17      <b:color>green</b:color>
 18     </b:favorites>
 19    </emp>
 20   </employees>')
 21                 COLUMNS
 22                 nam      VARCHAR2(20) PATH 'name',
 23                 color_t  XMLTYPE      PATH 'b:favorites') xt,  
 24        XMLTable(XMLNamespaces('xyz.net/456' AS "b"),
 25                 'b:favorites/b:color'
 26                 PASSING xt.color_t  
 27                 COLUMNS
 28                 color  VARCHAR2(10) PATH '.') xt2;
 
NAM                  COLOR
-------------------- ----------
Scott                red
Scott                orange
John                 blue
John                 green
 
 
Execution Plan
----------------------------------------------------------
Plan hash VALUE: 1368717035
 
-------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                   | ROWS  | Bytes | Cost (%CPU)| TIME     |
-------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                        |    66M|   254M|   221K  (1)| 00:44:21 |
|   1 |  NESTED LOOPS                      |                        |    66M|   254M|   221K  (1)| 00:44:21 |
|   2 |   COLLECTION ITERATOR PICKLER FETCH| XMLSEQUENCEFROMXMLTYPE |  8168 | 16336 |    29   (0)| 00:00:01 |
|   3 |   COLLECTION ITERATOR PICKLER FETCH| XMLSEQUENCEFROMXMLTYPE |  8168 | 16336 |    27   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------
 
Note
-----
   - Unoptimized XML construct detected (enable XMLOptimizationCheck FOR more information)
 
 
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          0  consistent gets
          0  physical reads
          0  redo SIZE
        557  bytes sent via SQL*Net TO client
        419  bytes received via SQL*Net FROM client
          2  SQL*Net roundtrips TO/FROM client
          0  sorts (memory)
          0  sorts (disk)
          4  ROWS processed

By noticing the “COLLECTION ITERATOR PICKLER FETCH” this already dawned with me. In principle a “COLLECTION ITERATOR PICKLER FETCH” means that the XML document or (intermediate) fragment is handled in memory and should be avoided because it is “serialized” and dealt via a Pickler Fetch routine, which in most cases is done via a standard XML parser, which can not be optimized by Oracle, for example, because Oracle doesn’t have enough information (provided maybe via an XML Schema) to re-write this query in a more optimal form. See this website for more information on collection iterator pickler fetches.

XMLOptimizationCheck

The “Unoptimized XML construct detected (enable XMLOptimizationCheck for more information)” is new in SQL*Plus / database version 11.2.0.2.0 and is the equivalent of setting a 19021 level 0×1 via for example: ALTER session SET events =’19021 trace name context forever, level 0×1′.

By setting the “XMLOptimizationCheck” setting in SQL*Plus, Oracle/the database will refuse to execute this unoptimized code.

BE AWARE:
Playing with internal Oracle support database events should only be done when advised by Oracle support, or on a test system were it is not a big deal when this gets corrupted! My advice from me to you, but don’t start whining if it break your environment…You can’t say I didn’t warn you.

According to an entry in the XMLDB Developers manual this is only used in a “test” or “debug” situation.

When this mode is on, the plan of execution is automatically checked for XQuery optimization, and if the plan is suboptimal then an error is raised and diagnostic information is written to the trace file indicating which operators are not rewritten.

And in the SQL*Plus manual for the latest release, under new features, 11.2.0.2, it states:

SET XMLOPTIMIZATIONCHECK
SET XMLOPTIMIZATIONCHECK specifies that only fully optimized XML queries and DML operations are executed. It is only to assist during code development and debugging.

 
SQL> SET XMLOptimizationCheck ON
 
SQL> SELECT xt.nam, xt2.color
  2  FROM XMLTable(XMLNamespaces(DEFAULT 'abc.com/123',
  3                              'xyz.net/456' AS "b"),
  4                'employees/emp'
  5                PASSING XMLTYPE('<employees xmlns="abc.com/123" xmlns:b="xyz.net/456">
  6   <emp>
  7    <name>Scott</name>
  8    <b:favorites>
  9     <b:color>red</b:color>
 10      <b:color>orange</b:color>
 11     </b:favorites>
 12    </emp>
 13    <emp>
 14     <name>John</name>
 15     <b:favorites>
 16      <b:color>blue</b:color>
 17      <b:color>green</b:color>
 18     </b:favorites>
 19    </emp>
 20   </employees>')
 21                 COLUMNS
 22                 nam      VARCHAR2(20) PATH 'name',
 23                 color_t  XMLTYPE      PATH 'b:favorites') xt,  -- path to the node that repeats
 24        XMLTable(XMLNamespaces('xyz.net/456' AS "b"),
 25                 'b:favorites/b:color'
 26                 PASSING xt.color_t  -- define input XMLType as output of above, aka a join
 27                 COLUMNS
 28                 color  VARCHAR2(10) PATH '.') xt2;
 
SELECT xt.nam, xt2.color
*
ERROR at line 1:
ORA-19022: Unoptimized XML construct detected
.

In the trace directory, a trace file will be created showing the following, or alike trace file content for your statement. In the example here a trace file was created with the following content

[oracle@localhost trace]$ cat orcl_ora_3092.trc
 
Trace file /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3092.trc
Oracle DATABASE 11g Enterprise Edition Release 11.2.0.2.0 - Production
WITH the Partitioning, OLAP, DATA Mining AND REAL Application Testing options
ORACLE_HOME = /home/oracle/app/oracle/product/11.2.0/dbhome_2
System name:    Linux
Node name:      localhost.localdomain
Release:        2.6.18-194.0.0.0.4.el5
Version:        #1 SMP Thu Apr 8 18:20:19 EDT 2010
Machine:        i686
Instance name: orcl
Redo thread mounted BY this instance: 1
Oracle process NUMBER: 19
Unix process pid: 3092, image: oracle@localhost.localdomain (TNS V1-V3)
 
 
*** 2010-10-04 14:51:46.775
*** SESSION ID:(1.7) 2010-10-04 14:51:46.775
*** CLIENT ID:() 2010-10-04 14:51:46.775
*** SERVICE NAME:(SYS$USERS) 2010-10-04 14:51:46.775
*** MODULE NAME:(SQL*Plus) 2010-10-04 14:51:46.775
*** ACTION NAME:() 2010-10-04 14:51:46.775
 
===============================================================================
XML Performance Diagnosis:
Unparsed Query:
******* UNPARSED QUERY IS *******
SELECT CAST(SYS_XQ_UPKXML2SQL(SYS_XQEXVAL(SYS_XQEXTRACT(VALUE(KOKBF$),
'/emp/name','xmlns="abc.com/123" xmlns:b="xyz.net/456" '),0,0,20971520,0),50,1,2) 
AS VARCHAR2(20) ) "NAM",CAST(SYS_XQ_UPKXML2SQL(SYS_XQEXVAL(VALUE(KOKBF$),0,0,
20971520,0),50,1,2) AS VARCHAR2(10) ) "COLOR" 
FROM TABLE("SYS"."XQSEQUENCE"(EXTRACT("SYS"."XMLTYPE"(
'<employees xmlns="abc.com/123" xmlns:b="xyz.net/456">
 <emp>
  <name>Scott</name>
  <b:favorites>
   <b:color>red</b:color>
    <b:color>orange</b:color>
   </b:favorites>
  </emp>
  <emp>
   <name>John</name>
   <b:favorites>
    <b:color>blue</b:color>
    <b:color>green</b:color>
   </b:favorites>
  </emp>
 </employees>'),'/oraxq_defpfx:employees/oraxq_defpfx:emp',
 ' xmlns:oraxq_defpfx="abc.com/123"'))) "KOKBF$",TABLE("SYS"."XQSEQUENCE"(EXTRACT
 (EXTRACT(VALUE(KOKBF$),'/oraxq_defpfx:emp/b:favorites',' xmlns:oraxq_defpfx=
 "abc.com/123" xmlns:b="xyz.net/456"'),'/b:favorites/b:color'
 ,' xmlns:b="xyz.net/456"'))) "KOKBF$" 
 
Reason: upkxml2sql
===============================================================================
.

As shown here its depicts the “upkxml2sql” method as the guilty one. You can now try to avoid this issue by using alternative means and/or provide the database with more information, for example, while using XMLType Binary storage, XML Schema based storage (Object Relational / Binary XML) or register an XML Schema in the XDB Repository. Other alternatives could be avoiding the use of the “//” XPath operator.

The moment the query is parsed and executed / shared in cache via the cursor sharing mechanism, then there is a chance you won’t see a trace file. To avoid cursor sharing you could set the cursor sharing to “exact” and/or add white space to your query or alternate upper/lower case and/or other small tricks to force re-parsing.

Before Oracle 11.2.0.2.0 there is an alternative since, AFAIK at least, Oracle version 11.x. by setting the 19027 event, level 0×2000 to get a bit more insight in what happens under the hood, if Oracle can optimize (or not), the request via query re-write.

19027 trace name context forever, level 0×2000

If you would set the 19027 event, level 0×2000, then a trace file is produced in the trace directory of the base DIAG directory structure.

 
SQL> ALTER SESSION SET events = '19027 trace name context forever, level 0x2000';
 
SESSION altered.
 
SQL> SELECT xt.nam, xt2.color
  2  FROM XMLTable(XMLNamespaces(DEFAULT 'abc.com/123',
  3                              'xyz.net/456' AS "b"),
  4                'employees/emp'
  5                PASSING XMLTYPE('<employees xmlns="abc.com/123" xmlns:b="xyz.net/456">
  6   <emp>
  7    <name>Scott</name>
  8    <b:favorites>
  9     <b:color>red</b:color>
 10      <b:color>orange</b:color>
 11     </b:favorites>
 12    </emp>
 13    <emp>
 14     <name>John</name>
 15     <b:favorites>
 16      <b:color>blue</b:color>
 17      <b:color>green</b:color>
 18     </b:favorites>
 19    </emp>
 20   </employees>')
 21                 COLUMNS
 22                 nam      VARCHAR2(20) PATH 'name',
 23                 color_t  XMLTYPE      PATH 'b:favorites') xt,  -- path to the node that repeats
 24        XMLTable(XMLNamespaces('xyz.net/456' AS "b"),
 25                 'b:favorites/b:color'
 26                 PASSING xt.color_t  -- define input XMLType as output of above, aka a join
 27                 COLUMNS
 28                 color  VARCHAR2(10) PATH '.') xt2;
 
NAM                  COLOR
-------------------- ----------
Scott                red
Scott                orange
John                 blue
John                 green
 
SQL> ALTER SESSION SET events ='19027 trace name errorstack off';
 
SESSION altered.

The trace file can be found via following the DIAG directory structure, which can be found, for example, via entering “show parameter diag” in SQL*Plus (as user SYS or alternative highly privileged database account).

One of the latest trace files in this directory shows now similar content in that trace file as shown below.

[oracle@localhost trace]$ pwd
 
/home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace
 
[oracle@localhost trace]$ cat orcl_ora_6167.trc
Trace file /home/oracle/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_6167.trc
Oracle DATABASE 11g Enterprise Edition Release 11.2.0.2.0 - Production
WITH the Partitioning, OLAP, DATA Mining AND REAL Application Testing options
ORACLE_HOME = /home/oracle/app/oracle/product/11.2.0/dbhome_2
System name:    Linux
Node name:      localhost.localdomain
Release:        2.6.18-194.0.0.0.4.el5
Version:        #1 SMP Thu Apr 8 18:20:19 EDT 2010
Machine:        i686
Instance name: orcl
Redo thread mounted BY this instance: 1
Oracle process NUMBER: 24
Unix process pid: 6167, image: oracle@localhost.localdomain (TNS V1-V3)
 
 
*** 2010-10-04 11:06:22.030
*** SESSION ID:(1.47) 2010-10-04 11:06:22.030
*** CLIENT ID:() 2010-10-04 11:06:22.030
*** SERVICE NAME:(SYS$USERS) 2010-10-04 11:06:22.030
*** MODULE NAME:(SQL*Plus) 2010-10-04 11:06:22.030
*** ACTION NAME:() 2010-10-04 11:06:22.030
 
        XMLTABLE RWT QUERY
SELECT CAST( sys_xq_upkxml2sql(sys_xqexval(sys_xqextract(VALUE(QMXTABF$), '/emp/name','xmlns="abc.com/123" xmlns:b="xyz.net/456" ')), 50,1, 2) AS VARCHAR2(20) )  AS "NAM",xmlquery( 'declare default element namespace "abc.com/123";declare namespace b="xyz.net/456";b:favorites' PASSING BY XMLTABLE VALUE(QMXTABF$) returning content ) AS "COLOR_T" FROM TABLE(xqsequence( xmlquery('declare default element namespace "abc.com/123";declare namespace b="xyz.net/456";employees/emp' passing BY VALUE QMXTABCOL$ returning SEQUENCE)  )) QMXTABF$
        XMLTABLE RWT QUERY END
        XMLTABLE RWT QUERY
SELECT CAST( sys_xq_upkxml2sql(sys_xqexval(xmlquery( 'declare namespace b="xyz.net/456";.' PASSING BY XMLTABLE VALUE(QMXTABF$) returning SEQUENCE )), 50,1, 2) AS VARCHAR2(10) )  AS "COLOR" FROM TABLE(xqsequence( xmlquery('declare namespace b="xyz.net/456";b:favorites/b:color' passing BY VALUE QMXTABCOL$ returning SEQUENCE)  )) QMXTABF$
        XMLTABLE RWT QUERY END
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> xseq:NOT lazydef

So both XMLTABLE subsections of the used query are attempted by Oracle to rewritten into internal XQuery (“xq”, XQuery, extract, evaluate, xml2sql, xq sequence routines). Looking at the original query…

SELECT xt.nam
,      xt2.color
FROM   XMLTable(XMLNamespaces(DEFAULT 'abc.com/123',
                              'xyz.net/456' AS "b"),
                'employees/emp'
                PASSING XMLTYPE('<employees xmlns="abc.com/123" xmlns:b="xyz.net/456">
                                 <emp>
                                  <name>Scott</name>
                                  <b:favorites>
                                   <b:color>red</b:color>
                                    <b:color>orange</b:color>
                                   </b:favorites>
                                  </emp>
                                  <emp>
                                   <name>John</name>
                                   <b:favorites>
                                    <b:color>blue</b:color>
                                    <b:color>green</b:color>
                                   </b:favorites>
                                  </emp>
                                 </employees>')
                 COLUMNS
                 nam      VARCHAR2(20) PATH 'name',
                 color_t  XMLTYPE      PATH 'b:favorites') xt   
  ,     XMLTable(XMLNamespaces('xyz.net/456' AS "b"),
                 'b:favorites/b:color'
                 PASSING xt.color_t  
                 COLUMNS
                 color  VARCHAR2(10) PATH '.')             xt2
;

You can see the two XMLTABLE statements…

SELECT CAST( sys_xq_upkxml2sql(sys_xqexval(sys_xqextract(VALUE(QMXTABF$), '/emp/name'
                                                                        , 'xmlns="abc.com/123" xmlns:b="xyz.net/456" ')
                                           ), 50,1, 2
                               ) AS VARCHAR2(20) )  AS "NAM"
,      xmlquery( 'declare default element namespace "abc.com/123";
                  declare namespace b="xyz.net/456";
                  b:favorites' 
                  PASSING BY XMLTABLE VALUE(QMXTABF$) 
                  returning content ) AS "COLOR_T" 
                  FROM TABLE(xqsequence( xmlquery('declare default element namespace "abc.com/123";
                                                   declare namespace b="xyz.net/456";employees/emp' 
                                                   passing BY VALUE QMXTABCOL$ 
                                                   returning SEQUENCE) 
                                        )
                            ) QMXTABF$

and…
.

SELECT CAST( sys_xq_upkxml2sql(sys_xqexval(xmlquery( 'declare namespace b="xyz.net/456";.' 
                                                      PASSING BY XMLTABLE VALUE(QMXTABF$) 
                                                      returning SEQUENCE )
                                           ), 50,1, 2
                               ) AS VARCHAR2(10) )  AS "COLOR" 
FROM   TABLE(xqsequence( xmlquery('declare namespace b="xyz.net/456";
                                   b:favorites/b:color' 
                                   passing BY VALUE QMXTABCOL$ 
                                   returning SEQUENCE)  
                        )
            ) QMXTABF$

Most of this long list in the trace file can be deducted as in a more regular “10053″ trace file / event…

NO REWRITE
        Reason ==> NOT SQLX operand
NO REWRITE
        Reason ==> non sqlx expression INPUT
NO REWRITE
        Reason ==> no TYPE info
NO REWRITE
        Reason ==> xseq:NOT lazydef
NO REWRITE
        Reason ==> non rewritable sqlx INPUT
...
...

…but I will have to dig a bit more to see how this all fits together…

For now / HTH / To be continued…