Pagina lenta nel CRM: prima la misuriamo, poi (forse) la ottimizziamo

C'era una pagina del nostro CRM che, quando la aprivi, ti faceva aspettare. Non abbastanza da bloccare il lavoro, ma abbastanza da farsi notare ogni volta. In un gestionale usato tutto il giorno, una pagina che esita diventa presto un fastidio di cui tutti parlano.

Il sospetto è caduto subito su una query. Dentro c'era una sottoquery correlata, un exists che per ogni riga andava a controllare qualcosa in un'altra parte dei dati. Avevamo già in testa come riscriverla.

Non l'abbiamo riscritta. Prima abbiamo misurato, e la misura ci ha detto che stavamo per sistemare la cosa sbagliata.

Il colpevole perfetto

Le sottoquery correlate hanno una cattiva reputazione, e non del tutto immeritata: sulla carta descrivono un lavoro da ripetere riga per riga, e chi ha letto qualche consiglio sulle prestazioni dei database impara a guardarle con diffidenza. Quando una pagina è lenta e nel codice ne trovi una, il caso sembra chiuso da solo.

È proprio questo il problema. Una query con l'aria sospetta è una spiegazione comoda, perché ci dà qualcosa di concreto da fare. Ma «sembra lenta» non è una misura. È un'impressione, e le impressioni sulle prestazioni sono sbagliate più spesso di quanto ci piaccia ammettere.

Cosa abbiamo misurato davvero

Il metodo che usiamo adesso è semplice, e lo applichiamo prima di toccare una riga di codice.

Primo: registriamo tutte le query fatte dal pool durante il caricamento della pagina. Non solo quella sospetta: tutte. Spesso una pagina fa più richieste al database di quelle che ricordiamo, e l'elenco completo è già un'informazione utile.

Secondo: le rigiochiamo una per una con explain analyze. A differenza del semplice explain, che mostra solo il piano previsto, explain analyze esegue davvero la query e restituisce il piano con i tempi reali di ogni passaggio. È la differenza tra chiedere a Postgres cosa pensa di fare e guardarlo mentre lo fa.

Il risultato ci ha spiazzati. La query incriminata, quella con l'exists, Postgres la risolveva in una sola scansione. Nessuna ripetizione riga per riga: il pianificatore aveva trovato da solo una strada efficiente. La riscrittura che avevamo in mente non avrebbe guadagnato niente.

E allora da dove venivano i quasi mille millisecondi di attesa?

Il database che dormiva

Venivano da un posto a cui non avevamo pensato: il nostro database è serverless, e dopo un periodo di inattività va a riposo. La lentezza che vedevamo era il risveglio. Chi apriva la pagina in quel momento pagava l'attesa per far ripartire il database, e la attribuiva alla prima cosa che gli veniva in mente.

Vale la pena fermarsi su cosa sarebbe successo se avessimo seguito l'istinto. Avremmo speso tempo a riscrivere una query che funzionava bene, con il rischio di introdurre un errore in una parte del sistema che non aveva problemi. E il guaio peggiore: avremmo potuto provare la nuova versione in un momento in cui il database era già sveglio, vedere la pagina rispondere in fretta e convincerci di aver risolto. Un falso successo è più pericoloso di un fallimento, perché chiude la ricerca.

È l'errore che ci ha insegnato di più, e lo raccontiamo proprio per questo.

La seconda domanda: il tempo è nel database o fuori?

Non sempre la lentezza sta nel database, e il metodo serve anche a capirlo. Il confronto che facciamo è tra due numeri: il tempo totale di caricamento della pagina e il tempo speso nel database, cioè la somma delle query che abbiamo registrato.

Se i due tempi sono vicini, il lavoro da fare è nelle query, e explain analyze ci dice dove. Se invece il tempo totale è molto più alto del tempo nel database, il collo di bottiglia è altrove: quasi sempre codice JavaScript sincrono che blocca il thread. Un calcolo pesante, un ciclo su troppi dati, una trasformazione fatta tutta in una volta: finché quel codice gira, nient'altro va avanti.

Per trovarlo usiamo un trucco molto artigianale: mettiamo un cronometro dopo ogni attesa. Ogni volta che il codice aspetta qualcosa, annotiamo quanto tempo è passato. Gli intervalli che contengono un'attesa vera si spiegano da soli; quello che cresce senza che ci sia nulla da aspettare indica il pezzo di codice che tiene occupato il thread. Non è elegante, ma porta dritti al punto, e una volta trovato il colpevole i cronometri si tolgono.

Il metodo, in breve

Questo è l'ordine in cui procediamo ogni volta che una pagina ci sembra lenta:

1. Registrare tutte le query che il pool esegue durante il caricamento.
2. Rigiocarle con explain analyze per vedere i tempi reali, non quelli immaginati.
3. Confrontare il tempo totale della pagina con il tempo passato nel database.
4. Se la differenza è grande, cercare il codice sincrono con un cronometro dopo ogni attesa.
5. Solo a questo punto decidere cosa ottimizzare.

Nessuno di questi passaggi richiede strumenti particolari. Richiede solo la pazienza di non partire subito con la soluzione.

Cosa ci portiamo a casa

La lezione, alla fine, sta in una riga: si ottimizza quello che si è misurato, non quello che sembra lento.

Detta così pare ovvia, ma in pratica va contro l'istinto. Quando una cosa è lenta vogliamo metterci le mani, e la tentazione di andare dritti sul sospetto più probabile è forte, soprattutto se il sospetto ha l'aria del colpevole da manuale. Nel nostro caso il colpevole da manuale era innocente, e il vero responsabile non era nemmeno nel codice che avevamo scritto.

Da allora, quando qualcuno di noi dice «questa pagina è lenta, secondo me è quella query», la risposta è sempre la stessa: va bene, misuriamola.