Using SQL Profiles to Tackle High Parse Time and CPU Consumption

The Challenge of Dynamic SQL with Literals   

The following example is taken from a PeopleSoft General Ledger system. The SQL was generated by the nVision reporting tool (some literal values have been obfuscated).

SELECT L4.TREE_NODE_NUM,SUM(A.POSTED_TOTAL_AMT) 
FROM PS_XX_SUM_XXXXX_VW A, PSTREESELECT10 L4, PSTREESELECT10 L2 
WHERE A.LEDGER='X_UKMGT' 
AND A.FISCAL_YEAR=2022 AND A.ACCOUNTING_PERIOD=1 
AND L4.SELECTOR_NUM=415 AND A.CHARTFIELD3=L4.RANGE_FROM_10 
AND L2.SELECTOR_NUM=416 AND A.ACCOUNT=L2.RANGE_FROM_10 
AND (A.DEPTID BETWEEN '10000' AND '18999' OR
A.DEPTID BETWEEN '20000' AND '29149' OR A.DEPTID='29156' OR
A.DEPTID='29158' OR A.DEPTID BETWEEN '29165' AND '29999' OR A.DEPTID
BETWEEN '30000' AND '39022' OR A.DEPTID BETWEEN '39023' AND '39999' OR
A.DEPTID BETWEEN '40000' AND '49999' OR A.DEPTID BETWEEN '50000' AND
'59999' OR A.DEPTID BETWEEN '60000' AND '69999' OR A.DEPTID BETWEEN
'70000' AND '79999' OR A.DEPTID BETWEEN '80000' AND '89999' OR
A.DEPTID='29150' OR A.DEPTID=' ') 
AND A.CHARTFIELD1='0120413' 
AND A.CURRENCY_CD='GBP' 
GROUP BY L4.TREE_NODE_NUM

