Detail! And don’t forget the notes…
October 26, 2020 2 Comments
…and how sparse tables can mess up your dynamic sampling.
A little lesson to self about paying attention to the detail, the obvious frickin’ detail. Getting older and slower.
We had one of those problems where a multitude of things were slow and yet there were no significant system-level problems (e.g. no general slow IO, no setting of the fast=false parameter, etc)
In such situations, if you check the high level system level metrics – AWR etc – and nothing is obvious then it makes sense to narrow the scope & drill into a specific problem, and distill that problem/statement as small as you can. If you can find the issue there then you might hope to find that that is the same as the wider problem and if not well you can just take that approach to every individual area,
I had a problem across a number of reporting modules, I picked on one module and from there I picked on the statement which was currently running and which was running for much longer than expected, I picked out one of the obvious problem joins within the problem statement and started looking at a simple two table join where the cardinality estimates were going wrong.
Most of the specific details of this plan and SQL can be ignored. It’s not important.
What is important is the cardinality difference.
And in fact, in this particular cut down example, the cardinality difference does not have the plan impact it does in the original setting.
set pages 999
explain plan for
SELECT /*+ parallel(4)*/
count(*)
FROM psbal
LEFT OUTER JOIN
prdct
ON (prdct.d_product_id = psbal.d_product_id
AND prdct.create_ts TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6'));
select * from table(dbms_xplan.display);
Plan hash value: 3885851338
--------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop | TQ |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 72 | 3430K (3)| 01:54:22 | | | | | |
| 1 | SORT AGGREGATE | | 1 | 72 | | | | | | | |
| 2 | PX COORDINATOR | | | | | | | | | | |
| 3 | PX SEND QC (RANDOM) | :TQ10003 | 1 | 72 | | | | | Q1,03 | P->S | QC (RAND) |
| 4 | SORT AGGREGATE | | 1 | 72 | | | | | Q1,03 | PCWP | |
|* 5 | HASH JOIN | | 7466M| 500G| 3430K (3)| 01:54:22 | | | Q1,03 | PCWP | |
| 6 | PART JOIN FILTER CREATE | :BF0000 | 286K| 1680K| 56 (0)| 00:00:01 | | | Q1,03 | PCWP | |
| 7 | PX RECEIVE | | 286K| 1680K| 56 (0)| 00:00:01 | | | Q1,03 | PCWP | |
| 8 | PX SEND BROADCAST | :TQ10000 | 286K| 1680K| 56 (0)| 00:00:01 | | | Q1,00 | P->P | BROADCAST |
| 9 | PX BLOCK ITERATOR | | 286K| 1680K| 56 (0)| 00:00:01 | | | Q1,00 | PCWC | |
| 10 | INDEX STORAGE FAST FULL SCAN| S_PK | 286K| 1680K| 56 (0)| 00:00:01 | | | Q1,00 | PCWP | |
|* 11 | HASH JOIN RIGHT OUTER | | 7466M| 458G| 3425K (3)| 01:54:12 | | | Q1,03 | PCWP | |
| 12 | PX RECEIVE | | 1 | 30 | 306 (0)| 00:00:01 | | | Q1,03 | PCWP | |
| 13 | PX SEND BROADCAST | :TQ10001 | 1 | 30 | 306 (0)| 00:00:01 | | | Q1,01 | P->P | BROADCAST |
| 14 | PX BLOCK ITERATOR | | 1 | 30 | 306 (0)| 00:00:01 | 1 | 3 | Q1,01 | PCWC | |
|* 15 | TABLE ACCESS STORAGE FULL | PRODUCT | 1 | 30 | 306 (0)| 00:00:01 | 1 | 3 | Q1,01 | PCWP | |
|* 16 | HASH JOIN | | 7466M| 250G| 3420K (3)| 01:54:01 | | | Q1,03 | PCWP | |
| 17 | PX RECEIVE | | 6903K| 118M| 16379 (1)| 00:00:33 | | | Q1,03 | PCWP | |
| 18 | PX SEND BROADCAST | :TQ10002 | 6903K| 118M| 16379 (1)| 00:00:33 | | | Q1,02 | P->P | BROADCAST |
| 19 | PX BLOCK ITERATOR | | 6903K| 118M| 16379 (1)| 00:00:33 | 1 | 3 | Q1,02 | PCWC | |
|* 20 | TABLE ACCESS STORAGE FULL | BOOK | 6903K| 118M| 16379 (1)| 00:00:33 | 1 | 3 | Q1,02 | PCWP | |
| 21 | PX PARTITION LIST JOIN-FILTER | | 8064M| 135G| 3398K (3)| 01:53:17 |:BF0000|:BF0000| Q1,03 | PCWC | |
| 22 | TABLE ACCESS STORAGE FULL | BALANCE | 8064M| 135G| 3398K (3)| 01:53:17 |:BF0000|:BF0000| Q1,03 | PCWP | |
--------------------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
5 - access("FCT"."S_VID"="DNSP"."S_VID")
11 - access("PRDCT"."PRODUCT_ID"(+)="FCT"."PRODUCT_ID")
15 - storage(NVL("PRDCT"."MODIFY_TS"(+),TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 08:16:34.822981000' AND
"PRDCT"."CREATE_TS"(+)TIMESTAMP' 2020-10-14 08:16:34.822981000' AND
"PRDCT"."CREATE_TS"(+)<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
16 - access("BOOK_ID"="FCT"."BOOK_ID" AND "VERSION"="FCT"."BOOK_VERSION")
20 - storage("COLUMN1" IS NULL OR "D_BOOK_VID"=(-2) OR "D_BOOK_VID"=(-1))
filter("COLUMN1" IS NULL OR "D_BOOK_VID"=(-2) OR "D_BOOK_VID"=(-1))
Note
-----
- dynamic sampling used for this statement (level=7)
- Degree of Parallelism is 4 because of hint
and this:
set pages 999
explain plan for
select count(*)
FROM prdct
WHERE prdct.create_ts <= TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6')
AND NVL(prdct.modify_ts, DATE '9999-12-31') > TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6');
select * from table(dbms_xplan.display);
Plan hash value: 2639949168
----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 14 | 1103 (1)| 00:00:14 | | |
| 1 | SORT AGGREGATE | | 1 | 14 | | | | |
| 2 | PARTITION LIST ALL | | 399 | 5586 | 1103 (1)| 00:00:14 | 1 | 3 |
|* 3 | TABLE ACCESS STORAGE FULL| PRODUCT | 399 | 5586 | 1103 (1)| 00:00:14 | 1 | 3 |
----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - storage(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14
08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
filter(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14
08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
Once you see the problem, you can’t unsee it but for whatever reason, for ages, I was focusing on why there would be such a cardinality difference between A and B for what are basically the single table cardinality estimates for the same table without seeing the explanation right there in front of me.
Note
-----
- dynamic sampling used for this statement (level=7)
I then got distracted and spent some time investigating why dynamic sampling was kicking in. Parallel query has different rules about when it can kick in. And I found reasons why it might.
But then I put that thought to one side.
Why is dynamic sampling saying this will return 1 row?
This is a small table and the estimate should be accurate and we like dynamic sampling so we want to show the feature to its full capability whenever and wherever it kicks in
Sure enough, as we might expect, if I hint dynamic sampling on the single table, estimate is one.
set pages 999
explain plan for
select /*+ dynamic_sampling(4) */ count(*)
FROM prdct
WHERE prdct.create_ts <= TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6')
AND NVL(prdct.modify_ts, DATE '9999-12-31') > TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6');
select * from table(dbms_xplan.display);
----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 14 | 1103 (1)| 00:00:14 | | |
| 1 | SORT AGGREGATE | | 1 | 14 | | | | |
| 2 | PARTITION LIST ALL | | 1 | 14 | 1103 (1)| 00:00:14 | 1 | 3 |
|* 3 | TABLE ACCESS STORAGE FULL| PRODUCT | 1 | 14 | 1103 (1)| 00:00:14 | 1 | 3 |
----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - storage(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14
08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
filter(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14
08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
Note
-----
- dynamic sampling used for this statement (level=4)
Without access to the sample statements, what suggestive evidence can we find?
select table_name, num_rows, blocks, avg_row_len
from user_tables
where table_name = 'PRODUCT';
TABLE_NAME NUM_ROWS BLOCKS AVG_ROW_LEN
------------------------------ ---------- ---------- -----------
PRODUCT 462 4064 193
So that’s not a lot of rows in a lot more blocks than should be necessary.
At this point, we should go off and find out what the reasons might be.
For what it’s worth, for this application, my suspicions are historic direct path maintenance code coupled with table partitioning on status (LATEST/SUPERSEDED) and therefore row movement means an update is a delete + insert, coupled with periods of very low rate of change and small row sizes.
So we end up with old rows moving partition – using a new block for the updated version and leaving behind an empty block where the version was before the update and then relatively few new version rows per run which are using new blocks, and so lots of empty blocks.
i.e. sparsely populated table.
And then dynamic sampling kicks in and samples a bunch of blocks, and finds few actual rows from those samples and comes up with a low estimate and then the whole problem starts. And these were shared tables across the reporting modules so it had a reasonable wide impact.
It would be nice to back this up with some trace files detailing any of the dynamic sampling numbers but I don’t have access by default and mocking this all up outside of work is always a worthwhile exercise but just takes up so much time.
Anyway… move some partitions, rebuild some indexes and 4000 blocks becomes just over 40.
Now our dynamic sampling is looking much better:
----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 14 | 1103 (1)| 00:00:14 | | |
| 1 | SORT AGGREGATE | | 1 | 14 | | | | |
| 2 | PARTITION LIST ALL | | 297 | 14 | 1103 (1)| 00:00:14 | 1 | 3 |
|* 3 | TABLE ACCESS STORAGE FULL| PRODUCT | 297 | 14 | 1103 (1)| 00:00:14 | 1 | 3 |
----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
3 - storage(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14
08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
filter(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14
08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
Note
-----
- dynamic sampling used for this statement (level=4)
Exercise repeated for a whole bunch of tables in a similar situation and everything across the board is a lot healthier.
OraStory 
Nice example and explanation.
Nice explanation Dom.