Database Administration Tips: Using RULE Based Optimizer When Querying GV$ Views

I had a complaint from one of the readers that dbalarm script for monitoring the DB is taking very long time to run against one RAC DB [11.2.0.3] especially in the part of reporting locked sessions on the database, when I dug deeper found that most of time is getting consumed by this statement:

select
substr(s.INST_ID||'|'||s.OSUSER||'/'||s.USERNAME||'| '||s.sid||','||s.serial#||' |'||substr(s.MACHINE,1,22)||'|'||substr(s.MODULE,1,18),1,75)"I|OS/DB USER|SID,SER|MACHN|MOD"
,substr(s.status||'|'||round(w.WAIT_TIME_MICRO/1000000)||'|'||LAST_CALL_ET||'|'||to_char(LOGON_TIME,'ddMon HH24:MI'),1,34) "ST|WAITD|ACT_SINC|LOGIN"
,substr(w.event,1,24) "EVENT"
,s.PREV_SQL_ID||'|'||s.SQL_ID||'|'||round(w.TIME_REMAINING_MICRO/1000000) "PREV|CURRENT_SQL|REMAIN_SEC"
from gv$session s, gv$session_wait w
where s.sid in (select distinct FINAL_BLOCKING_SESSION from gv$session where FINAL_BLOCKING_SESSION is not null)
and s.USERNAME is not null
and s.sid=w.sid
and s.FINAL_BLOCKING_SESSION is null
/

Elapsed: 00:00:11.34

Execution plan was showing this:

-------------------------------------------------------------------------------------------------------------------------------

-------------------------------------------------------------------------------------------------------------------------------

| 0 | SELECT STATEMENT | | 1 | 271 | 1 (100)| 00:00:01 | | | |

|* 1 | FILTER | | | | | | | | |

|* 2 | HASH JOIN | | 100 | 27100 | 1 (100)| 00:00:01 | | | |

| 3 | PX COORDINATOR | | 1 | 198 | 0 (0)| 00:00:01 | | | |

| 4 | PX SEND QC (RANDOM) | :TQ20000 | 1 | 270 | 0 (0)| 00:00:01 | Q2,00 | P->S | QC (RAND) |

| 6 | NESTED LOOPS | | 1 | 270 | 0 (0)| 00:00:01 | Q2,00 | PCWP | |

| 7 | NESTED LOOPS | | 1 | 257 | 0 (0)| 00:00:01 | Q2,00 | PCWP | |

|* 8 | FIXED TABLE FULL | X$KSUSE | 1 | 231 | 0 (0)| 00:00:01 | Q2,00 | PCWP | |

|* 9 | FIXED TABLE FIXED INDEX| X$KSLWT (ind:1) | 1 | 26 | 0 (0)| 00:00:01 | Q2,00 | PCWP | |

|* 10 | FIXED TABLE FIXED INDEX | X$KSLED (ind:2) | 1 | 13 | 0 (0)| 00:00:01 | Q2,00 | PCWP | |

| 11 | PX COORDINATOR | | 100 | 7300 | 0 (0)| 00:00:01 | | | |

| 12 | PX SEND QC (RANDOM) | :TQ30000 | 100 | 12500 | 0 (0)| 00:00:01 | Q3,00 | P->S | QC (RAND) |

| 14 | NESTED LOOPS | | 100 | 12500 | 0 (0)| 00:00:01 | Q3,00 | PCWP | |

| 15 | FIXED TABLE FULL | X$KSLWT | 100 | 7800 | 0 (0)| 00:00:01 | Q3,00 | PCWP | |

|* 16 | FIXED TABLE FIXED INDEX | X$KSLED (ind:2) | 1 | 47 | 0 (0)| 00:00:01 | Q3,00 | PCWP | |

| 17 | PX COORDINATOR | | 1 | 13 | 0 (0)| 00:00:01 | | | |

| 18 | PX SEND QC (RANDOM) | :TQ10000 | 1 | 91 | 0 (0)| 00:00:01 | Q1,00 | P->S | QC (RAND) |

| 20 | NESTED LOOPS | | 1 | 91 | 0 (0)| 00:00:01 | Q1,00 | PCWP | |

| 21 | NESTED LOOPS | | 1 | 78 | 0 (0)| 00:00:01 | Q1,00 | PCWP | |

|* 22 | FIXED TABLE FULL | X$KSUSE | 1 | 52 | 0 (0)| 00:00:01 | Q1,00 | PCWP | |

|* 23 | FIXED TABLE FIXED INDEX | X$KSLWT (ind:1) | 1 | 26 | 0 (0)| 00:00:01 | Q1,00 | PCWP | |

|* 24 | FIXED TABLE FIXED INDEX | X$KSLED (ind:2) | 1 | 13 | 0 (0)| 00:00:01 | Q1,00 | PCWP | |

-------------------------------------------------------------------------------------------------------------------------------

When traced the session found the following in the trace:

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 FILTER (cr=0 pr=0 pw=0 time=11647894 us)
2818 2818 2818 HASH JOIN (cr=0 pr=0 pw=0 time=74814 us cost=1 size=27100 card=100)
1875 1875 1875 PX COORDINATOR (cr=0 pr=0 pw=0 time=35972 us cost=0 size=198 card=1)
0 0 0 PX SEND QC (RANDOM) :TQ20000 (cr=0 pr=0 pw=0 time=0 us cost=0 size=270 card=1)
0 0 0 VIEW GV$SESSION (cr=0 pr=0 pw=0 time=0 us)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=0 size=270 card=1)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=0 size=257 card=1)
0 0 0 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=0 us cost=0 size=231 card=1)
0 0 0 FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1)
0 0 0 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=13 card=1)
2018 2018 2018 PX COORDINATOR (cr=0 pr=0 pw=0 time=5021 us cost=0 size=7300 card=100)
0 0 0 PX SEND QC (RANDOM) :TQ30000 (cr=0 pr=0 pw=0 time=0 us cost=0 size=12500 card=100)
0 0 0 VIEW GV$SESSION_WAIT (cr=0 pr=0 pw=0 time=0 us)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=0 size=12500 card=100)
0 0 0 FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us cost=0 size=7800 card=100)
0 0 0 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=47 card=1)
0 0 0 PX COORDINATOR (cr=0 pr=0 pw=0 time=11562142 us cost=0 size=13 card=1)
0 0 0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=7157212 us cost=0 size=91 card=1)
0 0 0 VIEW GV$SESSION (cr=0 pr=0 pw=0 time=7156047 us)
1488896 1488896 1488896 NESTED LOOPS (cr=0 pr=0 pw=0 time=6553126 us cost=0 size=91 card=1)
1488896 1488896 1488896 NESTED LOOPS (cr=0 pr=0 pw=0 time=5569809 us cost=0 size=78 card=1)
1488896 1488896 1488896 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=3967204 us cost=0 size=52 card=1)
1488896 1488896 1488896 FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=1142831 us cost=0 size=26 card=1)
1488896 1488896 1488896 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=567563 us cost=0 size=13 card=1)