Plan hash value: 1653134809

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                                   | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                                            |                    |       |       |    27 (100)|          |       |       |        |      |            |
|   1 |  PX COORDINATOR                                             |                    |       |       |            |          |       |       |        |      |            |
|   2 |   PX SEND QC (RANDOM)                                       | :TQ10006           |     1 |    29 |    27  (63)| 00:00:01 |       |       |  Q1,06 | P->S | QC (RAND)  |
|   3 |    HASH GROUP BY                                            |                    |     1 |    29 |    27  (63)| 00:00:01 |       |       |  Q1,06 | PCWP |            |
|   4 |     PX RECEIVE                                              |                    |     1 |    29 |    27  (63)| 00:00:01 |       |       |  Q1,06 | PCWP |            |
|   5 |      PX SEND HASH                                           | :TQ10005           |     1 |    29 |    27  (63)| 00:00:01 |       |       |  Q1,05 | P->P | HASH       |
|   6 |       HASH GROUP BY                                         |                    |     1 |    29 |    27  (63)| 00:00:01 |       |       |  Q1,05 | PCWP |            |
|   7 |        HASH JOIN                                            |                    |     1 |    29 |    27  (63)| 00:00:01 |       |       |  Q1,05 | PCWP |            |
|   8 |         JOIN FILTER CREATE                                  | :BF0000            |     1 |    16 |    25  (68)| 00:00:01 |       |       |  Q1,05 | PCWP |            |
|   9 |          PX RECEIVE                                         |                    |     1 |    16 |    25  (68)| 00:00:01 |       |       |  Q1,05 | PCWP |            |
|  10 |           PX SEND HYBRID HASH                               | :TQ10003           |     1 |    16 |    25  (68)| 00:00:01 |       |       |  Q1,03 | P->P | HYBRID HASH|
|  11 |            STATISTICS COLLECTOR                             |                    |       |       |            |          |       |       |  Q1,03 | PCWC |            |
|  12 |             VIEW                                            | VW_GBC_10          |     1 |    16 |    25  (68)| 00:00:01 |       |       |  Q1,03 | PCWP |            |
|  13 |              HASH GROUP BY                                  |                    |     1 |    67 |    25  (68)| 00:00:01 |       |       |  Q1,03 | PCWP |            |
|  14 |               PX RECEIVE                                    |                    |     1 |    67 |    25  (68)| 00:00:01 |       |       |  Q1,03 | PCWP |            |
|  15 |                PX SEND HASH                                 | :TQ10002           |     1 |    67 |    25  (68)| 00:00:01 |       |       |  Q1,02 | P->P | HASH       |
|  16 |                 HASH GROUP BY                               |                    |     1 |    67 |    25  (68)| 00:00:01 |       |       |  Q1,02 | PCWP |            |
|  17 |                  HASH JOIN                                  |                    |    60 |  4020 |    24  (67)| 00:00:01 |       |       |  Q1,02 | PCWP |            |
|  18 |                   JOIN FILTER CREATE                        | :BF0001            |    60 |  3120 |    22  (73)| 00:00:01 |       |       |  Q1,02 | PCWP |            |
|  19 |                    PX RECEIVE                               |                    |    60 |  3120 |    22  (73)| 00:00:01 |       |       |  Q1,02 | PCWP |            |
|  20 |                     PX SEND HYBRID HASH                     | :TQ10000           |    60 |  3120 |    22  (73)| 00:00:01 |       |       |  Q1,00 | P->P | HYBRID HASH|
|  21 |                      STATISTICS COLLECTOR                   |                    |       |       |            |          |       |       |  Q1,00 | PCWC |            |
|  22 |                       PX BLOCK ITERATOR                     |                    |    60 |  3120 |    22  (73)| 00:00:01 |    29 |    29 |  Q1,00 | PCWC |            |
|  23 |                        MAT_VIEW REWRITE ACCESS INMEMORY FULL| PS_XX_SUM_XXXXX_MV |    60 |  3120 |    22  (73)| 00:00:01 |    29 |    29 |  Q1,00 | PCWP |            |
|  24 |                   PX RECEIVE                                |                    |   306 |  4590 |     2   (0)| 00:00:01 |       |       |  Q1,02 | PCWP |            |
|  25 |                    PX SEND HYBRID HASH                      | :TQ10001           |   306 |  4590 |     2   (0)| 00:00:01 |       |       |  Q1,01 | P->P | HYBRID HASH|
|  26 |                     JOIN FILTER USE                         | :BF0001            |   306 |  4590 |     2   (0)| 00:00:01 |       |       |  Q1,01 | PCWP |            |
|  27 |                      PX BLOCK ITERATOR                      |                    |   306 |  4590 |     2   (0)| 00:00:01 |   416 |   416 |  Q1,01 | PCWC |            |
|  28 |                       TABLE ACCESS STORAGE FULL             | PSTREESELECT10     |   306 |  4590 |     2   (0)| 00:00:01 |   416 |   416 |  Q1,01 | PCWP |            |
|  29 |         PX RECEIVE                                          |                    |   202 |  2626 |     2   (0)| 00:00:01 |       |       |  Q1,05 | PCWP |            |
|  30 |          PX SEND HYBRID HASH                                | :TQ10004           |   202 |  2626 |     2   (0)| 00:00:01 |       |       |  Q1,04 | P->P | HYBRID HASH|
|  31 |           JOIN FILTER USE                                   | :BF0000            |   202 |  2626 |     2   (0)| 00:00:01 |       |       |  Q1,04 | PCWP |            |
|  32 |            PX BLOCK ITERATOR                                |                    |   202 |  2626 |     2   (0)| 00:00:01 |   415 |   415 |  Q1,04 | PCWC |            |
|  33 |             TABLE ACCESS STORAGE FULL                       | PSTREESELECT10     |   202 |  2626 |     2   (0)| 00:00:01 |   415 |   415 |  Q1,04 | PCWP |            |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$6240F0FF
  12 - SEL$B80655F7 / VW_GBC_10@SEL$9C8D6CC0
  13 - SEL$B80655F7
  23 - SEL$B80655F7 / PS_XX_SUM_XXXXX_MV@SEL$CAD4EEF6
  28 - SEL$B80655F7 / L2@SEL$1
  33 - SEL$6240F0FF / L4@SEL$1
