Хук system_cron() - время выполнения 7-8 минут

Главные вкладки

Аватар пользователя OldWarrior OldWarrior 1 июля 2020 в 17:29

На одном из подшефных сайтов обнаружилась проблема: хуки крона не успевают отрабатывать и предыдущий процесс, запущенный из crontab, всё ещё в работе при попытке запуска очередного задания. Периодичность запуска - порядка 5 минут (это необходимо для кастомного функционала отправки различных уведомлений). Сообщение об ошибке в журнале Друпала:

Attempting to re-run cron while it is already running.

Соответственно, хуки крона в текущем запуске не отрабатывают.
Путём анализа журнала был выявлен виновник: system_cron(). По интервалу времени с вызовом следующего хука было установлено длительность его выполнения: 7-8 минут. Что, конечно, слишком много. Ранее весь пул хуков hook_cron() выполнялся за минуту-другую. Т.е. проблема относительно недавняя.

Так, к сведению: размер БД по словам заказчика порядка 20Гб. Нод около 50 000.

Как временное решение - увеличили некоторые лимиты PHP и интервал запусков crontab (до 10 минут). Проблема вроде бы стала проявлять себя реже, но порой ошибка таки возникают.

В чём может быть причина и что может быть не так с system_cron()?

UPD. Немного уточнил описание проблемы.

Комментарии

Аватар пользователя ivnish ivnish 1 июля 2020 в 17:35
2

Рекомендую вынести кастомный функционал в drush функцию и дёргать её серверным кроном каждые 5 минут. Друпаловский крон при этом пусть работает раз в 1-3 часа как обычно

Аватар пользователя OldWarrior OldWarrior 1 июля 2020 в 17:42

ivnish wrote: Друпаловский крон при этом пусть работает раз в 1-3 часа как обычно

Друпаловский poormancron вообще отключили. Только запуски из кронтаба сервера.

Аватар пользователя ivnish ivnish 1 июля 2020 в 17:48
1

Я имел в виду не использовать крон друпала для запуска кастомных задач. Пусть крон друпала занимается своими делами типа проверки обновлений и удаления старых файлов

Неважно как запускается крон друпала : через веб или через крон сервера

Аватар пользователя Krotty@drupal.org Krotty@drupal.org 1 июля 2020 в 18:48

system_cron() делает всего две задачи - чистит таблицу flood и удаляет из таблицы file_managed и на диске временные файлы. Смотрите в этих направлениях.

Аватар пользователя marassa marassa 1 июля 2020 в 18:57

Krotty@drupal.org wrote: system_cron() делает всего две задачи - чистит таблицу flood и удаляет из таблицы file_managed и на диске временные файлы

Может с файловой системой что-то не так?

Аватар пользователя OldWarrior OldWarrior 1 июля 2020 в 19:32

Krotty@drupal.org wrote: удаляет из таблицы file_managed и на диске временные файлы

marassa wrote: Может с файловой системой что-то не так?

Тоже было смутное предположение на этот счёт. Но пока конкретных действий в этом направлении не делал - анализирую разные причины.

Кроме того, на конкретно этом сайте написан кастомный модуль для cleanup'а managed-файлов. Т.е. периодически выполняется чистка по собственным алгоритмам (удаление дубликатов и "потерянных файлов" ) и по конкретному дереву файловой структуры (кстати, самому ёмкому в плане размера). И поэтому вроде как особой нагрузки на крон в этом плане быть не должно. Но всё равно стоит проверить. Спасибо.

По-прежнему приветствуются альтернативные идеи/предположения/рекомендации.

Аватар пользователя marassa marassa 1 июля 2020 в 19:33
1

Я бы нашел код этого систем-крона и начал закомментаривать его куски прям в ядре и смотреть что выйдет. Для начала можно его вообще отключить, чтобы прямо, а не косвенно убедиться, что дело именно в нем.

Аватар пользователя OldWarrior OldWarrior 1 июля 2020 в 20:25

Спасибо.

Дело, в том что на продакшене подобная манипуляция требует определённой подготовки и согласования. Так же, как и предложенный выше вариант с комментированием тела хука system_cron(). Это всё можно сделать, но предварительно нужно забекапиться и обосновать клиенту необходимость этих пробных мер.

Есть и подобие dev-версии, полностью актуальной по коду и конфигурации, но уже в несколько неактуальном состоянии БД и контента. На ней такой проблемы нет. Т.е. - это проблема каких-то данных продакшена, судя по всему.

Аватар пользователя charOFF charOFF 1 июля 2020 в 20:58
1

system_cron еще чистит просроченные записи из кэш таблиц в бд. Посмотрите размеры таблиц в базе, может что-то разрослось. Объем базы мне кажется великоват. 50к нод это не так много. Можно еще глянуть медленные запросы, если лог включен, может там что-то будет.

Аватар пользователя OldWarrior OldWarrior 1 июля 2020 в 21:06

charOFF wrote: system_cron еще чистит просроченные записи из кэш таблиц в бд.

Да вот я тоже удосужился посмотреть system_cron(). Действительно, некоторая очистка кеша, expirable-значений, флуда и queues-очередей. Намёка на операции с managed-файлами не нашёл. А вот по поводу queues и батчей - тут возможно есть о чём подумать.

charOFF wrote: Объем базы мне кажется великоват.

Предметно БД пока не исследовал, но заказчик уверяет, что такой объём преимущественно из-за кеша.

Аватар пользователя charOFF charOFF 1 июля 2020 в 21:29

OldWarrior wrote: некоторая очистка кеша

да, вот здесь как раз очищаются expired строки из таблиц cache_*

<?php 
  
foreach (Cache::getBins() as $cache_backend) {
    
$cache_backend->garbageCollection();
  }
?>

OldWarrior wrote: expirable-значений

Это чистятся строки в таблице key_value_expire

Аватар пользователя Krotty@drupal.org Krotty@drupal.org 1 июля 2020 в 21:10
1

Да, я упустил этот момент, а он самый важный. Sad Обычно очень сильно разрастается таблица кэша форм cache_form.
Еще этот крон и батчи чистит, чтоб уж полностью упомянуть все его задачи. Smile

Аватар пользователя marassa marassa 1 июля 2020 в 21:03

charOFF wrote: Объем базы мне кажется великоват. 50к нод это не так много

Кстати да - у меня объем базы при таком же количестве нод в пределах 1ГБ.

Аватар пользователя OldWarrior OldWarrior 1 июля 2020 в 21:12

Думаю, количество, состав и множественность полей тоже имеют значение. Ещё около 5000 заказов коммерца по несколько позиций в каждом. Терминов, кстати, тоже несколько тысяч. Почти все обильно филдованные Smile

Аватар пользователя Krotty@drupal.org Krotty@drupal.org 1 июля 2020 в 21:13
1

OldWarrior wrote: Намёка на операции с managed-файлами не нашёл.

Вам надо было уточнить что речь идет о d8. С managed-файлами в кроне семерки делается зачиcтка.

Аватар пользователя OldWarrior OldWarrior 2 июля 2020 в 19:12

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

Размер БД сократился до 6 Гб. Видимо, таки был кеш или застрявшие батчи/очереди.

И, кстати, то, что всё решилось "само собой" - как-то напрягает, поскольку точная причина осталась невыясненной. Стало быть можно ждать прецедентов.

Аватар пользователя OldWarrior OldWarrior 3 июля 2020 в 18:07

Я думаю - вряд ли.

Кроме того, по свежим следам выявили ещё одну закономерность: system_cron() начинает тормозить, если по крону включена генерация XML sitemap. Причём, пока не очень понятно, как это связано - учитывая то, что у xml sitemap свой крон-хук и он отрабатывает самым последним в очереди - и отрабатывает в общем-то быстро. В итоге отключили регенерацию карты сайта по крону и решили регенерировать вручную.