Ok. Now I can see that most of the time is getting consumed on the fixed tables in red color.

Now, let's check executing the same statement but using RULE Based Optimizer (RBO) this time:

select /*+RULE*/

substr(s.INST_ID||'|'||s.OSUSER||'/'||s.USERNAME||'| '||s.sid||','||s.serial#||' |'||substr(s.MACHINE,1,22)||'|'||substr(s.MODULE,1,18),1,75)"I|OS/DB USER|SID,SER|MACHN|MOD"

,substr(s.status||'|'||round(w.WAIT_TIME_MICRO/1000000)||'|'||LAST_CALL_ET||'|'||to_char(LOGON_TIME,'ddMon HH24:MI'),1,34) "ST|WAITD|ACT_SINC|LOGIN"

,substr(w.event,1,24) "EVENT"

,s.PREV_SQL_ID||'|'||s.SQL_ID||'|'||round(w.TIME_REMAINING_MICRO/1000000) "PREV|CURRENT_SQL|REMAIN_SEC"

from gv$session s, gv$session_wait w

where s.sid in (select distinct FINAL_BLOCKING_SESSION from gv$session where FINAL_BLOCKING_SESSION is not null)

and s.USERNAME is not null

and s.sid=w.sid

and s.FINAL_BLOCKING_SESSION is null

Elapsed: 00:00:00.09

Wow, RULE Based Optimizer (RBO) runs the statement in 9 centiseconds much faster than CBO which ran it in 11 seconds. How this happened?

The following was the execution plan when using RBO

------------------------------------------------------------------------------------

------------------------------------------------------------------------------------

| 0 | SELECT STATEMENT | | | | |

| 1 | MERGE JOIN | | | | |

| 2 | MERGE JOIN | | | | |

| 3 | SORT JOIN | | | | |

| 4 | PX COORDINATOR | | | | |

| 5 | PX SEND QC (RANDOM) | :TQ10000 | Q1,00 | P->S | QC (RAND) |

| 7 | MERGE JOIN | | Q1,00 | PCWP | |

|* 9 | SORT JOIN | | Q1,00 | PCWP | |

|* 11 | SORT JOIN | | | | |

| 12 | PX COORDINATOR | | | | |

| 13 | PX SEND QC (RANDOM) | :TQ20000 | Q2,00 | P->S | QC (RAND) |

| 15 | MERGE JOIN | | Q2,00 | PCWP | |

| 16 | SORT JOIN | | Q2,00 | PCWP | |

| 17 | MERGE JOIN | | Q2,00 | PCWP | |

| 18 | SORT JOIN | | Q2,00 | PCWP | |

|* 20 | SORT JOIN | | Q2,00 | PCWP | |

|* 22 | SORT JOIN | | Q2,00 | PCWP | |

|* 24 | SORT JOIN | | | | |

| 26 | SORT UNIQUE | | | | |

| 27 | PX COORDINATOR | | | | |

| 28 | PX SEND QC (RANDOM) | :TQ30000 | Q3,00 | P->S | QC (RAND) |

| 30 | MERGE JOIN | | Q3,00 | PCWP | |

| 31 | SORT JOIN | | Q3,00 | PCWP | |

| 32 | MERGE JOIN | | Q3,00 | PCWP | |

| 33 | SORT JOIN | | Q3,00 | PCWP | |

|* 35 | SORT JOIN | | Q3,00 | PCWP | |

|* 37 | SORT JOIN | | Q3,00 | PCWP | |

------------------------------------------------------------------------------------

Checking the trace for the execution time when using RBO:

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 MERGE JOIN (cr=0 pr=0 pw=0 time=87623 us)
1 1 1 MERGE JOIN (cr=0 pr=0 pw=0 time=65256 us)
7 7 7 SORT JOIN (cr=0 pr=0 pw=0 time=23492 us)
2024 2024 2024 PX COORDINATOR (cr=0 pr=0 pw=0 time=14913 us)
0 0 0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us)
0 0 0 VIEW GV$SESSION_WAIT (cr=0 pr=0 pw=0 time=0 us)
0 0 0 MERGE JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSLED (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us)
1 1 1 SORT JOIN (cr=0 pr=0 pw=0 time=41766 us)
1877 1877 1877 PX COORDINATOR (cr=0 pr=0 pw=0 time=29246 us)
0 0 0 PX SEND QC (RANDOM) :TQ20000 (cr=0 pr=0 pw=0 time=0 us)
0 0 0 VIEW GV$SESSION (cr=0 pr=0 pw=0 time=0 us)
0 0 0 MERGE JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 MERGE JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSLED (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=22335 us)
0 0 0 VIEW VW_NSO_1 (cr=0 pr=0 pw=0 time=22327 us)
0 0 0 SORT UNIQUE (cr=0 pr=0 pw=0 time=22325 us)
0 0 0 PX COORDINATOR (cr=0 pr=0 pw=0 time=22293 us)
0 0 0 PX SEND QC (RANDOM) :TQ30000 (cr=0 pr=0 pw=0 time=0 us)
0 0 0 VIEW GV$SESSION (cr=0 pr=0 pw=0 time=0 us)
0 0 0 MERGE JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 MERGE JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSLED (cr=0 pr=0 pw=0 time=0 us)
0 0 0 SORT JOIN (cr=0 pr=0 pw=0 time=0 us)
0 0 0 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=0 us)

