Mohamed Houri’s Oracle Notes

August 19, 2020

A 2 min tuning case

Filed under: Oracle — hourim @ 1:20 pm

Here’s a practical performance troubleshooting case which took me a couple of minutes to fix but about one hour to write down 😊. It comes via an end user complaint about a load process (insert/select) triggered by Oracle Warehouse Builder(OWB) which was running since the last 3 days. When the on-call DBA handled this request to me, he said that he has already run a SQL tuning advisor and he was still unable to find the root cause of this performance degradation. Before I started the investigation I already knew what was happening in this case. Indeed, almost always, if a query lasts a couple of days without erroring out, then there is a big chance that a NESTED LOOPS is certainly for something in this delay. And, in this case, the CBO would have probably messed up its cardinality estimation by opting for the wrong JOIN method. That is why, based upon the DBA explanation, I have had, already, in my mind that this ETL load process is suffering from a lack of table/index/column statistics

Anyway, below is exactly the steps I followed to fix this issue

-- Get the SQL_ID of the running process
SQL> select sql_id, sql_exec_id from gv$sql_monitor where status = 'EXECUTING';

Hopefully, there was only a single SQL_ID in an EXECUTION phase.

-- Get the corresponding SQL Monitoring report
SQL> SELECT DBMS_SQLTUNE.report_sql_monitor(
  		sql_id       => ' bsgj02zjrfdbj',
  		type         => 'TEXT',
  		report_level => 'ALL') AS report
FROM dual;

Global Information
------------------------------
 Status                                 :  EXECUTING           
 Instance ID                            :  1                   
 Session                                :  XYZDATA (245:14813) 
 SQL ID                                 :  bsgj02zjrfdbj       
 SQL Execution ID                       :  16777227            
 Execution Started                      :  10/31/2019 14:26:21 
 First Refresh Time                     :  10/31/2019 14:26:33 
 Last Refresh Time                      :  11/04/2019 10:56:29 
 Duration                               :  333009s             
 Module/Action                          :  CCC_CCS/EXECUTION   
 Service                                :  MYAPL_1             
 Program                                :  JDBC Thin Client    
 PLSQL Entry Ids (Object/Subprogram)    :  10328167,7          
 PLSQL Current Ids (Object/Subprogram)  :  10328167,7          

Global Stats
======================================================================
| Elapsed |   Cpu   |    IO    | Concurrency | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Gets  | Reqs | Bytes |
======================================================================
|  553389 |  329894 |   223477 |          18 |     4G |   4G | 104TB |
======================================================================

SQL Plan Monitoring Details (Plan Hash Value=2281702856)

================================================================================================
| Id   |               Operation                |      Name       |  Rows   | Execs |   Rows   |
|      |                                        |                 | (Estim) |       | (Actual) |
================================================================================================
|    0 | INSERT STATEMENT                       |                 |         |     1 |          |
|    1 |   LOAD TABLE CONVENTIONAL              |                 |         |     1 |        0 |
|      |                                        |                 |         |       |          |
|    2 |    NESTED LOOPS OUTER                  |                 |      2M |     1 |    19932 |
|    3 |     PARTITION LIST OR                  |                 |      2M |     1 |    19932 |
| -> 4 |      TABLE ACCESS FULL                 | TT_XYZ_BAE      |      2M |     1 |    19932 |
|    5 |     PARTITION RANGE ITERATOR           |                 |       1 | 19932 |    19932 |
|    6 |      TABLE ACCESS BY LOCAL INDEX ROWID | T1_TAB          |       1 | 19932 |    19932 |
|      |                                        |                 |         |       |          |
|      |                                        |                 |         |       |          |
| -> 7 |       BITMAP CONVERSION TO ROWIDS      |                 |         | 19932 |       4G |
| -> 8 |        BITMAP INDEX SINGLE VALUE       | XY99_T1_TAB_BRI |         | 19932 |       1M |
|      |                                        |                 |         |       |          |
================================================================================================

As I’ve expected, there is a NESTED LOOPS operation in the mix(operation Id n°2). In addition, the cardinality estimation of 1 at line operation 6 is almost always an indication of a wrong estimation done by the CBO. Add to this the 4G rows generated when visiting the XY99_T1_TAB_BRI bitmap index and you end up by suspecting a statistic issue with the T1_TAB table.

So, the next immediate step I did was to check the statistics of the T1_TAB table and the XY99_T1_TAB_BRI bitmap index :

SQL> @GetPartTab
Enter value for owner: XYZDATA
Enter value for table_name: T1_TAB

