Regexp hungry for CPU? Real time sql monitoring shows just how
May 9, 2012 Leave a comment
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.
Recent Comments