Trenta secondi invisibili: la telemetria che ha fatto collassare un WordPress

Un sito WordPress va online e nel giro di poche ore il server è in ginocchio: CPU al massimo e pagine che ci mettono più di trenta secondi. Non tutte e non sempre, ed è questo che rende il guasto antipatico. Novanta richieste su cento vanno bene, poi una si pianta e nessuno sa dire perché.

Ci ho lavorato tre giorni, notti comprese. Ho accusato la configurazione di Apache, il database, la versione di PHP, la CPU della macchina, i buffer di nginx e alla fine Apache stesso. Erano tutti innocenti. Il colpevole era una chiamata di rete che un plugin fa per mandare le statistiche d’uso alla casa madre, con trenta secondi di pazienza, dentro ogni richiesta che non viene servita dalla cache. Si risolve togliendo una spunta da un pannello: tre giorni per trovarla, un secondo per toglierla.

Qui racconto come ci sono arrivato, sbagli inclusi, perché è quella la parte che serve. Il cliente resta anonimo. Il software no: senza nomi non potresti verificare niente di quello che scrivo.

Il problema non era la lentezza

Prima cosa: capire se il sito è lento sempre o solo qualche volta. Ho misurato le pagine servite dalla cache e poi le stesse pagine forzando WordPress a lavorare davvero. Per farlo basta attaccare una query string all’indirizzo: la cache non riconosce più l’URL e passa la richiesta a PHP.

Dalla cache il sito andava bene, 102 ms di mediana, in linea con il server di confronto dello sviluppatore precedente che stava a 101 ms. Senza cache si saliva a 691 ms contro 493. Fin qui niente di drammatico. Il punto era un altro: sulla stessa pagina, nello stesso quarto d’ora, misuravo 0,48 s e poi 33,9 s. Settanta volte tanto, senza aver cambiato nulla.

Con numeri che ballano così, la media non serve a niente. Ho smesso di guardarla e ho iniziato a contare quante richieste su cento sforavano i tre secondi. Quello era il problema da spiegare.

Le ipotesi che ho sbagliato

Il sito aveva un .htaccess da 144 KB e 1.286 righe, con 922 regole di riscrittura. Apri un file così e la diagnosi ti sembra già fatta: ci sono cascato anch’io. Poi l’ho misurato, con un test A/B contro un altro dominio sullo stesso Apache che non ha nessun .htaccess, quaranta richieste alternate su un file statico.

Costo reale: 5 ms, su un divario di circa 490 ms tra i due server. L’uno per cento. Il sospettato numero uno valeva un errore di arrotondamento.

Da lì in poi ho misurato tutto il resto invece di ragionarci sopra, e sono cadute quasi tutte le ipotesi da manuale.

L’ultima riga è quella che mi ha insegnato di più. Cambiare macchina ha portato un guadagno vero, il 29% sull’avvio di WordPress, e non ha risolto niente del problema per cui mi avevano chiamato. Capita spesso: migliori tutto quello che sai misurare e lasci intatto quello che manda giù il sito.

Metà delle mie misure erano sporche

A metà lavoro mi accorgo che i benchmark del giorno prima sono da buttare. Sul server girava un backup dell’intero sistema, con compressione e caricamento su uno storage esterno, partito proprio mentre facevo i test: tredici minuti di lavoro pesante su due vCPU, dentro la mia finestra di misura.

Nello stesso giro ho scoperto che il mio script calcolava le richieste al secondo dividendo la concorrenza per la mediana, invece di cronometrare quanto durava davvero il test. Sbagliava fino a undici volte, e io ci avevo costruito sopra una stima dell’hardware dell’altro server. Buttata anche quella.

Due cose che non c’entrano con WordPress ma che ormai faccio sempre: guardo cosa gira sulla macchina prima di misurare, e un numero che nasce dividendo altri due numeri non lo chiamo misura.

Una visita non è una richiesta sola

A quel punto ho smesso di interrogare il server e sono andato a vedere cosa fa il browser quando apre una pagina. Pannello Rete, home del sito: l’HTML arriva dalla cache in 139 ms, la pagina è già disegnata, e intanto restano appese quattro richieste a /wp-json/contact-form-7/…. Due sono refill, due sono feedback/schema. Si chiudono dopo 9,81 s.

Avevo passato due giorni a cronometrare una URL alla volta, e nessuna di quelle misure poteva vedere questa roba.

Contact Form 7 fa partire due chiamate REST per ogni form presente in pagina, dal JavaScript, appena la pagina si carica. Sono richieste PHP a tutti gli effetti: /wp-json/ non è un file, è index.php, e per rispondere carica il core, i 38 plugin e il tema. Nessuna cache di pagina le può servire, perché le REST non si cachano mai.

Il costo non c’entra niente con quello che restituiscono. L’endpoint refill risponde con due byte, una lista vuota, e ci mette da 0,50 a 0,88 s. Quello dello schema manda 1,6 KB negli stessi tempi. Una pagina intera da 399 KB, servita dalla cache, arrivava in 0,08 s.

E qui c’è il pezzo che mi ha fatto ridere. Il refill serve a rigenerare i campi che cambiano a ogni caricamento, tipo i CAPTCHA, e parte solo quando la costante WP_CACHE è attiva. A metterla è il plugin di cache. Quindi la cache accende una richiesta che la cache non può servire, su form che non hanno un solo campo dinamico da rigenerare, e infatti risponde vuoto. Fatica sprecata dalla prima all’ultima, e la pagina più carica del sito ne generava dodici a ogni visita.

Con dodici richieste PHP a visita non servono i bot per mettere in ginocchio un server con due vCPU: basta il traffico normale.

Il giorno che ho buttato dietro a un falso indizio

Mettendo a confronto gli orologi di Apache e di PHP al microsecondo avevo trovato una cosa che sembrava chiudere il caso: PHP finiva in 438 ms tutte le volte, e Apache ci metteva fino a 16,9 secondi in più a consegnare una risposta che era già pronta. Uno strace mostrava un processo fermo 16,4 secondi dentro una poll().

Conclusione dell’epoca: è Apache che si tiene la risposta in mano. Sbagliata. Sono andato a vedere cos’era davvero quel descrittore su tutti i processi figli, ed era la coda con cui Apache aspetta le connessioni in arrivo. Un processo fermo lì non trattiene niente: è a riposo. Avevo scambiato il respiro del server per un sintomo.

La misura era giusta, la lettura no. Da quella volta, prima di dare la colpa a un componente vado a vedere cos’è l’oggetto su cui è bloccato.

Ho tolto un pezzo alla volta

Davanti c’era nginx, dietro Apache, in fondo PHP-FPM. Invece di continuare a fare ipotesi ho misurato la stessa cosa tre volte, saltando un livello per volta: prima dall’esterno come un visitatore, poi bussando direttamente ad Apache sulla sua porta interna, poi parlando direttamente al socket di PHP-FPM.

Se la colpa fosse stata di nginx, i picchi sarebbero spariti alla seconda riga. Se fosse stata una coda o un blocco interno di Apache, sarebbero spariti alla terza. Sono rimasti tutti, nella stessa proporzione, anche parlando direttamente con PHP a una richiesta per volta, con sei processi liberi e nessun altro traffico sulla macchina.

Non era il web server. Era dentro PHP.

Dieci secondi fermo ad aspettare

Allora ho tracciato le chiamate di sistema di un singolo processo PHP mentre serviva una richiesta che il browser vedeva a 12,45 secondi.

Il processo prende la richiesta subito, fa il suo lavoro in mezzo secondo, e poi resta dieci secondi senza fare assolutamente niente, a controllare ogni secondo se è arrivata risposta da un indirizzo esterno sulla porta 443. Quando molla la presa, scrive la pagina al browser in tredici microsecondi. Era pronta da dieci secondi, ferma lì ad aspettare qualcun altro.

