"In the Cloud, Performance is Instrumented as Cost"

About 5 years ago, I was at a conference where someone put this statement up in a PowerPoint slide.  (I would like to be able to correctly credit the author, but I can't remember who it was).  We all looked it at, thought about and said 'yes, of course' to ourselves.  However, as a consultant who specialises in performance optimisation, it has taken until only recently that I started to have conversations with clients that reflect that idea.

In the good old/bad old days of 'on premises'

It is not that long ago that the only option for procuring new hardware was to go through a sizing exercise that involved guessing how much you needed, allowing for future growth in data and processing volumes, and then deciding how much you were actually willing to afford, purchase it, and finally wheel it into your data centre and hope for the best.

It was then normal to want to get the best possible performance out of whatever system was installed on that hardware.  It would inevitably slow down over time.  Eventually, after the hardware purchase had been fully depreciated, you would have to start the whole cycle again and replace the hardware with newer hardware.

Similarly, Oracle licencing.  You would have to licence Oracle for all your CPUs (there are a few exceptions where you can associate specific CPUs to specific VMs and only licence Oracle for the CPUs in those VMs).  You would also have to decide how many Oracle features you licenced.  Standard or Enterprise Edition?  Diagnostics? Tuning? RAC? Partitioning? Compression? In-Memory?

"You are gonna need a bigger boat"

Then when you encountered performance problems you did the best you could with what you had. As a consultant, there was rarely any point in saying to a customer that they had run out of resource and they needed more.  The answer was usually along the lines of 'we have spent our money on that, and it has to last for five years, we have no additional budget and it has to work'. So you got on with finding the rabbit in the hat.

In the cloud, instead of purchasing hardware as a capital expense, you rent hardware as an operational expense.

You can bring your own Oracle licence (BYOL), and then you have exactly what you were previously licenced for.  "At a high level, one Oracle Processor License maps to two OCPUs."

With Oracle's cloud licencing there are still lots of choices to make, not just how many CPUs and how much memory.  You can choose Infrastructure as a Service (IAAS) where you rent the server and install and licence Oracle on it just as you did on-premises.  You can choose different storage systems with different I/O profiles.  There are different levels of PAAS that have different database features.  You can go all the way up to Extreme performance on Exadata.  All of these choices have a cost consequence.  Oracle provides a Cloud cost estimator tool (other consultancies have produced their own versions).  These tools clearly show the link between these choices and their costs very clear.

You can have as much performance as you are willing to pay for

I have been working with a customer who is moving a PeopleSoft system from Supercluster on-premises to Exadata Cloud-at-Customer (so it is physically on-site, but in all other respects it is in the cloud).  They are not bringing their own licence (BYOL). Instead, they are on a tariff of US$1.3441/OCPU/hr, we have found it easier to talk about US$1000/OCPU/month.

Just as you would with an on-premises system, they went through a sizing exercise that predicted they needed 6 OCPU on each of 2 RAC nodes during the day, and 10 at night. 

It has been very helpful to have a clear quantitative definition of acceptable performance for the critical part of the system, the overnight reporting batch.  "The reports need to be available to users by the start of the working day in continental Europe, at 8am CET", which is 2am EST.  There is no benefit in providing additional resources to allow the batch to finish any earlier.  Instead, we only need to provide as much as is necessary to reliably meet the target.

A performance tuning/testing exercise quickly showed that fewer than the predicted number of CPUs were actually needed.  2-4 OCPUs/node during the day is looking comfortable.  The new Exadata has fewer but much faster CPUs.  As we adjusted the application configuration to match we found we are able to reduce the number of OCPUs. 

If we hadn't already been using base-level In Memory feature on Supercluster, then to complete the overnight batch in time for the start of the European working day, we would probably have needed 10 OCPUs/node.  The base-level In Memory option brought that down to around 7.  This shows the huge value of the careful use of database features and techniques to reduce CPU overhead.

We are not using BYOL, so we can use fully featured In Memory with a larger store.  Increasing the In Memory store from 16Gb to 40Gb per node saved another OCPU, but cost nothing.  If we had been using BYOL we would have had to pay additionally for fully featured In Memory.  I doubt the marginal benefit would have justified the cost.

The customer has been considering switching on the extra OCPUs overnight to facilitate the batch.  Doing so costs $1.33/hour, and at the end of the month, they get an invoice from Oracle.  That has concentrated minds and changed behaviours.  The customer understands that there is a real $ cost/saving to their business decisions.

One day I was asked: "What happens if we reduce the number of CPUs from 6 to 4?"

Essentially the batch will take longer.  We are already using the database resource manager to prioritise processes when all the CPU is in use.  The resource manager plan has been built to reflect the business priorities, and so keeps it fair for all users.  For example, it ensures that users of the online part of the application get CPU in preference to batch processes, this is important for users in Asia who are online when the batch runs overnight in North America.  We also use the resource plan to impose different parallel query limits to different groups of processes.   If we are going to vary the number of CPUs we will have to switch between different resource manager plans with different limits.  We will also have to reduce the number of reports that can be concurrently executed by the application, so some application configuration has to go hand in hand with the database configuration.

Effective caching by the database meant we already did relatively little physical I/O during the reporting.  Most of the time was already spent on CPU.  Use of In Memory further reduced physical I/O, and now nearly all the time is spent on CPU, but it also reduced the overall CPU consumption and therefore response time.

When we did vary the number of CPUs, we were not surprised to observe, from the Active Session History (ASH), that the total amount of database time spent on CPU by the nVision reporting processes is roughly constant (indicated by the blue area in the below charts).  If we reduce the number of concurrent processes, then the batch simply runs for longer.

There is no question that effective design and tuning are as important as they ever were.  The laws of physics are the same in the cloud as they are in your own data centre.  We worked hard to get the reporting to this level of performance and down to this CPU usage. 

The difference is that now you can measure exactly how much that effort is saving you on your cloud subscription, and you can choose to spend more or less on that cloud subscription in order to achieve your business objectives.

Determining the benefit to the business, in terms of the quantity and cost of users' time, remains as difficult as ever.  However, it was not a major consideration in this example because this all happens before the users are at work.

Adding Flags to Trace Level Overrides in Process Definitions

A trace level is set in a process definition in PS_PRCSDEFN precedence over a trace level set in the process scheduler configuration file (psprcs.cfg).

I often set the process scheduler trace level for Application Engine to 1152 to enable batch timings to both the database batch timings tables and the AE trace file, but then I often find that a trace is left enabled on a few processes to aid performance analysis of a troublesome process.

This script updates the trace level set in the parameter list in the process definition to include the bit flags set by 1152 (to enable batch timings).  

• The current trace level is extracted with regular expression substring functions.
• A bitwise OR is performed between the current trace level and the desired settings.  There is no single function to do this in Oracle SQL, but it can be calculated simply (see Oracle blog: There is no BITOR() in Oracle SQL).  
• The old trace value is replaced with the new one in the parameter list with a regular expression replace function.
• The version number on the process definition is also updated as it would be if updated by the process definition component in the PIA.  Thus it is correctly re-cached by the process scheduler, the scheduler does not need to be recycled, nor does the cache need to be cleared

The script is available on Github.

REM fixprcstracelevel.sql
set pages 99 lines 200 serveroutput on
spool fixprcstracelevel append
ROLLBACK;
DECLARE
  l_counter INTEGER := 0;
  l_trace_expr VARCHAR2(20); /*expression containing TRACE keyword and value*/
  l_req_trace_level INTEGER := 1152; /*trace value set in the scheduler config*/
  l_cur_trace_level INTEGER; /*current trace level*/
  l_new_trace_level INTEGER; /*new calculated trace level*/
  l_parmlist ps_prcsdefn.parmlist%TYPE;
BEGIN
  for i in (
    SELECT t.*
    FROM   ps_prcsdefn t
    WHERE  UPPER(t.parmlist) LIKE '%-%TRACE%'
    AND   prcstype LIKE 'Application Engine'
--  AND parmlisttype IN('1','2','3')
  ) LOOP
    l_trace_expr := REGEXP_SUBSTR(i.parmlist,'\-trace[ ]*[0-9]+',1,1,'i');
    l_cur_trace_level := TO_NUMBER(REGEXP_SUBSTR(l_trace_expr,'[0-9]+',1,1,'i'));
    l_new_trace_level := l_req_trace_level+l_cur_trace_level-bitand(l_cur_trace_level,l_req_trace_level);
    l_parmlist := REGEXP_REPLACE(i.parmlist,l_trace_expr,'-TRACE '||l_new_trace_level,1,1,'i');

    IF l_new_trace_level = l_cur_trace_level THEN
      dbms_output.put_line(i.prcstype||':'||i.prcsname||':'||i.parmlist||'=>No Change');
    ELSE
      l_counter := l_counter + 1;
      IF l_counter = 1 THEN
        UPDATE psversion
        SET    version = version+1
        WHERE  objecttypename IN('SYS','PPC');

        UPDATE pslock
        SET    version = version+1
        WHERE  objecttypename IN('SYS','PPC');
      END IF;
      dbms_output.put_line(l_counter||':'||i.prcstype||' '||i.prcsname||':'||i.parmlist||'=>'||l_parmlist);
      UPDATE ps_prcsdefn
      SET    version = (SELECT version FROM psversion WHERE objecttypename = 'PPC')
      ,      parmlist = l_parmlist
      WHERE  prcstype = i.prcstype
      AND    prcsname = i.prcsname;
    END IF;
  END LOOP;
  COMMIT;
END;
/
spool off

The script reports the old and new parameter list setting for each process definition altered.  

Below is a sample output:

Application Engine:GL_JEDIT:-TRACE 1159=>No Change
1:Application Engine PTDEFSECINRL:-toolstacepc 2048 -toolstracesql 15 -TRACE 15=>-toolstacepc 2048 -toolstracesql 15 -TRACE 1167

• TRACE for GL_JEDIT is already 1159, so no change is required.
• TRACE for PTDEFSECINRL was changed from 15 to 1167.

There is no BITOR() in Oracle SQL

In Oracle SQL, I can do a bitwise AND of two numbers, but there is no equivalent function to do a bitwise OR.  However, it turns out to be really easy to do using BITAND().
I was manipulating some trace values where each binary digit, or bit, corresponds to a different function (see PeopleSoft DBA Blog: Add Flags to Trace Level Overrides in Process Definitions).  I wanted to ensure certain attributes were set.  So, I wanted to do a bitwise OR between the current flag value and the value of the bits I wanted to set. 
In bitwise OR, if either or both bits are set, then the answer is 1.  It is like addition, but when both the bits are 1, the answer is 1 rather than 2.  I can add the bits up and then deduct BITAND().  Thus:

BITOR	0	1				+	0	1				BITAND	0	1
0	0	1		=		0	0	1		-		0	0	0
1	1	1				1	1	2				1	0	1

Or I could write it as 

BITOR(x,y)  =  x + y - BITAND(x,y)

Here is a simple example with two decimal numbers expressed in binary.  The results of AND and OR operations are below, with their decimal values.

 27 = 00011011
 42 = 00101010

AND = 00001010 = 10
 OR = 00111011 = 59

I can then write a simple SQL expression to calculate this, and perhaps put it into a PL/SQL function thus:

WITH FUNCTION bitor(p1 INTEGER, p2 INTEGER) RETURN INTEGER IS
BEGIN
  RETURN p1+p2-bitand(p1,p2);
END;
SELECT BITAND(27,42) 
,      27+42-BITAND(27,42) 
,      bitor(27,42)
FROM   DUAL
/

BITAND(27,42) 27+42-BITAND(27,42) BITOR(27,42)
------------- ------------------- ------------
           10                  59           59

No Execution Plan Survives Contact with the Optimizer Untransformed

One of the benefits of attending Oracle conferences is that by listening and talking to other people I get a different perspective on things. Sometimes, something gives me an idea or reminds me of the importance of something that I don't use often enough. I was talking with Neil Chandler about SQL Query Transformation. We came up with a variation of a well known quote:

Chatting with @ChandlerDBA #aced at #OUGIreland @UKOUG today we came to the conclusion that
"No plan of execution survives contact with the optimizer untransformed!"

— David Kurtz - /*+Go-Faster*/ Consultancy (@davidmkurtz) September 5, 2022

It isn't completely accurate.  Not every query gets transformed, but it occurs commonly, it made a good title, and you are reading this blog!

During SQL parse, the optimizer can transform a SQL query into another SQL query that is functionally identical but that results in an execution plan with a lower cost (and therefore should execute more quickly). Sometimes, multiple transformations can be applied to a single statement. 

The Oracle documentation describes various forms of transformation. You can see in the execution plan that something has happened, but you can't see the transformed SQL statement directly. However, it can be obtained from the optimizer trace that can be enabled by setting event 10053.

Demonstration 

I am going to take a simple SQL query

• For the first execution, a NO_UNNEST hint is used to prevent the subquery from being unnested. 
• Optimizer trace is enabled and disabled by setting and resetting event 10053. 
• Trace file names are enhanced with TRACEFILE_IDENTIFIER, so I know which trace file relates to which test. 
• Finally, I use my spooltrc script to spool the trace file locally from V$DIAG_TRACE_FILE_CONTENTS (see previous blog post Obtaining Trace Files without Access to the Database Server).

set pages 99 lines 200 autotrace off
alter session set tracefile_identifier='no_unnest';
alter session set events '10053 trace name context forever, level 1';
select emplid, name, effdt, last_name
from ps_names x
where x.last_name = 'Smith'
and x.name_type = 'PRI'
and x.effdt = (
  SELECT /*+NO_UNNEST*/ MAX(x1.effdt)
  FROM ps_names x1
  WHERE x1.emplid = x.emplid
  AND x1.name_type = x.name_type
  AND x1.effdt <= SYSDATE)
/
alter session set events '10053 trace name context off';
@spooltrc

• For the second execution, an UNNEST hint is used to force the optimizer to unnest the sub-query.

alter session set tracefile_identifier='unnest';
alter session set events '10053 trace name context forever, level 1';
select emplid, name, effdt, last_name
from ps_names x
where x.last_name = 'Smith'
and x.name_type = 'PRI'
and x.effdt = (
  SELECT /*+UNNEST*/ MAX(x1.effdt)
  FROM ps_names x1
  WHERE x1.emplid = x.emplid
  AND x1.name_type = x.name_type
  AND x1.effdt <= SYSDATE)
/
alter session set events '10053 trace name context off';
@spooltrc

This is the execution plan from the first trace file for the statement with the NO_UNNEST hint. The select query blocks are simply numbered sequentially and thus are called SEL$1 and SEL$2. SEL$2 is the sub-query that references PS_NAMES with the row source alias X1. No query transformation has occurred.

-------------------------------------------------------+-----------------------------------+
| Id  | Operation                            | Name    | Rows  | Bytes | Cost  | Time      |
-------------------------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT                     |         |       |       |   122 |           |
| 1   |  TABLE ACCESS BY INDEX ROWID BATCHED | PS_NAMES|     1 |    44 |   120 |  00:00:02 |
| 2   |   INDEX SKIP SCAN                    | PS_NAMES|    11 |       |   112 |  00:00:02 |
| 3   |    SORT AGGREGATE                    |         |     1 |    21 |       |           |
| 4   |     FIRST ROW                        |         |     1 |    21 |     2 |  00:00:01 |
| 5   |      INDEX RANGE SCAN (MIN/MAX)      | PS_NAMES|     1 |    21 |     2 |  00:00:01 |
-------------------------------------------------------+-----------------------------------+
Query Block Name / Object Alias (identified by operation id):
------------------------------------------------------------
 1 - SEL$1                / "X"@"SEL$1"
 2 - SEL$1                / "X"@"SEL$1"
 3 - SEL$2
 5 - SEL$2                / "X1"@"SEL$2"
------------------------------------------------------------
Predicate Information:
----------------------
1 - filter("X"."LAST_NAME"='Smith')
2 - access("X"."NAME_TYPE"='PRI')
2 - filter(("X"."NAME_TYPE"='PRI' AND "X"."EFFDT"=))
5 - access("X1"."EMPLID"=:B1 AND "X1"."NAME_TYPE"=:B2 AND "X1"."EFFDT"<=SYSDATE@!)

Now, let's look at the optimizer trace file for the statement with the UNNEST hint. First, we can see the statement as submitted with its SQL_ID.

Trace file /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM/trace/CDBHCM_ora_21909_unnest.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.7.0.0.0
…
----- Current SQL Statement for this session (sql_id=7r3mwa86fma5t) -----
select emplid, name, effdt, last_name
from ps_names x
where x.last_name = 'Smith'
and x.name_type = 'PRI'
and x.effdt = (
  SELECT /*+UNNEST*/ MAX(x1.effdt)
  FROM ps_names x1
  WHERE x1.emplid = x.emplid
  AND x1.name_type = x.name_type
  AND x1.effdt <= SYSDATE)
…

Later in the trace, we can see the fully expanded SQL statement preceded by the 'UNPARSED QUERY IS' message. 

• All the SQL language keywords have been forced into upper case.
• All the object and column names have been made upper case to match the objects.
• Every column and table is double-quoted which makes them case sensitive.    
• The columns all have row source aliases. 
• The row sources (tables in this case) are fully qualified.
• Only the literal 'Smith' is in mixed case.

Various unparsed queries may appear in the trace as the optimizer tries and costs different transformations. These are not nicely formatted, the expanded statements are just a long string of text.   The first one is the expanded form of the untransformed statement.

Stmt: ******* UNPARSED QUERY IS *******
SELECT "X"."EMPLID" "EMPLID","X"."NAME" "NAME","X"."EFFDT" "EFFDT","X"."LAST_NAME" "LAST_NAME" FROM "SYSADM"."PS_NAMES" 
"X" WHERE "X"."LAST_NAME"='Smith' AND "X"."NAME_TYPE"='PRI' AND "X"."EFFDT"= (SELECT /*+ UNNEST */ MAX("X1"."EFFDT") 
"MAX(X1.EFFDT)" FROM "SYSADM"."PS_NAMES" "X1" WHERE "X1"."EMPLID"="X"."EMPLID" AND "X1"."NAME_TYPE"="X"."NAME_TYPE" AND
"X1"."EFFDT"<=SYSDATE@!)

Here the sub-query has been transformed into an in-line view.  I have reformatted it to make it easier to read.

CVM:   Merging complex view SEL$683B0107 (#2) into SEL$C772B8D1 (#1).
qbcp:******* UNPARSED QUERY IS *******
SELECT "X"."EMPLID" "EMPLID","X"."NAME" "NAME","X"."EFFDT" "EFFDT","X"."LAST_NAME" "LAST_NAME" 
FROM  (SELECT /*+ UNNEST */ MAX("X1"."EFFDT") "MAX(X1.EFFDT)","X1"."EMPLID" "ITEM_0","X1"."NAME_TYPE" "ITEM_1" 
       FROM   "SYSADM"."PS_NAMES" "X1" 
       WHERE  "X1"."EFFDT"<=SYSDATE@! 
       GROUP BY "X1"."EMPLID","X1"."NAME_TYPE") "VW_SQ_1"
      ,"SYSADM"."PS_NAMES" "X" 
WHERE "X"."LAST_NAME"='Smith' 
AND   "X"."NAME_TYPE"='PRI' 
AND   "X"."EFFDT"="VW_SQ_1"."MAX(X1.EFFDT)" 
AND   "VW_SQ_1"."ITEM_0"="X"."EMPLID" 
AND   "VW_SQ_1"."ITEM_1"="X"."NAME_TYPE"

This is the final form of the statement that was executed and that produced the execution plan.  The in-line view has been merged into the parent query.  There will only be a final query section if any transformations have occurred. Again, I have reformatted it to make it easier to read.  

Final query after transformations:******* UNPARSED QUERY IS *******
SELECT /*+ UNNEST */ "X"."EMPLID" "EMPLID","X"."NAME" "NAME","X"."EFFDT" "EFFDT",'Smith' "LAST_NAME" 
FROM  "SYSADM"."PS_NAMES" "X1"
     ,"SYSADM"."PS_NAMES" "X" 
WHERE "X"."LAST_NAME"='Smith' 
AND   "X"."NAME_TYPE"='PRI' 
AND   "X1"."EMPLID"="X"."EMPLID" 
AND   "X1"."NAME_TYPE"="X"."NAME_TYPE" 
AND   "X1"."EFFDT"<=SYSDATE@! 
AND   "X1"."NAME_TYPE"='PRI' 
GROUP BY "X1"."NAME_TYPE","X".ROWID,"X"."EFFDT","X"."NAME","X"."EMPLID" 
HAVING "X"."EFFDT"=MAX("X1"."EFFDT")
…

• PS_NAMES X1 has been moved from the subquery into the main from clause. Instead of a correlated subquery, we now have a two-table join. 
• The query is grouped by the ROWID on row source X and the other selected columns. 
• Instead of joining the tables on NAME_TYPE, the literal criterion has been duplicated in X1 
• A having clause is used to join X.EFFDT to the maximum value of X1.EFFDT. 
• Instead of selecting LAST_NAME from X, the literal value in the predicate has been put in the select clause. 

If we look at the execution plan for the unnested statement we can see X and X1 are now in query block SEL$841DDE77 that has been unnested and merged.

…
----- Explain Plan Dump -----
…
----------------------------------------+-----------------------------------+
| Id  | Operation             | Name    | Rows  | Bytes | Cost  | Time      |
----------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT      |         |       |       |   139 |           |
| 1   |  FILTER               |         |       |       |       |           |
| 2   |   SORT GROUP BY       |         |     1 |    77 |   139 |  00:00:02 |
| 3   |    NESTED LOOPS       |         |     3 |   231 |   138 |  00:00:02 |
| 4   |     TABLE ACCESS FULL | PS_NAMES|     2 |   112 |   136 |  00:00:02 |
| 5   |     INDEX RANGE SCAN  | PS_NAMES|     1 |    21 |     1 |  00:00:01 |
----------------------------------------+-----------------------------------+
Query Block Name / Object Alias (identified by operation id):
------------------------------------------------------------
 1 - SEL$841DDE77
 4 - SEL$841DDE77         / "X"@"SEL$1"
 5 - SEL$841DDE77         / "X1"@"SEL$2"
------------------------------------------------------------
Predicate Information:
----------------------
1 - filter("EFFDT"=MAX("X1"."EFFDT"))
4 - filter(("X"."LAST_NAME"='Smith' AND "X"."NAME_TYPE"='PRI'))
5 - access("X1"."EMPLID"="X"."EMPLID" AND "X1"."NAME_TYPE"='PRI' AND "X1"."EFFDT"<=SYSDATE@!)
…

The new query block name is a hash value based on the names of other blocks.  The presence of such a block name is an indication of query transformation occurring.  The query block name is stable and it is referenced in the outline of hints. 

"A question that we could ask about the incomprehensible query block names that Oracle generates is: 'are they deterministic?' – is it possible for the same query to give you the same plan while generating different query block names on different versions of Oracle (or different days of the week). The answer is (or should be) no; when Oracle generates a query block name (after supplying the initial defaults of sel$1, sel$2 etc.) it applies a hashing function to the query block names that have gone INTO a transformation to generate the name that it will use for the block that comes OUT of the transformation." - Jonathan Lewis: Query Blocks and Inline Views 

As Jonathan points out "the 'Outline Data' section of the report tells us that query block" in my example SEL$841DDE77 "is an 'outline_leaf', in other words, it is a 'final' query block that has actually been subject to independent optimization". We can also see other query block names referenced in OUTLINE hints.

  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
…
      OUTLINE_LEAF(@"SEL$841DDE77")
      MERGE(@"SEL$683B0107" >"SEL$C772B8D1")
      OUTLINE(@"SEL$C772B8D1")
      UNNEST(@"SEL$2")
      OUTLINE(@"SEL$683B0107")
      OUTLINE(@"SEL$7511BFD2")
      OUTLINE(@"SEL$2")
      OUTLINE(@"SEL$1")
      FULL(@"SEL$841DDE77" "X"@"SEL$1")
      INDEX(@"SEL$841DDE77" "X1"@"SEL$2" ("PS_NAMES"."EMPLID" "PS_NAMES"."NAME_TYPE" "PS_NAMES"."EFFDT"))
      LEADING(@"SEL$841DDE77" "X"@"SEL$1" "X1"@"SEL$2")
      USE_NL(@"SEL$841DDE77" "X1"@"SEL$2")
    END_OUTLINE_DATA
  */

We can see these query block names being generated in the trace as a number of transformations are applied with some description of the transformation.

Registered qb: SEL$683B0107 0xfc6e3030 (SUBQ INTO VIEW FOR COMPLEX UNNEST SEL$2)
Registered qb: SEL$7511BFD2 0xfc6c5c68 (VIEW ADDED SEL$1)
Registered qb: SEL$C772B8D1 0xfc6c5c68 (SUBQUERY UNNEST SEL$7511BFD2; SEL$2)
Registered qb: SEL$841DDE77 0xfc6d91e0 (VIEW MERGE SEL$C772B8D1; SEL$683B0107; SEL$C772B8D1)

Obtaining Trace Files without Access to the Database Server

Why Trace? 

For many years, I used database SQL Trace to investigate SQL performance problems. I would trace a process, obtain the trace file, profile it (with Oracle's TKPROF or another profiling tool such as the Method R profiler, TVD$XTAT, or OraSRP), and analyse the profile. 

Active Session History (ASH) was introduced in Oracle 10g.  Today, it is usually where I start to investigate performance problems. It has the advantage that it is always on, and I can just query ASH data from the Automatic Workload Repository (AWR). However, ASH is only available on Enterprise Edition and requires the Diagnostics Pack licence. 

Sometimes, even if available, ASH isn't enough. ASH is based on sampling database activity, while trace is a record of all the SQL activity in a session. Some short-lived behaviour, that doesn't generate many samples, is difficult to investigate with ASH. Sometimes, it is necessary to dig deeper and use SQL trace. 

On occasion, you might want to generate other forms trace.  For example, an optimizer trace (event 10053) in order to understand how an execution plan was arrived at.

Where is my Trace File? 

A trend that I have observed over the years is that is is becoming ever more difficult to get hold of the trace files. If you are not the production DBA, you are unlikely to get access to the database server. Frequently, I find that pre-production performance test databases, which are often clones of the production database, are treated as production systems. After all, they contain production data. The move to the cloud has accelerated that trend. On some cloud services, you have no access to the database server at all! 

In the past, I have blogged about using an external table from which the trace file can be queried, a variation of a theme others had also written about. It required certain privileges, a new external table was required for each trace file, and you had to know the name of the trace file, and on which RAC instance it was located. 

However, in version 12.2, it is much easier.  Oracle has provided some new views that report what trace files are available and then query their contents. 

Where Is This Session Writing Its Trace File?

The Automatic Diagnostic Repository (ADR) was first documented in 11g. The view V$DIAG_INFO was introduced in 12c, from which you can query the state of the ADR. This includes the various directory paths to which files are written and the name of the current trace file.

select dbid, con_dbid, name from v$database;
column inst_id format 99 heading 'Inst|ID'
column con_id format 99 heading 'Con|ID'
column name format a22
column value format a95
select * from v$diag_info;

Inst                                                                                                                        Con
  ID NAME                   VALUE                                                                                            ID
---- ---------------------- ----------------------------------------------------------------------------------------------- ---
   1 Diag Enabled           TRUE                                                                                              0
   1 ADR Base               /opt/oracle/psft/db/oracle-server                                                                 0
   1 ADR Home               /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM                                        0
   1 Diag Trace             /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM/trace                                  0
   1 Diag Alert             /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM/alert                                  0
   1 Diag Incident          /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM/incident                               0
   1 Diag Cdump             /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM/cdump                                  0
   1 Health Monitor         /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM/hm                                     0
   1 Default Trace File     /opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM/trace/CDBHCM_ora_27009_unnest.trc      0
   1 Active Problem Count   0                                                                                                 0
   1 Active Incident Count  0                                                                                                 0
   1 ORACLE_HOME            /opt/oracle/psft/db/oracle-server/19.3.0.0                                                        0

What files have been written? 

The available files are reported by V$DIAG_TRACE_FILE

column adr_home format a60
column trace_filename format a40
column change_time format a32
column modify_time format a32
column con_id format 999
select *
from v$DIAG_TRACE_FILE
where adr_home = '&adr_Home'
order by modify_time
/

ADR_HOME                                                     TRACE_FILENAME                           CHANGE_TIME                      MODIFY_TIME                      CON_ID
------------------------------------------------------------ ---------------------------------------- -------------------------------- -------------------------------- ------
…
/opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM   CDBHCM_ora_27674_no_unnest.trc           13-SEP-22 02.06.10.000 PM +00:00 13-SEP-22 02.06.10.000 PM +00:00      3
/opt/oracle/psft/db/oracle-server/diag/rdbms/cdbhcm/CDBHCM   CDBHCM_ora_27674_unnest.trc              13-SEP-22 02.06.11.000 PM +00:00 13-SEP-22 02.06.11.000 PM +00:00      3

What is in the file? 

I can then extract the contents of the file from V$DIAG_TRACE_FILE_CONTENTS. Each line of the trace is returned in a different row. 

This script spools the contents of the current trace file from SQL Plus locally to a file of the same name. It stores the name of the ADR home and its file path and the trace file name to SQL*Plus variables and then uses these to query the trace file contents. 

I can generate a trace and then run this script to extract it locally.

REM spooltrc.sql

clear screen
set heading on pages 99 lines 180 verify off echo off trimspool on termout on feedback off
column value format a95
column value new_value adr_home heading 'ADR Home' 
select value from v$diag_info where name = 'ADR Home';
column value new_value diag_trace heading 'Diag Trace'
select value from v$diag_info where name = 'Diag Trace';
column value new_value trace_filename heading 'Trace File'
select SUBSTR(value,2+LENGTH('&diag_trace')) value from v$diag_info where name = 'Default Trace File'
/
column adr_home format a60
column trace_filename format a40
column change_time format a32
column modify_time format a32
column con_id format 999
select *
from v$DIAG_TRACE_FILE
where adr_home = '&adr_home'
and trace_filename = '&trace_filename'
/
set head off pages 0 lines 5000 verify off echo off timi off termout off feedback off long 5000
spool &trace_filename
select payload
from v$diag_trace_file_contents
where adr_home = '&adr_home'
and trace_filename = '&trace_filename'
order by line_number
/
spool off
set head on pages 99 lines 180 verify on echo on termout on feedback on

The spooltrc.sql script is available on Github.  In a subsequent blog, I will demonstrate how to use it.

The payload is a VARCHAR2 column, so it is easy to search one or several trace files for specific text. This is useful if you are having trouble identifying the trace file of interest. 

See also:

• Franck Pachot's Blog: Exadata Express Cloud Service: SQL and Optimizer trace.