Opened 8 years ago

Closed 8 years ago

Last modified 8 years ago

#2313 closed problem (fixed)

Navigating HERON term hierarchy is slow for users with REDCap access

Reported by: rwaitman Owned by: badagarla
Priority: major Milestone: heron-toronto-update
Component: data-repository Keywords: performance, public-web
Cc: dconnolly, ngraham, badagarla Blocked By:
Blocking: Sensitive: no

Description

Opening non-REDCap folders in REDCap-i2b2 projects is very slow. This is pronounced in the case of MR ORDERABLES folder under IMAGING procedure orders.

The relevant non-REDCap terms are in redcapmetadata.heron_terms which is a copy of blueheronmetadata.heron_terms. Aim of the ticket is to diagnose the problem and resolve it.

Change History (16)

comment:1 Changed 8 years ago by ngraham

Blocking: 2275 added

Adding blocker for the current release (milestone:heron-chikaskia-update).

comment:2 Changed 8 years ago by dconnolly

added a failing test case to source:heron_load/test_heron_query.py in [73c52929d9a0]
on nav_perf_2213 branch (oops; should have been nav_perf_2313).

comment:3 Changed 8 years ago by dconnolly

Owner: changed from dconnolly to ngraham
Status: newassigned

comment:4 Changed 8 years ago by ngraham

"Bad case" - selecting from redcapmetadata2:

SELECT COUNT(*)
FROM redcapmetadata2.HERON_TERMS
WHERE m_exclusion_cd IS NULL
AND c_fullname       IN
  (SELECT c_fullname
  FROM redcapmetadata2.HERON_TERMS
  WHERE c_hlevel      = 1
  AND m_exclusion_cd IS NULL
  AND (m_applied_path = '\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\' 
  or m_applied_path = '\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%' 
  or m_applied_path = '\i2b2\Procorders\Imaging\MR ORDERABLES\%' 
  or m_applied_path = '\i2b2\Procorders\Imaging\%' 
  or m_applied_path = '\i2b2\Procorders\%' 
  or m_applied_path = '\i2b2\%' 
  or m_applied_path = '\%' ) MINUS  
  (select c_fullname from redcapmetadata2.HERON_TERMS where m_exclusion_cd is not null and 
  (m_applied_path = '\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\'
  OR m_applied_path   = '\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%'
  OR m_applied_path   = '\i2b2\Procorders\Imaging\MR ORDERABLES\%'
  OR m_applied_path   = '\i2b2\Procorders\Imaging\%'
  OR m_applied_path   = '\i2b2\Procorders\%'
  OR m_applied_path   = '\i2b2\%'
  OR m_applied_path   = '\%' )
  ));
SELECT PLAN_TABLE_OUTPUT
FROM TABLE(DBMS_XPLAN.DISPLAY());

Plan from above:

Plan hash value: 2208525922
 
----------------------------------------------------------------------------------------------
| Id  | Operation              | Name        | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |             |     1 |   486 |       | 63257   (1)| 00:12:40 |
|   1 |  SORT AGGREGATE        |             |     1 |   486 |       |            |          |
|*  2 |   HASH JOIN            |             | 37921 |    17M|    12M| 63257   (1)| 00:12:40 |
|   3 |    VIEW                | VW_NSO_1    | 37035 |    12M|       | 37987   (1)| 00:07:36 |
|   4 |     MINUS              |             |       |       |       |            |          |
|   5 |      SORT UNIQUE       |             | 37035 |  5063K|  5600K|            |          |
|*  6 |       TABLE ACCESS FULL| HERON_TERMS | 37035 |  5063K|       | 18419   (1)| 00:03:42 |
|   7 |      SORT UNIQUE       |             |   145 | 19865 |       |            |          |
|*  8 |       TABLE ACCESS FULL| HERON_TERMS |   145 | 19865 |       | 18417   (1)| 00:03:42 |
|*  9 |    TABLE ACCESS FULL   | HERON_TERMS |   899K|   114M|       | 18417   (1)| 00:03:42 |
----------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - access("C_FULLNAME"="C_FULLNAME")
   6 - filter("C_HLEVEL"=1 AND ("M_APPLIED_PATH"='\%' OR "M_APPLIED_PATH"='\i2b2\%' 
              OR "M_APPLIED_PATH"='\i2b2\Procorders\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%') AND 
              "M_EXCLUSION_CD" IS NULL)
   8 - filter("M_EXCLUSION_CD" IS NOT NULL AND ("M_APPLIED_PATH"='\%' OR 
              "M_APPLIED_PATH"='\i2b2\%' OR "M_APPLIED_PATH"='\i2b2\Procorders\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%'))
   9 - filter("M_EXCLUSION_CD" IS NULL)

