Oracle Exadata 11.2.0.4, RAC на 4 ноды.

Наблюдаю в базе что некие процессы периодически ( нестабильно) работают медленней чем должны. Анализ показывает, что замедляют их некоторые запросы - например, некий запрос работает 30 минут вместо 30 секунд. Сравниваю планы и данные в этих запросах ( быстрое выполнение vs медленное ) - планы совершенно идентичны, outline совпадает до строчки, распределение данных тоже практически не меняется изо дня в день.
По awr тоже непонятно в чем проблема. Скажем анализ dba_hist_active_sess_history сгруппированный по event для плохого случая дает такую картину:

eventcount(*)ON CPU112reliable message64enq: RO - fast object reuse54cell smart table scan15enq: PS - contention2PX Deq: Signal ACK RSG2latch free1PX Deq: Signal ACK EXT1log file switch completion1library cache: mutex X1PX qref latch1

Не так много удалось найти по reliable message, гугл про enq: RO - fast object reuse говорит что-то о транкейтах и темповых таблицах, но это insert as select и ни одной темповой таблицы в запросе нет.

А вот тот же запрос с тем же планом на тех же данных но хорошее выполнение:

eventcount(*)/10ON CPU5.7direct path read temp0.5cursor: pin S wait on X0.3cell smart table scan0.3enq: RO - fast object reuse0.1

( цифры разделил на 10, т.к. второй раз цифры из gv$active_session_history, а первый - из db_hist_active_sess_hist ).

Сравнивая dba_hist_sqlstat для хорошего и плохого выполнения вижу что цифры похожи ( например , buffer_gets, физические чтения, количество прочитанных данных, показатели смартскана т.п. ) и только один показатель удивляет.
В то время как для "хорошего" выполнения мы имеем на 1 execution 9 parse_calls ( потому что DOP= 4, 8 дочерних сессий + 1 координатор ), то у "плохого" выполнения эти цифры составляют тысячи и десятки тысяч на 1 execution. Например такой запрос:



Выдает нам такую картину:

parse_callsexecutionsinvalidationssql_id48366167ryv0syzqb9kp4540410avc1dqza7pz7d4401616f66thvqhb2nvt374011567n6pbjpphfnm23812143ac0bmwc2uj282005610077fy92upp8d519744102znx8jhabd5r0

И вот это дико непонятно. Никто не сталкивался с таким? Доступа к металинку у меня пока нет.

xtenderValergrad,

Что там в sql in parse. Меняются ли sql exec id?

Не меняются, конечно, иначе бы я понял что дело в каких-то инвалидациях курсоров.

xtenderValergrad,
Сколько разных сессий там?


Как обычно, координатор + дочерние. В плане довольно много p->s, так что частенько остается только координатор.


xtenderValergrad,
Покажи что есть в ash по любому такому sqlid за проблемный период. Без группировок. Тупо в экселе выложи все строки.


Ок.

DВАСталкивался.
Включайте трассировку и поймаете ошибку, она как правило связана с динамическим сбором статистики во время парсинга

Немного не понял. Речь о том, что для парса оракл собирает какую-то статистику? И фейлится во время сбора этой статистики, что засчитывается как парс? ( Dynamic_sampling в плане не было, на всякий случай).
Трассировку будет трудно включить - т.к. происходит это только периодически, скажем, один ворклоу из 10. Заранее не угадаешь - пройдет или нет. И проблемным каждый раз оказывается разный запрос. Включить же трассу на весь воркфлоу - это убить весь прод.

На остальные вопросы отвечу в понедельник как будет доступ к рабочему компу.

feagorValergrad,



по тормозящему запросу посмотреть можно?

Этот запрос ничего не возвращает. Дело в том, что executions_delta по нему равен нулю ( хотя он совершенно точно выполнился и вставил данные ). В executions_total = 1. Если же убрать фильтр по executions_delta, то получается так:

BEGIN_INTERVAL_TIMEPLAN_HASH_VALUESQL_PROFILEEXECSELA_PER_EXEC_SECPX_PER_EXECROWS_PER_EXECFETCHES_PER_EXEC22-AUG-19 13.00.15.43240311011520791.169585810022-AUG-19 14.00.19.08040311011520489.865925000

Полный бред, потому что delta/total почему-то показывают противоречивую информацию по этому запросу.

xtenderValergrad,

Покажи что есть в ash по любому такому sqlid за проблемный период. Без группировок. Тупо в экселе выложи все строки. Что там в sql in parse. Меняются ли sql exec id? Сколько разных сессий там?

Выложил для Xtenderа и может еще кого полный лог dba_hist_active_sess_history. Возможно, сможете что-то увидеть в нем, наводящее на мысли. Запрос выполнялся 45 минут с таким же планом, с которым среднее время - 25 секунд.
( только поля dbid, program, module, action, machine занулил на всякий случай, а чтобы влезло в 150кб убрал session_type = 'FOREGROUND' для всех)

P.S. Пока выкладывал обнаружил очень странное поведение в sql_child_number. sql_child_number не только постоянно плавает, но еще и иногда равен -1.

Vadim LejninValergrad,

Согласно документу MOS, Вам рекомендуется обновить jdbc до 12.2

Боюсь, я не понял, какой документ, и почему jdbc? Как джава здесь учавствует?

Melkomyagkii_newbiНе похоже на https://iusoltsev.wordpress.com/2019/07/27/long-long-parse/#more-7585
?

Да не очень, там один длительный парс.

SeaGateValergrad,

"Высокий" parse_calls/executions типично для некоторых параллельных планов ( Parallel Fun – 2 )

Да, похоже это именно оно. У Льюиса точно такие же высокие цифры цифры px_servers_allocated и parse_calls как и у меня. И в структурах запроса и плана просматривается общее ( в запросе есть NOT EXISTS который превращается планом в FILTER, при этом эта постоянные переходы между DFO деревьями и смены DOP в плане). Льюис пишет:

авторOracle really did start and stop something like 6,700 PX session (constantly re-using the same small set of PX slave processes) for each execution of the filter subquery. This is definitely a performance threat – we keep acquiring and releasing PX slaves, we keep creating new sessions (yes, really), and we keep searching for cursors in the library cache. All these activities are highly contentious. If you start running multiple queries that do this sort of thing you find that you see increasing amounts of time being spent on latch contention, PX slave allocation, mutex waits, and all the other problems you get with sessions that log on, do virtually nothing, then log off in rapid succession.


Возможно на что-то такое мы и нарываемся периодически: еще раз тщательно покопаю.

xtender
Сразу видно, что SESSION_SERIAL# менялись: сначала слейв успел поработать, затем несколько раз перезапускался и парсил запрос снова

Да, почитайте по ссылке выше от Льюиса - Льюис именно об этом и пишет, что сессия создается на каждую строчку фильтра ( !!!).

SeaGatextender,

xtender тут гораздо важнее, что слейвы умирали и перезапускались, что легко увидеть, например, по SID 3008:
Это совершенно не важно на данном этапе с текущими данными. Это легко воспроизвести, используя ту ссылку, что я дал.

К сожалению металинковские ссылки я открыть пока не могу - возможно там что-то интересное. Но суть в том, что если
про "Bug 21422580 - DBWR Using 100% CPU With ENQ: RO - FAST OBJECT REUSE During Truncate Or Drop Table (Doc ID 21422580.8)"
то запрос простой инсерт ас селект, и он не использует таблицы, по которым кто-то еще в этот момент может их транкейтить или дропать. Поэтому я эту сторону особо не смотел.