Querying fixed objects (X$KSLWT, X$KSLED, X$KSUSE) with RBO took less than second.

When tried to check the statistics date on referenced fixed objects found no statistics:

SQL> select OWNER, TABLE_NAME, LAST_ANALYZED from DBA_TAB_STATISTICS where TABLE_NAME in ('X$KSUSE','X$KSLWT','X$KSLED');

OWNER TABLE_NAME LAST_ANALYZED
------------------ ------------------------------ --------------------
SYS X$KSLED
SYS X$KSLWT
SYS X$KSUSE

OK, this may explain why CBO was producing a bad plan when querying those fixed objects. Statistics are the eyes of the CBO if they are not exist CBO will generate plans based on Dynamic Sampling which may generate inaccurate plans.

Now let's prove this by gathering fixed objects statistics while the DB is highly used in order to get accurate statistics on X$ tables representing the actual load:

Check this link to know more about Fixed Objects Statistics and how to gather:
http://dba-tips.blogspot.com/2012/11/all-about-statistics-in-oracle.html

SQL> exec dbms_stats.gather_fixed_objects_stats;

Let's check if the new Fixed Objects statistics will make the difference:

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 FILTER (cr=0 pr=0 pw=0 time=14075373 us)
3882 3882 3882 HASH JOIN (cr=0 pr=0 pw=0 time=104766 us cost=1 size=262 card=1)
2376 2376 2376 PX COORDINATOR (cr=0 pr=0 pw=0 time=54948 us cost=0 size=198 card=1)
0 0 0 PX SEND QC (RANDOM) :TQ20000 (cr=0 pr=0 pw=0 time=0 us cost=0 size=243 card=1)
0 0 0 VIEW GV$SESSION (cr=0 pr=0 pw=0 time=0 us)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=0 size=243 card=1)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=0 size=239 card=1)
0 0 0 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=0 us cost=0 size=231 card=1)
0 0 0 FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=8 card=1)
0 0 0 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)
2525 2525 2525 PX COORDINATOR (cr=0 pr=0 pw=0 time=8645 us cost=0 size=85376 card=1334)
0 0 0 PX SEND QC (RANDOM) :TQ30000 (cr=0 pr=0 pw=0 time=0 us cost=0 size=77372 card=1334)
0 0 0 VIEW GV$SESSION_WAIT (cr=0 pr=0 pw=0 time=0 us)
0 0 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=0 size=77372 card=1334)
0 0 0 FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us cost=0 size=37352 card=1334)
0 0 0 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=30 card=1)
0 0 0 PX COORDINATOR (cr=0 pr=0 pw=0 time=13959372 us cost=0 size=13 card=1)
0 0 0 PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=10443626 us cost=0 size=64 card=1)
0 0 0 VIEW GV$SESSION (cr=0 pr=0 pw=0 time=10442090 us)
2339876 2339876 2339876 NESTED LOOPS (cr=0 pr=0 pw=0 time=10767975 us cost=0 size=64 card=1)
2339876 2339876 2339876 NESTED LOOPS (cr=0 pr=0 pw=0 time=9109717 us cost=0 size=60 card=1)
2339876 2339876 2339876 FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=6389468 us cost=0 size=52 card=1)
2339876 2339876 2339876 FIXED TABLE FIXED INDEX X$KSLWT (ind:1) (cr=0 pr=0 pw=0 time=1872304 us cost=0 size=8 card=1)
2339876 2339876 2339876 FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=962703 us cost=0 size=4 card=1)

Theoretically, this is embarrassing :-) No big improvement after gathering statistics on fixed objects.
RULE Based Optimizer managed to beat CBO when querying V$ views at least in this scenario.

Conclusion:
- RULE Based Optimizer can produce better plans than CBO when querying V$/GV$ views.
- It's always recommended to have good statistics on fixed objects representing the real system load to help CBO produce good execution plans when V$ views are queried, this can also improve the performance of your monitoring tools, RMAN, Enterprise Manager performance as well as they are heavily dependant on querying V$/GV$ views.

Above experiment was done on 11.2.0.3 but I've experienced the same on 11.2.0.4 and 12c as well.

Update: I've opened an SR with Oracle Support to get an explanation for this behavior and after going through many actions plans they finally suggested to use RULE Based Optimizer.

Database Administration Tips

Tuesday, April 30, 2019

Using RULE Based Optimizer When Querying GV$ Views

No comments:

Post a Comment