… 

In my example, ASH sampled 276 different SQL IDs.  Each one was only executed once.  There may have been more statements, but ASH only persists one sample every 10s. Cumulatively, they consumed 2843 seconds of DB time in SQL hard parse.

                                                                                                                                          Plan
                                                                                          SQL Plan        Force Matching    SQL   Plan   Parse
 # OPRID        RUNCNTLID              ACTION                           SQL_ID          Hash Value             Signature    IDs  Execs    Secs Table Name
-- ------------ ---------------------- -------------------------------- ------------- ------------ --------------------- ------ ------ ------- ------------------ 
 1 NVISION      NVS_RPTBOOK_99         PI=9984520:UKGL999I:12345        01g5hvs91k4hn   1653134809   1995330195085985689    276    276    2843 PS_XX_SUM_XXXXX_MV 
… 

This is one of at least 276 different SQL statements that all have the same force-matching signature. The statements are essentially the same but differ in some of their literal values. That means that the database has to treat each one as a different SQL statement that must be fully parsed separately. 

SQL Parse involves checking the statement is syntactically correct, and that the user has permission to access the objects, then during the SQL optimization stage the optimizer decides how to execute the statement before it moves to row source generation. 

If the statement has been parsed previously and is still in the shared pool, Oracle can skip the optimization and row source generation stages. This is often called soft parse. 

SQL Optimization 

During the optimization stage, the optimizer calculates the 'cost' of different possible execution plans. Depending upon the SQL, the optimizer considers different table join orders, different table join methods, and different SQL transformations. The optimizer cost is an estimation of the time that it will take to execute a particular plan. The unit of cost is roughly equivalent to the duration of a single block read. More expensive plans are abandoned as they become more expensive than the cheapest known plan so far. Thus the 'cost-based' optimizer produces the cheapest plan. However, the process of optimization consumes time and CPU. 

If I write SQL that is executed many times with bind variables rather than literals, then I should avoid some hard parses and the associated CPU consumption. Oracle has always recommended using bind variables rather than literals to improve performance as well as protect against SQL injection. However, there are many applications that still use literals, particularly in dynamically generated SQL. Every statement has to be hard parsed, and the cumulative CPU consumption can start to become significant. PeopleSoft is one such application that does this in some areas of the product, but it is by no means an isolated example. 

Oracle produced a feature called Cursor Sharing. Literals in statements are automatically converted to bind variables. It can be very effective. It does reduce SQL parse, but can sometimes also produce undesirable side effects where the execution plan may not change as the bind variable values change. 

Hints 

Hints are directives to the optimizer. They tell it to do something or more generally not to do something else. If I were to add some optimizer hints to a statement that will produce the same, or a similar, execution plan, then the optimizer should do less work, consume less CPU, and less time coming to the same or similar conclusion. 

 For example, if I add a LEADING hint to force the optimizer to start with a particular object, that will reduce the number of join orders to be considered. 

• A two-table query has 2 possible join orders; a LEADING hint will reduce it to 1. 
• A three-table query has 6 possible join orders; a LEADING hint on a single table will reduce it to 2. 

Often, it is not possible to add hints directly to the code in the application because it is all dynamically generated inside a package, or it may not be desirable to alter third-party code. In my example, the SQL was generated by compiled code within the nVision reporting tool that I cannot alter. I can't use a SQL Patch because I would need a patch for every SQL_ID and I can't predicate the SQL_IDs. Instead, I can create a force-matching SQL profile that will match every statement with the same force-matching signature. 