TABLE_NAME   PNAME                PPOS   NUM_ROWS TABLESPACE_NAME  LAST_ANAL
------------ ------------------ ------ ---------- ---------------- -------------------
T1_TAB       P_T1_TAB_200001         1          0 XY99_TBS_DONN    26/10/2019 15:26:55
T1_TAB       P_T1_TAB_201708         2    3934618 XY99_TBS_DONN    26/10/2019 15:21:50
T1_TAB       P_T1_TAB_201709         3    3948128 XY99_TBS_DONN    26/10/2019 14:35:11
T1_TAB       P_T1_TAB_201710         4    4078620 XY99_TBS_DONN    26/10/2019 13:47:20
T1_TAB       P_T1_TAB_201711         5    4093099 XY99_TBS_DONN    26/10/2019 12:52:13
T1_TAB       P_T1_TAB_201712         6    4059354 XY99_TBS_DONN    26/10/2019 11:53:52
T1_TAB       P_T1_TAB_201801         7    4080096 XY99_TBS_DONN    26/10/2019 10:58:33
T1_TAB       P_T1_TAB_201802         8    4096904 XY99_TBS_DONN    26/10/2019 09:58:16
T1_TAB       P_T1_TAB_201803         9    4115548 XY99_TBS_DONN    26/10/2019 08:59:04
T1_TAB       P_T1_TAB_201804        10    4175894 XY99_TBS_DONN    26/10/2019 07:54:15
T1_TAB       P_T1_TAB_201805        11    4187923 XY99_TBS_DONN    26/10/2019 07:05:42
T1_TAB       P_T1_TAB_201806        12    4224300 XY99_TBS_DONN    26/10/2019 06:21:28
T1_TAB       P_T1_TAB_201807        13    4233116 XY99_TBS_DONN    26/10/2019 05:30:46
T1_TAB       P_T1_TAB_201808        14    4242821 XY99_TBS_DONN    26/10/2019 04:42:50
T1_TAB       P_T1_TAB_201809        15    4291935 XY99_TBS_DONN    26/10/2019 03:49:06
T1_TAB       P_T1_TAB_201810        16    2596486 XY99_TBS_DONN    26/10/2019 02:57:36
T1_TAB       P_T1_TAB_201811        17    4305042 XY99_TBS_DONN    26/10/2019 02:08:20
T1_TAB       P_T1_TAB_201812        18    4314987 XY99_TBS_DONN    26/10/2019 01:12:00
T1_TAB       P_T1_TAB_201901        19    4333586 XY99_TBS_DONN    26/10/2019 00:21:52
T1_TAB       P_T1_TAB_201902        20    4428940 XY99_TBS_DONN    25/10/2019 23:22:28
T1_TAB       P_T1_TAB_201903        21    4493339 XY99_TBS_DONN    25/10/2019 22:17:44
T1_TAB       P_T1_TAB_201904        22    4420400 XY99_TBS_DONN    25/10/2019 20:54:34
T1_TAB       P_T1_TAB_201905        23    4408412 XY99_TBS_DONN    25/10/2019 19:43:10
T1_TAB       P_T1_TAB_201906        24    4277786 XY99_TBS_DONN    25/10/2019 18:49:03
T1_TAB       P_T1_TAB_201907        25    4250320 XY99_TBS_DONN    25/10/2019 17:39:26
T1_TAB       P_T1_TAB_201908        26          0 XY99_TBS_DONN    25/10/2019 16:53:29  --> looks suspicious
                                       ----------
Total num_rows                         99591654

SQL> @GetPartInd
Enter value for owner: XYZDATA
Enter value for index_name: XY99_T1_TAB_BRI

