Why CURSOR_SHARING=FORCE sucks

As you might have guessed, my colleagues involved my in load testing activities. Actually, there is nothing challenging in writing load tests (I do think that analysis is another topic), but forcing Documentum to work under load is a big challenge. On first iteration we got following docbase sessions graph:

Which is actually weird, because I do suppose that collected metrics should somehow reflect load, but in our scenario we put ~ constant load, but docbase sessions metric not seemed to be a constant 😦 , which could mean one of the following:

  • I’m an idiot and my estimations were wrong, but in this case it means that customer should not use Documentum due to unpredictable performance
  • Something was wrong on Documentum side

Let’s check database side …

Recommendation 1: SQL Tuning
Estimated benefit is 22.41 active sessions, 56.8% of total activity.
--------------------------------------------------------------------
Action
   Investigate the SELECT statement with SQL_ID "34h8xv6j5mx04" for 
   possible performance improvements. You can supplement the information 
   given here with an ASH report for this SQL_ID.
   Related Object
      SQL statement with SQL_ID 34h8xv6j5mx04.
      select gs.group_name, gs.is_dynamic, 
      gs.is_dynamic_default,gs.is_protected, gs.is_module_only from 
      dm_group_s gs, dm_group_r gr where gs.r_object_id = gr.r_object_id 
      and gs.is_dynamic = :"SYS_B_0" and gs.is_dynamic_default = :"SYS_B_1" 
      and (gr.users_names = :P0 or gr.groups_names = :"SYS_B_2" or 
      gr.groups_names in (select gr1.i_nondyn_supergroups_names from 
      dm_group_r gr1, dm_group_r gr2 where gr1.r_object_id = 
      gr2.r_object_id and (gr2.users_names = :P1 or gr2.groups_names = 
      :"SYS_B_3") and gr1.i_nondyn_supergroups_names IS NOT NULL))


SQL ID: 34h8xv6j5mx04                     DB/Inst: ECM/ECM      Snaps: 13-14
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> select gs.group_name, gs.is_dynamic, gs.is_dynamic_default,gs.is_prote...

    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   2451896125             85,924,271       16,7191            14             14
          -------------------------------------------------------------       

Execution Plan
------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop
------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                    |       |       | 15936 (100)|          |       |      
|   1 |  FILTER                             |                    |       |       |            |          |       |      
|   2 |   PX COORDINATOR                    |                    |       |       |            |          |       |      
|   3 |    PX SEND QC (RANDOM)              | :TQ10001           |  9328K|   676M| 15936   (2)| 00:03:12 |       |      
|   4 |     HASH JOIN                       |                    |  9328K|   676M| 15936   (2)| 00:03:12 |       |      
|   5 |      BUFFER SORT                    |                    |       |       |            |          |       |      
|   6 |       PART JOIN FILTER CREATE       | :BF0000            |   386K|    19M|  1859   (1)| 00:00:23 |       |      
|   7 |        PX RECEIVE                   |                    |   386K|    19M|  1859   (1)| 00:00:23 |       |      
|   8 |         PX SEND PARTITION (KEY)     | :TQ10000           |   386K|    19M|  1859   (1)| 00:00:23 |       |      
|   9 |          TABLE ACCESS BY INDEX ROWID| DM_GROUP_S         |   386K|    19M|  1859   (1)| 00:00:23 |       |      
|  10 |           INDEX RANGE SCAN          | D_XXXXXXXX8000010A |   773K|       |   124   (1)| 00:00:02 |       |      
|  11 |      PX PARTITION HASH JOIN-FILTER  |                    |    18M|   407M| 14035   (2)| 00:02:49 |:BF0000|:BF000
|  12 |       TABLE ACCESS FULL             | DM_GROUP_R         |    18M|   407M| 14035   (2)| 00:02:49 |:BF0000|:BF000
|  13 |   NESTED LOOPS                      |                    |     4 |   228 |     3   (0)| 00:00:01 |       |      
|  14 |    NESTED LOOPS                     |                    |    88 |   228 |     3   (0)| 00:00:01 |       |      
|  15 |     PARTITION HASH ALL              |                    |     4 |   136 |     2   (0)| 00:00:01 |     1 |    20
|  16 |      INDEX RANGE SCAN               | D_XXXXXXXX80000056 |     4 |   136 |     2   (0)| 00:00:01 |     1 |    20
|  17 |     PARTITION HASH ITERATOR         |                    |    22 |       |     1   (0)| 00:00:01 |   KEY |   KEY
|  18 |      INDEX RANGE SCAN               | D_XXXXXXXX80000109 |    22 |       |     1   (0)| 00:00:01 |   KEY |   KEY
|  19 |    TABLE ACCESS BY LOCAL INDEX ROWID| DM_GROUP_R         |     1 |    23 |     1   (0)| 00:00:01 |     1 |     1
------------------------------------------------------------------------------------------------------------------------
 
