This was first published on https://blog.dbi-services.com/exadata-express-cloud-service-sql-and-optimizer-trace (2017-02-06)
Republishing here for new followers. The content is related to the the versions available at the publication date
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
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.trcAnd 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.
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.
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 ...
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.
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'; ...
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.