INDEX_NAME        PNAME              PPOS   NUM_ROWS TABLESPACE_NAME LAST_ANAL
----------------- ---------------- ------ ---------- --------------- -------------------
XY99_T1_TAB_BRI   P_T1_TAB_200001       1          0 XY99_TBS_INDX   26/10/2019 15:26:56
XY99_T1_TAB_BRI   P_T1_TAB_201708       2         67 XY99_TBS_INDX   26/10/2019 15:22:13
XY99_T1_TAB_BRI   P_T1_TAB_201709       3         64 XY99_TBS_INDX   26/10/2019 14:35:34
XY99_T1_TAB_BRI   P_T1_TAB_201710       4         66 XY99_TBS_INDX   26/10/2019 13:47:40
XY99_T1_TAB_BRI   P_T1_TAB_201711       5         67 XY99_TBS_INDX   26/10/2019 12:52:32
XY99_T1_TAB_BRI   P_T1_TAB_201712       6         66 XY99_TBS_INDX   26/10/2019 11:54:15
XY99_T1_TAB_BRI   P_T1_TAB_201801       7         66 XY99_TBS_INDX   26/10/2019 10:58:57
XY99_T1_TAB_BRI   P_T1_TAB_201802       8         67 XY99_TBS_INDX   26/10/2019 09:58:44
XY99_T1_TAB_BRI   P_T1_TAB_201803       9         67 XY99_TBS_INDX   26/10/2019 08:59:31
XY99_T1_TAB_BRI   P_T1_TAB_201804      10         68 XY99_TBS_INDX   26/10/2019 07:54:36
XY99_T1_TAB_BRI   P_T1_TAB_201805      11         68 XY99_TBS_INDX   26/10/2019 07:06:05
XY99_T1_TAB_BRI   P_T1_TAB_201806      12         69 XY99_TBS_INDX   26/10/2019 06:21:52
XY99_T1_TAB_BRI   P_T1_TAB_201807      13         69 XY99_TBS_INDX   26/10/2019 05:31:09
XY99_T1_TAB_BRI   P_T1_TAB_201808      14         69 XY99_TBS_INDX   26/10/2019 04:43:13
XY99_T1_TAB_BRI   P_T1_TAB_201809      15         72 XY99_TBS_INDX   26/10/2019 03:49:29
XY99_T1_TAB_BRI   P_T1_TAB_201810      16        200 XY99_TBS_INDX   26/10/2019 02:57:51
XY99_T1_TAB_BRI   P_T1_TAB_201811      17         70 XY99_TBS_INDX   26/10/2019 02:08:46
XY99_T1_TAB_BRI   P_T1_TAB_201812      18         70 XY99_TBS_INDX   26/10/2019 01:12:25
XY99_T1_TAB_BRI   P_T1_TAB_201901      19         70 XY99_TBS_INDX   26/10/2019 00:22:16
XY99_T1_TAB_BRI   P_T1_TAB_201902      20         72 XY99_TBS_INDX   25/10/2019 23:22:55
XY99_T1_TAB_BRI   P_T1_TAB_201903      21         73 XY99_TBS_INDX   25/10/2019 22:18:13
XY99_T1_TAB_BRI   P_T1_TAB_201904      22         72 XY99_TBS_INDX   25/10/2019 20:55:06
XY99_T1_TAB_BRI   P_T1_TAB_201905      23         72 XY99_TBS_INDX   25/10/2019 19:43:34
XY99_T1_TAB_BRI   P_T1_TAB_201906      24         70 XY99_TBS_INDX   25/10/2019 18:49:27
XY99_T1_TAB_BRI   P_T1_TAB_201907      25         70 XY99_TBS_INDX   25/10/2019 17:39:51
XY99_T1_TAB_BRI   P_T1_TAB_201908      26          0 XY99_TBS_INDX   25/10/2019 16:53:31 --> looks suspicious
                                          ----------
Total num_rows                                  1784

The 26th partition looks suspicious. For the sake of simplicity and quick fix, I asked the end user whether their process deals with the last created partition? and the answer was YES.

Then, I killed the session, gathered the statistics, and asked the end-user to relaunch the process

SQL> @GetPartTab
Enter value for owner: XYZDATA
Enter value for table_name: T1_TAB

