Trage admin-ajax.php: 30 seconden terug naar één plugin

Om 23:41 op een dinsdag landde er een Loom in onze gedeelde inbox. Een Nederlands bureau van 22 mensen draaide een vijf jaar oude WooCommerce-shop voor een regionale retailer. Hun contentredacteur was kwaad naar bed gegaan. Elke save in de post-editor liep een halve minuut vast en sprong dan weer tot leven alsof er niets aan de hand was. De trage request was steeds hetzelfde pad: admin-ajax.php. Steeds rond de dertig seconden. Tegen de ochtend had het bureau een ticket bij de hosting aangemaakt. Tegen 10:00 had de hostingmaatschappij de schuld bij "plugin-bloat" gelegd en het ticket gesloten. De bureau-lead nam de Loom op met de vraag die elke freelancer uiteindelijk stelt: waar begin je nou eigenlijk.

Eerst de access log lezen

Voordat we WordPress openden, openden we de access log. SSH erin, de combined log tailen, kijken hoe een editor-refresh er vanuit het perspectief van de server uitziet.

tail -f /var/log/nginx/access.log | grep admin-ajax

Het patroon dook binnen een minuut op.

"POST /wp-admin/admin-ajax.php HTTP/2" 200 412 30.014
"POST /wp-admin/admin-ajax.php HTTP/2" 200 412 29.987
"POST /wp-admin/admin-ajax.php HTTP/2" 200 412 30.122

Elke vijftien seconden, terwijl er een admin-tab openstond, bleef een request naar admin-ajax.php dertig seconden hangen voordat hij een minuscule payload teruggaf. De omvang van de response (412 bytes) was de verklikker. Dit was geen zware editor-save. Dit was de WordPress Heartbeat API die tikte, en iets dat eraan vasthing wachtte op iets anders.

Heartbeat is een kleine JavaScript-poll die in de browser draait zodra een admin is ingelogd. Standaard pingt hij elke vijftien tot zestig seconden admin-ajax.php met de action heartbeat. Plugins haken erop in om autosave, lock-indicators, notificaties te leveren, alles wat near-real-time admin-data wil zonder WebSockets. De bedoeling is onschuldig. Het impactbereik, wanneer iets er een dure callback aan koppelt, is de hele admin.

De heartbeat-receivers traceren

WordPress stelt twee filters bloot bij elke heartbeat-tik: heartbeat_received en heartbeat_send. Elke plugin kan er werk aan koppelen. Om te vinden welke plugin dertig seconden per tik opat, schreven we een korte tracer en lieten die in wp-content/mu-plugins/ vallen.

<?php
// wp-content/mu-plugins/heartbeat-trace.php
add_filter('heartbeat_received', function ($response, $data, $screen_id) {
    $bound = $GLOBALS['wp_filter']['heartbeat_received']->callbacks ?? [];
    $names = [];
    foreach ($bound as $priority => $set) {
        foreach ($set as $cb) {
            $fn = $cb['function'];
            if (is_array($fn)) {
                $names[] = (is_object($fn[0]) ? get_class($fn[0]) : $fn[0]) . '::' . $fn[1];
            } elseif (is_string($fn)) {
                $names[] = $fn;
            } else {
                $names[] = 'closure@' . $priority;
            }
        }
    }
    error_log('[heartbeat] receivers: ' . implode(', ', $names));
    return $response;
}, 1, 3);

Dit draait op prioriteit 1, vóór elke andere callback. Hij loopt het globale filter-array door, bouwt een lijst van gekoppelde functienamen op, schrijft die naar error_log en stapt dan opzij. mu-plugins laden bij elke request en kunnen niet vanuit wp-admin worden uitgeschakeld, wat ze ideaal maakt voor incident-tooling. Niemand kan je tracer per ongeluk halverwege het onderzoek deactiveren.

Herlaad de editor, wacht één tik, tail de PHP error log:

tail -f /var/log/php/error.log

[heartbeat] receivers: WP_Auto_Updates::on_heartbeat, NinjaFormsLive\Listener::sync, MainWP_Child::heartbeat

Drie callbacks. Auto-updates is core. MainWP is de remote-management bridge van het bureau, die kenden we. De middelste was een forms-plugin die een "live" sync deed van submissions naar een externe CRM. De auteur ging er kennelijk van uit dat Heartbeat een gratis klok was. Dat was hij niet.

De kosten bevestigen voordat we de stekker eruit trekken

De verdachte kennen is niet hetzelfde als het bewijzen. We voegden een paar timing-filters toe: één op prioriteit 0 om de starttijd te stempelen, één op PHP_INT_MAX om het totaal te loggen.

<?php
add_filter('heartbeat_received', function ($r) {
    $GLOBALS['hb_t0'] = microtime(true);
    return $r;
}, 0, 1);

add_filter('heartbeat_received', function ($r) {
    $dt = microtime(true) - ($GLOBALS['hb_t0'] ?? microtime(true));
    error_log(sprintf('[heartbeat] total %.2fs', $dt));
    return $r;
}, PHP_INT_MAX, 1);

Herladen, wachten, kijken:

[heartbeat] total 29.84s

