Ομαδοποίηση των slow logs του PHP-FPM για να βρείτε τι περιμένει το site σας

Το «το site είναι αργό» δεν είναι κάτι που μπορεί κανείς να διορθώσει. Το «τέσσερα στα δέκα αργά αιτήματα περιμένουν μία κλήση εξωτερικού API» είναι. Το PHP-FPM μπορεί να σας πει τη δεύτερη πρόταση δωρεάν, μέσα από ένα log που οι περισσότεροι servers έχουν απενεργοποιημένο. Να πώς το ενεργοποιείτε, πώς το διαβάζετε, και πώς το ομαδοποιείτε ώστε η απάντηση να πέσει μόνη της.

Το πρόβλημα: αργό, αλλά πού;

Όταν οι σελίδες PHP είναι αργές, οι περισσότερες έρευνες ξεκινούν από έξω (εργαλεία χρονομέτρησης σελίδας) ή από τη βάση δεδομένων (slow query log). Και τα δύο είναι χρήσιμα, και τα δύο χάνουν την πιο συνηθισμένη αιτία σε σύγχρονα sites: η PHP περιμένει κάτι που δεν είναι ούτε CPU ούτε η τοπική βάση δεδομένων. Ένα payment gateway. Ένα API αποθέματος ή ERP. Έναν έλεγχο άδειας. Ένα session lock που κρατά άλλο αίτημα από τον ίδιο επισκέπτη. Αυτές οι αναμονές δεν εμφανίζονται ως CPU, άρα ο server μοιάζει αδρανής ενώ οι επισκέπτες κοιτούν ένα spinner.

Το slow log του PHP-FPM τα πιάνει όλα, γιατί δεν το νοιάζει γιατί ένα αίτημα είναι αργό. Απλώς παίρνει ένα στιγμιότυπο του τι κάνει το αίτημα.

Ενεργοποιήστε το

Στη διαμόρφωση του pool (για παράδειγμα /etc/php-fpm.d/www.conf):

slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 3s
request_terminate_timeout = 60s

Όταν ένα αίτημα τρέχει περισσότερο από το request_slowlog_timeout, ο FPM master παίρνει ένα backtrace του worker και το γράφει στο slow log. Το αίτημα συνεχίζει. Τίποτα δεν τερματίζεται. Το request_terminate_timeout είναι ξεχωριστό δίχτυ ασφαλείας που όντως τερματίζει αιτήματα που έχουν ξεφύγει, και αξίζει να το ορίσετε όσο είστε εδώ.

Διαλέξτε ένα κατώφλι λίγο πάνω από αυτό που μοιάζει «κανονικό» για τις μη cached σελίδες σας. Πολύ χαμηλό, και καταγράφετε υγιή αιτήματα. Πολύ υψηλό, και βλέπετε μόνο τις καταστροφές. Κάντε reload το FPM και αφήστε το να συλλέξει μέσα σε μια περίοδο με κίνηση.

Διαβάστε μία εγγραφή

Μια εγγραφή slow log μοιάζει έτσι:

[22-Oct-2026 10:14:07]  [pool www] pid 41822
script_filename = /var/www/shop/index.php
[0x00007f1c2a614f20] curl_exec() /var/www/shop/modules/erpsync/Client.php:188
[0x00007f1c2a614e10] request() /var/www/shop/modules/erpsync/Client.php:97
[0x00007f1c2a614d00] getStock() /var/www/shop/modules/erpsync/Stock.php:42
[0x00007f1c2a614bf0] hookDisplayProduct() /var/www/shop/classes/Hook.php:1017
...
[0x00007f1c2a6140a0] dispatch() /var/www/shop/index.php:28

Το πάνω frame, αυτό ακριβώς κάτω από το script_filename, είναι αυτό στο οποίο ήταν μπλοκαρισμένο το αίτημα τη στιγμή του στιγμιότυπου. Από κάτω είναι το πώς έφτασε εκεί. Σε αυτό το παράδειγμα, μια σελίδα προϊόντος περιμένει το curl_exec(), που καλείται από ένα module συγχρονισμού αποθέματος, κατά την εμφάνιση του προϊόντος.

Μία εγγραφή είναι ανέκδοτο. Μια μέρα από αυτές είναι profile.

Ομαδοποιήστε ανά frame που μπλοκάρει

Ομαδοποιήστε κάθε εγγραφή ανά το πάνω frame της και μετρήστε:

