Пропатчили Oracle 10.2.0.4 --> 10.2.0.5, linux.

2 почти одинаковых sched_jobs, выполняющих процедуру (выгрузку select'а в файл на диск).
Одна процедура работает регулярно 3 раза в час по 30 сек,
вторая запускается по правильному расписанию ,
первый раз выполняется за 1,5 мин, как и должно, а в следующий раз 14:57 часов, потом 1,5 мин, потом 14:37 часов.

А до установки 10.2.0.5, работала нормально по 1,5 мин

Куда копать?

Если вручную многократно выполнить Run job, то он выполняется нормально по 1,5 мин.

Джоб такой:
автор SYS.DBMS_SCHEDULER.CREATE_JOB
(
job_name => 'CENTER.ISHOP_HOURLY'
,start_date => TO_TIMESTAMP_TZ('2016/01/27 00:00:00.000000 +03:00','yyyy/mm/dd hh24:mi:ss.ff tzr')
,repeat_interval => ' Freq=Daily;ByHour=10,12,14,16,18,20,22;ByMinute=00 '
,end_date => NULL
,job_class => 'DEFAULT_JOB_CLASS'
,job_type => 'PLSQL_BLOCK'
,job_action => ' unload_ishoprest ;'
,comments => NULL
);

На 10.2.0.4 сработал прекрасно за 1,5 мин,

14.02.2019 пропатчила БД 10.2.0.4 --> 10.2.0.5, БД открылась 10:05,
т.е. один запуск джоба по расписанию в 10:00 был пропущен,
следующий запуск джоба по расписанию в 12:00 выполнился нормально,
а дальше, с 2019/02/14 14:00, началась свистопляска.

Если из процедуры unload_ishoprest выполнить отдельно только select, то он выполняется за 1,5 мин.
Если вручную запустить процедуру unload_ishoprest , то она выполняется за 1,5 мин.

Программист-автор смотрел план заспроса, когда джоб выполнялся несколько часов, в плане все нормально.

Грешила на 10.2.0.5, но на тестовом сервере, который был пропатчен неделей ранее, всё работает прекрасно.



Log DateStatusRequired Start DateActual Start DateRun DurationCPU UsedAdditional Info (Run)2019/02/20 14:57:34.010430 +03:00STOPPED2019/02/20 10:00:00.500000 +03:002019/02/20 14:56:04.385355 +03:00+000 00:01:30+000 00:00:00.00REASON="Job slave process was terminated"2019/02/20 14:56:04.383284 +03:00STOPPED2019/02/19 20:00:00.400000 +03:002019/02/20 08:26:13.530834 +03:00+000 06:29:51+000 00:00:00.00REASON="Job slave process was terminated"2019/02/20 08:26:13.528606 +03:00SUCCEEDED2019/02/19 18:00:00.500000 +03:002019/02/19 18:00:02.443857 +03:00+000 14:26:11+000 00:03:40.912019/02/19 17:14:14.997110 +03:00SUCCEEDED2019/02/19 10:00:00.500000 +03:002019/02/19 17:12:40.538634 +03:00+000 00:01:34+000 00:00:48.522019/02/19 17:12:40.537116 +03:00SUCCEEDED2019/02/18 14:00:00.700000 +03:002019/02/19 02:07:47.455821 +03:00+000 15:04:53+000 00:03:23.732019/02/19 02:07:47.453525 +03:00SUCCEEDED2019/02/18 12:00:00.700000 +03:002019/02/18 12:00:01.732581 +03:00+000 14:07:46+000 00:04:23.252019/02/18 10:01:43.127428 +03:00SUCCEEDED2019/02/18 10:00:00.300000 +03:002019/02/18 10:00:02.710587 +03:00+000 00:01:40+000 00:00:47.782019/02/18 07:33:20.928841 +03:00STOPPED2019/02/17 16:00:00.200000 +03:002019/02/18 04:37:38.410920 +03:00+000 02:55:43+000 00:00:59.72REASON="Stop job called by user: 'CENTER'"2019/02/18 04:37:38.408738 +03:00SUCCEEDED2019/02/17 14:00:00.000000 +03:002019/02/17 14:00:00.163232 +03:00+000 14:37:38+000 00:03:43.712019/02/17 12:59:31.754189 +03:00SUCCEEDED2019/02/17 10:00:00.700000 +03:002019/02/17 12:57:53.021292 +03:00+000 00:01:39+000 00:00:52.762019/02/17 12:57:53.019346 +03:00SUCCEEDED2019/02/16 22:00:00.500000 +03:002019/02/16 22:00:01.692665 +03:00+000 14:57:51+000 00:03:38.342019/02/16 20:01:39.732939 +03:00SUCCEEDED2019/02/16 20:00:00.700000 +03:002019/02/16 20:00:02.518800 +03:00+000 00:01:37+000 00:00:53.352019/02/16 19:52:37.712759 +03:00SUCCEEDED2019/02/16 10:00:00.500000 +03:002019/02/16 19:50:51.708151 +03:00+000 00:01:46+000 00:00:58.402019/02/16 19:50:51.706804 +03:00SUCCEEDED2019/02/15 18:00:00.200000 +03:002019/02/16 06:10:06.522883 +03:00+000 13:40:45+000 00:03:48.80 изменилось поведение sched_job странно он запустился2019/02/16 06:10:06.520993 +03:00SUCCEEDED2019/02/15 16:00:00.000000 +03:002019/02/15 16:00:00.150182 +03:00+000 14:10:06 +000 00:03:33.852019/02/15 14:01:45.207342 +03:00SUCCEEDED2019/02/15 14:00:00.100000 +03:002019/02/15 14:00:00.995692 +03:00+000 00:01:44+000 00:00:54.632019/02/15 12:00:18.410285 +03:00STOPPED2019/02/15 12:00:00.800000 +03:002019/02/15 12:00:02.127875 +03:00+000 00:00:16+000 00:00:00.00REASON="Job slave process was terminated"2019/02/15 10:01:27.907312 +03:00STOPPED2019/02/15 10:00:00.100000 +03:002019/02/15 10:00:00.815074 +03:00+000 00:01:27+000 00:00:00.00REASON="Job slave process was terminated"2019/02/14 22:01:24.785442 +03:00STOPPED2019/02/14 22:00:00.200000 +03:002019/02/14 22:00:01.097749 +03:00+000 00:01:24+000 00:00:00.00REASON="Job slave process was terminated"2019/02/14 20:01:43.557096 +03:00SUCCEEDED2019/02/14 20:00:00.400000 +03:002019/02/14 20:00:02.161676 +03:00+000 00:01:41+000 00:00:52.022019/02/14 18:01:37.370290 +03:00SUCCEEDED2019/02/14 18:00:00.500000 +03:002019/02/14 18:00:02.351515 +03:00+000 00:01:35+000 00:00:46.872019/02/14 16:00:15.300037 +03:00STOPPED2019/02/14 16:00:00.200000 +03:002019/02/14 16:00:01.524233 +03:00+000 00:00:14+000 00:00:00.00REASON="Job slave process was terminated"2019/02/14 14:01:15.625968 +03:00STOPPED2019/02/14 14:00:00.500000 +03:002019/02/14 14:00:01.189565 +03:00+000 00:01:14+000 00:00:00.00REASON="Job slave process was terminated"2019/02/14 12:01:36.782099 +03:00SUCCEEDED2019/02/14 12:00:00.300000 +03:002019/02/14 12:00:01.546299 +03:00+000 00:01:35+000 00:00:47.11 в 2019/02/14 10:05 запустила БД 10.2.0.5 2019/02/13 22:01:27.137892 +03:00SUCCEEDED2019/02/13 22:00:00.000000 +03:002019/02/13 22:00:00.137666 +03:00+000 00:01:27+000 00:00:44.252019/02/13 20:01:26.196185 +03:00SUCCEEDED2019/02/13 20:00:00.000000 +03:002019/02/13 20:00:00.453759 +03:00+000 00:01:26+000 00:00:45.222019/02/13 18:01:26.643029 +03:00SUCCEEDED2019/02/13 18:00:00.000000 +03:002019/02/13 18:00:00.131502 +03:00+000 00:01:27+000 00:00:44.232019/02/13 16:01:26.143726 +03:00SUCCEEDED2019/02/13 16:00:00.000000 +03:002019/02/13 16:00:00.147261 +03:00+000 00:01:26+000 00:00:44.442019/02/13 14:01:20.845085 +03:00SUCCEEDED2019/02/13 14:00:00.000000 +03:002019/02/13 14:00:00.146162 +03:00+000 00:01:21+000 00:00:38.952019/02/13 12:01:24.530894 +03:00SUCCEEDED2019/02/13 12:00:00.000000 +03:002019/02/13 12:00:00.227580 +03:00+000 00:01:24+000 00:00:42.472019/02/13 10:01:27.424689 +03:00SUCCEEDED2019/02/13 10:00:00.000000 +03:002019/02/13 10:00:00.258134 +03:00+000 00:01:27+000 00:00:41.35

Сервер работает в штатном режиме, не особо загружен, как обычно.
Если бы сервер был загружен, я бы сюда бы не писала.
вручную джоб запускали многократно, раз по 5 подряд, выполняется по 1,5 мин, потом через несколько минут он запускается по расписанию и зависает.

Все остальные джобы работают нормально, кроме этого, который не самый тяжёлый.

jan2aryAliona,

А график пересекается с майнтенанс джобами? Может еще ресурс менеджер зарезал?

Не пересекается с майнтенанс джобами.
ресурс менеджер - сейчас посмотрю.

andrey_anonymousОднако первые сутки после апгрейда предположительно работало штатно,
...
...
Нет, не работало штатно первые сутки,
ждоб запускается каждые 2 часа, только днём:10,12,14,16, 18 , 20,22

14/02/2019 Один раз (первый) сработал штатно в 12:00
Поэтому я и подумала, что 10.2.0.5 виноват

123ййAliona,

кол-во доступных джобов хватает ?

*.job_queue_processes=20
Сейчас сервер очень мощный, все джобы выполнятся быстро, поэтому одновременно не работает более 10 шт.

andrey_anonymousКроме того, апгрейд БД мог быть поводом донакатить функционал - технологический перерыв же.


Простите мою темноту, донакатить функционал - это что?
Прикладное ПО написано лет 20 назад на oracle 8.

andrey_anonymousИзменение в поведении может быть связано:
- С "поехавшими" планами (изучать v$sql на предмет чилдов, сравнивать их планы)

Если вручнкю процедуру джоб , то один план,1.5 мин,
через 5 мин стартует джоб по расписанию - другой план на 14 часов,
через пару часов убиваю джоб и запускаю вручную джоб, опять другой план, 1.5 мин.

Так бывает?

andrey_anonymous- С багом, который пролечен на тесте но не пролечен на продуктиве.
...
На тесте развернула ПО промышленного сервера и развернуда БД и бэкапа пром БД.
Выполнила патчи
10.2.0.4 -> 10.2.0.5 (p8202632)
10.2.0.5 -> 10.2.0.5.12 (p16619894, OPatch 6880880)
10.2.0.5.12 -> patch dblink on 10.2.0.5.12 (p14121009)

Тут джоб работает нормально.


Через неделю 14.02.2019 на проме выполнила патч
10.2.0.4 -> 10.2.0.5 (p8202632)
джоб "съехал" почти сразу

18.02.2019 оставшиеся патчи
10.2.0.5 -> 10.2.0.5.12 (p16619894, OPatch 6880880)
джоб работает через пень-колоду, то 1,5 мин, то 14 часов
10.2.0.5.12 -> patch dblink on 10.2.0.5.12 (p14121009)

123ййAliona,

а если пересоздать джоб ?
пересоздавали несколько раз.

andrey_anonymousAlionaЕсли вручнкю процедуру джоб , то один план,1.5 мин,
через 5 мин стартует джоб по расписанию - другой план на 14 часов,
через пару часов убиваю джоб и запускаю вручную джоб, опять другой план, 1.5 мин.

Ну так тут и копать...
Я уже не помню, что там в 10.2.0.5 из новофич забекпортили, но если просто игры в статистику не помогут, то 10053 никто не отменял.

Я не сказала что, через 5 мин стартует джоб по расписанию - другой план на 14 часов,
Я спросила может ли так быть, чтобы план меняется каждые 5 мин.
(в БД ничего особого не грузится и не происходит много изменений,так чтобы плпны съезжали каждые 5 мин)

Совсем забыла,
трассировку снимала 10 мин, когда запрос висел
exec sys.dbms_system.set_ev(3227, 894, 10046, 12, '');
exec sys.dbms_system.set_ev(3227, 894, 10046, 0, '');


tkprof sunset_ora_200893.trc output=sunset_ora_200893.out explain=ххх sys=no

файл трассировки

andrey_anonymousЯ уже не помню, что там в 10.2.0.5 из новофич забекпортили, но если просто игры в статистику не помогут, то 10053 никто не отменял.

Статистика считается, как надо, с этого начала всё проверять.

Oracle 11.2.0.1 вышел 15.08.2009
...
Oracle 11.2.0.4 вышел 27.08.2013

Патч 10.2.0.5 вышел в 29.04.2010, предполагаю, что на этом патче мало кто работал.

Мы получила приказ не него перейти СРОЧНО, без всяких проверок и тестов, мои возражения никто не слушал :(
Вот теперь хлебаем, разгребаем ...

Stax
план может зависеть и от НЛС настроек, мож они разные для "ручного" запуска и джоба


их я уже смотрела.
ещё надо на тестовом сервере посмотреть.