N.B. SQL Profiles require the SQL Tuning pack licence. 

Example SQL Profile 

I don't have to use the full outline of hints from the execution plan, I have chosen to apply just a few. 

• LEADING(L2): I want the query to start with the dimension table PSTREESELECT10. This will result in a change to the execution plan 
• REWRITE: PS_XX_SUM_XXXXX_MV is a materialized view built on the view PS_XX_SUM_XXXXX_VW of an underlying summary ledger. Rewriting the SQL to use the materialized view is a cost-based decision. Oracle usually decides to rewrite it to use the materialized view, but I want to ensure that this always happens with this hint. 
• NO_PARALLEL: This query selects only a single accounting period, so it is only scanning a single partition, therefore I don't want to invoke a parallel query. 
• PX_JOIN_FILTER(PS_XX_SUM_XXXXX_MV@SEL$CAD4EEF6): The dimension table is equijoined to the fact table. Therefore, it is a good candidate for using a Bloom filter on the look-up fact table. This doesn't always happen naturally on this statement. I have had to use the query block name taken from the execution plan of the rewritten statement.  The query block name is stable, it is a hash value based on the object name and the operation.
  

The profile is then created with DBMS_SQLTUNE.IMPORT_SQL_PROFILE.

set serveroutput on
DECLARE
  l_sql_text CLOB;
  l_signature NUMBER;
  h       SYS.SQLPROF_ATTR;
…
BEGIN
…
h := SYS.SQLPROF_ATTR(
q'[BEGIN_OUTLINE_DATA]',
q'[NO_PARALLEL]',
q'[LEADING(L2)]',
q'[PX_JOIN_FILTER(PS_XX_SUM_XXXXX_MV@SEL$CAD4EEF6)]',
q'[REWRITE]',
q'[END_OUTLINE_DATA]');

l_signature := DBMS_SQLTUNE.SQLTEXT_TO_SIGNATURE(l_sql_text);

DBMS_SQLTUNE.IMPORT_SQL_PROFILE (
sql_text    => l_sql_text,
profile     => h,
name        => 'NVS_UKGL999I_FUNC_ACEXP1',
category    => 'DEFAULT',
validate    => TRUE,
replace     => TRUE,
force_match => TRUE);
…
END;
/

This is the execution plan with the SQL Profile. The note confirms that a SQL profile was used. The hint report shows the hints from the SQL Profile.  

Note that the SELECTOR_NUM and CHARTFIELD1 predicates have changed.

SELECT L4.TREE_NODE_NUM,SUM(A.POSTED_TOTAL_AMT) 
FROM PS_XX_SUM_XXXXX_VW A, PSTREESELECT10 L4, PSTREESELECT10 L2 
WHERE A.LEDGER='X_UKMGT' 
AND A.FISCAL_YEAR=2023 AND A.ACCOUNTING_PERIOD=1 
AND L4.SELECTOR_NUM=433 AND A.CHARTFIELD3=L4.RANGE_FROM_10 
AND L2.SELECTOR_NUM=434 AND A.ACCOUNT=L2.RANGE_FROM_10 
AND (A.DEPTID BETWEEN '10000' AND '18999' OR
A.DEPTID BETWEEN '20000' AND '29149' OR A.DEPTID='29156' OR
A.DEPTID='29158' OR A.DEPTID BETWEEN '29165' AND '29999' OR A.DEPTID
BETWEEN '30000' AND '39022' OR A.DEPTID BETWEEN '39023' AND '39999' OR
A.DEPTID BETWEEN '40000' AND '49999' OR A.DEPTID BETWEEN '50000' AND
'59999' OR A.DEPTID BETWEEN '60000' AND '69999' OR A.DEPTID BETWEEN
'70000' AND '79999' OR A.DEPTID BETWEEN '80000' AND '89999' OR
A.DEPTID='29150' OR A.DEPTID=' ') 
AND A.CHARTFIELD1='0051001' 
AND A.CURRENCY_CD='GBP' 
GROUP BY L4.TREE_NODE_NUM

