Oracle 19: Сравнение Query Block Registry

Для ускорения/оптимизации выполнения запроса коллега Сергей Перегудин проанализировал и предложил поправить/зафиксировать план важного, но замедлившегося запроса:

SQL> @sql_profile_from_sql 947wjnz21sdv1 3090864955 947wjnz21sdv1_3090864955 947wjnz21sdv1_3090864955

PL/SQL procedure successfully complete

, что привело к хорошему ожидаемому рез-ту:

SQL> @shared_cu12 947wjnz21sdv1 0 11

INST EXECS USERS_OPENING FIRST_LOAD_TIME      LAST_LOAD_TIME       PARSE_USER LAST_ACTIVE_TIME    ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC PLSQL_PER_EXEC CURSOR_STATUS       PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE CBO_MODE   OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  CF  REOPT REOPT_HINTS V$SQL.Adapt XML.Adapt SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON NOT_SHARED_BY REASON SQL_PROFILE               IS_OBSOLETE
---- ----- ------------- -------------------- -------------------- ---------- ------------------- ------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------ -------------- ------------------- --------------- -------------------- ---------- -------------- ----- ---------- ---------- ---------- --- ----- ----------- ----------- --------- --------- --------- -------- --- ---------- ------------- ------ ------------------------- -----------
   1     3             0 2024-02-09/15:30:26  2024-02-09/15:30:26  APPS       09.02.2024 16:00:39             0       472888       305120               1           958              5         1098        193184         7265              0 INVALID_UNAUTH           3090864955           1605889768 ALL_ROWS           246634     0 N          N          Y              N                 N                                                                                                                N          
   3     2             0 2024-02-09/15:29:44  2024-02-09/15:29:44  APPS       09.02.2024 16:00:47             0       696668       448275               1          1494             66         9580        286532         7219              0 INVALID_UNAUTH           3090864955           1605889768 ALL_ROWS           246636     0 N          N          Y              N                 N                                                                                                                N          
   2     1             1 2024-02-09/17:30:34  2024-02-09/17:30:34  APPS       09.02.2024 17:31:55             0     81856619     21530087               1        898437         286982     62166268        637855      5207870          52903 VALID                    3090864955           1605889768 ALL_ROWS          1130752     0 N          N          Y              N                 N                                                                                      947wjnz21sdv1_3090864955  N          
   4     3             1 2024-02-09/10:41:27  2024-02-09/10:41:27  APPS       09.02.2024 17:31:56             0   8218294609   8177073682               1     174802168         183115     11756834        179604      3877313           6539 INVALID_UNAUTH           2165674671           2799055495 ALL_ROWS           657548     0 N          N          Y              N                 N                                                                                                                N          

--------------------------------------------------------------
SQL_ID=947wjnz21sdv1 Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------

INST PARSING_SCHEMA EXECS PLAN_HASH_VALUE LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC PLSQL_PER_EXEC FETCH_PER_EXEC ROWS_PER_EXEC AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PROFILE
---- -------------- ----- --------------- -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------ -------------- -------------- ------------- ------------ ---------- ---------- ---------- ----- ----- -------------------------
   1 APPS               3      3090864955 2024-02-09/15:30:26  09.02.2024 16:00:39       472888       305120               1           958              5         1098        193184         7265              0              1             0       246634          1 N          N          N     N     
   3 APPS               2      3090864955 2024-02-09/15:29:44  09.02.2024 16:00:47       696668       448275               1          1494             66         9580        286532         7219              0              1             0       246636          1 N          N          N     N     
   2 APPS               1      3090864955 2024-02-09/17:30:34  09.02.2024 17:31:55     81856619     21530087               1        898437         286982     62166268        637855      5207870          52903              0             0      1130752          1 N          N          N     N     947wjnz21sdv1_3090864955
   4 APPS               3      2165674671 2024-02-09/10:41:27  09.02.2024 17:31:56   8218294609   8177073682               1     174802168         183115     11756834        179604      3877313           6539              1             0       657548          1 N          N          N     N     

--------------------------------------------------------------
ASH TOP11 SQL_ID=947wjnz21sdv1 Executions by Elapsed Time
--------------------------------------------------------------

INST_ID    SID    SERIAL# SQL_ID        SQL_PLAN_HASH_VALUE SQL_FULL_PLAN_HASH_VALUE SQL_EXEC_ID CHILD C   ASH_ROWS         PX SQL_EXEC_START            DURATIONs                 MIN_SAMPLE_TIME           MAX_SAMPLE_TIME           TEMP_SPACE_ALLOCATED
------- ------ ---------- ------------- ------------------- ------------------------ ----------- ----- - ---------- ---------- ------------------------- ------------------------- ------------------------- ------------------------- --------------------
      4   8738      53404 947wjnz21sdv1          2165674671               2799055495    67108864     0 *      24575          1 09.02.2024 10:41:28       +000000000 06:50:27.654   09-ФЕВ-24 10.41.29.271 AM 09-ФЕВ-24 05.31.56.925 PM           2764046336
      1  11580      11427 947wjnz21sdv1          2165674671               2799055495    16777216     0         7631          1 08.02.2024 10:32:51       +000000000 02:07:26.089   09-ФЕВ-24 09.27.24.942 AM 09-ФЕВ-24 11.34.51.031 AM           1519910912
      2   4026      26231 947wjnz21sdv1          3090864955               1605889768    33554433     0 *         82          1 09.02.2024 17:30:34       +000000000 00:01:21.187   09-ФЕВ-24 05.30.35.794 PM 09-ФЕВ-24 05.31.56.981 PM              1048576
      4   6265      53412 947wjnz21sdv1          2165674671               2799055495    67108866     0           20          1 09.02.2024 15:32:04       +000000000 00:00:19.039   09-ФЕВ-24 03.32.05.614 PM 09-ФЕВ-24 03.32.24.653 PM              1048576
      4   7912      31730 947wjnz21sdv1          2165674671               2799055495    67108865     0            6          1 09.02.2024 15:30:39       +000000000 00:00:05.010   09-ФЕВ-24 03.30.40.439 PM 09-ФЕВ-24 03.30.45.449 PM            459800576
...

— видно, что зафиксированный PHV 3090864955 , предварительно на пару порядков быстрее чем прежний PHV 2165674671 (подтвердилось впоследствии)

Внимание привлекло различие длин «хорошего» и плохого планов:

Анализ выполнений стандартного concurrent request

SQL> @oebs_conc_trend4long 142108 10 dd 0 0

DT_START   PROGRAM_ID CONCURRENT_PROGRAM_NAME  REQ_COUNT AVG_DURATION_SECS SUM_DURATION_SECS REQ_LIST
---------- ---------- ----------------------- ---------- ----------------- ----------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
27.11.2023     142108 XLAACCPB|Создать учет          526                46             24254 198780172:G(1679 s); 198795936:G(550 s); 198721884:G(430 s); 198805826:C(410 s); 198903512:C(264 s); 198903280:C(253 s); 198901622:C(205 s); 198900803:G(203 s); 198903577:G(202 s); 198801050:G(200 s);
28.11.2023     142108 XLAACCPB|Создать учет          361                62             22439 198927218:G(2648 s); 198932779:G(1780 s); 198987472:C(1774 s); 198775545:G(1502 s); 198950350:G(821 s); 198999002:G(641 s); 199025449:C(307 s); 198776670:G(220 s); 198953401:G(211 s); 199016953:C(161
29.11.2023     142108 XLAACCPB|Создать учет          441                62             27158 199075202:G(2537 s); 199167555:G(891 s); 199099606:G(873 s); 199119083:C(770 s); 199165369:C(683 s); 198928600:G(664 s); 198938700:C(528 s); 199103734:G(500 s); 199105475:C(347 s); 199153146:C(277 s);
30.11.2023     142108 XLAACCPB|Создать учет          446                61             27180 199222498:G(2191 s); 199279389:C(1838 s); 199300946:G(1187 s); 199254884:G(766 s); 199072668:G(563 s); 199341832:C(407 s); 199302220:G(333 s); 199233828:G(285 s); 199073533:G(211 s); 199223977:G(198 s
01.12.2023     142108 XLAACCPB|Создать учет          594                59             35211 199396698:G(2855 s); 199370706:C(2698 s); 199368947:C(2111 s); 199367763:G(1586 s); 199491571:G(1388 s); 199485518:G(648 s); 199505900:C(592 s); 199474497:G(586 s); 199219598:G(318 s); 199220641:G(305
02.12.2023     142108 XLAACCPB|Создать учет          118               102             11983 199544748:G(2439 s); 199363043:G(1520 s); 199544739:G(1434 s); 199544740:C(901 s); 199544743:C(317 s); 199544779:C(299 s); 199544746:C(242 s); 199544735:G(229 s); 199544767:G(191 s); 199544736:C(177 s
03.12.2023     142108 XLAACCPB|Создать учет          191                92             17485 199628323:G(8455 s); 199595914:G(1848 s); 199533402:G(886 s); 199595901:G(152 s); 199595902:C(128 s); 199595909:C(128 s); 199595905:G(126 s); 199595933:G(123 s); 199595903:G(121 s); 199538759:G(112 s)
04.12.2023     142108 XLAACCPB|Создать учет          817               128            104705 199738741:G(15591 s); 199661557:G(8287 s); 199589754:G(6647 s); 199750985:G(6004 s); 199671819:E(3472 s); 199672009:C(3210 s); 199661103:G(2227 s); 199768058:G(1918 s); 199758135:C(1899 s); 199740896:
05.12.2023     142108 XLAACCPB|Создать учет          933               190            177643 199749495:G(37550 s); 199914412:C(13485 s); 199933244:C(10383 s); 199936952:C(9817 s); 199935890:C(8923 s); 199939253:C(7997 s); 199840713:C(6783 s); 199943198:C(5451 s); 199929287:E(4768 s); 19965925
06.12.2023     142108 XLAACCPB|Создать учет          871                81             70665 199994959:G(11521 s); 199858166:G(3938 s); 200084489:E(2928 s); 200020899:G(2254 s); 200038145:G(2193 s); 200101264:G(1918 s); 200098627:G(1904 s); 200091665:G(1403 s); 200039236:C(1365 s); 200027419:
07.12.2023     142108 XLAACCPB|Создать учет          386                94             36108 200017373:G(6791 s); 200270431:G(1803 s); 200357625:R(1622 s); 200295220:G(1261 s); 200313591:G(1121 s); 200292309:C(1101 s); 200270422:C(871 s); 200305312:G(858 s); 200287773:C(825 s); 200321585:C(72

11 rows selected

отразил флуктуации как суммарного (SUM_DURATION_SECS — на порядок), так и индивидуального времени выполнения, в частности, OEBS concurrent request (конкаррент) 199749495 выполнялся 37550, а 199738741 — 15591 секунд!:(

В процессе выполнения конкаррента 199738741 можно заметить стандартный sql_id 2s0c9hrnp6tdr с существенно отличными планами (SQL_PLAN_HASH_VALUE) и временами выполнения (ASH_ROWS PER_EXECS ROUGH_DURATION):

Oracle 19: ORDER BY in VIEW в присутствии PL/SQL и выбор View Merging | JPPD

Проблема проявилась в запросах типа:

SELECT DISTINCT G.REC_PRINT_ID,
                G.REC_REPORT_ID,
                H.PARTY_ID,
                apps.CUST_PACKAGE.GET_INFO('CUSTOMER_ID',H.PARTY_ID,H.K_HEADER_ID) CUSTOMER_ID -- any PL/SQL function
  FROM apps.CUST_TABLE G,
       apps.CUST_VIEW H -- view with ORDER BY
 WHERE G.REC_REPORT_ID = H.REC_REPORT_ID
   AND G.REC_GROUP_ID = :1;

с использованием view with ORDER BY и PL/SQL функции

При наличии всех необходимых индексов план выглядел пессимистично:

------------------------------------------------------------------------------------------------
| Id  | Operation                              | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |     4 |   148 |       |  9851K  (1)| 00:06:25 |
|   1 |  HASH UNIQUE                           |     4 |   148 |       |  9851K  (1)| 00:06:25 |
|*  2 |   HASH JOIN                            |     4 |   148 |       |  9851K  (1)| 00:06:25 |
|   3 |    JOIN FILTER CREATE                  |     4 |    76 |       |     4   (0)| 00:00:01 |
|   4 |     TABLE ACCESS BY INDEX ROWID BATCHED|     4 |    76 |       |     4   (0)| 00:00:01 |
|*  5 |      INDEX RANGE SCAN                  |     4 |       |       |     3   (0)| 00:00:01 |
|   6 |    VIEW                                |  6785K|   116M|       |  9851K  (1)| 00:06:25 |
|   7 |     SORT ORDER BY                      |  6785K|  1857M|    33G|  9851K  (1)| 00:06:25 |
|*  8 |      FILTER                            |       |       |       |            |          |
|   9 |       JOIN FILTER USE                  |   115M|    30G|       |  2720K  (2)| 00:01:47 |
|* 10 |        HASH JOIN RIGHT OUTER           |   115M|    30G|       |  2720K  (2)| 00:01:47 |
|* 11 |         INDEX RANGE SCAN               |    44 |       |       |     4   (0)| 00:00:01 |
|* 12 |         HASH JOIN RIGHT OUTER          |   115M|    25G|   126M|  2719K  (1)| 00:01:47 |
|* 13 |          TABLE ACCESS FULL             |  4406K|    75M|       |   521K  (1)| 00:00:21 |
|  14 |          TABLE ACCESS FULL             |   115M|    23G|       |   955K  (3)| 00:00:38 |
|* 15 |       COLLECTION ITERATOR PICKLER FETCH|    82 |   164 |       |    30   (4)| 00:00:01 |
------------------------------------------------------------------------------------------------

со странным комментарием в трейсе:

SVM:     SVM bypassed: ORDER BY clause.

, несмотря на:

SQL> @param+ _optimizer_order_by_elimination_enabled

NAME                                     SESS_VALUE INST_VALUE Default Value IS_MODIFIED IS_SESS_MOD IS_SYS_MOD IS_PDB_MODIFIABLE IS_ADJ   DSC
---------------------------------------- ---------- ---------- ------------- ----------- ----------- ---------- ----------------- -------- ------------------------------------------------------------
_optimizer_order_by_elimination_enabled  TRUE       TRUE       TRUE          FALSE       TRUE        IMMEDIATE  TRUE              FALSE    Eliminates order bys from views before query transformation

— до этого я как-то искренне считал, что проблема Order BY Elimination (OBYE) для Oracle 19 давно неактуальна

Легковоспроизводимый тесткейс с заменой VIEW -> INLINE VIEW и использованием inline PL/SQL function:

Oracle 19 CDB: замедление системного процесса CJQ0, оператор/операции CONTAINERS и баг с ожиданиями gc cr block lost для процессов параллельного выполнения

Во время периодически наблюдаемых (с коллегой Николаем Грузинцевым) приостановок выполнения заданий Scheduler Jobs, процесс CJQ0 (Job Queue Coordinator) периодически отвлекался от выполнения прямых обязанностей/координации, не всегда быстро, но неизменно параллельно выполняя служебные запросы типа a6frhy5cw03g6 и bmcj2k06ncg3y (*):

19.10@ SQL> with CJQ as
  2   (select distinct inst_id, session_id, session_serial#
  3      from gv$active_session_history
  4     where program like 'oracle@host_ins (CJQ_)')
  5  select inst_id,
  6         sql_id,
  7         sql_exec_id,
  8         count(*)                                          as seconds,
  9         listagg(distinct program, '; ')                   as program_list,
 10         listagg(distinct nvl(event, session_state), '; ') as wait_list,
 11         min(sample_time),
 12         max(sample_time)
 13    from gv$active_session_history
 14   where ((inst_id, session_id, session_serial#) in
 15         (select inst_id, session_id, session_serial# from cjq) or
 16         (qc_instance_id, qc_session_id, qc_session_serial#) in
 17         (select inst_id, session_id, session_serial# from cjq))
 18   group by inst_id, sql_id, sql_exec_id
 19   order by min(sample_time);

INST_ID SQL_ID        SQL_EXEC_ID    SECONDS PROGRAM_LIST                                    WAIT_LIST                                                    MIN(SAMPLE_TIME)           MAX(SAMPLE_TIME)
------- ------------- ----------- ---------- ----------------------------------------------- ------------------------------------------------------------ -------------------------- --------------------------
      2                                   61 oracle@host2ins (CJQ0)                          Disk file Mirror Read; ON CPU; control file sequential read; 06-ИЮН-23 11.28.15.364 AM  06-ИЮН-23 03.11.04.143 PM
                                                                                              oracle thread bootstrap                                                                
      2 5wua9ymkf2056    33566763          1 oracle@host2ins (CJQ0)                          ON CPU                                                       06-ИЮН-23 12.34.07.818 PM  06-ИЮН-23 12.34.07.818 PM
      2 a6frhy5cw03g6    33554471          2 oracle@host2ins (P01M); oracle@host2ins (P01N)  ON CPU                                                       06-ИЮН-23 01.56.43.266 PM  06-ИЮН-23 01.56.43.266 PM
      1 a6frhy5cw03g6    16777257        243 oracle@host1ins (P027)                          gc cr block lost; gc cr request                              06-ИЮН-23 02.02.08.772 PM  06-ИЮН-23 02.06.13.178 PM
      1                                    8 oracle@host1ins (CJQ0)                          ON CPU; oracle thread bootstrap                              06-ИЮН-23 02.10.21.198 PM  06-ИЮН-23 02.39.22.223 PM
      1 a6frhy5cw03g6    16777259        165 oracle@host1ins (P027)                          gc cr block lost; gc cr request                              06-ИЮН-23 02.25.08.649 PM  06-ИЮН-23 02.27.53.873 PM
      1 a6frhy5cw03g6    16777260        626 oracle@host1ins (P02E); oracle@host1ins (P02F)  gc cr block lost; gc cr multi block request; gc cr request   06-ИЮН-23 02.41.29.766 PM  06-ИЮН-23 02.52.02.334 PM -- *
      1 bmcj2k06ncg3y    16777238       1130 oracle@host1ins (P02F)                          ON CPU; gc cr block lost; gc cr request                      06-ИЮН-23 02.52.03.347 PM  06-ИЮН-23 03.11.04.101 PM -- *

8 rows selected

Oracle 19c: SQL запросы c PLAN_HASH_VALUE = 0 в ACTIVE SESSION HISTORY

Отображение в ASH sql-выполнений c PHV=0 успешно продолжается и, поскольку часто требуется оценить производительность/возможность ускорения запроса средствами SQL Plan Management (SPM) и кол-во выполнений может быть небольшим, желательно точно определить план в том числе для таких не совсем типичных выполнений
Тем более, что в отличие от 12c, в версиях 19c наюлюдаются обычные операции SELECT с заметным числом реальных выполнений, например: 8 из 50 выполнений (поля SQL_EXECS/SUM_SQL_EXECS) sql_id 3cz257gq4fxsp с зафиксированным PHV=0:

Oracle 23c New Feature против enq: SS — contention

Крайне ожидаемое улучшение — Improved System Monitor (SMON) Process Scalability:

…SMON is responsible for cleaning up temporary segments that are no longer in use. SMON checks regularly to see whether it is needed, and other processes can call SMON. Temporary space management can affect SMON’s scalability for other critical actions. This new enhancement instead uses the Space Management Coordinator (SMCO) process so that the responsibility of managing temporary space is offloaded from SMON, thereby improving its scalability.
This feature improves the overall scalability of the SMON process, particularly in a multitenant Oracle RAC cluster.

Типичная связанная проблема:

19.10@ SQL> @ash_sql_wait3_dev "event = 'enq: SS - contention'" 0 "gv$active_session_history ash where sample_time between to_date('25.08.2022 11:00','dd.mm.yyyy hh24:mi') and to_date('25.08.2022 11:01','dd.mm.yyyy hh24:mi')" "SQL WAIT"

LVL INST_ID BLOCKING_TREE XID EVENT                 WAIT_CLASS      Param[RAW]     WAITS_COUNT     EVENTS EXECS_COUNT AVG_WA SESS_COUNT BLOCKING_SID SQL_OPNAME      MIN_STIME                  MAX_STIME                  SQL_ID        TOP_LEVEL_SQL_ID SQL_PLAN_HASH
--- ------- ------------- --- --------------------- --------------- -------------- ----------- ---------- ----------- ------ ---------- ------------ --------------- -------------------------- -------------------------- ------------- ---------------- -------------
  1       2 (USER)            enq: SS - contention  Configuration                         4055       4055           0      0         94 VALID i#2                    25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM                                 0            
  1       2 (USER)            enq: SS - contention  Configuration                         2956       2956           0     31         62 VALID i#2    SELECT          25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  b79sx6p1rkxgy b79sx6p1rkxgy    707559059    
  1       2 (USER)         X  enq: SS - contention  Configuration                         2136       2136           0     61         65 VALID i#2                    25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM                                 0            
  1       2 (USER)            enq: SS - contention  Configuration                         1836       1836          41     34         41 VALID i#2    SELECT          25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  0c39p8nazk5ks 0c39p8nazk5ks    198979182    
  1       2 (USER)            enq: SS - contention  Configuration                          670        670          17      0         17 VALID i#2    INSERT          25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  a3xatmsxnm2cs a3xatmsxnm2cs    0            
  1       2 (USER)         X  enq: SS - contention  Configuration                          600        600          10      0         10 VALID i#2    SELECT          25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  1pmcxrujj1c27 1pmcxrujj1c27    3326359747   
  1       2 (USER)            enq: SS - contention  Configuration                          578        578           0      0         13 VALID i#2                    25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM                                 0            
  1       2 (P...)            enq: SS - contention  Configuration                          480        480           1      0          8 VALID i#2    SELECT          25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  0zjsjfv10n7n9 0zjsjfv10n7n9    1136233048   
  1       2 (J...)            enq: SS - contention  Configuration                          480        480           8      0          8 VALID i#2    PL/SQL EXECUTE  25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  0qbzfjt00pbsx 0qbzfjt00pbsx    0            
  1       2 (P...)            enq: SS - contention  Configuration                          420        420           1      0          7 VALID i#2    SELECT          25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  c0gv7nft03yt9 c0gv7nft03yt9    2134133020   
...
  2       2   (P...)       X  DFS lock handle       Other           1128857605 14        17423         60           1      0          1 NO HOLDER i# SELECT          25-АВГ-22 11.00.00.536 AM  25-АВГ-22 11.00.59.745 AM  dh412wkg65vzb dh412wkg65vzb    662588620    

52 rows selected

— какой-то пользовательский процесс (в данном случае PX-slave, обозначаемый как (P…)) на ожидании DFS lock handle типа Cross-Instance Call Invocation с p2 = 14 (*) выстраивает очередь желающих получить немного места во временных (TEMP) сегментах:

UNDO-чтения при параллельной обработке и эффективность индексов

Стандарный 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) в сравнении с предыдущим месяцем:

Особенности one-off patch 32753472 Many Slowdowns in «GCS DRM FREEZE IN ENTER SERVER MODE» Each Day

Ободрившись схожестью описываемых и наблюдаемых симптомов, включая:

$ less CDBORCL1_lmhb_68815.trc
*** 2023-01-17T11:52:14.159448+03:00 (CDB$ROOT(1))
kjgcr_CPUDisableDRM: one or more node is unhealthy, disabling DRM (act-id 45)

*** 2023-01-17T11:52:14.159466+03:00 (CDB$ROOT(1))
kjgcr_DoAction: KJGCR_ACTION - id:45 disable drm (cpu) ran with status:0 clr:1

*** 2023-01-17T11:52:14.159486+03:00 (CDB$ROOT(1))
kjgcr_CPUEnableDRM: All nodes now healthy, DRM enabled(act-id 47)

*** 2023-01-17T11:52:34.136672+03:00 (CDB$ROOT(1))
kjgcr_DoPreAction: KJGCR_PREACTION? disable drm (cpu) - id:45

*** 2023-01-17T11:52:34.136772+03:00 (CDB$ROOT(1))
kjgcr_DoAction: KJGCR_ACTION? disable drm (cpu) - id:45

*** 2023-01-17T11:52:34.136791+03:00 (CDB$ROOT(1))
kjgcr_CPUDisableDRM: one or more node is unhealthy, disabling DRM (act-id 45)
...

и тем фактом, что The fix for 32753472 is first included in 19.13.0.0.DBRU (т.е. включён в процесс DBRU и в составе работающих систем версии 19.13 проблем не вызывает), установили патч на нагруженную тестовую систему версии 19.10 со следующим неприятным рез-том:

— где «снежные вершины» на правой 2й ноде отразили существенно возросшие кластерные ожидания:

Рекурсивный sql_id gcfw4cgp0hh53 Oracle e-Business Suite R12.2.9

На инстансах EBS в зависимости от кол-ва и активности Concurrent Manager-ов общего назначения (****) в отчётах AWR можно видеть запросы типа:

SQL ordered by Elapsed Time           DB/Inst: CDB95H/CDB95H  Snaps: 1688-1690
-> Resources reported for PL/SQL code includes the resources used by all SQL 
   statements called by the code.
-> % Total DB Time is the Elapsed Time of the SQL statement divided 
   into the Total Database Time multiplied by 100
-> %Total - Elapsed Time  as a percentage of Total DB time
-> %CPU   - CPU Time      as a percentage of Elapsed Time
-> %IO    - User I/O Time as a percentage of Elapsed Time
-> Captured SQL account for   96.2% of Total DB Time (s):          81,300
-> Captured PL/SQL account for   47.4% of Total DB Time (s):          81,300

        Elapsed                  Elapsed Time                                   
        Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id    
---------------- -------------- ------------- ------ ------ ------ -------------
        17,141.3         97,683          0.18   21.1   99.3     .0 742prwzv0uf0d
Module: e:FND:cp:Stand_temp
   PDB: OEBS
Select R.Rowid From Fnd_Concurrent_Requests R Where R.Hold_Flag = 'N' And R.St
atus_Code = 'I' And R.Requested_Start_Date <= Sysdate And (R.Node_Name1 is nul
l or (R.Node_Name1 is not null and FND_DCP.target_node_mgr_chk(R.requ
est_id) = 1)) And (R.Edition_Name is null or R.Edition_Name <= sys_context

         8,593.6         48,863          0.18   10.6   99.3     .0 bw8114kz4rq3w
Module: e:FND:cp:STANDARD
   PDB: OEBS
Select R.Rowid From Fnd_Concurrent_Requests R Where R.Hold_Flag = 'N' And R.St
atus_Code = 'I' And R.Requested_Start_Date <= Sysdate And (R.Node_Name1 is nul
l or (R.Node_Name1 is not null and FND_DCP.target_node_mgr_chk(R.requ
est_id) = 1)) And (R.Edition_Name is null or R.Edition_Name <= sys_context

         7,642.7     24,716,221          0.00    9.4   99.5     .0 gcfw4cgp0hh53
Module: e:FND:cp:STANDARD
   PDB: OEBS
...

— при этом первые 2 (в этом случае) запроса непосредственно от дочерних процессов Concurrent Manager-ов выполняются со стабильным и совпадающим PLAN_HASH_VALUE:

SQL> select distinct sql_id, plan_hash_value from v$sql where sql_id in ('742prwzv0uf0d','bw8114kz4rq3w');

SQL_ID        PLAN_HASH_VALUE
------------- ---------------
bw8114kz4rq3w       855599798
742prwzv0uf0d       855599798

, а запросу с заметным кол-вом выполнений sql_id gcfw4cgp0hh53 посвящены отдельные ноты — Bug 31841845 : PERFORMANCE ISSUE WITH SQL ID GCFW4CGP0HH53 AFTER UPGRADE FROM 12.1 TO 12.2, патч из которой в нашем случае/конфигурации не сработал — никак не повлиял на изрядное кол-во выполнений:(

Oracle 19c bug: JPPD не работает в присутствии GROUP BY и TABLE expression

Некоторое время назад коллега-разработчик Рустам Кучукбаев обратил внимание на проблему, для которой мне удалось подготовить и выложить на Oracle Live SQL (для эффективного общения с поддержкой) до сих пор доступный тесткейс

Кратко:
, использование конструкции TABLE() (в любом месте запроса) в общем случае совместимо с использованием Join Predicate Push-Down (JPPD)
, Join Predicate Push-Down into Group by View использует механизм OJPPD = old-style (non-cost-based) JPPD
, и, хотя в обоих случаях результатом является похожая комбинация операций NESTED LOOPS OUTER + VIEW PUSHED PREDICATE, одновременное использование GROUP BY и TABLE expression не всегда совместимы и допускаются CBO

Соответствующий BUG 33490092: JPPD does not works if query contains GROUP BY и TABLE expression зарегистрирован, но проблема остаётся актуальной вплоть до версии 19.14 включительно (https://livesql.oracle.com), и, вероятно, далее

Под катом — технические детали теста