Magento 2 cron_schedule op 14M rijen: een vrijdagpostmortem

De ping van 16:42

Vrijdagmiddag. Een Nederlands bureau waar we mee werken pingde ons om 16:42 omdat hun Magento 2.4.6-shop geen admin-saves meer accepteerde. De pagina draaide dertig seconden en gaf dan een generieke 500 terug. De frontend stond technisch nog overeind, maar elke categoriepagina deed acht tot twaalf seconden over de eerste byte. Ze hebben een ops-team van 22 man, maar het was vrijdag, de helft was al onderweg naar huis, en de shop draait een fors deel van zijn weekendomzet tussen 18:00 en 22:00.

Voor we de database aanwezen, hebben we in negentig seconden de voorkant van de stack uitgesloten. PHP-FPM zat op 71% utilisation over zijn 32 workers, niet vastgepind. Redis antwoordde op PING in 0,4 ms en had 18% geheugenmarge over. Varnish liet admin-verkeer netjes door zoals geconfigureerd, maar zijn backend-timing-log toonde 28 seconden wachten op elke admin-route. Opcache was warm en draaide niet vol. De vertraging zat downstream van PHP, en dat liet één plek over om te kijken.

Het eerste dat we de on-call developer lieten doen, was de MySQL-prompt openen en een SHOW PROCESSLIST draaien. De output verraadde alles. Drie van de bovenste rijen waren Sending data op de cron_schedule-tabel, en de oudste draaide al 412 seconden. Het volgende dat we vroegen was het aantal rijen.

SELECT COUNT(*) FROM cron_schedule;
-- 14.217.883

Ter context: een gezonde Magento 2 cron_schedule-tabel zit tussen een paar honderd en een paar duizend rijen. Veertien miljoen krijg je als de ingebouwde cleanup maanden niet meer heeft gedraaid en de cron-dispatcher al die tijd elke minuut blijft vuren.

Wat veertien miljoen rijen in cron_schedule eigenlijk betekent

De cron_schedule-tabel is een queue. Elke job die in een crontab.xml staat over alle geïnstalleerde modules krijgt een paar minuten in de toekomst een rij ingepland, schuift dan door pending, running en uiteindelijk success of error. Een job genaamd system_cron_clean_history hoort rijen ouder dan de ingestelde lifetime te verwijderen. Die cleanup is zelf een cron-job. Als iets de cleanup blokkeert, groeit de tabel. Als de tabel boven een bepaalde grootte komt, wordt de cleanup zelf trager. Daarna besteedt elke cron-tick meer tijd aan het scannen van cron_schedule dan aan nuttig werk.

De diagnostische query die we altijd als eerste draaien op een zieke Magento-shop:

SELECT status, COUNT(*) AS n
FROM cron_schedule
GROUP BY status
ORDER BY n DESC;

-- pending     11.402.118
-- success      2.701.455
-- missed         108.773
-- error            5.537

Elf miljoen pending rijen is de killer. De Magento cron-dispatcher laadt bij elke tick de pending rijen in om te bepalen wat er moet draaien. Zonder de juiste index-hit valt de planner terug op een full scan voor iets dat vijf microseconden hoort te kosten. Ondertussen triggert een merchant-save in admin een indexer-reschedule, die schrijft naar cron_schedule, en die INSERT stond nu in de wachtrij achter zeven readers. Vandaar de draaiende admin-pagina.

Ter bevestiging vroegen we de planner wat hij eigenlijk deed met de leesquery van de dispatcher:

EXPLAIN SELECT * FROM cron_schedule
WHERE status = 'pending' AND scheduled_at <= NOW()
ORDER BY scheduled_at ASC;

-- type:          ALL
-- possible_keys: IDX_STATUS, IDX_SCHEDULED_AT
-- key:           NULL
-- rows:          14217883
-- Extra:         Using where; Using filesort

type: ALL met key: NULL betekent dat de planner naar de indexes heeft gekeken, de selectivity heeft afgewogen en alsnog voor een full table scan koos. Met elf van de veertien miljoen rijen in pending is de status-index nutteloos. De planner besloot terecht dat de hele tabel scannen goedkoper was dan een index doorlopen die 80% van de rijen teruggeeft. De fix is geen betere index. De fix is minder rijen.

De prune die we draaiden en de lock die we accepteerden

Er zijn twee redelijke manieren om uit een gigantische InnoDB-tabel te verwijderen. De eerste is een gechunkte DELETE in een shell-loop. De tweede is een swap met CREATE TABLE LIKE en RENAME TABLE. De eerste is veiliger als er veel writers actief zijn en je uren mag malen. De tweede is sneller, maar je ruilt het in voor een korte read-lock tijdens de kopie en een atomaire flip op het eind.

