Infrastructure at your Service

Franck Pachot

Exadata Express Cloud Service: SQL and Optimizer trace

The Oracle PDBaaS is for database developers. And database developers may need to trace what happens with their queries: SQL trace and Optimizer trace. Let’s see what we can do on Exadata Express Cloud Service

V$DIAG_TRACE_FILE_CONTENTS

On the managed PDBaaS you don’t have access to the filesystem. But in 12.2 you have a view that can display the content of the trace files: V$DIAG_TRACE_FILE lists the files you can access (that pertain to your container) and V$DIAG_TRACE_FILE_CONTENTS can display the content.

Here is an example how to read it.
I get my tracefile name from v$process:

SQL> column tracefile new_value tracefile
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=sys_context('userenv','sid'));
 
TRACEFILE
--------------------------------------------------------------------------------
/u02/app/oracle/diag/rdbms/cfcdba1/cfcdba1_1/trace/cfcdba1_1_ora_24389.trc

And read the ‘payload’ from the view:

SQL> set linesize 4000 pagesize 0 trimspool on
SQL> spool last.trc
SQL> select payload from V$DIAG_TRACE_FILE_CONTENTS where trace_filename='&tracefile';
old 1: select payload from V$DIAG_TRACE_FILE_CONTENTS where trace_filename='&tracefile'
new 1: select payload from V$DIAG_TRACE_FILE_CONTENTS where trace_filename='/u02/app/oracle/diag/rdbms/cfcdba1/cfcdba1_1/trace/cfcdba1_1_ora_24389.trc'
 
no rows selected

Of course, I didn’t enable any trace, so the file is empty.

10046

You can’t enable SQL Trace in the Exadata Express Cloud Service. This is disabled by lockdown profile and by not granting execute to the packages that can do it.
Here is what I tried. Please tell me if you have other ideas:
SQL> alter session set sql_trace=true;
ERROR:
ORA-01031: insufficient privileges
 
SQL> exec sys.dbms_support.start_trace;
BEGIN sys.dbms_support.start_trace; END;
 
*
ERROR at line 1:
ORA-06550: line 1, column 7:
PLS-00201: identifier 'SYS.DBMS_SUPPORT' must be declared
ORA-06550: line 1, column 7:
PL/SQL: Statement ignored
 
SQL> exec dbms_session.set_sql_trace(true);
BEGIN dbms_session.set_sql_trace(true); END;
 
*
ERROR at line 1:
ORA-01031: insufficient privileges
ORA-06512: at "SYS.DBMS_SESSION", line 178
ORA-06512: at line 1
 
