Regexp hungry for CPU? Real time sql monitoring shows just how

Not exactly a snappy blog post title…

First up, an execution plan showing the old problem of how the costs of a scalar subquery are not properly accounted for, even in the latest 11gR2 releases.

The SQL looks something like this:

INSERT...
SELECT ...
,      (SELECT to_some_object(....) 
        FROM   XXX,YYY ... 
        WHERE  ...
        AND    INSTR(outer.something,YYY.something) >0
FROM   <outer>

The execution plan like so:

------------------------------------------------------------------------------------
| Id  | Operation                | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT         |         |     1 |   173 |   827K  (1)| 01:08:59 |
|   1 |  LOAD TABLE CONVENTIONAL | ABC     |       |       |            |          |
|*  2 |   COUNT STOPKEY          |         |       |       |            |          |
|   3 |    NESTED LOOPS          |         |     1 |    45 |    12   (0)| 00:00:01 |
|*  4 |     TABLE ACCESS FULL    | XXX     | 37535 |   879K|     2   (0)| 00:00:01 |
|   5 |     INLIST ITERATOR      |         |       |       |            |          |
|*  6 |      INDEX RANGE SCAN    | YYY_IDX |     1 |    21 |     5   (0)| 00:00:01 |
|   7 |   NESTED LOOPS           |         |       |       |            |          |
...................
                   
Predicate Information (identified by operation id):
---------------------------------------------------
                                                   
   2 - filter(ROWNUM=1)                            
   4 - filter(INSTR(:B1,"XXX"."INST_USER_CODE")<>0 AND "XXX"."INST_TYPE_CODE"='BOND' 
              AND "XXX"."ACTIVE_FLAG"='Y')
   6 - access(("YYY"."XCOD_CODE"='ACON' OR "YYY"."XCOD_CODE"='CUSP' 
               OR "YYY"."XCOD_CODE"='ISIN' OR "YYY"."XCOD_CODE"='SEDL') 
               AND "YYY"."INST_NUM"="XXX"."INST_NUM" 
               AND "YYY"."INST_CODE"="XXX"."INST_USER_CODE")
..................

There are two problems with a scalar subselect:
1. As mentioned, the costs are not properly accounted for and
2. The scalar subselect gives the optimizer no chance to unnest the subquery so for the FULL table scan, this could be really problematic.

But it’s only after a change from INSTR to a regular expression that we see:
1. Just how expensive this lack of an unnest might be and
2. Just how cpu hungry regular expressions can be.

Using real time sql monitoring to demonstrate… (I’ve had to brutally cut out the extra columns to keep the width within the boundaries of this layour)

Original with INSTR:

SQL ID                                 :  a85q079dshta4                   
Duration                               :  92s                             

Global Stats
====================================================
| Elapsed |   Cpu   |    IO    |  Other   | Buffer |
| Time(s) | Time(s) | Waits(s) | Waits(s) |  Gets  |
====================================================
|      92 |      92 |     0.22 |     0.02 |    12M |
====================================================

================================================================================================
| Id |      Operation            |  Name   |  Time   | Execs |  Rows  |Activity|Activity Detail|
|    |                           |         |Active(s)|       |(Actual)|  (%)   |  (# samples)  |
================================================================================================
|  0 | INSERT STATEMENT          |         |         |     1 |        |        |               |
|  1 |   LOAD TABLE CONVENTIONAL |         |      87 |     1 |      0 |        |               |
|  2 |    COUNT STOPKEY          |         |      87 |   480 |    480 |        |               |
|  3 |     NESTED LOOPS          |         |      87 |   480 |    480 |        |               |
|  4 |      TABLE ACCESS FULL    | XXX     |      91 |   480 |    542 |  97.83 | Cpu (90)      |
|  5 |      INLIST ITERATOR      |         |      87 |   542 |    480 |        |               |
|  6 |       INDEX RANGE SCAN    | YYY_IDX |      87 |  1671 |    480 |        |               |
|  7 |    NESTED LOOPS           |         |      87 |     1 |    481 |        |               |
...................

And then the modified version using regular expression (done to solve a problem with the original hence the very slight decrease in some of the rows in the rowsources)
Note:

  • SQL duration gone from 92 seconds to 2290 seconds
  • Both plans spend most of the time on Step 4
SQL ID                                 :  4d1yffvgrzyxv                   
Duration                               :  2302s                           

Global Stats
====================================================
| Elapsed |   Cpu   |    IO    |  Other   | Buffer |
| Time(s) | Time(s) | Waits(s) | Waits(s) |  Gets  |
====================================================
|    2302 |    2299 |     2.56 |     0.40 |    12M |
====================================================

================================================================================================
| Id |      Operation            |  Name   |  Time   | Execs |  Rows  |Activity|Activity Detail|
|    |                           |         |Active(s)|       |(Actual)|  (%)   |  (# samples)  |
================================================================================================
|  0 | INSERT STATEMENT          |         |         |     1 |        |        |               |
|  1 |   LOAD TABLE CONVENTIONAL |         |    2297 |     1 |      0 |        |               |
|  2 |    COUNT STOPKEY          |         |    2297 |   480 |    480 |        |               |
|  3 |     NESTED LOOPS          |         |    2297 |   480 |    480 |        |               |
|  4 |      TABLE ACCESS FULL    | XXX     |    2301 |   480 |    541 |  99.74 | Cpu (2290)    |
|  5 |      INLIST ITERATOR      |         |    2297 |   541 |    480 |        |               |
|  6 |       INDEX RANGE SCAN    | YYY_IDX |    2297 |  1666 |    480 |        |               |
|  7 |    NESTED LOOPS           |         |    2297 |     1 |    481 |        |               |
...................

I love real time sql monitoring, just wish the output included the predicates section of the execution plan.

About these ads

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

Follow

Get every new post delivered to your Inbox.

Join 70 other followers

%d bloggers like this: