Partition List Iterator occasionally reading way too many partitions still
June 24, 2022 3 Comments
I’m triple posting this on oracle-l, my blog and on Oracle community to get some more help.
Apologies if you’ve tried to help before and it didn’t come to anything.
This is a redux of an old issue which I looked at 18 months ago but with a new example of the problem.
https://orastory.wordpress.com/2021/02/22/oracle-19c-upgrade-query-reading-way-more-partitions-than-it-should/
https://community.oracle.com/tech/developers/discussion/4480886/partition-list-iterator-reading-too-many-partitions/
When the problem originally surfaced it was after an upgrade from 11.2.0.4 to 19.6. Now version is 19.12.
Now I have one example which gets executed four or five times a day
The example has two sql ids involved in the process but both are almost identical and have identical sql plans.
Queries in question get executed after specific data loads.
For each data load where it gets executed, it will be doing pretty much the same workload day-on-day.
The query gets supplied a collection which tends to have one or a couple of rows row and each row in the collection provides the values to prune to a specific subpartition.
The issue is that about once a week, an execution will go slow.
Exactly the same sql plan each execution.
When it works, it runs in a couple of seconds max.
When it goes wrong, the partition list iterator decides to read every partition/subpartition.
This is the snippet of the plan in question:
| 4 | NESTED LOOPS | | 39 | 4017 | 334 (2)| 00:00:01 | | |
| 5 | COLLECTION ITERATOR PICKLER FETCH | | 1 | 2 | 29 (0)| 00:00:01 | | |
| 6 | PARTITION LIST ITERATOR | | 3853 | 380K| 305 (2)| 00:00:01 | KEY | KEY |
| 7 | PARTITION LIST ITERATOR | | 3853 | 380K| 305 (2)| 00:00:01 | KEY | KEY |
| 8 | TABLE ACCESS STORAGE FULL | POSITION_BALANCE | 3853 | 380K| 305 (2)| 00:00:01 | KEY | KEY |There was some speculation about possible causes in the OTN thread.
The best guess was that there is some timeout or invalidation or event or contention which means Oracle decides that it cannot reliably prune.
There might be other data loads ongoing.
There could be a partition operation (add new or exchange) which coincides with the degraded iterator performance.
There are > 70k partitions / subpartitions.
select count(*) from dba_tab_partitions where table_name = 'POSITION_BALANCE';
COUNT(*)
----------
60941
select count(*), sum(case when segment_created = 'YES' then 1 else 0 end) from dba_tab_subpartitions where table_name = 'POSITION_BALANCE';
COUNT(*) SUM(CASEWHENSEGMENT_CREATED='YES'THEN1ELSE0END)
---------- -----------------------------------------------
78154 33705I’m reasonably comfortable that what I’ve described is roughly what’s happening.
ASH confirms that it’s reading lots of subpartitions
Just got no idea why and how to figure that out.
The average-ish once-a-week occurence makes it tricker.
Even though when it runs in runs in a couple of seconds, I do have some of the ASH samples that show this.
select /*+ parallel(4) */ instance_number, sql_id, sql_plan_hash_value, sql_full_plan_hash_value, sql_exec_id, sql_exec_start, min(sample_time), max(sample_time), max(sample_time) - min(sample_time) duration, count(*) cnt_samples
, sum(case when in_sql_execution = 'Y' then 1 else 0 end) cnt_in_sql_execution
, sum(case when in_parse = 'Y' then 1 else 0 end) cnt_in_parse
, sum(case when in_hard_parse = 'Y' then 1 else 0 end) cnt_in_hard_parse
from dba_hist_active_sess_history h
where 1=1
and h.user_id IN (select user_id from dba_users where username like '%TODS%')
and sql_id in ('fw985yayy1mfz','0gk5hj9wnp2vs')
--and sql_id = 'ft2prc1xx2hmd'
and sql_exec_id is not null
group by instance_number, sql_id, sql_plan_hash_value, sql_full_plan_hash_value, sql_exec_id, sql_exec_start
order by h.sql_exec_start;
INSTANCE_NUMBER SQL_ID SQL_PLAN_HASH_VALUE SQL_FULL_PLAN_HASH_VALUE SQL_EXEC_ID SQL_EXEC_START MIN(SAMPLE_TIME) MAX(SAMPLE_TIME) DURATION CNT_SAMPLES CNT_IN_SQL_EXECUTION CNT_IN_PARSE CNT_IN_HARD_PARSE
--------------- ------------- ------------------- ------------------------ ----------- -------------------- ------------------------------- ------------------------------- ------------------- ----------- -------------------- ------------ -----------------
4 0gk5hj9wnp2vs 2221895109 2867134094 67108864 23-MAY-2022 09:18:24 23-MAY-22 09.18.27.378000000 AM 23-MAY-22 09.18.27.378000000 AM +00 00:00:00.000000 1 1 0 0
3 0gk5hj9wnp2vs 2221895109 2867134094 50331648 24-MAY-2022 07:59:49 24-MAY-22 07.59.50.659000000 AM 24-MAY-22 07.59.50.659000000 AM +00 00:00:00.000000 1 1 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554432 25-MAY-2022 07:09:07 25-MAY-22 07.09.08.709000000 AM 25-MAY-22 07.09.08.709000000 AM +00 00:00:00.000000 1 1 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554434 25-MAY-2022 09:41:53 25-MAY-22 09.41.59.718000000 AM 25-MAY-22 12.41.49.605000000 PM +00 02:59:49.887000 1054 1054 0 0
2 fw985yayy1mfz 2221895109 2867134094 33554434 25-MAY-2022 10:57:41 25-MAY-22 10.57.49.221000000 AM 25-MAY-22 01.56.37.861000000 PM +00 02:58:48.640000 1048 1048 0 0
3 0gk5hj9wnp2vs 2221895109 2867134094 50331648 25-MAY-2022 11:41:04 25-MAY-22 11.41.05.539000000 AM 25-MAY-22 11.41.05.539000000 AM +00 00:00:00.000000 1 1 0 0
3 0gk5hj9wnp2vs 2221895109 2867134094 50331648 27-MAY-2022 08:01:28 27-MAY-22 08.01.30.371000000 AM 27-MAY-22 08.01.30.371000000 AM +00 00:00:00.000000 1 1 0 0
3 fw985yayy1mfz 2221895109 2867134094 50331648 27-MAY-2022 08:01:38 27-MAY-22 08.01.40.611000000 AM 27-MAY-22 08.01.40.611000000 AM +00 00:00:00.000000 1 1 0 0
1 0gk5hj9wnp2vs 2221895109 2867134094 16777218 01-JUN-2022 06:48:24 01-JUN-22 06.48.27.979000000 AM 01-JUN-22 09.48.17.547000000 AM +00 02:59:49.568000 1054 1054 0 0
3 0gk5hj9wnp2vs 2221895109 2867134094 50331649 01-JUN-2022 09:27:03 01-JUN-22 09.27.10.915000000 AM 01-JUN-22 09.27.10.915000000 AM +00 00:00:00.000000 1 1 0 0
3 fw985yayy1mfz 2221895109 2867134094 50331648 02-JUN-2022 07:11:55 02-JUN-22 07.11.57.315000000 AM 02-JUN-22 07.11.57.315000000 AM +00 00:00:00.000000 1 1 0 0
3 0gk5hj9wnp2vs 2221895109 2867134094 50331648 07-JUN-2022 07:04:13 07-JUN-22 07.04.17.155000000 AM 07-JUN-22 07.04.17.155000000 AM +00 00:00:00.000000 1 1 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554434 07-JUN-2022 08:17:56 07-JUN-22 08.17.58.693000000 AM 07-JUN-22 11.17.49.285000000 AM +00 02:59:50.592000 1054 1054 0 0
1 0gk5hj9wnp2vs 2221895109 2867134094 16777216 08-JUN-2022 07:09:22 08-JUN-22 07.09.24.427000000 AM 08-JUN-22 07.09.24.427000000 AM +00 00:00:00.000000 1 1 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554432 08-JUN-2022 08:14:25 08-JUN-22 08.14.26.278000000 AM 08-JUN-22 08.14.26.278000000 AM +00 00:00:00.000000 1 1 0 0
3 fw985yayy1mfz 2221895109 2867134094 50331649 09-JUN-2022 06:51:27 09-JUN-22 06.51.29.219000000 AM 09-JUN-22 06.51.29.219000000 AM +00 00:00:00.000000 1 1 0 0
3 fw985yayy1mfz 2221895109 2867134094 50331648 10-JUN-2022 11:10:13 10-JUN-22 11.10.14.595000000 AM 10-JUN-22 11.10.14.595000000 AM +00 00:00:00.000000 1 1 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554433 13-JUN-2022 08:45:43 13-JUN-22 08.45.45.509000000 AM 13-JUN-22 08.45.45.509000000 AM +00 00:00:00.000000 1 1 0 0
2 fw985yayy1mfz 2221895109 2867134094 33554433 13-JUN-2022 08:45:55 13-JUN-22 08.45.55.749000000 AM 13-JUN-22 08.45.55.749000000 AM +00 00:00:00.000000 1 1 0 0
3 0gk5hj9wnp2vs 2221895109 2867134094 50331648 15-JUN-2022 07:08:19 15-JUN-22 07.08.22.275000000 AM 15-JUN-22 07.08.22.275000000 AM +00 00:00:00.000000 1 1 0 0
3 0gk5hj9wnp2vs 2221895109 2867134094 50331649 15-JUN-2022 09:08:54 15-JUN-22 09.08.56.387000000 AM 15-JUN-22 12.08.46.083000000 PM +00 02:59:49.696000 1054 1054 0 0
1 fw985yayy1mfz 2221895109 2867134094 16777216 16-JUN-2022 06:54:04 16-JUN-22 06.54.05.259000000 AM 16-JUN-22 06.54.05.259000000 AM +00 00:00:00.000000 1 1 0 0
1 0gk5hj9wnp2vs 2221895109 2867134094 16777217 16-JUN-2022 08:54:13 16-JUN-22 08.54.18.891000000 AM 16-JUN-22 11.54.08.844000000 AM +00 02:59:49.953000 1054 1054 0 0
3 fw985yayy1mfz 2221895109 2867134094 50331649 16-JUN-2022 11:16:29 16-JUN-22 11.16.31.491000000 AM 16-JUN-22 11.16.31.491000000 AM +00 00:00:00.000000 1 1 0 0
4 0gk5hj9wnp2vs 2221895109 2867134094 67108865 17-JUN-2022 07:33:10 17-JUN-22 07.33.11.282000000 AM 17-JUN-22 07.33.11.282000000 AM +00 00:00:00.000000 1 1 0 0
4 fw985yayy1mfz 2221895109 2867134094 67108865 17-JUN-2022 07:33:20 17-JUN-22 07.33.21.522000000 AM 17-JUN-22 07.33.21.522000000 AM +00 00:00:00.000000 1 1 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554432 21-JUN-2022 06:59:24 21-JUN-22 06.59.25.728000000 AM 21-JUN-22 06.59.25.728000000 AM +00 00:00:00.000000 1 1 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554433 21-JUN-2022 09:14:05 21-JUN-22 09.14.10.464000000 AM 21-JUN-22 12.14.00.096000000 PM +00 02:59:49.632000 1054 1054 0 0
2 0gk5hj9wnp2vs 2221895109 2867134094 33554434 21-JUN-2022 11:07:36 21-JUN-22 11.07.44.480000000 AM 21-JUN-22 02.07.23.680000000 PM +00 02:59:39.200000 1053 1053 0 0
4 fw985yayy1mfz 2221895109 2867134094 67108865 21-JUN-2022 11:43:04 21-JUN-22 11.43.13.010000000 AM 21-JUN-22 02.42.33.651000000 PM +00 02:59:20.641000 1051 1051 0 0
4 fw985yayy1mfz 2221895109 2867134094 67108866 21-JUN-2022 12:06:49 21-JUN-22 12.06.57.586000000 PM 21-JUN-22 03.06.38.514000000 PM +00 02:59:40.928000 1053 1053 0 0
3 fw985yayy1mfz 2221895109 2867134094 50331649 23-JUN-2022 10:05:02 23-JUN-22 10.05.05.667000000 AM 23-JUN-22 01.04.45.251000000 PM +00 02:59:39.584000 1053 1053 0 0
1 0gk5hj9wnp2vs 2221895109 2867134094 16777216 23-JUN-2022 10:57:04 23-JUN-22 10.57.04.857000000 AM 23-JUN-22 10.57.04.857000000 AM +00 00:00:00.000000 1 1 0 0
This is a section of a RTSM report when it was ok:
Status : DONE (ALL ROWS)
SQL ID : 0gk5hj9wnp2vs
SQL Execution ID : 16777216
Execution Started : 06/15/2022 10:45:41
First Refresh Time : 06/15/2022 10:45:44
Last Refresh Time : 06/15/2022 10:45:44
SQL Plan Monitoring Details (Plan Hash Value=2221895109)
===============================================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Mem | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | (Max) | (%) | (# samples) |
===============================================================================================================================================================================================
| 0 | SELECT STATEMENT | | | | 1 | +3 | 1 | 2255 | | | . | | |
| 1 | TEMP TABLE TRANSFORMATION | | | | 1 | +3 | 1 | 2255 | | | . | | |
| 2 | LOAD AS SELECT (CURSOR DURATION MEMORY) | SYS_TEMP_5FD9DBC0F_97EDDA7B | | | 1 | +3 | 1 | 1 | | | 1MB | | |
| 3 | FILTER | | | | 1 | +3 | 1 | 2255 | | | . | | |
| 4 | NESTED LOOPS | | 39 | 713 | 1 | +3 | 1 | 243K | | | . | | |
| 5 | COLLECTION ITERATOR PICKLER FETCH | | 1 | 29 | 1 | +3 | 1 | 4 | | | . | | |
| 6 | PARTITION LIST ITERATOR | | 3853 | 684 | 1 | +3 | 4 | 243K | | | . | | |
| 7 | PARTITION LIST ITERATOR | | 3853 | 684 | 1 | +3 | 4 | 243K | | | . | | |
| 8 | TABLE ACCESS STORAGE FULL | POSITION_BALANCE | 3853 | 684 | 1 | +3 | 4 | 243K | 71 | 33MB | . | | |
| 9 | NESTED LOOPS | | 1 | 9 | 1 | +3 | 67382 | 140 | | | . | | |
| 10 | NESTED LOOPS | | 1 | 7 | 1 | +3 | 67382 | 140 | | | . | | |
| 11 | NESTED LOOPS | | 1 | 3 | 1 | +3 | 67382 | 67382 | | | . | | |
| 12 | TABLE ACCESS BY INDEX ROWID | CLASS_SCHEME | 1 | 1 | 2 | +2 | 67382 | 67382 | | | . | | |
| 13 | INDEX UNIQUE SCAN | UK_CLASS_SCHEME_CODE | 1 | | 1 | +3 | 67382 | 67382 | | | . | | |
| 14 | TABLE ACCESS BY INDEX ROWID BATCHED | CLASS | 1 | 2 | 1 | +3 | 67382 | 67382 | | | . | | |
| 15 | INDEX RANGE SCAN | UK_CLASS_STATUS2 | 1 | 1 | 1 | +3 | 67382 | 67382 | | | . | | |
| 16 | TABLE ACCESS BY INDEX ROWID BATCHED | BOOK_CLASS | 1 | 4 | 1 | +3 | 67382 | 140 | | | . | | |
| 17 | INDEX RANGE SCAN | UK_BOOK_CLASS_STATUS2 | 2 | 2 | 1 | +3 | 67382 | 336K | 230 | 2MB | . | | |
| 18 | INDEX RANGE SCAN | IDX_BOOK_STATUS_01 | 1 | 2 | 1 | +3 | 140 | 140 | | | . | | |
| 19 | VIEW | | 1 | 2 | 1 | +3 | 1 | 2255 | | | . | | |
| 20 | TABLE ACCESS STORAGE FULL | SYS_TEMP_5FD9DBC0F_97EDDA7B | 1 | 2 | | | 1 | | | | . | | |
===============================================================================================================================================================================================This is a section taken whilst running in the middle of the problem:
Status : EXECUTING
SQL ID : 0gk5hj9wnp2vs
SQL Execution ID : 33554434
Execution Started : 06/21/2022 11:07:36
First Refresh Time : 06/21/2022 11:07:41
Last Refresh Time : 06/21/2022 13:55:15
SQL Plan Monitoring Details (Plan Hash Value=2221895109)
================================================================================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Mem | Activity | Activity Detail | Progress |
| | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | | (%) | (# samples) | |
================================================================================================================================================================================================================================
| 0 | SELECT STATEMENT | | | | | | | | | | . | | | |
| 1 | TEMP TABLE TRANSFORMATION | | | | | | | | | | . | | | |
| 2 | LOAD AS SELECT (CURSOR DURATION MEMORY) | SYS_TEMP_0FD9E59B6_25BEB636 | | | | | 1 | | | | . | | | |
| 3 | FILTER | | | | | | 1 | | | | . | | | |
| 4 | NESTED LOOPS | | 39 | 710 | 1 | +5 | 1 | 0 | | | . | | | |
| -> 5 | COLLECTION ITERATOR PICKLER FETCH | | 1 | 29 | 10061 | +5 | 1 | 1 | | | . | | | |
| 6 | PARTITION LIST ITERATOR | | 3853 | 681 | | | 1 | | | | . | | | |
| 7 | PARTITION LIST ITERATOR | | 3853 | 681 | | | 38175 | | | | . | | | |
| -> 8 | TABLE ACCESS STORAGE FULL | POSITION_BALANCE | 3853 | 681 | 10065 | +1 | 44021 | 0 | 625K | 162GB | . | 100.00 | gc cr block remote read (1) | 100% |
| | | | | | | | | | | | | | gc cr grant 2-way (26) | |
| | | | | | | | | | | | | | gc cr multi block request (85) | |
| | | | | | | | | | | | | | gc current grant 2-way (1) | |
| | | | | | | | | | | | | | Cpu (7530) | |
| | | | | | | | | | | | | | cell multiblock physical read (1946) | |
| | | | | | | | | | | | | | cell single block physical read (215) | |
| | | | | | | | | | | | | | cell smart table scan (15) | |
| 9 | NESTED LOOPS | | 1 | 9 | | | | | | | . | | | |
| 10 | NESTED LOOPS | | 1 | 7 | | | | | | | . | | | |
| 11 | NESTED LOOPS | | 1 | 3 | | | | | | | . | | | |
| 12 | TABLE ACCESS BY INDEX ROWID | CLASS_SCHEME | 1 | 1 | | | | | | | . | | | |
| 13 | INDEX UNIQUE SCAN | UK_CLASS_SCHEME_CODE | 1 | | | | | | | | . | | | |
| 14 | TABLE ACCESS BY INDEX ROWID BATCHED | CLASS | 1 | 2 | | | | | | | . | | | |
| 15 | INDEX RANGE SCAN | UK_CLASS_STATUS2 | 1 | 1 | | | | | | | . | | | |
| 16 | TABLE ACCESS BY INDEX ROWID BATCHED | BOOK_CLASS | 1 | 4 | | | | | | | . | | | |
| 17 | INDEX RANGE SCAN | UK_BOOK_CLASS_STATUS2 | 2 | 2 | | | | | | | . | | | |
| 18 | INDEX RANGE SCAN | IDX_BOOK_STATUS_01 | 1 | 2 | | | | | | | . | | | |
| 19 | VIEW | | 1 | 2 | | | | | | | . | | | |
| 20 | TABLE ACCESS STORAGE FULL | SYS_TEMP_0FD9E59B6_25BEB636 | 1 | 2 | | | | | | | . | | | |
================================================================================================================================================================================================================================
Potentially I could set system level trace for this sql id and wait for it to reoccur but what events would I be setting to try to capture what causes this runtime decision?
I presume it wouldn’t be an optimizer trace?
Any thoughts or ideas?
OraStory 
Dom,
Quite an intriguing problem and I can see quite a lot of analysis done by you and Jonathan on this. I can’t think of any logical reason causing this so I am wondering whether any bug anywhere is causing this? I am guessing you have already engaged MOS with a SR (and probably has not been lucky with it).
Intermittent problems are always a challenge, especially when you can’t seem to find a pattern.
Anyways, for no particular reason, I thought of mentioning below (but feel free to ignore if you have already looked at these possibilities or if they seem so “beyond logic” that they are best ignored)
1. Does the TABLE operator and/or collection usage in SQL, has anything to do with it? Would it be possible to find out if a “normal” table is used in place of collection, used with TABLE operator, then we still see the same symptoms?
2. Could there be a limitation/bug in the storage software that is preventing “smart scan” when this issue is occurring?
Also, I am sure you know this already but any chance you can enable event 10128 tracing, preferably for the specific SQL (have a feeling that it is possible but not sure how). I know it will still not be ideal and would almost certainly involve housekeeping trace files at regular intervals but I can’t think of a better way to get more insight into this issue
Thanks to your problem, I discovered MOS note 1165827.1 that appears to suggest a way to trace sql statements based on bespoke conditions.
I have to admit I am not really convinced it is elegant and whether you can use it given that your issue appears once per week but I thought I would still mention it here just in case…