SQL> exec for i in (select sid,serial# from v$session where sid=sys_context('userenv','sid')) loop sys.dbms_system.set_sql_trace_in_session(i.sid,i.serial#,true); end loop;
BEGIN for i in (select sid,serial# from v$session where sid=sys_context('userenv','sid')) loop sys.dbms_system.set_sql_trace_in_session(i.sid,i.serial#,true); end loop; END;
 
*
ERROR at line 1:
ORA-06550: line 1, column 96:
PLS-00201: identifier 'SYS.DBMS_SYSTEM' must be declared
ORA-06550: line 1, column 96:
PL/SQL: Statement ignored
 
SQL> exec for i in (select sid,serial# from v$session where sid=sys_context('userenv','sid')) loop sys.dbms_support.start_trace_in_session(i.sid,i.serial#,true); end loop;
BEGIN for i in (select sid,serial# from v$session where sid=sys_context('userenv','sid')) loop sys.dbms_support.start_trace_in_session(i.sid,i.serial#,true); end loop; END;
 
*
ERROR at line 1:
ORA-06550: line 1, column 96:
PLS-00201: identifier 'SYS.DBMS_SUPPORT' must be declared
ORA-06550: line 1, column 96:
PL/SQL: Statement ignored
 
SQL> alter session set events 'sql_trace';
ERROR:
ORA-01031: insufficient privileges
 
SQL> exec execute immediate q'{alter session set events 'sql_trace'}';
BEGIN execute immediate q'{alter session set events 'sql_trace'}'; END;
 
*
ERROR at line 1:
ORA-01031: insufficient privileges
ORA-06512: at line 1
 
SQL> create or replace procedure sys.my_sql_trace as begin execute immediate q'{alter session set events 'sql_trace'}'; end;
2 /
create or replace procedure sys.my_sql_trace as begin execute immediate q'{alter session set events 'sql_trace'}'; end;
*
ERROR at line 1:
ORA-01031: insufficient privileges

No doubt, we can’t sql_trace. I’m not sure it is a big problem because we have all options in the Exadata Express Cloud Service so we have ASH, SQL monitor, etc. I’m not saying that sql_trace is not useful anymore – there are cases where you need to see the wait events one by one – but from development point of view an plan with execution statistics should be sufficient.

10053

Tracing the CBO is a different thing. There is no alternative when you want to understand the choices of the optimizer. It is not something I use every day, but there are some cases where it is the only tool to troubleshoot.

SQL> alter session set events 'trace [SQL_Optimizer.*]';
ERROR:
ORA-01031: insufficient privileges

The ALTER SESSION SET EVENT is blocked by the S20 lockdown profile. But there is another way.

I’ve run the following query:

SQL> select * from dual;
X
 
SQL> select * from table(dbms_xplan.display_cursor);
SQL_ID a5ks9fhw2v9s1, child number 0
-------------------------------------
select * from dual
 
Plan hash value: 272002086
 
----------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 (100)| |
| 1 | TABLE ACCESS STORAGE FULL| DUAL | 1 | 2 | 2 (0)| 00:00:01 |
----------------------------------------------------------------------------------
 
13 rows selected.

Now I want more information about the execution plan.


SQL> exec dbms_sqldiag.dump_trace('a5ks9fhw2v9s1', 0, 'Compiler','Compiler');
PL/SQL procedure successfully completed.

Cool. It seems I’m allowed to do that. This procedures sets the SQL Compiler event, but it seems that it is allowed from the procedure.

I can now get the trace:


SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=sys_context('userenv','sid'));
/u02/app/oracle/diag/rdbms/cfcdba1/cfcdba1_1/trace/cfcdba1_1_ora_24389_Compiler.trc
 
SQL> spool last.trc
SQL> select payload from V$DIAG_TRACE_FILE_CONTENTS
2 where adr_home=regexp_replace('&tracefile','^(.*)/trace/([^/]*)','\1')
3 and trace_filename=regexp_replace('&tracefile','^(.*)/trace/([^/]*)','\2')
4 ;
old 2: where adr_home=regexp_replace('&tracefile','^(.*)/trace/([^/]*)','\1')
new 2: where adr_home=regexp_replace('/u02/app/oracle/diag/rdbms/cfcdba1/cfcdba1_1/trace/cfcdba1_1_ora_24389_Compiler.trc','^(.*)/trace/([^/]*)','\1')
old 3: and trace_filename=regexp_replace('&tracefile','^(.*)/trace/([^/]*)','\2')
new 3: and trace_filename=regexp_replace('/u02/app/oracle/diag/rdbms/cfcdba1/cfcdba1_1/trace/cfcdba1_1_ora_24389_Compiler.trc','^(.*)/trace/([^/]*)','\2')
Trace file /u02/app/oracle/diag/rdbms/cfcdba1/cfcdba1_1/trace/cfcdba1_1_ora_24389_Compiler.trc

This outputs the full 10053 trace:


Oracle Database 12c Enterprise Edition Release 12.2.0.0.3 - 64bit Production
Build label: RDBMS_12.2.0.0.3_LINUX.X64_160720
ORACLE_HOME: /u01/app/oracle/product/12.2.0.0.3/dbhome_1
System name: Linux
Node name: cfcldx0171.usdc2.oraclecloud.com
Release: 2.6.39-400.264.1.el6uek.x86_64
Version: #1 SMP Wed Aug 26 16:42:25 PDT 2015
Machine: x86_64
Storage: Exadata
Instance name: cfcdba1_1
Redo thread mounted by this instance: 1
Oracle process number: 109
Unix process pid: 24389, image: oracle@cfcldx0171.usdc2.oraclecloud.com
 
*** 2017-02-05T20:42:38.580323+00:00 (EPTDOJVM1KG(47))
 
*** SESSION ID:(2343.25237) 2017-02-05T20:42:38.580349+00:00
*** CLIENT ID:() 2017-02-05T20:42:38.580354+00:00
*** SERVICE NAME:(eptdojvm1kg.usdc2.oraclecloud.com) 2017-02-05T20:42:38.580358+00:00
*** MODULE NAME:(SQL*Plus) 2017-02-05T20:42:38.580363+00:00
*** ACTION NAME:() 2017-02-05T20:42:38.580368+00:00
*** CLIENT DRIVER:(SQL*PLUS) 2017-02-05T20:42:38.580372+00:00
*** CONTAINER ID:(47) 2017-02-05T20:42:38.580377+00:00
 
Enabling tracing for cur#=6 sqlid=bqf9h9bhb6c88 recursive
Parsing cur#=6 sqlid=bqf9h9bhb6c88 len=45
sql=/* SQL Analyze(2343,0) */ select * from dual
 
End parsing of cur#=6 sqlid=bqf9h9bhb6c88
Semantic Analysis cur#=6 sqlid=bqf9h9bhb6c88
OPTIMIZER INFORMATION
 
******************************************
 
----- Current SQL Statement for this session (sql_id=3u37gu3fhx3q1) -----
/* SQL Analyze(2343,0) */ select * from dual
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x3c5cdebc38 161 package body SYS.DBMS_SQLTUNE_INTERNAL.I_PROCESS_SQL_CALLOUT
0x3c5cdebc38 14080 package body SYS.DBMS_SQLTUNE_INTERNAL.I_PROCESS_SQL
0x3e17d89590 1599 package body SYS.DBMS_SQLDIAG.DUMP_TRACE
0x25dda27db0 1 anonymous block
...

Unified Trace Service views

Those views are new in 12.2 and are declined to show only part of files so that you can grant access to read those files only for 10046 (SQL Trace) or for 10053 (Optimizer Trace), for all sessions or only the user’s one.

GV$DIAG_TRACE_FILE (from x$dbgtflist) and GV$DIAG_TRACE_FILE_CONTENTS (from x$dbgtfview) show all files from the ADR traces
GV$DIAG_APP_TRACE_FILE (from x$dbgatflist) is a subset showing all files containing SQL Trace or Optimizer Trace
GV$DIAG_SQL_TRACE_RECORDS (from x$dbgtfsqlt) is a subset showing all files containing SQL Trace
GV$DIAG_OPT_TRACE_RECORDS (from x$dbgtfoptt) is a subset showing all files containing Optimizer Trace
V$DIAG_SESS_SQL_TRACE_RECORDS (from x$dbgtfssqlt) and V$DIAG_SESS_OPT_TRACE_RECORDS (from x$dbgtfsoptt) are similar, but for your session (and then no GV$ as your session is on one instance only).

A new role APPLICATION_TRACE_VIEWER grants to select on views that show only SQL and Optimizer traces.

Alert.log

This is not new in 12.2, you can query V$DIAG_ALERT_EXT to see the alert.log content. Of course, from the PDB you will see only PDB related content:

Endian type of dictionary set to little
Autotune of undo retention is turned on.
This instance was first to open pluggable database EPTDOJVM1KG (container=47)
attach called for domid 47 (domuid: 0x7fa9e59a, options: 0x0, pid: 111297)
queued attach broadcast request 0x3e26185d68
[111297] Successfully onlined Undo Tablespace 2.
Undo initialization finished serial:0 start:2570370849 end:2570371107 diff:258 ms (0.3 seconds)
Database Characterset for EPTDOJVM1KG is AL32UTF8
JIT: pid 111297 requesting full stop
detach called for domid 47 (domuid: 0x7fa9e59a, options: 0x0, pid: 111297)
queued detach broadcast request 0x3e26185d18
Autotune of undo retention is turned on.
This instance was first to open pluggable database EPTDOJVM1KG (container=47)
attach called for domid 47 (domuid: 0x7fa9e59a, options: 0x0, pid: 111297)
queued attach broadcast request 0x3e26185cc8
Endian type of dictionary set to little
[111297] Successfully onlined Undo Tablespace 2.
Undo initialization finished serial:0 start:2570382111 end:2570382464 diff:353 ms (0.4 seconds)
Deleting old file#8 from file$
Deleting old file#9 from file$
Deleting old file#10 from file$
Deleting old file#11 from file$
Deleting old file#12 from file$
Deleting old file#14 from file$
Deleting old file#17 from file$
Adding new file#486 to file$(old file#8)
Adding new file#487 to file$(old file#9)
Adding new file#488 to file$(old file#10)
Adding new file#489 to file$(old file#11)
Adding new file#490 to file$(old file#12)
Adding new file#491 to file$(old file#14)
Adding new file#492 to file$(old file#17)
Successfully created internal service eptdojvm1kg.usdc2.oraclecloud.com at open
Database Characterset for EPTDOJVM1KG is AL32UTF8
Opatch validation is skipped for PDB EPTDOJVM1KG (con_id=0)
Opening pdb with no Resource Manager plan active
Creating new database key for new master key and wallet
Creating new database key with the new master key
Retiring: ena 2 flag 6 mkloc 0
encrypted key 32ce589b50b3105f9419d0a86ce8e7f400000000000000000000000000000000
mkid cbcd33d929f64fd0bf1367f6e69f2dd5
Creating: ena 2 flag e mkloc 1
encrypted key baf27c1e11623fe9837f678df2e48f8a00000000000000000000000000000000
mkid 2d99ba8694054fd5bf41f998513e1d4c
New database key and new master key created successfully
create temporary tablespace "EPTDOJVM1KG_TEMP" tempfile size 20M extent management local uniform size 16M
Force tablespace EPTDOJVM1KG_TEMP to be encrypted with AES128
Completed: create temporary tablespace "EPTDOJVM1KG_TEMP" tempfile size 20M extent management local uniform size 16M
create BIGFILE tablespace "EPTDOJVM1KG_DATA" datafile size 10485760 autoextend on next 1M maxsize UNLIMITED extent management local autoallocate segment space management auto
Force tablespace EPTDOJVM1KG_DATA to be encrypted with AES128
Completed: create BIGFILE tablespace "EPTDOJVM1KG_DATA" datafile size 10485760 autoextend on next 1M maxsize UNLIMITED extent management local autoallocate segment space management auto
Resize operation completed for file# 486, old size 307200K, new size 317440K
ALTER SYSTEM SET pdb_lockdown='S20' SCOPE=BOTH PDB='EPTDOJVM1KG';
...

So what?

We can access SQL Trace and Optimizer trace and this is very nice. Access to trace has always been a problem because they are on the server, may contain sensitive data, etc. Having views to give access easily and in a controlled way is a very nice 12.2 feature.
I don’t know if enabling Optimizer trace on Exadata Express Cloud Service is expected, or just something that was forgotten by the lockdown profile. I hope the first hypothesis is the right one and I hope that we will be allowed to enable SQL Trace as well. This service is for developers, and I’m a big advocate of giving all tools to developers so that performance is addressed before production.

 

Leave a Reply


5 × eight =

Franck Pachot
Franck Pachot

Technology Leader