Plan hash value: 3033847137

---------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
---------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |                    |       |       |   214 (100)|          |       |       |
|   1 |  SORT GROUP BY                             |                    |     5 |   400 |   214  (62)| 00:00:01 |       |       |
|   2 |   HASH JOIN                                |                    |  2347 |   183K|   213  (62)| 00:00:01 |       |       |
|   3 |    HASH JOIN                               |                    |  2347 |   153K|   210  (63)| 00:00:01 |       |       |
|   4 |     JOIN FILTER CREATE                     | :BF0000            |   306 |  4590 |     3   (0)| 00:00:01 |       |       |
|   5 |      PARTITION RANGE SINGLE                |                    |   306 |  4590 |     3   (0)| 00:00:01 |   434 |   434 |
|   6 |       TABLE ACCESS STORAGE FULL            | PSTREESELECT10     |   306 |  4590 |     3   (0)| 00:00:01 |   434 |   434 |
|   7 |     JOIN FILTER USE                        | :BF0000            | 26468 |  1344K|   206  (64)| 00:00:01 |       |       |
|   8 |      PARTITION RANGE SINGLE                |                    | 26468 |  1344K|   206  (64)| 00:00:01 |    42 |    42 |
|   9 |       MAT_VIEW REWRITE ACCESS INMEMORY FULL| PS_XX_SUM_XXXXX_MV | 26468 |  1344K|   206  (64)| 00:00:01 |    42 |    42 |
|  10 |    PARTITION RANGE SINGLE                  |                    |   202 |  2626 |     3   (0)| 00:00:01 |   433 |   433 |
|  11 |     TABLE ACCESS STORAGE FULL              | PSTREESELECT10     |   202 |  2626 |     3   (0)| 00:00:01 |   433 |   433 |
---------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$38F8C49D
   6 - SEL$38F8C49D / L2@SEL$1
   9 - SEL$38F8C49D / PS_XX_SUM_XXXXX_MV@SEL$CAD4EEF6
  11 - SEL$38F8C49D / L4@SEL$1

Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 4 (U - Unused (1))
---------------------------------------------------------------------------

   0 -  STATEMENT
         U -  NO_PARALLEL
…
   1 -  SEL$38F8C49D
           -  LEADING(L2)
           -  REWRITE

   9 -  SEL$38F8C49D / PS_XX_SUM_XXXXX_MV@SEL$CAD4EEF6
           -  PX_JOIN_FILTER(PS_XX_SUM_XXXXX_MV@SEL$CAD4EEF6)

Note
-----
…
   - SQL profile "NVS_UKGL999I_FUNC_ACEXP1" used for this statement

• The new execution plan does indeed start with the dimension table 
• The query was rewritten to use the materialized view 
• A Bloom filter was used on the materialized view that is now the fact table
• The NO_PARALLEL hint wasn't used because Oracle chose not to parallelise this statement anyway.

                                                                                 Plan
                                                                                          SQL Plan        Force Matching    SQL   Plan   Parse
 # OPRID        RUNCNTLID              ACTION                           SQL_ID          Hash Value             Signature    IDs  Execs    Secs Table Name
-- ------------ ---------------------- -------------------------------- ------------- ------------ --------------------- ------ ------ ------- ------------------ 
…
 1 NVISION      NVS_RPTBOOK_99         PI=9984933:UKGL278I:12345        03nwc4yy1r1r7   3033847137   1995330195085985689    138    138    1428 PS_XX_SUM_XXXXX_MV

Now just 1428s is spent on parse time. We only found 138 SQL IDs, but that is just because there are fewer ASH samples because it is taking less time. 

In this case, adding these hints with a SQL Profile has halved the time spent parsing this set of SQL statements.

Programmatically Suspending and Restarting the Process Scheduler