We kozen voor de swap omdat de cron-dispatcher de MySQL-connection pool op het punt stond op te stoppen, voorbij het punt waar de frontend nog nieuwe sessions kon openen. De swap ziet er zo uit.

CREATE TABLE cron_schedule_new LIKE cron_schedule;

INSERT INTO cron_schedule_new
SELECT * FROM cron_schedule
WHERE scheduled_at > DATE_SUB(NOW(), INTERVAL 6 HOUR)
  AND status IN ('pending','running');

RENAME TABLE
  cron_schedule TO cron_schedule_old,
  cron_schedule_new TO cron_schedule;

Drie dingen zijn belangrijk aan deze volgorde. CREATE LIKE kopieert het schema met alle indexes, niet alleen de kolommen. De INSERT SELECT hield op deze host ongeveer 41 seconden een read-lock vast op cron_schedule, en in die tijd kwamen de INSERTs van de dispatcher erachter in de wachtrij. De RENAME is atomair en was binnen ongeveer 80 milliseconden klaar. Na de rename landden de wachtende INSERTs van de dispatcher op de nieuwe tabel en kwam alles weer op gang.

Wat we niet hebben gedaan, is één unbounded DELETE draaien. Op 14 miljoen rijen genereert één DELETE een undo log die de InnoDB buffer pool van een host met 16 GB overspoelt, en een kill-signaal is dan zelf ook traag omdat de undo moet rollbacken. De MySQL-documentatie over InnoDB-locking is de juiste referentie als je wilt begrijpen waarom een langlopende DELETE op een hot queue-tabel het slechtste van alle werelden is. We hebben die fout een Magento-shop twee uur offline zien knallen.

Na de swap kwamen admin-saves binnen 600 milliseconden terug. De TTFB van categoriepagina's zakte naar 1,2 seconden. We hadden tijd gekocht om de oorzaak echt aan te pakken.

Waarom de cleanup niet liep

Magento heeft ingebouwde pruning. De instellingen zitten onder Stores, Configuration, Advanced, System, Cron, en dan per cron-group. De twee die ertoe doen zijn default en index. Elke group toont dezelfde handvol getallen.

• schedule_generate_every, minuten tussen scheduling-rondes
• schedule_ahead_for, minuten vooruit om alvast in te plannen
• schedule_lifetime, minuten dat een rij te laat mag zijn voor hij als missed wordt gemarkeerd
• history_cleanup_every, minuten tussen cleanup-runs
• history_success_lifetime en history_failure_lifetime

Bij dit incident stond de cleanup op redelijke waarden. Het echte probleem was dat system_cron_clean_history zelf een rij in cron_schedule was, en elke keer dat hij wilde draaien, laadde hij alle pending rijen om zichzelf in de queue te vinden. Met 11 miljoen pending rijen duurde dat laden langer dan de cron-tick-interval, dus werd de cleanup-job als missed gemarkeerd voor hij klaar was, en de volgende tick scheduledde er weer een. We hadden duizenden vastzittende cleanup-pogingen op elkaar in de wachtrij staan, elk trager dan de vorige. Een volledig zichzelf versterkend failure-mode.

Het downstream-effect was de connection pool. max_connections op deze host stond op 300. De dispatcher hield één connectie vast per vastzittende cleanup-poging; PHP-FPM-workers openden er ieder nog een of twee voor de admin-saves die ze probeerden te committen. De pool zat op 248 toen we begonnen te kijken en was bij voltooiing van de swap geklommen naar 287. Nog tien of vijftien minuten en admin-saves waren het kleinste probleem geweest. Elke nieuwe frontend-bezoeker zou een SQLSTATE[08004]-pagina hebben gezien omdat de pool geen slot meer had om uit te delen. Queue rot ziet eruit als een database-probleem totdat het het connection-budget begint op te eten, op welk moment het eruitziet als een outage.

De fix op config-niveau zit in app/etc/env.php in plaats van in admin, want het bureau gebruikt config:dump en houdt hun env.php in version control.

'system' => [
    'default' => [
        'system' => [
            'cron' => [
                'default' => [
                    'schedule_lifetime'         => '15',
                    'history_cleanup_every'     => '10',
                    'history_success_lifetime'  => '60',
                    'history_failure_lifetime'  => '600',
                ],
                'index' => [
                    'schedule_lifetime'         => '15',
                    'history_cleanup_every'     => '10',
                    'history_success_lifetime'  => '60',
                    'history_failure_lifetime'  => '600',
                ],
            ],
        ],
    ],
],