awk '/^script_filename/ { w = 1; next }
     w && /^\[0x/ {
       fn = $2
       match($0, /[^ ]+:[0-9]+$/)
       print fn " @ " substr($0, RSTART, RLENGTH)
       w = 0
     }' /var/log/php-fpm/www-slow.log \
  | sort | uniq -c | sort -rn | head -25

Η έξοδος είναι μια ταξινομημένη λίστα του τι έκαναν πραγματικά τα αργά αιτήματα. Σε ένα τυπικό αργό e-shop μπορεί να μοιάζει έτσι:

 812 curl_exec() @ .../modules/erpsync/Client.php:188
 497 execute() @ .../classes/db/DbPDO.php:132
 251 session_start() @ .../config/bootstrap.php:61
  88 file_get_contents() @ .../themes/shop/fonts.php:12

Μετά ομαδοποιήστε με έναν δεύτερο τρόπο, ανά το πρώτο frame μέσα σε κατάλογο plugin, module ή θέματος. Αυτό μετατρέπει τη λίστα από «ποια συνάρτηση» σε «ποιανού κώδικας», που είναι η ερώτηση που θα κάνουν οι developers.

Τι σημαίνουν τα συνηθισμένα frames

• curl_exec(), file_get_contents() σε URL, fsockopen(): μια εξωτερική κλήση που γίνεται σύγχρονα κατά τη δημιουργία της σελίδας. Κοιτάξτε το timeout που χρησιμοποιεί. Ένα μεγάλο timeout σε έναν αργό τρίτο κολλάει έναν worker για τόσο. Η διόρθωση είναι σύντομο timeout, caching της απάντησης, ή μετακίνηση της κλήσης έξω από το αίτημα της σελίδας.
• execute(), query(), mysqli_query(): αναμονή βάσης δεδομένων. Πάρτε το αρχείο και τη γραμμή στο slow query log και κάντε EXPLAIN στο query που τρέχει εκεί. Αν το buffer pool απαντά από τη μνήμη και το query εξακολουθεί να παίρνει δευτερόλεπτα, το πρόβλημα είναι το query ή τα indexes του, όχι το hardware.
• session_start(): σχεδόν πάντα session locking. Οι handlers session σε αρχεία και κάποιοι σε βάση δεδομένων κλειδώνουν το session για ολόκληρο το αίτημα, άρα ένας επισκέπτης του οποίου ο browser στέλνει αρκετά αιτήματα ταυτόχρονα τα βλέπει να περιμένουν το ένα πίσω από το άλλο. Κλείστε το session νωρίς με session_write_close() μόλις ο κώδικας έχει αυτό που χρειάζεται, ή χρησιμοποιήστε non blocking handler.
• sleep(), usleep(), βρόχοι επανάληψης: ο κώδικας κάποιου περιμένει εσκεμμένα. Συνήθως επανάληψη προς μια εξωτερική υπηρεσία που έχει κακή μέρα.
• Καθαρές συναρτήσεις PHP βαθιά μέσα σε template ή βρόχο: γνήσια δουλειά CPU. Σπανιότερη απ' όσο περιμένουν οι περισσότεροι, και η μόνη κατηγορία όπου το ταχύτερο hardware βοηθά άμεσα.

Ζυγίστε το, και μετά επιβεβαιώστε το pool

Το slow log μετρά αιτήματα πάνω από το κατώφλι. Δεν σας λέει πόσο συνολικό χρόνο κοστίζει κάθε κατηγορία. Συνδυάστε το με το access log του web server σας, καταγράφοντας $request_time και $upstream_response_time στο nginx, για να ζυγίσετε τα αργά αιτήματα ανά URL και ανά διάρκεια. Μια κατηγορία με λιγότερες εγγραφές αλλά πολύ μεγαλύτερα αιτήματα μπορεί να μετράει περισσότερο.

Μετά ελέγξτε αν τα αργά αιτήματα στερεύουν και το pool:

grep -c 'reached pm.max_children' /var/log/php-fpm/error.log
curl -s 'http://localhost/fpm-status?full' | head -20

Αν οι workers εξαντλούνται, οι επισκέπτες περιμένουν ακόμα και για σελίδες που είναι γρήγορες από μόνες τους. Η αύξηση του pm.max_children αντιμετωπίζει το σύμπτωμα. Η συντόμευση της αργής εξωτερικής κλήσης αντιμετωπίζει την αιτία.

Δυο λόγια για το overhead

Η λήψη backtrace σημαίνει ότι ο FPM master προσαρτάται για λίγο στον worker. Σε λογικό κατώφλι το overhead είναι αμελητέο, γιατί συμβαίνει μόνο σε αιτήματα που είναι ήδη αργά. Μην ορίσετε το κατώφλι σε κλάσμα του δευτερολέπτου σε ένα πολυσύχναστο site και το αφήσετε εκεί. Συλλέξτε, αναλύστε, και μετά ανεβάστε το ξανά σε επίπεδο παρακολούθησης.

Η λίστα ελέγχου σας

• slowlog, request_slowlog_timeout και request_terminate_timeout ορισμένα σε κάθε pool.
• Μια μέρα slow log ομαδοποιημένη ανά frame που μπλοκάρει, και μετά ανά plugin ή module.
• Εξωτερικές κλήσεις εντοπισμένες και τα timeouts τους διαβασμένα.
• Frames βάσης δεδομένων ιχνηλατημένα στα queries εκείνων των γραμμών, με EXPLAIN.
• Εγγραφές session_start() ελεγμένες για session locking.
• Αργά αιτήματα ζυγισμένα ανά διάρκεια από το access log, και εξάντληση pool επιβεβαιωμένη ή αποκλεισμένη.

Όταν ένα slow log δείχνει κάπου που δεν μπορείτε εύκολα να ακολουθήσετε, θα χαρούμε να βοηθήσουμε να διαβαστεί.

Μιλήστε με έναν μηχανικό

Related

Σχετικά: Έλεγχοι επιδόσεων web εφαρμογών · Αναβαθμίσεις PHP και security patching σε όλο τον στόλο · Web tiers υψηλής διαθεσιμότητας, N+1 σε κάθε επίπεδο