Truncated CTAS statements seem to be no longer shortened

Many bloggers have already discussed that Oracle can truncate the text of a “create table as select” statement to 20 characters depending on your version and patch level. This can be a problem in case a CTAS statement is a resource hog, yet you don’t see the SQL text that is needed for troubleshooting. A quick search on My Oracle Support reveals this can happen on 11.2.0.4, 12.1.0.1 and 12.1.0.2 systems unless patched of course. This has been bugging me for quite some time now, and merits a blog post.

Reproducing the offending behaviour

Oracle has provided a number of patches over time to fix this undesirable short-cutting of the SQL text. I wanted to reproduce the issue on 12.1 to demonstrate the effect. To my shame I have to admit that since 12.2 has come out I have somewhat neglected my 12.1 lab system. It was quite a bit out of date, which was useful for this blog post as it will turn out.

One of my 12.1 systems (a two-node RAC) was patched to July 2016:

[oracle@rac12node1 ~]$ opatch lspatches
23177536;Database PSU 12.1.0.2.160719, Oracle JavaVM Component (JUL2016)
23144544;DATABASE BUNDLE PATCH: 12.1.0.2.160719 (23144544)
23520664;OCW Interim patch for 23520664 

OPatch succeeded.

This isn’t great, I prefer my lab systems to be more current. Long story short, this RAC system is about a year and a bit behind on patches. It shall be rectified at the next opportunity!

I am going to connect to a PDB to run the following steps, although it should not matter whether I’m running the test against a non-CDB or PDB.

To ensure repeated execution of my test case I have created a small script:

[oracle@rac12node1 ~]$ cat ctas_test.sql 
set echo on

sho user

alter session set events 'sql_trace level 8';

create table ctastest tablespace users as 
select * from dba_objects where object_id < 1000;

alter session set events 'sql_trace off';

select value from v$diag_info where name like 'Def%';
[oracle@rac12node1 ~]$ 

In the next step I am connecting to the database to run the script:

[oracle@rac12node1 ~]$ sqlplus martin@pdb_srv

SQL*Plus: Release 12.1.0.2.0 Production on Tue Oct 17 20:26:56 2017

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

Enter password: 
Last Successful login time: Tue Oct 17 2017 18:52:35 +01:00

Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Advanced Analytics and Real Application Testing options

SQL> @ctas_test
SQL> 
SQL> sho user
USER is "MARTIN"
SQL> 
SQL> alter session set events 'sql_trace level 8';

Session altered.

SQL> 
SQL> create table ctastest tablespace users as 
  2  select * from dba_objects where object_id < 1000;

Table created.

SQL> alter session set events 'sql_trace off';

Session altered.

SQL> 
SQL> select value from v$diag_info where name like 'Def%';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/cdb/CDB1/trace/CDB1_ora_16279.trc

And indeed, the SQL trace shows that the statement is truncated:

=====================
PARSING IN CURSOR #140207826820160 len=90 dep=0 uid=102 oct=1 lid=102 
tim=28239487087 hv=3859378539 ad='afafdb58' sqlid='d7y8ssmm0kwbb'
create table ctastest tab
END OF STMT
PARSE #140207826820160:c=282000,e=688749,p=90,cr=6300,cu=0,mis=1,r=0,dep=0,og=1,
 bplh=12630425,tim=28239487087
WAIT #140207826820160: nam='row cache lock' ela= 62 cache id=8 mode=0 request=3
 obj#=656 tim=28239487351

My Oracle Support also mentioned a couple of other places where the command was found to be truncated. I randomly picked one that matters to me, please consider MOS for more locations where the statements were truncated. Your mileage may vary.

SQL> set long 1000000

SQL> select sql_text, sql_fulltext from v$sql where sql_id = 'd7y8ssmm0kwbb';

SQL_TEXT
-------------------------------------------------------------------------------
SQL_FULLTEXT
-------------------------------------------------------------------------------
create table ctastest tablespace users as select * from dba_objects where 
object_id < 1000
create table ctastest tablespace users as select * from dba_objects where 
object_id < 1000

Thankfully the SQL_TEXT and SQL_FULLTEXT show the entire statement, which is good.

Now what about 12.2?

Out of curiosity I repeated the test in 12.2 to see if the problem was fixed, and it actually appears to be the case. Using the same script to connect to the database I get a different behaviour. This time around I am patched to a more recent release:

[oracle@server2 ~]$ opatch lspatches
26609817;DATABASE RELEASE UPDATE: 12.2.0.1.170814 (26609817)

OPatch succeeded.

Let’s try again:

[oracle@server2 ~]$ sqlplus martin@orcl

SQL*Plus: Release 12.2.0.1.0 Production on Tue Oct 17 20:22:15 2017

Copyright (c) 1982, 2016, Oracle.  All rights reserved.

Enter password: 
Last Successful login time: Tue Oct 17 2017 20:19:24 +02:00

Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

SQL> @ctas_test
SQL>
SQL> sho user
USER is "MARTIN"
SQL>
SQL> alter session set events 'sql_trace level 8';

Session altered.

SQL>
SQL> create table ctastest tablespace users as 
  2  select * from dba_objects where object_id < 1000;

Table created.

SQL>
SQL> alter session set events 'sql_trace off';

Session altered.

SQL>
SQL> select value from v$diag_info where name like 'Def%';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/ORCL/trace/ORCL_ora_16370.trc

SQL>

Well and it seems the statement is no longer truncated. Looking at ORCL_ora_16370.ora I can find the complete statement:

=====================
PARSING IN CURSOR #140577803287552 len=90 dep=0 uid=74 oct=1 lid=74 
 tim=39078309869 hv=3859378539 ad='64d25e58' sqlid='d7y8ssmm0kwbb'
create table ctastest tablespace users as select * from dba_objects 
where object_id < 1000
END OF STMT
PARSE #140577803287552:c=26826,e=27778,p=0,cr=140,cu=0,mis=1,r=0,dep=0,og=1,
 plh=3155089718,tim=39078309868
...

Wait-what about later patch levels for 12.1?

This could easily have turned out to be “one of these posts” where the information presented is correct, yet the picture isn’t complete. Things change with the Oracle database, and newer patches address old problems. Just to be sure what I said is accurate at least at the time of writing I created a new VM with the August 2017 patch set:

[oracle@server1 ~]$ opatch lspatches
26027162;Database PSU 12.1.0.2.170718, Oracle JavaVM Component (JUL2017)
26609783;Database Patch Set Update : 12.1.0.2.170814 (26609783)
18705302;

OPatch succeeded.

And interestingly, the issue with the truncated SQL statement in SQL traces disappeared:

=====================
PARSING IN CURSOR #140433649086704 len=90 dep=0 uid=111 oct=1 lid=111 
tim=797240178 hv=3859378539 ad='1b1add420' sqlid='d7y8ssmm0kwbb'
create table ctastest tablespace users as select * from dba_objects
 where object_id < 1000
END OF STMT
PARSE #140433649086704:c=165843,e=184715,p=197,cr=5489,cu=0,mis=1,r=0,dep=0,og=1,
 plh=12630425,tim=797240177
...

Great stuff: the problem is fixed in the current version for 12.1.0.2 and 12.2.0.1. This is seriously good news for me, especially the part about 12.1.