I found this question on a message forum, wrote a note, and forgot about it:

Anyone have any tricks on suspending the process schedulers programmatically?  I just tried using the following but the weird thing was I saw at least one of my process schedulers unsuspend itself, so I must be missing an update to a table.

UPDATE PSSERVERSTAT set SERVERSTATUS = '2' where SERVERNAME like '%PSUNX%'

The process scheduler writes its status to SERVERSTATUS so that it can be seen in the Process Monitor.  Instructions to the process scheduler are read from SERVERACTION, so this is the column that must be updated.  Both columns have a set of XLAT values that translate the status.

PeopleSoft Field Name	Description
SERVERSTATUS	Server Status 0=Error 1=Down 2=Suspended 3=Running 4=Purging 5=Running With No Report Node 6=Suspended - Disk Low 7=Suspended - Offline 8=Running - Report Rep. Full 9=Overloaded
SERVERACTION	Process Server Action 0=None 1=Stop 2=Suspended 3=Restart 4=Purge

See PSSERVERSTAT.

You can see how PeopleSoft does this by tracing the Process Monitor component as it issues commands to the process scheduler.  Hence you can issue commands as follows:

• Stop

update psserverstat
set    serveraction = 1 /*Stop*/
where  serverstatus = 3 /*Running*/
and    servername = …
/
commit
/

• Suspend

update psserverstat
set    serveraction = 2 /*Suspend*/
where  serverstatus = 3 /*Running*/
and    servername = …
/
commit
/

• Restart (after suspension)

update psserverstat
set    serveraction = 3 /*Restart*/
where  serverstatus = 2 /*Suspended*/
and    servername = …
/
commit
/

• Startup (if the Tuxedo domain is running)

update psserverstat
set    serveraction = 3
where  servername = …
/
commit
/

Reading Trace files with SQL

Oracle 12.2 provided some new views that enable trace files to be read via SQL. Previously, it had been possible to do this by creating external tables, but the new views make it much easier. You can simply query what trace files exist with SQL, and then access them without need for server access. 

This is particularly useful on some cloud platforms such as autonomous database, where there is no server access, even for the DBA. However, this technique is applicable to all Oracle databases.  Now, not just the DBA, but developers can easily obtain trace files.

Lots of other people have blogged about this, but Chris Antognini makes the point extremely well:

• TKPROF’s Argument PDBTRACE
• SQL Trace in Oracle Database Exadata Express Cloud Service 

In a post on my PeopleSoft blog, I demonstrated enabling trace on an application server process.  I also specified that as a trace file identifier. Now I can query the trace files that exist, and restrict the query by filename or date.

set pages 99
select * from gv$diag_trace_file f
where 1=1
and f.modify_time > trunc(sysdate)-1
and f.trace_filename like 'finprod%ora%.trc'
order by modify_time desc
/

   INST_ID ADR_HOME                                                     TRACE_FILENAME                 CHANGE_TIME                          MODIFY_TIME                              CON_ID
---------- ------------------------------------------------------------ ------------------------------ ------------------------------------ ------------------------------------ ----------
         1 /u02/app/oracle/diag/rdbms/finprod/finprod1                  finprod1_ora_306641.trc        23/03/2023 21.25.41.000000000 -05:00 23/03/2023 21.25.41.000000000 -05:00          0

Then I can also query the trace file contents, and even just spool it to a local file.

clear screen 
set head off pages 0 feedback off
with x as (
select /*+LEADING(F)*/ f.trace_filename, c.line_number, c.payload
--, max(c.line_number) over (partition by c.trace_filename) max_line_number
from gv$diag_trace_file f, gv$diag_trace_File_contents c
where c.adr_home = f.adr_home
and c.trace_filename = f.trace_filename
and f.modify_time > trunc(sysdate)-1
and f.trace_filename like 'finprod%ora%306641.trc'
)
select payload from x
ORDER BY line_number
/

