Reduce Hard Parse time using SQL Profile

Few days ago we had concurrency problem with "cursor: pin S wait on X" wait event. This wait event is mostly associated with parsing in some form.

After quick diagnosis I’ve found problematic query. It was fairly complex query which was executed very often with average 0.20 seconds of execution time. As this query was using bind variables, Oracle reused existing plan and problems with "cursor: pin S wait on X" wait events weren’t appearing.

But when hard parse occurred we experienced problems with specified mutex waits. Query execution with hard parsing jumped from 0.20 seconds to over 2,1 seconds.

One session would hold mutex pin in exclusive mode while other sessions were waiting to get a mutex pin in share mode - waiting with "Cursor: pin S wait on X" wait event.

Rewriting query would solve this issue but we needed some solution quickly.


I have decided to perform few tests using SQL plan baselines and SQL profiles and measure effect on hard parse. Tested query is intentionally excluded from the post.

Version : Oracle 12.1.0.2

Query execution statistics:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      1.15       2.09          0         10          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.01          0        177          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.16       2.11          0        187          0           1

Statistics
----------------------------------------------------------
       1691  recursive calls
          0  db block gets
       1594  consistent gets
          0  physical reads
          0  redo size
       7266  bytes sent via SQL*Net to client
       8393  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         60  sorts (memory)
          0  sorts (disk)
          1  rows processed

Total query execution is 2.11 seconds where parsing took 2.09 seconds which is practically whole query execution time.


What will happen if we create fixed baseline for the query:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      1.15       2.09          0          7          0           0
Execute      1      0.00       0.00          0          0          1           0
Fetch        2      0.00       0.01          0        177          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.16       2.11          0        184          1           1

Note
-----
   - SQL plan baseline "SQL_PLAN_6q3anxq5dfsj4e57c1833" used for this statement

Statistics
----------------------------------------------------------
       1691  recursive calls
          0  db block gets
       1594  consistent gets
          0  physical reads
          0  redo size
       7287  bytes sent via SQL*Net to client
       8393  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         60  sorts (memory)
          0  sorts (disk)
          1  rows processed

I have practically the same results which means that SQL plan baseline had no effect on parse time.


But, what will happen if I create SQL profile instead of baseline:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.65       1.21          6         21          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.01       0.01          0        177          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.66       1.23          6        198          0           1

Note
-----
   - SQL profile "PROFILE_09vf7nstqk7n2" used for this statement

Statistics
----------------------------------------------------------
        654  recursive calls
          0  db block gets
       1300  consistent gets
          6  physical reads
          0  redo size
       7284  bytes sent via SQL*Net to client
       8393  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
         60  sorts (memory)
          0  sorts (disk)
          1  rows processed

This is big improvement.
Notice elapsed time for parse - from 2.09 secs to 1.21 secs.
Check query statistics - almost three times less recursive calls.


But why?
This is my explanation and I might be wrong so please leave comment below if this is the case.

When we’re using SQL baselines for plan management first step is always generating execution plans from optimizer. Cost based optimizer produces several plans and then compares plans with plans in the SQL plan baseline. Many different plans will be probed as a part of optimizer calculations. SQL plan baseline has no effect on number of calculations.

With SQL profiles we will feed optimizer with estimations and hints before calculation starts. Future plan will be influenced by the SQL profile. Basically we will point optimizer "in the right direction" and optimizer will not perform the same amount of calculations like before. As a result we have less recursive calls and less time spent on hard parsing.


After "fixing" plan with SQL profile, I’ve tried to reproduce mutex concurrency intentionally forcing hard parse but now Oracle managed to perform hard parse without affecting many sessions. Maybe I’ve solved problem temporarily and bought some time for developers to rewrite problematic query.