De MySQL slow query log vertelde de rest van het verhaal. De sync-methode van de plugin vuurde een wp_remote_post af op een HTTPS-endpoint met de standaard timeout van dertig seconden. De CRM was zes weken eerder achter een nieuwe Cloudflare-regel verplaatst die op het oude subdomein een 522 teruggaf. Elke vijftien seconden, in elke admin-tab, in elke editor-sessie, wachtte WordPress beleefd op een host die niet meer antwoordde. De "plugin-bloat"-theorie van de hostingmaatschappij was technisch correct en operationeel waardeloos.

De patch die Heartbeat in leven hield

Drie opties lagen op tafel.

De eerste was de forms-plugin volledig uitschakelen. Dat zou de embeds breken die het bureau al twee jaar gebruikte op de contact- en offertepagina's van de retailer. Niet acceptabel.

De tweede was Heartbeat globaal uitschakelen met wp_deregister_script('heartbeat'). Dat legt autosave, post-locking en de waarschuwing die afgaat zodra een andere editor dezelfde post opent, stil. Te tolereren voor een eenmanssite, pijnlijk voor een team van vier redacteuren die tegelijk aan dezelfde productcatalogus werken.

De derde was de juiste. Haak de overtredende callback los, laat Heartbeat actief voor al het andere. Eén bestand in mu-plugins:

<?php
// wp-content/mu-plugins/throttle-forms-live-sync.php
add_action('init', function () {
    if (class_exists('NinjaFormsLive\\Listener')) {
        remove_filter(
            'heartbeat_received',
            ['NinjaFormsLive\\Listener', 'sync'],
            10
        );
    }
}, 99);

Het prioriteit-argument doet ertoe. remove_filter verwijdert een callback alleen als de prioriteit die je doorgeeft overeenkomt met de prioriteit waarop hij oorspronkelijk werd toegevoegd. Dat bevestigden we door de broncode van de plugin te lezen: add_filter('heartbeat_received', [...], 10, 3). Hadden we klakkeloos de standaard 10 doorgegeven, dan was er fifty-fifty kans op een stille mis en een woedende redacteur geweest.

Bij de volgende herlaad werd het stil in de access log. admin-ajax.php kwam terug in ongeveer 60 milliseconden in plaats van dertig seconden. De editor was weer bruikbaar. De forms werkten nog. Heartbeat tikte nog. Autosave bleef opslaan.

Daarna openden we een kleine pull request tegen de forms-plugin. De auteur accepteerde hem binnen een week. De sync draait nu als wp-cron event eens per vijf minuten met een timeout van vijf seconden, in plaats van bij elke heartbeat met een timeout van dertig. Dat is de vorm die elke near-real-time integratie hoort te hebben: begrensd, gepland en geïsoleerd van het request-pad van de editor.

Een audit die je op elke overgenomen site kunt draaien

Heartbeat is niet het probleem. Het is een van de meest bruikbare ingebouwde onderdelen die WordPress meelevert. Het probleem is dat elke plugin er onbegrensd werk aan kan koppelen, en niets in core dwingt een timeout, een queue of een circuit breaker af. Wanneer je een vijf jaar oude installatie overneemt en de admin voelt zwaar, is de eerste plek om te kijken welke filters er deelnemers bij hebben gekregen.

Een korte audit die je vandaag kunt draaien, op elke admin-pagina, als gebruiker met manage_options:

<?php
// wp-content/mu-plugins/heartbeat-audit.php
add_action('admin_footer', function () {
    if (!current_user_can('manage_options')) return;
    $hooks = ['heartbeat_received', 'heartbeat_send', 'heartbeat_tick'];
    foreach ($hooks as $hook) {
        $cb = $GLOBALS['wp_filter'][$hook]->callbacks ?? [];
        $count = 0;
        foreach ($cb as $set) { $count += count($set); }
        printf("<!-- %s: %d callbacks -->\n", $hook, $count);
    }
});

Plak hem erin. Open een willekeurige admin-pagina. Bekijk de broncode. Onderaan de HTML staat een comment met daarin hoeveel callbacks elke Heartbeat-hook draagt. Alles boven de drie is het onderzoeken waard. Alles boven de vijf is bijna zeker een regressie die staat te gebeuren.

Hoe dit werk er meestal uitziet

Dit was een klein incident met een duidelijke schuldige. De meeste tickets over een trage admin die we zien volgen dezelfde vorm. Een plugin haakt zich vast aan een tik (Heartbeat, shutdown, wp_loaded) zonder na te denken over de failure-mode van datgene waar hij naar belt. Het endpoint verdwijnt. De plugin blijft wachten. De admin wordt traag. De host krijgt de schuld.

Toen we Pier bouwden om aan verouderde sites zoals deze te dokken, was precies dit patroon een van de eerste onderzoeksworkflows die we erin draadden: access log tailen, een tracer-mu-plugin neerzetten, één editor-pagina vernieuwen, de error log teruglezen. De tracer-plugin en de uiteindelijke remove_filter komen beide als losse edits in de versiegeschiedenis terecht, zodat beide met één toetsaanslag teruggedraaid kunnen worden.

Als je een admin hebt die zwaar aanvoelt en je nog niet weet waarom, is de kleinste stap voor vanavond het audit-snippet hierboven in mu-plugins plakken, één wp-admin-pagina vernieuwen, en de HTML-comments onderaan lezen. Vijf minuten, geen plugin-activatie, geen service-restart. De helft van de diagnose is dan al gedaan.