Full SQL Text

SQL ID       SQL Text                                                         
------------ -----------------------------------------------------------------
34h8xv6j5mx0 select gs.group_name, gs.is_dynamic, gs.is_dynamic_default, gs.is
             _protected, gs.is_module_only from dm_group_s gs, dm_group_r gr w
             here gs.r_object_id = gr.r_object_id and gs.is_dynamic = :"SYS_B_
             0" and gs.is_dynamic_default = :"SYS_B_1" and (gr.users_names = :
             P0 or gr.groups_names = :"SYS_B_2" or gr.groups_names in (select 
             gr1.i_nondyn_supergroups_names from dm_group_r gr1, dm_group_r gr
             2 where gr1.r_object_id = gr2.r_object_id and (gr2.users_names = 
             :P1 or gr2.groups_names = :"SYS_B_3") and gr1.i_nondyn_supergroup
             s_names IS NOT NULL))

That is awesome! Single SQL query consumes 60% of database resources! Before trying to optimize this query we need to figure out how it really looks – how can we understand that we optimized some query if we don’t know how to execute it? And here we are:

SELECT gs.group_name,
       gs.is_dynamic,
       gs.is_dynamic_default,
       gs.is_protected,
       gs.is_module_only
  FROM dm_group_s gs, dm_group_r gr
 WHERE     gs.r_object_id = gr.r_object_id
       AND gs.is_dynamic = 1
       AND gs.is_dynamic_default = 1
       AND (   gr.users_names = :P0
            OR gr.groups_names = 'dm_world'
            OR gr.groups_names IN (
          SELECT gr1.i_nondyn_supergroups_names
            FROM dm_group_r gr1, dm_group_r gr2
           WHERE     gr1.r_object_id = gr2.r_object_id
                     AND (   gr2.users_names = :P1
                             OR gr2.groups_names = 'dm_world')
                     AND gr1.i_nondyn_supergroups_names IS NOT NULL)
       );

This query is intended to return dynamic groups (gs.is_dynamic = 1 AND gs.is_dynamic_default = 1) enabled by default, now guess how many dynamic groups enabled by default does our docbase have? Zero! 60% of database resources to return empty resultset! But due to CURSOR_SHARING=FORCE Oracle do not understand that we ask him to return empty resultset and, so, it selects “suboptimal” execution plan, though the optimal is following:

--------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                    |     1 |    77 |     2   (0)| 00:00:01 |       |       |
|*  1 |  FILTER                             |                    |       |       |            |          |       |       |
|   2 |   NESTED LOOPS                      |                    |     1 |    77 |     2   (0)| 00:00:01 |       |       |
|   3 |    NESTED LOOPS                     |                    |    25 |    77 |     2   (0)| 00:00:01 |       |       |
|*  4 |     TABLE ACCESS BY INDEX ROWID     | DM_GROUP_S         |     1 |    53 |     1   (0)| 00:00:01 |       |       |
|*  5 |      INDEX RANGE SCAN               | D_XXXXXXXX8000010A |     1 |       |     1   (0)| 00:00:01 |       |       |
|   6 |     PARTITION HASH ITERATOR         |                    |    25 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|*  7 |      INDEX RANGE SCAN               | D_XXXXXXXX80000109 |    25 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|   8 |    TABLE ACCESS BY LOCAL INDEX ROWID| DM_GROUP_R         |    25 |   600 |     1   (0)| 00:00:01 |     1 |     1 |
|   9 |   NESTED LOOPS                      |                    |     2 |   114 |     3   (0)| 00:00:01 |       |       |
|  10 |    NESTED LOOPS                     |                    |    26 |   114 |     3   (0)| 00:00:01 |       |       |
|  11 |     PARTITION HASH ALL              |                    |    15 |   495 |     2   (0)| 00:00:01 |     1 |    20 |
|* 12 |      INDEX RANGE SCAN               | D_XXXXXXXX80000056 |    15 |   495 |     2   (0)| 00:00:01 |     1 |    20 |
|  13 |     PARTITION HASH ITERATOR         |                    |    13 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|* 14 |      INDEX RANGE SCAN               | D_XXXXXXXX80000109 |    13 |       |     1   (0)| 00:00:01 |   KEY |   KEY |
|* 15 |    TABLE ACCESS BY LOCAL INDEX ROWID| DM_GROUP_R         |     1 |    24 |     1   (0)| 00:00:01 |     1 |     1 |
--------------------------------------------------------------------------------------------------------------------------

So, we stabilised execution plan for this query and on next iteration we got following docbase sessions graph:

Good news: I’m not an idiot.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s