"good" case (from blueheronmetadata):

Plan hash value: 246194330
 
------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                        | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                             |     1 |   486 |   112   (2)| 00:00:02 |
|   1 |  SORT AGGREGATE                    |                             |     1 |   486 |            |          |
|   2 |   NESTED LOOPS                     |                             |       |       |            |          |
|   3 |    NESTED LOOPS                    |                             |     1 |   486 |   112   (2)| 00:00:02 |
|   4 |     VIEW                           | VW_NSO_1                    |     1 |   352 |   108   (2)| 00:00:02 |
|   5 |      MINUS                         |                             |       |       |            |          |
|   6 |       SORT UNIQUE                  |                             |     1 |   140 |            |          |
|   7 |        INLIST ITERATOR             |                             |       |       |            |          |
|*  8 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS                 |     1 |   140 |    53   (0)| 00:00:01 |
|*  9 |          INDEX RANGE SCAN          | META_APPLIED_PATH_HERON_IDX |   570 |       |     9   (0)| 00:00:01 |
|  10 |       SORT UNIQUE                  |                             |     1 |   137 |            |          |
|  11 |        INLIST ITERATOR             |                             |       |       |            |          |
|* 12 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS                 |     1 |   137 |    53   (0)| 00:00:01 |
|* 13 |          INDEX RANGE SCAN          | META_APPLIED_PATH_HERON_IDX |   570 |       |     9   (0)| 00:00:01 |
|* 14 |     INDEX RANGE SCAN               | META_FULLNAME_HERON_IDX     |     1 |       |     3   (0)| 00:00:01 |
|* 15 |    TABLE ACCESS BY INDEX ROWID     | HERON_TERMS                 |     1 |   134 |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   8 - filter("C_HLEVEL"=1 AND "M_EXCLUSION_CD" IS NULL)
   9 - access("M_APPLIED_PATH"='\%' OR "M_APPLIED_PATH"='\i2b2\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\%' OR "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%')
  12 - filter("M_EXCLUSION_CD" IS NOT NULL)
  13 - access("M_APPLIED_PATH"='\%' OR "M_APPLIED_PATH"='\i2b2\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\%' OR "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%')
  14 - access("C_FULLNAME"="C_FULLNAME")

After Bhargav gave me REDCap permissions, I can run the test...but it's not failing, right? It came back in just under 2 minutes - still a long time:

...heron_load>python test_heron_query.py https:
//<test webclient server>.kumc.edu/heron
INFO:__main__:opening Heron homepage...
INFO:__main__:Found page with title: KUMC Central Authentication Service
...
INFO:__main__:Submitting CAS login form...
INFO:__main__:Found page with title: HERON Research Data Repository
INFO:__main__:Following link to i2b2 query tool...
INFO:__main__:Found page with title: i2b2 Web Client
INFO:__main__:Getting user configuration...
INFO:__main__:Got it.
INFO:__main__:using project: REDCap_10
INFO:__main__:re-playing saved message: mr_orderables_term_query
INFO:__main__:reply status: ['DONE']
**********************************************************************
File "test_heron_query.py", line 28, in __main__
Failed example:
    ua.saved_message(project, 'mr_orderables_term_query')
Expected:
    ['@@OK']
Got:
    ['DONE']

Oops...above notes redcapmetadata2, but I was given access to redcapmetadata10. However, same results as far as execution plans were the same.

rebuild table statistics from the GUI

begin 
  	  	DBMS_STATS.GATHER_TABLE_STATS (
  	  	  ownname => '"REDCAPMETADATA10"',
          tabname => '"HERON_TERMS"',
          estimate_percent => 5
          );
          end;

Execution plans look the same, but it's still very slow - accessing parts of the hierarchy in the webclient took a long time but more like a minute (<3 minutes at least).

Plan hash value: 2171854115
 
------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                  | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                       |     1 |   486 |    38   (6)| 00:00:01 |
|   1 |  SORT AGGREGATE                    |                       |     1 |   486 |            |          |
|   2 |   NESTED LOOPS                     |                       |       |       |            |          |
|   3 |    NESTED LOOPS                    |                       |     1 |   486 |    38   (6)| 00:00:01 |
|   4 |     VIEW                           | VW_NSO_1              |     1 |   352 |    34   (6)| 00:00:01 |
|   5 |      MINUS                         |                       |       |       |            |          |
|   6 |       SORT UNIQUE                  |                       |     1 |   140 |            |          |
|   7 |        INLIST ITERATOR             |                       |       |       |            |          |
|*  8 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS           |     1 |   140 |    16   (0)| 00:00:01 |
|*  9 |          INDEX RANGE SCAN          | M_APPLIED_PATH_HT_IDX |    70 |       |     9   (0)| 00:00:01 |
|  10 |       SORT UNIQUE                  |                       |     1 |   137 |            |          |
|  11 |        INLIST ITERATOR             |                       |       |       |            |          |
|* 12 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS           |     1 |   137 |    16   (0)| 00:00:01 |
|* 13 |          INDEX RANGE SCAN          | M_APPLIED_PATH_HT_IDX |    70 |       |     9   (0)| 00:00:01 |
|* 14 |     INDEX RANGE SCAN               | M_FULLNAME_HT_IDX     |     1 |       |     3   (0)| 00:00:01 |
|* 15 |    TABLE ACCESS BY INDEX ROWID     | HERON_TERMS           |     1 |   134 |     4   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   8 - filter("C_HLEVEL"=1 AND "M_EXCLUSION_CD" IS NULL)
   9 - access("M_APPLIED_PATH"='\%' OR "M_APPLIED_PATH"='\i2b2\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\%' OR "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%')
  12 - filter("M_EXCLUSION_CD" IS NOT NULL)
  13 - access("M_APPLIED_PATH"='\%' OR "M_APPLIED_PATH"='\i2b2\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\%' OR "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\%' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\' OR 
              "M_APPLIED_PATH"='\i2b2\Procorders\Imaging\MR ORDERABLES\10203910\%')
  14 - access("C_FULLNAME"="C_FULLNAME")

This seems to make it better

alter table "REDCAPMETADATA10"."HERON_TERMS" cache

However, CACHE NO seems to be the setting for blueheronmetadata.HERON_TERMS, so I don't know why it seems fast since it shows the same execution plan.

comment:5 Changed 8 years ago by dconnolly

The one minute execution time could be swapping between copies of heron_terms.

I wonder if the execution plan was bad when Bhargav was investigating performance with Oracle synonyms (ticket:1880#comment:18). I'd like to see that explored before closing this ticket.

comment:6 Changed 8 years ago by dconnolly

Owner: changed from ngraham to badagarla

Bhargav is to apply the alter ... cache and such to all REDCap schemas.

comment:7 Changed 8 years ago by badagarla

Blocking: 2275 removed

Ran the following for each of the 10, redcapmetadata.heron_terms

begin 
  	  	DBMS_STATS.GATHER_TABLE_STATS (
  	  	  ownname => '"REDCAPMETADATA9"',
          tabname => '"HERON_TERMS"',
          estimate_percent => 5
          );
          end;
alter table "REDCAPMETADATA9"."HERON_TERMS" cache;

comment:8 Changed 8 years ago by badagarla

Milestone: heron-chikaskia-updateheron-solomon-update

comment:9 Changed 8 years ago by ngraham

Bhargav,

I also ran the following for each of the 10 (in addition to the stats noted in comment:7):

alter table "REDCAPMETADATA1"."HERON_TERMS" cache;

comment:10 Changed 8 years ago by dconnolly

Milestone: heron-solomon-updateheron-milford-update

Batch update from file solomon-release-triage.xls

comment:11 Changed 8 years ago by badagarla

From meeting with Debbie Swineheart: The non-redcap folders (Tumor registry, Medications) opened up slower when Russ was looking at them from a REDCap HERON project. We thought this would have been resolved after caching (ref comment:9)

comment:12 Changed 8 years ago by badagarla

  1. First looking at caching:
  1. Looking at statistics for the query from comment:4 with redcapmetadata10 instead of redcapmetadata2:
    plan FOR succeeded.
    PLAN_TABLE_OUTPUT                                                                                                                                                                                                                                                                                            
    ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ 
    Plan hash value: 2171854115                                                                                                                                                                                                                                                                                  
                                                                                                                                                                                                                                                                                                                 
    ------------------------------------------------------------------------------------------------------------                                                                                                                                                                                                 
    | Id  | Operation                          | Name                  | Rows  | Bytes | Cost (%CPU)| Time     |                                                                                                                                                                                                 
    ------------------------------------------------------------------------------------------------------------                                                                                                                                                                                                 
    |   0 | SELECT STATEMENT                   |                       |     1 |   485 |    28   (8)| 00:00:01 |                                                                                                                                                                                                 
    |   1 |  SORT AGGREGATE                    |                       |     1 |   485 |            |          |                                                                                                                                                                                                 
    |   2 |   NESTED LOOPS                     |                       |       |       |            |          |                                                                                                                                                                                                 
    |   3 |    NESTED LOOPS                    |                       |     1 |   485 |    28   (8)| 00:00:01 |                                                                                                                                                                                                 
    |   4 |     VIEW                           | VW_NSO_1              |     1 |   352 |    24   (9)| 00:00:01 |                                                                                                                                                                                                 
    |   5 |      MINUS                         |                       |       |       |            |          |                                                                                                                                                                                                 
    |   6 |       SORT UNIQUE                  |                       |     1 |   139 |            |          |                                                                                                                                                                                                 
    |   7 |        INLIST ITERATOR             |                       |       |       |            |          |                                                                                                                                                                                                 
    |*  8 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS           |     1 |   139 |    11   (0)| 00:00:01 |                                                                                                                                                                                                 
    |*  9 |          INDEX RANGE SCAN          | M_APPLIED_PATH_HT_IDX |    11 |       |     9   (0)| 00:00:01 |                                                                                                                                                                                                 
    |  10 |       SORT UNIQUE                  |                       |     1 |   136 |            |          |                                                                                                                                                                                                 
    |  11 |        INLIST ITERATOR             |                       |       |       |            |          |                                                                                                                                                                                                 
    |* 12 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS           |     1 |   136 |    11   (0)| 00:00:01 |                                                                                                                                                                                                 
    |* 13 |          INDEX RANGE SCAN          | M_APPLIED_PATH_HT_IDX |    11 |       |     9   (0)| 00:00:01 |                                                                                                                                                                                                 
    |* 14 |     INDEX RANGE SCAN               | M_FULLNAME_HT_IDX     |     1 |       |     3   (0)| 00:00:01 |                                                                                                                                                                                                 
    |* 15 |    TABLE ACCESS BY INDEX ROWID     | HERON_TERMS           |     1 |   133 |     4   (0)| 00:00:01 |                                                                                                                                                                                                 
    ------------------------------------------------------------------------------------------------------------      
    

Then gathering stats again...

begin 
  	  	DBMS_STATS.GATHER_TABLE_STATS (
  	  	  ownname => '"REDCAPMETADATA10"',
          tabname => '"HERON_TERMS"',
          estimate_percent => 5
          );
          end;
PLAN_TABLE_OUTPUT                                                                                                                                                                                                                                                                                            
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ 
Plan hash value: 2171854115                                                                                                                                                                                                                                                                                  
                                                                                                                                                                                                                                                                                                             
------------------------------------------------------------------------------------------------------------                                                                                                                                                                                                 
| Id  | Operation                          | Name                  | Rows  | Bytes | Cost (%CPU)| Time     |                                                                                                                                                                                                 
------------------------------------------------------------------------------------------------------------                                                                                                                                                                                                 
|   0 | SELECT STATEMENT                   |                       |     1 |   486 |    38   (6)| 00:00:01 |                                                                                                                                                                                                 
|   1 |  SORT AGGREGATE                    |                       |     1 |   486 |            |          |                                                                                                                                                                                                 
|   2 |   NESTED LOOPS                     |                       |       |       |            |          |                                                                                                                                                                                                 
|   3 |    NESTED LOOPS                    |                       |     1 |   486 |    38   (6)| 00:00:01 |                                                                                                                                                                                                 
|   4 |     VIEW                           | VW_NSO_1              |     1 |   352 |    34   (6)| 00:00:01 |                                                                                                                                                                                                 
|   5 |      MINUS                         |                       |       |       |            |          |                                                                                                                                                                                                 
|   6 |       SORT UNIQUE                  |                       |     1 |   140 |            |          |                                                                                                                                                                                                 
|   7 |        INLIST ITERATOR             |                       |       |       |            |          |                                                                                                                                                                                                 
|*  8 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS           |     1 |   140 |    16   (0)| 00:00:01 |                                                                                                                                                                                                 
|*  9 |          INDEX RANGE SCAN          | M_APPLIED_PATH_HT_IDX |    70 |       |     9   (0)| 00:00:01 |                                                                                                                                                                                                 
|  10 |       SORT UNIQUE                  |                       |     1 |   137 |            |          |                                                                                                                                                                                                 
|  11 |        INLIST ITERATOR             |                       |       |       |            |          |                                                                                                                                                                                                 
|* 12 |         TABLE ACCESS BY INDEX ROWID| HERON_TERMS           |     1 |   137 |    16   (0)| 00:00:01 |                                                                                                                                                                                                 
|* 13 |          INDEX RANGE SCAN          | M_APPLIED_PATH_HT_IDX |    70 |       |     9   (0)| 00:00:01 |                                                                                                                                                                                                 
|* 14 |     INDEX RANGE SCAN               | M_FULLNAME_HT_IDX     |     1 |       |     3   (0)| 00:00:01 |                                                                                                                                                                                                 
|* 15 |    TABLE ACCESS BY INDEX ROWID     | HERON_TERMS           |     1 |   134 |     4   (0)| 00:00:01 |                                                                                                                                                                                                 
------------------------------------------------------------------------------------------------------------ 

The plans don't differ, but the queries seem faster.

  1. Looking at using synonyms:
    • Are private synonyms bad for performance? (for older versions of Oracle)
    • Looking at it on prod deid: Opening MR ORDERABLES TOOK 2013-12-04 15:55:09,741 to 2013-12-04 15:56:56,142
    • Then ran the following
        drop table redcapmetadata10.heron_terms;
       
        create synonym redcapmetadata10.heron_terms
        for blueheronmetadata.heron_terms;
      
        grant select on blueheronmetadata.heron_terms
        to redcapmetadata10;
      
  • Then opened the MR ORDERABLES folder from front end. It was lightning quick.

Next step: Change create_redcap_projects to reflect this.

comment:13 Changed 8 years ago by badagarla

Replacing copies of heron_terms with synonyms under redcapmetadata schemas : 99bc972e097a

Testing:

  • We tested the fact that synonyms lead to faster browsing experience. (comment:12 bullet 3)
  • Confirmed with Nathan that this is enough testing.

Assigning it to Nathan for review.

comment:14 Changed 8 years ago by ngraham

Looks good to me. Bhargav and I talked about this we're happy to run this against production during the next ETL. The create_redcap_projects task is easy to re-run if we find a problem and need to change something.

comment:15 Changed 8 years ago by badagarla

Resolution: fixed
Status: assignedclosed

Merged into default b193fea5f279

comment:16 Changed 8 years ago by ngraham

Keywords: public-web added
Sensitive: unset
Note: See TracTickets for help on using tickets.