SQL Profile appears to not work but really does

Over the weekend a coworker applied a SQL profile to a long running SQL statement but it looked like the profile was not applied.  For one thing, the SQL statement ran just as long after applying the profile.  Also, the hash value for the plan that the optimizer chose for the statement after applying the SQL Profile was not the same as the desired plan.  But, after looking at it today I’ve realized that the SQL Profile did apply the desired plan.  It was just that the desired plan wasn’t really any more efficient than the one picked by the optimizer.

Here are earlier posts related to our use of SQLT to force a given SQL statement to run with a good plan:

Using coe_xfr_sql_profile.sql to force a good plan

SQLT Emergency Plan Change

In this weekend’s case we were looking at sql_id fpa2sb9pt9d6s.  It looked like plan 1394068771 was faster than the most recently used plan because it had a lower average elapsed time:

SQL_ID        PLAN_HASH_VALUE END_INTERVAL_TIME         EXECUTIONS_DELTA Elapsed Average ms CPU Average ms IO Average ms Cluster Average ms Application Average ms Concurrency Average ms Average buffer gets Average disk reads Average rows processed
------------- --------------- ------------------------- ---------------- ------------------ -------------- ------------- ------------------ ---------------------- ---------------------- ------------------- ------------------ ----------------------
fpa2sb9pt9d6s      1615990741 11-MAY-14 11.00.06.474 AM                1         21550951.2        9720630    467066.276                  0                  27.24              82825.793           126238536            1913606                      0
fpa2sb9pt9d6s      1394068771 18-MAY-14 12.00.52.752 PM                1         1687493.09         657760    402607.781                  0                 39.814               36561.61             4701985             566205                      0
fpa2sb9pt9d6s      1611789738 25-MAY-14 10.00.59.900 AM                1         11390629.8        6835390    462073.968                  0                 32.818              39010.945            86448768             993957                      0

So we used SQLT to force fpa2sb9pt9d6s to use plan 1394068771 but instead it appeared to use plan 420390762 and it didn’t run any faster:

SQL_ID        PLAN_HASH_VALUE END_INTERVAL_TIME         EXECUTIONS_DELTA Elapsed Average ms CPU Average ms IO Average ms Cluster Average ms Application Average ms Concurrency Average ms Average buffer gets Average disk reads Average rows processed
------------- --------------- ------------------------- ---------------- ------------------ -------------- ------------- ------------------ ---------------------- ---------------------- ------------------- ------------------ ----------------------
fpa2sb9pt9d6s      1615990741 11-MAY-14 11.00.06.474 AM                1         21550951.2        9720630    467066.276                  0                  27.24              82825.793           126238536            1913606                      0
fpa2sb9pt9d6s      1394068771 18-MAY-14 12.00.52.752 PM                1         1687493.09         657760    402607.781                  0                 39.814               36561.61             4701985             566205                      0
fpa2sb9pt9d6s      1611789738 25-MAY-14 10.00.59.900 AM                1         11390629.8        6835390    462073.968                  0                 32.818              39010.945            86448768             993957                      0
fpa2sb9pt9d6s       420390762 25-MAY-14 11.00.27.175 PM                1         19055402.5        8975130    492406.429                  0                  24.93              64279.331           120027479            1943256                      0

But if you look at the plan for fpa2sb9pt9d6s that has hash value 420390762 it says it is using the sql profile we created which should result in a plan with hash value 1394068771:

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

So, I dumped out both plans – 420390762 and 1394068771 and edited out the columns from the plan output that were irrelevant and did a diff and came up with this result:

45c45
< |  41 |                          TABLE ACCESS FULL      | SYS_TEMP_0FD9D67B9_9DB13F0D |       |       |  Q2,01 | PCWP |            |
---
> |  41 |                          TABLE ACCESS FULL      | SYS_TEMP_0FD9D6897_9DB13F0D |       |       |  Q2,01 | PCWP |            |

420390762 and 1394068771 were identical except that the system generated temporary segment name was slightly different.  The temp segment name affects the hash value for the plan so this is a gotcha on using plan hash value to compare plans.  Two distinct plan hash values could really represent the same plan if they have system generated temporary segments in the plan.

So, SQLT did successfully apply a given plan to a given sql_id using a SQL Profile but it didn’t improve performance and the resulting plan hash value was not what we expected.

– Bobby