TABLE_NAME    PNAME               PPOS   NUM_ROWS TABLESPACE_NAME  LAST_ANAL
------------- ----------------- ------ ---------- ---------------- -------------------
T1_TAB        P_T1_TAB_200001        1          0 XY99_TBS_DONN    26/10/2019 15:26:55
T1_TAB        P_T1_TAB_201708        2    3934618 XY99_TBS_DONN    26/10/2019 15:21:50
T1_TAB        P_T1_TAB_201709        3    3948128 XY99_TBS_DONN    26/10/2019 14:35:11
T1_TAB        P_T1_TAB_201710        4    4078620 XY99_TBS_DONN    26/10/2019 13:47:20
T1_TAB        P_T1_TAB_201711        5    4093099 XY99_TBS_DONN    26/10/2019 12:52:13
T1_TAB        P_T1_TAB_201712        6    4059354 XY99_TBS_DONN    26/10/2019 11:53:52
T1_TAB        P_T1_TAB_201801        7    4080096 XY99_TBS_DONN    26/10/2019 10:58:33
T1_TAB        P_T1_TAB_201802        8    4096904 XY99_TBS_DONN    26/10/2019 09:58:16
T1_TAB        P_T1_TAB_201803        9    4115548 XY99_TBS_DONN    26/10/2019 08:59:04
T1_TAB        P_T1_TAB_201804       10    4175894 XY99_TBS_DONN    26/10/2019 07:54:15
T1_TAB        P_T1_TAB_201805       11    4187923 XY99_TBS_DONN    26/10/2019 07:05:42
T1_TAB        P_T1_TAB_201806       12    4224300 XY99_TBS_DONN    26/10/2019 06:21:28
T1_TAB        P_T1_TAB_201807       13    4233116 XY99_TBS_DONN    26/10/2019 05:30:46
T1_TAB        P_T1_TAB_201808       14    4242821 XY99_TBS_DONN    26/10/2019 04:42:50
T1_TAB        P_T1_TAB_201809       15    4291935 XY99_TBS_DONN    26/10/2019 03:49:06
T1_TAB        P_T1_TAB_201810       16    2596486 XY99_TBS_DONN    26/10/2019 02:57:36
T1_TAB        P_T1_TAB_201811       17    4305042 XY99_TBS_DONN    26/10/2019 02:08:20
T1_TAB        P_T1_TAB_201812       18    4314987 XY99_TBS_DONN    26/10/2019 01:12:00
T1_TAB        P_T1_TAB_201901       19    4333586 XY99_TBS_DONN    26/10/2019 00:21:52
T1_TAB        P_T1_TAB_201902       20    4428940 XY99_TBS_DONN    25/10/2019 23:22:28
T1_TAB        P_T1_TAB_201903       21    4493339 XY99_TBS_DONN    25/10/2019 22:17:44
T1_TAB        P_T1_TAB_201904       22    4420400 XY99_TBS_DONN    25/10/2019 20:54:34
T1_TAB        P_T1_TAB_201905       23    4408412 XY99_TBS_DONN    25/10/2019 19:43:10
T1_TAB        P_T1_TAB_201906       24    4277786 XY99_TBS_DONN    25/10/2019 18:49:03
T1_TAB        P_T1_TAB_201907       25    4250320 XY99_TBS_DONN    25/10/2019 17:39:26
T1_TAB        P_T1_TAB_201908       26    4185925 XY99_TBS_DONN    04/11/2019 18:51:48
                                       ----------                  
Total num_rows                         103777579                   


SQL> @getPartInd
Enter value for owner: XYZDATA
Enter value for index_name: XY99_T1_TAB_BRI

INDEX_NAME        PNAME               PPOS   NUM_ROWS TABLESPACE_NAME   LAST_ANAL
----------------- ----------------- ------ ---------- ----------------- -------------------
XY99_T1_TAB_BRI   P_T1_TAB_200001        1          0 XY99_TBS_INDX     26/10/2019 15:26:56
XY99_T1_TAB_BRI   P_T1_TAB_201708        2         67 XY99_TBS_INDX     26/10/2019 15:22:13
XY99_T1_TAB_BRI   P_T1_TAB_201709        3         64 XY99_TBS_INDX     26/10/2019 14:35:34
XY99_T1_TAB_BRI   P_T1_TAB_201710        4         66 XY99_TBS_INDX     26/10/2019 13:47:40
XY99_T1_TAB_BRI   P_T1_TAB_201711        5         67 XY99_TBS_INDX     26/10/2019 12:52:32
XY99_T1_TAB_BRI   P_T1_TAB_201712        6         66 XY99_TBS_INDX     26/10/2019 11:54:15
XY99_T1_TAB_BRI   P_T1_TAB_201801        7         66 XY99_TBS_INDX     26/10/2019 10:58:57
XY99_T1_TAB_BRI   P_T1_TAB_201802        8         67 XY99_TBS_INDX     26/10/2019 09:58:44
XY99_T1_TAB_BRI   P_T1_TAB_201803        9         67 XY99_TBS_INDX     26/10/2019 08:59:31
XY99_T1_TAB_BRI   P_T1_TAB_201804       10         68 XY99_TBS_INDX     26/10/2019 07:54:36
XY99_T1_TAB_BRI   P_T1_TAB_201805       11         68 XY99_TBS_INDX     26/10/2019 07:06:05
XY99_T1_TAB_BRI   P_T1_TAB_201806       12         69 XY99_TBS_INDX     26/10/2019 06:21:52
XY99_T1_TAB_BRI   P_T1_TAB_201807       13         69 XY99_TBS_INDX     26/10/2019 05:31:09
XY99_T1_TAB_BRI   P_T1_TAB_201808       14         69 XY99_TBS_INDX     26/10/2019 04:43:13
XY99_T1_TAB_BRI   P_T1_TAB_201809       15         72 XY99_TBS_INDX     26/10/2019 03:49:29
XY99_T1_TAB_BRI   P_T1_TAB_201810       16        200 XY99_TBS_INDX     26/10/2019 02:57:51
XY99_T1_TAB_BRI   P_T1_TAB_201811       17         70 XY99_TBS_INDX     26/10/2019 02:08:46
XY99_T1_TAB_BRI   P_T1_TAB_201812       18         70 XY99_TBS_INDX     26/10/2019 01:12:25
XY99_T1_TAB_BRI   P_T1_TAB_201901       19         70 XY99_TBS_INDX     26/10/2019 00:22:16
XY99_T1_TAB_BRI   P_T1_TAB_201902       20         72 XY99_TBS_INDX     25/10/2019 23:22:55
XY99_T1_TAB_BRI   P_T1_TAB_201903       21         73 XY99_TBS_INDX     25/10/2019 22:18:13
XY99_T1_TAB_BRI   P_T1_TAB_201904       22         72 XY99_TBS_INDX     25/10/2019 20:55:06
XY99_T1_TAB_BRI   P_T1_TAB_201905       23         72 XY99_TBS_INDX     25/10/2019 19:43:34
XY99_T1_TAB_BRI   P_T1_TAB_201906       24         70 XY99_TBS_INDX     25/10/2019 18:49:27
XY99_T1_TAB_BRI   P_T1_TAB_201907       25         70 XY99_TBS_INDX     25/10/2019 17:39:51
XY99_T1_TAB_BRI   P_T1_TAB_201908       26         68 XY99_TBS_INDX     04/11/2019 18:52:14
                                           ----------