The contents of the spool file looks just like the trace file.  I can profile it with tkprof or another trace profiler.

Trace file /u02/app/oracle/diag/rdbms/finprod/finprod1/trace/finprod1_ora_306641.trc
Oracle Database 19c EE Extreme Perf Release 19.0.0.0.0 - Production
Version 19.16.0.0.0
Build label:    RDBMS_19.16.0.0.0DBRU_LINUX.X64_220701
ORACLE_HOME:    /u02/app/oracle/product/19.0.0.0/dbhome_1
System name:      Linux 
Node name:  naukp-aora101
Release:    4.14.35-2047.514.5.1.2.el7uek.x86_64 
Version:    #2 SMP Thu Jul 28 15:33:31 PDT 2022 
Machine:    x86_64 
Storage:    Exadata 
Instance name: finprod1
Redo thread mounted by this instance: 1
Oracle process number: 225
Unix process pid: 306641, image: oracle@xxxxp-aora102

*** 2023-03-23T21:46:34.632063-04:00
*** SESSION ID:(2337.13457) 2023-03-23T21:46:34.632080-04:00
*** CLIENT ID:(NVRUNCNTL) 2023-03-23T21:46:34.632086-04:00
*** SERVICE NAME:(finprod.acme.com) 2023-03-23T21:46:34.632161-04:00
*** MODULE NAME:(RPTBOOK) 2023-03-23T21:46:34.632166-04:00
*** ACTION NAME:(PI=9980346:NVGL0042:42001) 2023-03-23T21:46:34.632171-04:00
*** CLIENT DRIVER:() 2023-03-23T21:46:34.632177-04:00

IPCLW:[0.0]{-}[RDMA]:RC: [1679622394631549]Connection 0x7f83ee131550 not formed (2). Returning retry.
IPCLW:[0.1]{E}[RDMA]:PUB: [1679622394631549]RDMA lport 0x400012c62778 dst 100.107.2.7:40056 bid 0x1805ea7b58 rval 2

Oracle SQL Tracing Processes from Startup

Sometimes, ASH and AWR are not enough.  SQL may not be sampled by ASH if it is short-lived, and even if it is sampled, the SQL may not be captured by AWR.  Sometimes, in order to investigate a problem effectively, it is necessary to use database session SQL trace.  

It is easy to trace a process initiated by the process scheduler with a trigger (see Enabling Oracle Database Trace on PeopleSoft processes with a Trigger).

Another tactic is to use an AFTER LOGON trigger with logic to look at the program name.  The program name can be read using SYS_CONTEXT().  If it matches what I am looking for, I can enable session trace.

Here is an example I used for the OpenXML nVision server PSNVSSRV

• I want to trace SQL and not any wait events or bind variables.  Therefore, I will set event 10046 at level 1.
• I also set a tracefile_identifier that will be included in the trace file name, so I can more easily identify the trace file.

REM additional SQL trace triggers
CREATE OR REPLACE TRIGGER sysadm.gfc_nvision_trace_on_logon
AFTER LOGON
ON sysadm.schema
DECLARE
  l_process_instance INTEGER;
  l_program          VARCHAR2(64 CHAR);
  l_sql              VARCHAR2(100);
BEGIN

  SELECT sys_context('USERENV', 'CLIENT_PROGRAM_NAME')
  INTO   l_program
  FROM   dual;

  IF l_program like 'PSNVSSRV%' THEN --then this is a NVISION session
    EXECUTE IMMEDIATE 'ALTER SESSION SET tracefile_identifier = ''PSNVSSRV''';
    EXECUTE IMMEDIATE 'ALTER SESSION SET events ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 1''';
  END IF;

EXCEPTION 
  WHEN OTHERS THEN NULL;
END;
/
show errors
ALTER TRIGGER sysadm.gfc_nvision_trace_on_logon ENABLE;

See also Reading Trace files with SQL

"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.