Il nome del server dall’altra parte si legge nella negoziazione TLS: mixpanel-proxy.group.one. Trenta richieste al sito, trenta connessioni verso quell’indirizzo. Una per richiesta.

Il codice è dentro WP Rocket, il plugin di cache, e non è nascosto:

• wp-rocket/vendor/wp-media/wp-mixpanel/src/Tracking.php dichiara l’host di destinazione;
• WPConsumer.php spedisce i dati con wp_remote_post() e 'timeout' => 30, aspettando la risposta;
• parte da inc/Engine/Tracking/Tracking.php, dentro la richiesta del visitatore.

È la telemetria del prodotto, quella che il fornitore usa dal 2017 per sapere quali opzioni vengono attivate. Niente di losco. Il problema è dove viene eseguita e quanto è disposta ad aspettare: WordPress di suo dà cinque secondi di tempo alle chiamate HTTP, qui ce ne sono trenta, e in quel periodo l’endpoint rispondeva a singhiozzo tra 404, 500, 502 e silenzio totale. Ogni richiesta non cachata giocava alla roulette su una scala da zero a trenta secondi.

Perché non lo vedevo con gli strumenti che avevo

Questa è la parte che mi ha fatto perdere più tempo, ed è quella che mi porto dietro sugli altri lavori.

Avevo un profiler dentro WordPress che contava anche le chiamate verso l’esterno, e diceva zero. Il log di PHP-FPM diceva 0,44 s tondi. Il browser diceva dodici secondi. Tre misure vere che si contraddicono.

Il motivo è che quella chiamata parte quando la richiesta è già finita, in fase di chiusura, cioè fuori dal tratto che i miei due strumenti stavano cronometrando. Avevo escluso le chiamate esterne fidandomi di uno strumento che non poteva vederle. Non era una prova, era un buco.

Quando il browser dice un numero e il server ne dice un altro, non serve chiedersi chi ha ragione. Hanno ragione tutti e due, e il tempo che manca sta in mezzo, in un pezzo che nessuno dei due sta guardando.

La prova: blocco l’indirizzo e rimisuro

Una spiegazione che sta in piedi non è ancora una diagnosi. Ho messo una regola sul firewall che rifiuta il traffico verso quell’indirizzo, ho rifatto cento richieste, poi ho tolto la regola e ne ho fatte altre quaranta.

Con l’indirizzo bloccato tutte e cento le richieste stanno dentro 130 millisecondi di differenza l’una dall’altra: da 0,97 a 1,10 s. Tolgo il blocco e nel giro di quaranta richieste i picchi tornano, con una che arriva a 16,9 s. Si accende e si spegne con una riga di firewall.

Un avvertimento che mi sono meritato sul campo: qualche giorno prima avevo dato per risolta un’altra ipotesi con dodici misure, e mi ero sbagliato. Su un problema che va a ondate servono più campioni, venti o trenta, e una pagina di controllo che deve restare tranquilla mentre l’altra esplode. Senza quella pagina di controllo stai misurando anche la giornata storta del server.

Come si chiude, su tre livelli

La prova A/B è già il collaudo del rimedio: con quell’indirizzo fuori gioco, cento richieste di fila stanno tutte sotto 1,10 s e i picchi non esistono più. Da lì in avanti il lavoro è solo mettere quella stessa condizione in modo pulito e farla restare.

Primo livello, la spunta. WP Rocket lascia disattivare l’invio delle statistiche dal suo pannello, ed è la strada giusta perché spegne la cosa alla fonte, senza toccare il codice del plugin. L’opzione risulta attiva di default, cosa che al fornitore è già stata segnalata anche in ottica GDPR. Si toglie la spunta, si svuota la cache e si controlla che il sito non apra più connessioni verso quell’host mentre serve le pagine.

Secondo livello, la rete di sicurezza. Di una spunta non mi fido, e non per sfiducia nel plugin: basta un ripristino da backup, un aggiornamento che reintroduce un default o un collega che riattiva la voce senza sapere cosa fa, e il problema torna in un momento in cui nessuno lo sta guardando. Quindi la blindo nel codice.

