Стандарный OEBS запрос 1ap5awtfdvhp9, не меняя простого плана выполнения по стандартному индексу:
--------------------------------------------------
Plan hash value: 4013141424
----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 17 | 4 (0)| 00:00:01 |
|* 1 | TABLE ACCESS BY INDEX ROWID BATCHED| IBY_USED_PAYMENT_DOCS | 1 | 17 | 4 (0)| 00:00:01 |
|* 2 | INDEX RANGE SCAN | IBY_USED_PAYMENT_DOCS_N1 | 1 | | 3 (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("DOCUMENT_USE"<>'SKIPPED')
2 - access("PAYMENT_DOCUMENT_ID"=TO_NUMBER(:B2) AND "USED_DOCUMENT_NUMBER"=TO_NUMBER(:B1))
, значительно увеличил среднее время выполнения (ELA_PER_EXEC) в сравнении с предыдущим месяцем:
SQL> @dba_hist_sqlstat "sql_id = '1ap5awtfdvhp9' and (snap_id between 85740 and 88340) and (elapsed_time_delta > 0 and executions_delta is not null)" PLAN I BEGIN_SNAP_ID BEGIN_SNAP_TIME EXECS ROWS_PROCESSED SQL_ID PLAN COST ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC FETCHES_PER_EXEC IOWAITS_PER_EXEC CLWAITS_PER_EXEC_US CCWAITS_PER_EXEC - ------------- --------------- ---------- -------------- ------------- ---------- ---- ------------ ------------ ------------- ---------------- ---------------- ------------------- ---------------- 1 85739 04.02 10:00 10449 0 1ap5awtfdvhp9 4013141424 4 17 14 3 1 0 0 0 1 85740 04.02 10:15 10556 0 1ap5awtfdvhp9 4013141424 4 17 13 3 1 0 0 0 1 85872 05.02 19:15 49767 0 1ap5awtfdvhp9 4013141424 4 13 12 3 1 0 0 0 1 85875 05.02 20:00 41546 0 1ap5awtfdvhp9 4013141424 4 14 11 3 1 0 0 0 ... 1 88335 03.03 11:00 1823 0 1ap5awtfdvhp9 4013141424 4 980145 974586 61222 1 91 365 10 2 88335 03.03 11:00 486 0 1ap5awtfdvhp9 4013141424 4 1122064 1110434 85349 1 34 7297 5 1 88336 03.03 11:15 1845 0 1ap5awtfdvhp9 4013141424 4 998367 988427 62268 1 88 1829 1 2 88336 03.03 11:15 479 0 1ap5awtfdvhp9 4013141424 4 1108855 1095223 86002 1 6 8504 4 1 88337 03.03 11:30 1770 0 1ap5awtfdvhp9 4013141424 4 1008781 998293 62950 1 140 522 1 2 88337 03.03 11:30 485 0 1ap5awtfdvhp9 4013141424 4 1122134 1108894 86969 1 16 8703 2 1 88338 03.03 11:45 1892 0 1ap5awtfdvhp9 4013141424 4 1024759 1015188 64443 1 58 856 7 2 88338 03.03 11:45 421 0 1ap5awtfdvhp9 4013141424 4 1157370 1148476 88210 1 6 1079 1 ...
, совместно с кол-вом читаемых блоков на выполнение GETS_PER_EXEC без значительного изменения ожиданий
и — важно — без какого-либо взрывного роста сегментов данных запроса — таблицы и индексов IBY_USED_PAYMENT_DOCS
Оценочный экспресс-анализ buffer gets/ON CPU показал активное чтение UNDO сегментов:
SQL> select session_state, 2 case when p1text = 'file#' then p1 else 0 end as file#, 3 count(*) ash_rows, 4 count(distinct instance_number || '*' || session_id) sids, 5 current_obj#, 6 tablespace_name, 7 to_char(RATIO_TO_REPORT(count(*)) OVER() * 100, '990.99') AS "waits%" 8 from dba_hist_active_sess_history 9 left join dba_data_files 10 on p1 = file_id 11 where sql_id = '1ap5awtfdvhp9' 12 and snap_id between 88335 and 88345 13 group by session_state, 14 case when p1text = 'file#' then p1 else 0 end, 15 current_obj#, tablespace_name 16 order by count(*) desc; SESSION_STATE FILE# ASH_ROWS SIDS CURRENT_OBJ# TABLESPACE_NAME waits% ------------- ---------- ---------- ---------- ------------ ---------------- ------- ON CPU 1232 1418 7 0 UNDOTBS2 55.28 ON CPU 1210 342 6 0 UNDOTBS1 13.33 ON CPU 1221 136 4 0 UNDOTBS1 5.30 ON CPU 1196 96 4 0 UNDOTBS1 3.74 ON CPU 1215 87 1 0 UNDOTBS1 3.39 ON CPU 1194 83 6 0 UNDOTBS1 3.24 ON CPU 826 68 5 1752214 APPS_TS_TX_IDX 2.65 -- IBY_USED_PAYMENT_DOCS_N1 ON CPU 1197 62 4 0 UNDOTBS1 2.42 ON CPU 0 49 6 0 1.91 ON CPU 825 37 4 1752214 APPS_TS_TX_IDX 1.44 ON CPU 1204 35 4 0 UNDOTBS1 1.36 ON CPU 824 30 4 1752214 APPS_TS_TX_IDX 1.17 ON CPU 1225 30 5 0 UNDOTBS1 1.17 ON CPU 1206 29 5 0 UNDOTBS1 1.13 ON CPU 1195 19 4 0 UNDOTBS1 0.74 ON CPU 1205 15 3 0 UNDOTBS1 0.58 ON CPU 0 8 3 -1 0.31
…
, что косвенно подтверждает системная статистика data blocks consistent reads — undo records applied (*) за проблемный период и нагляднее подтвердила бы статистика на уровне сессий — но увы(:
SQL> select trunc(begin_interval_time) as dt, 2 sum(value) as sum_undo_block_cr_reads 3 from (select instance_number as "INST_ID", 4 snap_id as snap_id, 5 end_interval_time as begin_interval_time, 6 stat_name, 7 case WHEN (LEAD(value, 1) over(PARTITION BY instance_number, stat_name ORDER BY snap_id) <= value) THEN null 8 ELSE (LEAD(value, 1) over(PARTITION BY instance_number, stat_name ORDER BY snap_id) - value) END as Value 9 from dba_hist_sysstat hse 10 join dba_hist_snapshot sna 11 using (snap_id, instance_number) 12 where stat_name = 'data blocks consistent reads - undo records applied' 13 order by 2 desc, 1) 14 where Value is not null 15 and begin_interval_time > sysdate - 30 16 group by trunc(begin_interval_time) 17 order by trunc(begin_interval_time) desc 18 / DT SUM_UNDO_BLOCK_CR_READS ----------- ----------------------- ... 09.03.2023 9843011002 08.03.2023 5931957327 07.03.2023 23750941468 06.03.2023 24184473489 05.03.2023 43232161735 04.03.2023 76422478234 03.03.2023 219390281202 -- and here * 02.03.2023 103790963680 -- here * 01.03.2023 54546837381 28.02.2023 24088213729 27.02.2023 24123065985 26.02.2023 12907658145
…
Проблема [п]оказалась порождена/связана с оптимизацией выполнения batch-обработки через переход от «однопроцессной» обработки массива данных к конкурентной обработке пулом одновременно выполняемых процессов/запросов (OEBS Concurrent requests) с продолжительными открытыми транзакциями
К счастью, в рассматриваемом случае «стандартный план стандартного OEBS запроса» 1ap5awtfdvhp9 оказался классически неэффективным в части порядка индексированных столбцов:
SQL> select ic.column_position, ic.column_name, num_distinct, num_nulls
2 from dba_ind_columns ic
3 join dba_tab_col_statistics cs
4 on ic.table_owner = cs.owner
5 and ic.table_name = cs.table_name
6 and ic.column_name = cs.column_name
7 where index_name = 'IBY_USED_PAYMENT_DOCS_N1'
8 and cs.owner = 'IBY'
9 and cs.table_name = 'IBY_USED_PAYMENT_DOCS'
10 /
COLUMN_POSITION COLUMN_NAME NUM_DISTINCT NUM_NULLS
--------------- --------------------- ------------ ----------
1 PAYMENT_DOCUMENT_ID 125 0
2 USED_DOCUMENT_NUMBER 19189760 0
, что при однопоточной обработке влияло слабо**, многопоточная параллельная обработка добавила красок)
Со стороны бд проблема решалась созданием нестандартного (для OEBS) индекса с правильным порядком столбцов:
SQL> create index IBY.IBY_USED_PAYMENT_DOCS_X1 on IBY.IBY_USED_PAYMENT_DOCS(USED_DOCUMENT_NUMBER, PAYMENT_DOCUMENT_ID) tablespace APPS_TS_TX_IDX online; Index created SQL> @sqlpatch+ 1ap5awtfdvhp9 INDEX_RS_ASC(@"SEL$1" "IBY_USED_PAYMENT_DOCS"@"SEL$1" "IBY_USED_PAYMENT_DOCS_X1") 1ap5awtfdvhp9_x1 PL/SQL procedure successfully completed
— с закреплением использования «правильного» индекса по причине эквивалентной стоимости планов (известная особенность), что заметно улучшило ELA_PER_EXEC/GETS_PER_EXEC, несмотря на логично проявившееся влияние Cluster waits (CLWAITS_PER_EXEC_US) — неопределяющее на общем фоне, но легкообъяснимое мультипроцессной обработкой единого массива данных без привязки к инстансу:
SQL> @dba_hist_sqlstat "sql_id = '1ap5awtfdvhp9' and snap_id between 88371 and 88391 and (elapsed_time_delta > 0 and executions_delta is not null)" 0 I BEGIN_SNAP_ID BEGIN_SNAP_TIME EXECS ROWS_PROCESSED SQL_ID PLAN COST ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC CLWAITS_PER_EXEC_US CLWAITS_SEC - ------------- --------------- ---------- -------------- ------------- ---------- ------ ------------ ------------ ------------- ------------------- ----------- 1 88370 03.03 19:45 7329 0 1ap5awtfdvhp9 4013141424 4 219267 216613 18851 0 0 1 88371 03.03 20:00 5561 0 1ap5awtfdvhp9 4013141424 4 383829 379392 25467 0 0 1 88372 03.03 20:15 8051 0 1ap5awtfdvhp9 4013141424 4 272088 269390 17418 0 0 ... 1 88387 04.03 00:00 7554 0 1ap5awtfdvhp9 2655306188 4 2608 2101 127 299 2 2 88387 04.03 00:00 3338 0 1ap5awtfdvhp9 2655306188 4 4040 3007 189 785 3 1 88388 04.03 00:15 31019 0 1ap5awtfdvhp9 2655306188 4 2694 2105 127 371 11 2 88388 04.03 00:15 19976 0 1ap5awtfdvhp9 2655306188 4 3388 2446 153 696 14 1 88389 04.03 00:30 31071 0 1ap5awtfdvhp9 2655306188 4 2586 1958 118 425 13 2 88389 04.03 00:30 16202 0 1ap5awtfdvhp9 2655306188 4 3706 2607 160 851 14 21 rows selected
Текущая/фоновая статистика курсоров удовлетворительна:
SQL> @shared_cu12 1ap5awtfdvhp9 0 10 INST EXECS LAST_LOAD_TIME LAST_ACTIVE_TIME ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC CURSOR_STATUS PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE CBO_MODE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE CF REOPT SQL_PATCH IS_OBSOLETE ---- ------------ -------------------- ------------------- ------------- ------------ ------------ ------------- -------------- ------------ ------------- ------------ ------------- --------------- -------------------- ---------- -------------- ----- ---------- ---------- ---------- --- ----- ---------------- ----------- 1 184 2023-03-25/13:40:23 27.03.2023 10:22:09 0 739 298 5 0 84 33 372 VALID 2655306188 2183859174 ALL_ROWS 4 1 Y N Y N 1ap5awtfdvhp9_x1 N 4 1077 2023-03-26/18:12:40 27.03.2023 11:00:13 0 275 66 3 0 5 3 223 VALID 2655306188 2183859174 ALL_ROWS 4 0 Y N Y N 1ap5awtfdvhp9_x1 N 2 120 2023-03-25/13:41:23 27.03.2023 11:17:40 0 1096 302 6 0 27 45 770 VALID 2655306188 2183859174 ALL_ROWS 4 0 Y N Y N 1ap5awtfdvhp9_x1 N 3 4266 2023-03-13/10:51:21 27.03.2023 11:22:21 0 173 88 3 0 59 1 60 VALID 2655306188 2183859174 ALL_ROWS 4 0 Y N Y N 1ap5awtfdvhp9_x1 N
Проблема UNDO generated By Index blocks during INSERT известна и хорошо описана, и на основе предложенного классиками тесткейса легко проверить влияние оптимальности используемых индексов на генерацию UNDO:
--1st session on 1st instance SID#1/INST#1@19.10 SQL> create table system.temp_undo_usage tablespace users 2 as 3 select * from dba_objects 4 / Таблица создана. SQL> create index system.temp_indx_low_card1st on system.temp_undo_usage(namespace,object_id) tablespace users 2 / Индекс создан. SQL> create index system.temp_indx_high_card1st on system.temp_undo_usage(object_id,namespace) tablespace users 2 / Индекс создан. SQL> insert into system.temp_undo_usage select * from dba_objects; Создано строк: 528208. SQL> / Создано строк: 528208. SQL> / Создано строк: 528207. SQL> / Создано строк: 528207. --no COMMIT
, после чего запрос в другой сессии по неэффективному индексу TEMP_INDX_LOW_CARD1ST(namespace,object_id):
--2nd session on 1st instance
SID#2/INST#1 SQL> select /*+ index(t temp_indx_low_card1st)*/ * from system.temp_undo_usage t where namespace > 0;
Выбрано строк: 528197.
Затрач.время: 00:00:34.45
План выполнения
----------------------------------------------------------
Plan hash value: 1634110300
-------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 618K| 283M| 69873 (1)| 00:00:03 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TEMP_UNDO_USAGE | 618K| 283M| 69873 (1)| 00:00:03 |
|* 2 | INDEX RANGE SCAN | TEMP_INDX_LOW_CARD1ST | 618K| | 11161 (1)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("NAMESPACE">0 AND "NAMESPACE" IS NOT NULL)
Статистика
----------------------------------------------------------
68 recursive calls
149 db block gets
2135227 consistent gets
5 physical reads
909212 redo size
71698525 bytes sent via SQL*Net to client
1553 bytes received via SQL*Net from client
107 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
528197 rows processed
SQL> select 'undo: '||to_char(to_number(value)) from v$mystat natural join v$statname where name = 'data blocks consistent reads - undo records applied';
'UNDO:'||TO_CHAR(TO_NUMBER(VALUE))
----------------------------------------------
undo: 2056673
— выполняется 2135227 consistent gets при 2056673 блоках, реконструированных из UNDO
Запрос по правильному эффективному индексу TEMP_INDX_HIGH_CARD1ST(object_id,namespace):
SID#2/INST#1 SQL> select /*+ index(t temp_indx_high_card1st)*/ * from system.temp_undo_usage t where object_id > 0;
Выбрано строк: 528197.
Затрач.время: 00:00:20.18
План выполнения
----------------------------------------------------------
Plan hash value: 3807785061
--------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 618K| 283M| 52480 (1)| 00:00:03 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TEMP_UNDO_USAGE | 618K| 283M| 52480 (1)| 00:00:03 |
|* 2 | INDEX RANGE SCAN | TEMP_INDX_HIGH_CARD1ST | 618K| | 11161 (1)| 00:00:01 |
--------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("OBJECT_ID">0 AND "OBJECT_ID" IS NOT NULL)
Статистика
----------------------------------------------------------
9 recursive calls
0 db block gets
530882 consistent gets
0 physical reads
878268 redo size
71698525 bytes sent via SQL*Net to client
1553 bytes received via SQL*Net from client
107 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
528197 rows processed
SQL> select 'undo: '||to_char(to_number(value-2056673)) from v$mystat natural join v$statname where name = 'data blocks consistent reads - undo records applied';
'UNDO:'||TO_CHAR(TO_NUMBER(VALUE-2056673))
----------------------------------------------
undo: 468826
— читает в 4 раза меньше блоков, т.е. в зависимости от порядка столбцов High — Low Cardinality наблюдается кратная разница consistent gets за счет пропорционального увеличения data blocks consistent reads — undo records applied
При этом формальные характеристики индексов различаются незначительно:
SQL> select index_name, clustering_factor, blevel, leaf_blocks, distinct_keys from dba_indexes where table_name = 'TEMP_UNDO_USAGE'; INDEX_NAME CLUSTERING_FACTOR BLEVEL LEAF_BLOCKS DISTINCT_KEYS ----------------------- ----------------- ---------- ----------- ------------- TEMP_INDX_LOW_CARD1ST 62336 2 1547 541209 TEMP_INDX_HIGH_CARD1ST 43265 2 1547 541209 SQL> /-- after 4x insert into system.temp_undo_usage select * from dba_objects; INDEX_NAME CLUSTERING_FACTOR BLEVEL LEAF_BLOCKS DISTINCT_KEYS ----------------------- ----------------- ---------- ----------- ------------- TEMP_INDX_LOW_CARD1ST 2706057 2 11190 534104 TEMP_INDX_HIGH_CARD1ST 2706057 2 11155 545011
, что и отражается в незначительной разнице CBO Cost
При выполнении того же запроса по неэффективному индексу (при всё ещё открытой транзакции) на другом инстансе:
SID#2419/INST#2 SQL> select /*+ index(t temp_indx_low_card1st)*/ * from system.temp_undo_usage t where namespace > 0;
Выбрано строк: 528197.
Затрач.время: 00:00:38.24
План выполнения
----------------------------------------------------------
Plan hash value: 1634110300
-------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 618K| 283M| 69873 (1)| 00:00:03 |
| 1 | TABLE ACCESS BY INDEX ROWID BATCHED| TEMP_UNDO_USAGE | 618K| 283M| 69873 (1)| 00:00:03 |
|* 2 | INDEX RANGE SCAN | TEMP_INDX_LOW_CARD1ST | 618K| | 11161 (1)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("NAMESPACE">0 AND "NAMESPACE" IS NOT NULL)
Статистика
----------------------------------------------------------
117 recursive calls
0 db block gets
69983 consistent gets
0 physical reads
0 redo size
71698525 bytes sent via SQL*Net to client
1553 bytes received via SQL*Net from client
107 SQL*Net roundtrips to/from client
6 sorts (memory)
0 sorts (disk)
528197 rows processed
SQL> select 'undo: '||to_char(to_number(value)) from v$mystat natural join v$statname where name = 'data blocks consistent reads - undo records applied';
'UNDO:'||TO_CHAR(TO_NUMBER(VALUE))
----------------------------------------------
undo: 0
— рапортуемое кол-во consistent gets низко (точнее, соответствует числу блоков таблицы и индекса), при формально нулевом кол-ве локально применённых UNDO блоков — локальная статистика RAC не очень информативна для анализа, всё время тратится на:
SQL> @sessof 2419 ... Session Wait Events NAME WAIT_CLASS WAITS TIME_MS TIMEOUTS AVG_WAIT_MS ---------------------------- ----------- ------------ ------------ ------------ ----------- gc cr block busy Cluster 10696 28893 0 2,7 SQL*Net more data to client Network 8793 740 0 0,1 gc cr block 2-way Cluster 186 615 0 3,3 gc current block 3-way Cluster 4194 517 0 0,1 gc current block 2-way Cluster 4103 314 0 0,1 gc cr multi block mixed Cluster 697 126 0 0,2 row cache mutex Concurrency 1 9 0 9,4 SQL*Net message to client Network 118 0 0 0 latch: shared pool Concurrency 1 0 0 0,1 enq: TM - contention Application 1 0 0 0,1 gc current grant 2-way Cluster 1 0 0 0,1 gc current block busy Cluster 1 0 0 0,1 12 rows selected
или так:
SQL> select sql_plan_operation || ' ' || sql_plan_options as sql_plan_operation, 2 session_state || ' ' || event, 3 case when event = 'gc cr block busy' then p1 else 0 end as file#, 4 tablespace_name, 5 count(*) ash_rows, 6 to_char(RATIO_TO_REPORT(count(*)) OVER() * 100, '990.99') AS "waits%" 7 from v$active_session_history 8 left join dba_data_files 9 on p1 = file_id 10 where (session_id, session_serial#) in ((2419, 30979)) 11 and sql_id = 'dwxk82h8cbfdm' 12 group by sql_plan_operation || ' ' || sql_plan_options, 13 session_state || ' ' || event, 14 case when event = 'gc cr block busy' then p1 else 0 end, 15 tablespace_name 16 order by count(*) desc; SQL_PLAN_OPERATION SESSION_STATE||''||EVENT FILE# TABLESPACE ASH_ROWS waits% ------------------------------------ ----------------------------------- ----- ---------- -------- ------- INDEX RANGE SCAN WAITING gc cr block busy 886 USERS 7 20.00 INDEX RANGE SCAN WAITING gc cr block busy 881 USERS 5 14.29 INDEX RANGE SCAN WAITING gc cr block busy 887 USERS 5 14.29 INDEX RANGE SCAN WAITING gc cr block busy 889 USERS 4 11.43 INDEX RANGE SCAN WAITING gc cr block busy 884 USERS 4 11.43 INDEX RANGE SCAN WAITING gc cr block busy 888 USERS 4 11.43 INDEX RANGE SCAN WAITING gc cr block busy 882 USERS 3 8.57 INDEX RANGE SCAN WAITING gc cr block 2-way 0 USERS 1 2.86 TABLE ACCESS BY INDEX ROWID BATCHED ON CPU 0 USERS 1 2.86 TABLE ACCESS BY INDEX ROWID BATCHED WAITING SQL*Net more data to client 0 1 2.86 10 rows selected
— кластерное ожидание gc cr block busy пользовательских (tablespace USERS, не UNDO) блоков таблицы и индекса, и в этом случае определённо отображает задержки , связанные с восстановлением CR версии блока на удалённом инстансе
Oracle mechanics 
Оставьте комментарий