Daarna bin/magento app:config:import gevolgd door bin/magento cache:clean config. Zestig minuten succes-history en tien uur failure-history is ruim genoeg voor vrijwel elke shop. De defaults waar Magento mee komt zijn veel ruimer, en dat is mede waarom deze tabel überhaupt zo groeit.

De indexer-config die de aangroei stopte

De diepere oorzaak was indexer-mode. Magento heeft twee modes per index. realtime herindexeert synchroon bij elke save. schedule schrijft een change-record naar een materialized view (mview) tabel en indexeert out of band. Op een shop met veel product-saves is realtime brutaal. Elke save indexeert inline, blokkeert de admin-save, en op deze shop schoot ook nog één cron-job per save per index in de queue. Twaalf indexers maal een paar honderd catalogus-imports per uur was het volume dat de cleanup overspoelde.

De juiste instelling voor elke niet-triviale Magento 2-shop is schedule voor elke index. De ondersteunde manier vanaf de CLI:

bin/magento indexer:set-mode schedule \
  catalog_product_price \
  catalog_product_attribute \
  catalogrule_product \
  catalogsearch_fulltext \
  catalog_category_product \
  catalog_product_category \
  cataloginventory_stock \
  inventory \
  customer_grid \
  design_config_grid

bin/magento indexer:reindex

De Adobe Commerce-documentatie over het beheren van indexers behandelt de afwegingen per index. Kort gezegd: schedule mode schrijft change-records naar mview-tabellen en draait de reindex out of band, waardoor cron_schedule niet bij elke admin-save klappen krijgt.

De mode-switch is omkeerbaar. Als indexer:reindex zelf een error geeft of buiten je maintenance-window valt, meestal omdat een orphan-rij in een _idx- of _replica-tabel een JOIN doet exploderen, zet je de betreffende index terug op realtime met hetzelfde commando, los je de orphan op en zet je hem terug op schedule. De mode is één rij per index in de indexer_state-tabel; flippen vernietigt geen data en vereist geen maintenance mode. We houden hier een one-liner voor in het runbook, want de verleiding onder druk is om de mview-tabellen te verwijderen, en dat is precies de zet die wél data kost.

De monitoring-regel die we toevoegden

De shop had geen alerting op cron_schedule-grootte. We voegden een regel toe aan het bestaande custom-query-bestand van de Prometheus mysqld_exporter.

cron_schedule_rows:
  query: "SELECT COUNT(*) AS rows_total FROM cron_schedule"
  metrics:
    - rows_total:
        usage: GAUGE
        description: "Total rows in Magento cron_schedule"

Alert-drempel op 50.000 rijen, page op 250.000. Die getallen zijn royaal; dezelfde shop in schedule mode zit nu rond de 4.000 rijen op een gewone dag en piekt rond 12.000 tijdens een flash sale.

Wat we in het runbook hebben gezet

Drie regels die na dit incident aan het on-call runbook zijn toegevoegd.

1. Als een Magento 2 admin-save traag is of een 500 teruggeeft, draai dan SELECT status, COUNT(*) FROM cron_schedule GROUP BY status voor je iets anders doet. Het antwoord vertelt je of je naar queue rot kijkt of iets anders.
2. Boven een miljoen rijen in cron_schedule: swappen in plaats van deleten. De undo log van één DELETE doet meer pijn dan de read-lock van de kopie.
3. Elke nieuwe Magento 2-installatie krijgt bij go-live indexer:set-mode schedule op elke index. Realtime is een ontwikkelconvenience, geen productie-instelling.

Het bureau draait de row-count-query nu als onderdeel van hun wekelijkse maandagochtend-healthcheck, naast de gebruikelijke bin/magento setup:db:status en een tail van var/log/exception.log. Het kost vijftien seconden.

Het kleinste wat je vandaag kunt doen

Toen we Pier bouwden, kwamen we dit precieze recept zo vaak tegen bij werk aan een legacy site dat we het hebben ingebakken. De MySQL editor heeft een saved query voor de cron_schedule-statusbreakdown en een one-click swap-and-rename voor de queue-tabellen die Magento- en WordPress-shops opbouwen. Elke swap belandt in de version history, dus als de nieuwe tabel minder rijen heeft dan je bedoelde, is de vorige er één klik vandaan.

Als je dit leest omdat je eigen cron_schedule uit de hand is gelopen, dan is het enige nuttige wat je vandaag kunt doen: MySQL openen op je Magento 2-shop en de COUNT plus de statusbreakdown draaien. Onder vijftigduizend rijen: niets aan de hand. Boven een miljoen: plan een maintenance-window voor volgende week vrijdagmiddag, en zet meteen alle indexers in schedule mode terwijl je toch bezig bent.