WordPress ha un filtro, pre_http_request, che viene chiamato prima di ogni richiesta HTTP in uscita. Se il filtro restituisce qualcosa al posto di false, WordPress prende quel valore come risposta e in rete non esce proprio: nessuna connessione, nessun DNS, nessuna attesa. Il file va messo in wp-content/mu-plugins/, che si carica sempre e per primo, non compare tra i plugin disattivabili e sopravvive agli aggiornamenti.

<?php
// mu-plugins/blocca-telemetria.php
add_filter( 'pre_http_request', function ( $short, $args, $url ) {
    $host = wp_parse_url( $url, PHP_URL_HOST );
    $vietati = array( 'mixpanel-proxy.group.one' );

    if ( in_array( $host, $vietati, true ) ) {
        return new WP_Error( 'telemetria_bloccata', 'Chiamata non eseguita' );
    }
    return $short; // tutto il resto passa come sempre
}, 10, 3 );

Due accortezze. La lista contiene solo l’host della telemetria: i domini che il plugin usa per licenza e aggiornamenti vanno lasciati stare, altrimenti si rompe qualcosa di importante per risolvere qualcosa di secondario. E si restituisce un WP_Error, non una risposta finta: il plugin capisce che la chiamata non è riuscita, la registra come tale e va avanti, che è esattamente quello che deve fare.

Terzo livello, quando il codice non si può toccare. Se il sito è di qualcun altro o il tema è sotto contratto di manutenzione altrui, resta il firewall in uscita: una regola che rifiuta il traffico verso quell’indirizzo sulla 443, ed è quella che ho usato per la prova. Va resa persistente, altrimenti al riavvio non c’è più: su Debian e Ubuntu si salva con netfilter-persistent, altrove si mette nella configurazione di rete della macchina. Resta comunque la mia ultima scelta, perché vive sul server e non dentro il sito: se il sito trasloca su un’altra macchina la protezione non lo segue, e chi un domani cercherà il problema nel codice non penserà mai di andare a guardare le regole di firewall.

Il controllo finale è lo stesso in tutti e tre i casi e dura cinque minuti: mando un po’ di traffico che la cache non serve, e intanto guardo sul server se si aprono ancora connessioni verso quell’host. Se la lista resta vuota e i tempi stanno inchiodati sotto il secondo, il caso è chiuso.

Cosa mi porto dietro

• Mai una chiamata di rete che aspetta risposta dentro una pagina web. Se un servizio esterno va contattato, lo si fa dopo, in coda o con un cron. Quando proprio non se ne può fare a meno, il timeout si conta in secondi singoli: trenta vuol dire regalare a qualcun altro il diritto di tenerti fermo un processo per mezzo minuto.
• Guardare nel punto giusto. Un profiler ti racconta solo il tratto che copre. Se il browser vede dodici secondi e il server ne vede uno, quei secondi esistono e sono in un pezzo che non stai misurando.
• Misurare una visita, non una pagina. Finché ho cronometrato una URL alla volta, dodici richieste per visita mi sono passate sotto il naso.
• Togliere invece di indovinare. Tre misure con un pezzo in meno per volta hanno chiuso tre ipotesi in un’ora, dopo giorni passati a supporre.
• Scriversi anche gli errori. Tengo un registro dove ogni conclusione ha accanto la misura che la regge. È per questo che ne ho potute buttare due senza rifare tutto da capo: sapevo su cosa stavano in piedi.

Ogni tanto il collo di bottiglia di un sito non è nel sito. È in qualcosa che il sito chiama e sta aspettando, e che quel giorno non stava rispondendo.

Se hai un sito che ogni tanto si inchioda e nessuno riesce a dirti dove finisce il tempo, io quel tempo lo so cercare. Guarda come lavoro sulla manutenzione, oppure raccontami cosa succede: Sfidami →