Total num_rows                                   1852

When this insert/select has been relaunched it has completed in less than one hour as shown by the corresponding SQL monitoring report:

Global Information
------------------------------
 Status                                 :  EXECUTING           
 Instance ID                            :  1                   
 Session                                :  XYZDATA (245:14813) 
 SQL ID                                 :  bsgj02zjrfdbj       
 SQL Execution ID                       :  16777216           
 Execution Started                      :  11/05/2019 10:02:17
 First Refresh Time                     :  11/05/2019 10:02:24
 Last Refresh Time                      :  11/05/2019 11:00:03
 Duration                               :  3466s     -------------------> The new execution time        
 Module/Action                          :  CCC_CCS/EXECUTION   
 Service                                :  MYAPL_1             
 Program                                :  JDBC Thin Client    
 PLSQL Entry Ids (Object/Subprogram)    :  10328167,7          
 PLSQL Current Ids (Object/Subprogram)  :  10328167,7          

-- The new execution plan
Global Stats
======================================================================
| Elapsed |   Cpu   |    IO    | Concurrency | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Gets  | Reqs | Bytes |
======================================================================
|  3766   |  607    |   3158   |         0.00|      5M|  219K|  142GB|
======================================================================

SQL Plan Monitoring Details (Plan Hash Value=2281702856)
================================================================================================
| Id   |               Operation                |      Name       |  Rows   | Execs |   Rows   |
|      |                                        |                 | (Estim) |       | (Actual) |
================================================================================================
|    0 | INSERT STATEMENT                       |                 |         |     1 |          |
|    1 |   LOAD TABLE CONVENTIONAL              |                 |         |     1 |          |
|    2 |    HASH JOIN OUTER                     |                 |      2M |     1 |        0 |
|    3 |     PARTITION LIST OR                  |                 |      2M |     1 |     971K |
|    4 |      TABLE ACCESS FULL                 | TT_XYZ_BAE      |      2M |     2 |     971K |
|    5 |     PARTITION RANGE ITERATOR           |                 |     104M|     1 |     100M |
|    6 |      TABLE ACCESS FULL                 | T1_TAB          |     104M|    26 |     100M |
================================================================================================

Bottom Line

This simple note shows how diagnosing and fixing a real-life performance issue can, sometimes, be accomplished in a couple of minutes (in this case the time fixing equals to the duration of the call to dbms_stats package). It will not be always as obvious as the current case tends to indicate but, I can say that I’ve very often spent more time answering, explaining, and writing on how I have fixed a performance issue than the time it took me to diagnose and fix this performance pain.

Leave a Comment »

No comments yet.

RSS feed for comments on this post. TrackBack URI

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 )

Google photo

You are commenting using your Google 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 )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Create a free website or blog at WordPress.com.

Tony's Oracle Tips

Tony Hasler's light hearted approach to learning about Oracle

Richard Foote's Oracle Blog

Focusing Specifically On Oracle Indexes, Database Administration and Some Great Music

Hatem Mahmoud Oracle's blog

Just another Oracle blog : Database topics and techniques

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Diagnostician

Performance troubleshooting as exact science

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

Oracle Scratchpad

Just another Oracle weblog

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)

%d bloggers like this: