Несовместимость и совместное использование SQL Patch и SQL Plan Baseline

Тесты с простым тестовым запросом проводились на версии 18c — там трассировка и комментарии Oracle полнее, хотя описываемые особенности известны и наблюдаемы, как минимум, с версии 12.1

Итак, для запроса одновременно созданы два элемента SPM — SQL Patch и SQL Plan Baseline:

18.0.0.0.SCOTT@localhost/ORCLCDB SQL> @spm_check4sql_id 2rv6gr3ufpa78

SIGNATURE             SPM_TYPE          SQL_HANDLE                     PATCH_NAME                     ORIGIN         VERSION    CREATED             LAST_MODIFIED       LAST_EXECUTED       ENABLED ACCEPTED FIXED REPROD PURGE ADAPT
--------------------- ----------------- ------------------------------ ------------------------------ -------------- ---------- ------------------- ------------------- ------------------- ------- -------- ----- ------ ----- -----
 17843842952808529353 SQL Patch         SQL_f7a2109ff6027dc9           2rv6gr3ufpa78_hash             MANUAL-SQLTUNE 18.0.0.0.0 26.07.2019 02:25:34 26.07.2019 02:25:34                     YES     NO       NO    YES    NO    NO
 17843842952808529353 SQL Plan Baseline SQL_f7a2109ff6027dc9           SQL_PLAN_gg8hhmzv04zf916ed3edf UNKNOWN        18.0.0.0.0 25.07.2019 04:09:23 25.07.2019 04:09:29 25.07.2019 04:09:29 YES     YES      YES   YES    YES   NO

, Baseline фиксирует индексный доступ:

SQL> @bl12_hints SQL_PLAN_gg8hhmzv04zf916ed3edf

OUTLINE_HINTS
--------------------------------------------------------------------------------
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('18.1.0')
DB_VERSION('18.1.0')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
FULL(@"SEL$1" "O"@"SEL$1")
INDEX(@"SEL$1" "P"@"SEL$1" ("PRODUCT_INFORMATION"."PRODUCT_ID"))
LEADING(@"SEL$1" "O"@"SEL$1" "P"@"SEL$1")
USE_NL(@"SEL$1" "P"@"SEL$1")
NLJ_BATCHING(@"SEL$1" "P"@"SEL$1")

, в то время как SQL Patch настроен на Hash Join / Full Table Scan:

SQL> @sqlpatch_hints 2rv6gr3ufpa78_hash

SQL_PATCH_HINTS
-------------------------------------------------------------
FULL(@"SEL$1" "P"@"SEL$1") USE_HASH(@"SEL$1" "P"@"SEL$1")

Long-long parse

Обсуждая с Юрием Пудовченко длительный разбор/long parse запроса, обратили внимание на расхождения отображение длительности процесса parsing-а в отчётах tkprof и V$ACTIVE_SESSION_HISTORY,
в то время как tkprof показывает:

, данные ASH говорят о том, что в течение этих 14 секунд запрос был как бы одновременно IN_SQL_EXECUTION, IN_PARSE, IN_HARD_PARSE с нулевым SQL_EXEC_ID, но уже правильно определившимся PLAN_HASH_VALUE (что, как будет видно, намекает на не совсем честное заполнение ASH методом postfactum)):

Трейс CBO/10053 и документы поддержки, конечно же, всё объясняют:

index on temp table is not parallelized

Столкнулся с принципиальной невозможностью форсировать параллельное выполнение даже на этапе EXPLAIN PLAN:

12.1.0.2.@ SQL> explain plan for
  2  WITH SubQuery_Fact AS
...
 21    SELECT /*+ PARALLEL(8) */
...

Explained.

SQL> select * from table(dbms_xplan.display('','','+alias +outline -predicate'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2199720476

-------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                   | Name                      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                            |                           |     3 |   966 | 67010   (1)| 00:00:03 |
|   1 |  HASH GROUP BY                              |                           |     3 |   966 | 67010   (1)| 00:00:03 |
|   2 |   NESTED LOOPS                              |                           |     3 |   966 | 67010   (1)| 00:00:03 |
|   3 |    NESTED LOOPS                             |                           |     1 |   269 | 67009   (1)| 00:00:03 |
|   4 |     NESTED LOOPS                            |                           |     1 |   256 | 67009   (1)| 00:00:03 |
|*  5 |      HASH JOIN                              |                           |     1 |   216 | 67009   (1)| 00:00:03 |
|*  6 |       HASH JOIN                             |                           |     8 |  1368 | 67007   (1)| 00:00:03 |
|*  7 |        TABLE ACCESS FULL                    |                           |     1 |    48 |     2   (0)| 00:00:01 |
|   8 |        NESTED LOOPS                         |                           | 22481 |  2700K| 67005   (1)| 00:00:03 |
|   9 |         NESTED LOOPS                        |                           | 22504 |  2700K| 67005   (1)| 00:00:03 |
|* 10 |          TABLE ACCESS BY INDEX ROWID BATCHED|                           | 22504 |  1384K| 57625   (1)| 00:00:03 |
|* 11 |           INDEX RANGE SCAN                  |                           | 90854 |       | 41250   (1)| 00:00:02 |
|* 12 |          INDEX UNIQUE SCAN                  |                           |     1 |       |     0   (0)| 00:00:01 |
|* 13 |         TABLE ACCESS BY INDEX ROWID         |                           |     1 |    60 |     0   (0)| 00:00:01 |
|* 14 |       TABLE ACCESS FULL                     |                           |     1 |    45 |     2   (0)| 00:00:01 |
|* 15 |      TABLE ACCESS BY INDEX ROWID BATCHED    |                           |     1 |    40 |     1   (0)| 00:00:01 |
|* 16 |       INDEX RANGE SCAN                      |                           |     1 |       |     0   (0)| 00:00:01 |
|* 17 |     INDEX UNIQUE SCAN                       | MO_GLOB_ORG_ACCESS_TMP_U1 |   128 |  1664 |     0   (0)| 00:00:01 |
|  18 |    TABLE ACCESS BY INDEX ROWID              | SOME_CUSTOM_TABLE         |    11 |   583 |     1   (0)| 00:00:01 |
|* 19 |     INDEX UNIQUE SCAN                       | SOME_CUSTOM_TABLE_U1      |     1 |       |     0   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------------------

Outline Data
-------------
...
Note
-----
   - Degree of Parallelism is 1 because of hint -- *

— т.е. текст запроса форсирует /*+ PARALLEL(8) */, а DBMS_XPLAN.DISPLAY использует DOP 1 because of hint (*) => когнитивный диссонанс detected)

Особенности, наблюдаемые при применении подсказки STATEMENT_QUEUING

Особенность первая

Проблема с непараллельным выполнением казалось бы гарантированно захинтованного запроса, SQL Monitor которого показывал:

SQL Text
------------------------------
select /*+ STATEMENT_QUEUING PARALLEL(16) */...

Global Information
------------------------------
 Status              :  DONE (ERROR)
...
 SQL ID              :  64mga9tafr17z
 SQL Execution ID    :  50331648
 Execution Started   :  07/01/2019 11:23:28
 First Refresh Time  :  07/01/2019 11:23:28
 Last Refresh Time   :  07/01/2019 13:33:25
 Duration (Queued)   :  7797s (83s)
...
 DOP Downgrade       :  100%                -- *
 Fetch Calls         :  1

Binds
...

Global Stats
==================================================================================================================================================
| Elapsed | Queuing |   Cpu   |    IO    | Application | Concurrency | Cluster  | Fetch | Buffer | Read | Read  | Write | Write |    Offload     |
| Time(s) | Time(s) | Time(s) | Waits(s) |  Waits(s)   |  Waits(s)   | Waits(s) | Calls |  Gets  | Reqs | Bytes | Reqs  | Bytes | Returned Bytes |
==================================================================================================================================================
|    8705 |      83 |    2573 |     1836 |        0.00 |        0.00 |     4213 |     1 |   647M |  11M |  42GB |  7387 |   2GB |            2GB |
==================================================================================================================================================

SQL Plan Monitoring Details (Plan Hash Value=47594419)
=================================================================================================================================================================================================
| Id  |    Operation          |      Name      |  Rows   | Cost  |   Time    | Start  | Execs |   Rows   | Read | Read  | Write | Write |  Mem  | Temp  | Activity |         Activity Detail    |
|     |                       |                | (Estim) |       | Active(s) | Active |       | (Actual) | Reqs | Bytes | Reqs  | Bytes | (Max) | (Max) |   (%)    |           (# samples)      |
================================================================================================================================================================================================
|   0 | SELECT STATEMENT      |                |         |       |       100 |     +2 |     1 |        0 |      |       |       |       |     . |     . |     4.93 | cursor: pin S wait on X (8)| -- ***
|     |                       |                |         |       |           |        |       |          |      |       |       |       |       |       |          | library cache lock (303)   | -- ***
|     |                       |                |         |       |           |        |       |          |      |       |       |       |       |       |          | resmgr:pq queued (80)      | -- **
|   1 |   PX COORDINATOR      |                |         |       |         1 |    +84 |     1 |        0 |  576 |   2MB |       |       |     . |     . |     0.01 | Cpu (1)                    |
|   2 |    PX SEND QC (ORDER) | :TQ60024       |       1 |    2M |           |        |     1 |          |      |       |       |       |     . |     . |          |                            |
...
| 192 |     INDEX UNIQUE SCAN | SYS_C002853735 |       1 |       |           |        |       |          |      |       |       |       |     . |     . |          |                            |
=================================================================================================================================================================================================

ASH CPU trace

Запрос со ср.временем выполнения 3,7 мс периодически выполняется 22 секунды (*):

12.1.0.2@ SQL> @shared_cu12 4g02xxnvrk8j9 0

 EXECS LAST_LOAD_TIME      ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC 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 NOT_SHARED_BY  REASON                          SQL_PLAN_BASELINE SQL_PATCH              OUTLINE_CATEGORY SQL_PROFILE IS_OBSOLETE
------ ------------------- ------------- ------------ ------------ ------------- -------------- ------------ ------------- --------------- -------------------- ---------- -------------- ----- ---------- ---------- ---------- --- ----- ----------- ----------- --------- --------- --------- -------- --- -------------- ------------------------------- ----------------- ---------------------- ---------------- ----------- -----------
  9050 2019-06-05/10:12:04             1         3665         1076           291              0         2241            32       763530515            311975141 ALL_ROWS              429    53 N          N          Y              N                 N                                                      PURGED_CURSOR  Bind UACs mismatch(0)                             NO_ADAPT_4g02xxnvrk8j9                              N
                                                                                                                                                                                                                                                                                                                             Auto Reoptimization Mismatch(1)                                                                                            

1 rows selected
...

--------------------------------------------------------------
ASH TOP5 SQL_ID=4g02xxnvrk8j9 Executions by Elapsed Time
--------------------------------------------------------------

INST_ID SQL_ID        SQL_PLAN_HASH_VALUE SQL_FULL_PLAN_HASH_VALUE SQL_EXEC_ID   ASH_ROWS DURATIONs                 MIN_SAMPLE_TIME    MAX_SAMPLE_TIME
------- ------------- ------------------- ------------------------ ----------- ---------- ------------------------- ------------------ -----------------
      1 4g02xxnvrk8j9           763530515                311975141                     30 +000000000 12:26:39.998   04.06.19 20:54:28  05.06.19 09:21:08
      1 4g02xxnvrk8j9           763530515                311975141    18306846         22 +000000000 00:00:21.070   05.06.19 03:02:22  05.06.19 03:02:43 -- *
      1 4g02xxnvrk8j9                   0                311975141                      5 +000000000 08:07:56.983   05.06.19 00:03:32  05.06.19 08:11:29
      1 4g02xxnvrk8j9           763530515                311975141    18404662          3 +000000000 00:00:02.010   05.06.19 04:40:39  05.06.19 04:40:41
      1 4g02xxnvrk8j9           763530515                311975141    18506517          3 +000000000 00:00:02.010   05.06.19 06:36:50  05.06.19 06:36:52
...

— учитывая, что SQL Patch NO_ADAPT_4g02xxnvrk8j9 применяется как стандартное средство отключения адаптивных фич на уровне запроса и не способен повлиять на отдельное выполнение, остаётся вопрос, что же замедлило выполнение запроса SQL_EXEC_ID = 18306846 ?

Особенности Oracle Real-Time SQL Monitoring

В процессе анализа запросов удобно использовать SQL Monitor через процедуру DBMS_SQLTUNE.REPORT_SQL_MONITOR напрямую или через OEM/OCM/SQL Developer

Полезно при этом иметь в виду некоторые «врождённые» особенности отображения статистики выполнения запроса, как я полагаю, неизменные с версии 11g:

1) Если в процессе выполнения запрос, например, через PL/SQL функции вызывает рекурсивные запросы (классический пример — Oracle E-Business Suite), эти рекурсивные в выводе SQL Monitor на отражаются почти никак*:

PDB 12.2: Ожидание cursor: pin S wait on X, неявные рекурсивные запросы и Bug 25054064

С Максимом Филатовым рассматривали кейс с заметным кол-вом ожиданий cursor: pin S wait on X в том месте/тесте, где их быть по идее быть не должно

По данным AWR проблема выглядела следующим образом:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Avg   % DB Wait    
Event                                Waits Time (sec)      Wait   time Class   
------------------------------ ----------- ---------- --------- ------ --------
DB CPU                                          13,9K             32.6         
cursor: pin S wait on X             30,552      13,3K  436.29ms   31.2 Concurre -- проблема тут
direct path read                 2,599,928     7007,6    2.70ms   16.4 User I/O
...
SQL ordered by Elapsed Time

Elapsed Time (s)  Executions  Elapsed Time per Exec (s) %Total  %CPU  %IO   SQL Id        PDB  Name SQL Text
9,966.54          1           9,966.54                  20.77   32.51 43.03 0894g8ba3tyv6 PDB1 insert /*+ append parallel(32)... -- тестовый запрос, формально страдающий от этих ожидания
8,601.63                                                17.92    7.01       8fsc5qtsv33x1 PDB1                                   -- (*) запрос неясной природы, без SQL Text, Executions,...
8,578.76          1           8,578.76                  17.88   34.37 47.76 cms2kju6wfmp9 PDB1 insert /*+ append parallel(32)... -- тестовый запрос, формально страдающий от этих ожидания
*/
...
Mutex Sleep Summary
ordered by number of sleeps desc
Mutex Type         Location                              Sleeps   Wait Time (ms)
Cursor Pin         kkslce [KKSCHLPIN2]               12,662,512       12,933,116          -- заметный максимум
Cursor Parent      kkscsAddChildNode [KKSPRTLOC28]      836,063          457,151
...

Oracle 12.2: Неуникальность PLAN_HASH_VALUE для адаптивных планов выполнения

Предыдущее наблюдение касалось обычных (неадаптивных) планов выполнения, адаптивные планы демонстрируют тот же эффект в версии 12.2, что логично и любопытно выглядит

Итак, запрос с нестабильным / небыстрым выполнением показывает признаки адаптивности — столбцы «V$SQL.Adapt», «XML.Adapt» (V$SQL_PLAN.OTHER_XML), плюс BIND_SENSE=Y — т.е. чувствителен к значениям связанных переменных, но для применения Adaptive Cursor Sharing оказался не готов — BIND_AWARE=N:

Oracle 12.2: неоднозначность определения PLAN_HASH_VALUE

Начиная с версии 12.2 часто наблюдаю, как 2 плана выполнения с различными PHV используются для обозначения одного и того же фактического плана выполнения

Например, запрос в анамнезе показывает 2 несовпадающих PLAN_HASH_VALUE при эквивалентной паре (FULL_PLAN_HASH_VALUE, PLAN_HASH_2):

SQL>  @sql_plan_hashs cj1sg1hk1n3ct

SRC SQL_ID        FULL_PLAN_HASH_VALUE PLAN_HASH_VALUE PLAN_HASH_2 TIMESTAMP
--- ------------- -------------------- --------------- ----------- --------------------
AWR cj1sg1hk1n3ct           2164351587      2164351587  2164351587 26.02.2019 17:37:36
AWR cj1sg1hk1n3ct           2164351587      3400946657  2164351587 26.02.2019 17:29:31

При этом, PHV=2164351587 и PHV=3400946657 по содержимому совпадают абсолютно:

Oracle LiveSQL 19c. Вопросы Real-Time Statistics и DYNAMIC SAMPLING при добавлении партиций

Продолжая тесты с Oracle LiveSQL 19c, проверил наличие проблемы с плохими FULL SCAN-ами при [авто]добавлении [INTERVAL] PARTITION в процессе каждодневной DML активности и запросами с условием IN

Тестовая таблица простая, и в процессе первоначальной Direct PATH загрузки партиции добавляются, по крайней мере global statistics успешно собирается: