Performance Analyse mit strace
Ich hatte neulich einen Kunden am Telefon, der sich über ein langsam ablaufendes Script beschwerte. Es handelte sich dabei um einen Import, welcher in der Regel mehrere Stunden läuft.
Der Quellcode stammt nicht von mir und das Script greift auf mehrere Datenbanken auf verschiedenen Servern zu.
Die üblichen Tools für eine Performance-Analyse konnten hier nicht zum Einsatz kommen: Für mindestens eine Datenbank haben wir nicht genügend Rechte, um z.B. das MySQL Slow Query Log einzuschalten und zu überwachen.
Nach einem ersten Einblick in den Quellcode sehen wir, dass das Script sehr viele Queries verschickt sowie auch viele Dateien kopiert und verarbeitet. Wir müssen also zuerst herausfinden, was wirklich langsam ist. Ist es wirklich die Datenbank? Oder am Ende der Datentransfer?
Irrwege
Der erste Instinkt ist in solchen Fällen häufig, die SQL-Queries auf ineffiziente Patterns zu checken und die Datenbanken auf fehlende Indizes zu prüfen.
Einige der Queries hatten in der Tat solche Patterns – zum Beispiel fällt die folgende Bedingung schon früh als verdächtig auf:
WHERE `p`.`product_ean` LIKE '%123456789'
Wie man relativ früh in der Schule lernt, können solche Abfragen nicht mittels Index abgedeckt werden und sind daher immer mit einem Table Scan verbunden – was bei wenigen Daten vielleicht noch geht, aber mit zunehmender Datenmenge garantiert zu Problemen führt.
Aber: Welches dieser Queries im Code ist wirklich problematisch? Und: Wie dürfte man die Queries korrigieren? Der obere Fall deutet auf eine EAN hin und wir können die Vermutung anstellen, dass hier wohl führende Nullen abgedeckt werden sollen. Aber Vermutungen können zu Fehleinschätzungen führen, daher fahren wir weiter mit dem Fakten-Check…
Ziele setzen
Wichtig ist, dass wir das Ziel nicht aus den Augen verlieren. Welche dieser ineffizienten Queries sind wirklich problematisch? Und welche davon können wir ignorieren? Und wie häufig werden all diese Queries ausgeführt?
Ich bin seit langer Zeit Fan des Tools strace. strace zeichnet alle System Calls eines Programms auf. Man sieht also damit, welche Auswirkungen ein Programm wirklich auf seine Umgebung hat. Da unser Script vermutlich primär aufgrund der Interaktionen mit seinen Umsystemen langsam wird, denke ich, dass wir hiermit das richtige Tool haben.
Debugging
Ich werfe also Strace an und hänge es mit dem Parameter -p $PID an den bereits laufenden Prozess.
# strace -p 933950
Process 933950 attached
write(1, "Produkt wurde erfolgreich aktual"..., 133) = 133
sendto(5, "\334\4\0\0\3\n\t\t\tSELECT\n\t\t\t\tentryID AS I"..., 1248, MSG_DONTWAIT, NULL, 0) = 1248
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "\1\0\0\1\30+\0\0\2\3def\6mmdb15\1t\5Entry\2ID\7"..., 1139, MSG_DONTWAIT, NULL, NULL) = 1139
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "\31\3def\6mmdb15\1t\5Entry\10statusID\10st"..., 1519, MSG_DONTWAIT, NULL, NULL) = 69
sendto(5, "\304\0\0\0\3\n\t\t\t\tSELECT\n\t\t\t\t\tEAN,\n\t\t\t\t\t"..., 200, MSG_DONTWAIT, NULL, 0) = 200
poll([{fd=5, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=5, revents=POLLIN}])
recvfrom(5, "\1\0\0\1\10,\0\0\2\3def\6mmdb15\5Track\5Track"..., 1450, MSG_DONTWAIT, NULL, NULL) = 443
Okay, ich sehe hier viele Interaktionen, aber gefühlt bleibt der Output immer mal wieder für den Bruchteil einer Sekunde stehen. Was genau passiert da? Ich vermute ja schon, dass das Script auf die Antwort einer Datenbank wartet. Können wir prüfen, wo das Script genau hängt?
Stellt sich heraus – ja, man kann: strace kennt eine Option -c, welche nicht “live” einen Output generiert, sondern am Ende (nachdem man strace abbricht, oder der Zielprozess fertig ist) eine Statistik ausgibt. Klingt gut, testen wir das mal:
# strace -p 933950 -c
Process 933950 attached
^CProcess 933950 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
46.43 0.000970 10 99 poll
45.14 0.000943 236 4 stat
3.49 0.000073 5 16 lstat
3.45 0.000072 1 71 sendto
0.91 0.000019 0 100 recvfrom
0.19 0.000004 0 48 write
0.19 0.000004 0 16 open
0.05 0.000001 0 22 lseek
0.05 0.000001 0 6 mmap
Und hier sehen wir auch schon den ersten Verdächtigen: poll wird sehr oft aufgerufen und verbraucht damit den Grossteil der Zeit! stat hingegen können wir wohl vorerst vernachlässigen, da er nur 4 mal aufgerufen wird. poll wird verwendet um auf Antworten vom Netzwerk zu warten. Ein Programm braucht diesen System Call, um zu schlafen, bis von einer Gegenstelle wieder Daten geliefert werden. Aber welche Daten? Und wie kommen wir anhand dieser Informationen wieder zu möglichen Lösungen für unser eigentliches Problem?
Wenn wir den Output von oben nochmals anschauen, sehen wir ein Pattern von System Calls: Es wird immer ein sendto gemacht, gefolgt von poll und schlussendlich recvfrom. Wie die Namen andeuten, sind diese System Calls für das Senden und Empfangen von Daten via Netzwerk zuständig.
Wir könnten jetzt also schauen, wie lange es zwischen einem sendto– und recvfrom-Paar genau dauert. Vielleicht gibt uns das ja Aufschluss! Aber wie geht das am einfachsten?
Manpage to the rescue!
Nach etwas lesen in der Manpage von strace finde ich eine Option, die mir sehr nützlich erscheint:
-r Print a relative timestamp upon entry to each system call.
This records the time difference between the beginning of
successive system calls.
Mit dieser Option sehe ich also, wieviel Zeit seit dem letzten System Call verging. Etwas Nachdenken, dann der Geistesblitz: Was passiert wohl, wenn ich mit strace nur die beiden System Calls sendto und recvfrom anzeige und den Rest ausfiltere? Mal schauen:
strace -p 933950 -r -e recvfrom,sendto
Process 933950 attached
0.000169 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`"..., 271, MSG_DONTWAIT, NULL, 0) = 271
1.036864 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1"..., 131, MSG_DONTWAIT, NULL, NULL) = 131
0.000088 recvfrom(4, "0.jpg\5\0\0\5\376\0\0\"\0", 173, MSG_DONTWAIT, NULL, NULL) = 14
Perfekt! Und bereits einen Verdächtigen erwischt! Da haben wir ein Query (man sieht ein SELECT) und irgendwelche Tabellennamen im Output (recvfrom-Zeile). Interessant. Aber vielleicht war es ja nur ein statistischer Ausreisser. Denn die anderen Calls brauchen viel weniger und ich sehe auch nicht das ganze Query.
Du bist umzingelt!
Wir wissen also wonach wir suchen müssen. Jetzt muss die Falle nur noch richtig gestellt werden und dann schauen was passiert. Mein Plan ist folgender:
Wir lassen strace in eine Datei schreiben (Option -o), sortieren dann die Aufrufe nach Zeit und sollten so, statistisch gesehen, die langsamsten Queries finden.
Und wenn wir schon dabei sind, möchten wir dann auch sehen, welche Queries daran schuld sind. Der obige Output zeigt uns, dass strace lange String-Argumente stark zusammenkürzt. In der Manpage finden wir den Parameter -s, mit welchem man angeben kann, wie stark die Kürzung ist. Wir wollen möglicht die ganzen Daten; ich gebe also einen extrem langen Parameter von 10000 Zeichen an. Also:
# strace -p 933950 -r -e sendto,recvfrom -s 10000 -o import_db_stats.txt
Process 933950 attached
Wir lassen den Trace etwas laufen und brechen dann mit Ctrl-C ab. Anschliessend sortieren wir die Aufzeichnung numerisch und schauen uns die letzten paar Zeilen an:
# sort -n import_db_stats.txt | tail -n5
0.749176 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\nimage_name\nimage_name\f!\0\375\2\0\0\375\1P\0\0\0\5\0\0\3\376\0\0\"\0\24\0\0\4\0231234567890_1.jpg\5\0\0\5\376\0\0\"\0", 159, MSG_DONTWAIT, NULL, NULL) = 145
0.769669 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\nimage_name\nimage_name\f!\0\375\2\0\0\375\1P\0\0\0\5\0\0\3\376\0\0\"\0\24\0\0\4\0231234567890_0.jpg\5\0\0\5\376\0\0\"\0", 172, MSG_DONTWAIT, NULL, NULL) = 145
0.803661 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\n", 69, MSG_DONTWAIT, NULL, NULL) = 69
0.814297 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21me", 16, MSG_DONTWAIT, NULL, NULL) = 16
0.947148 recvfrom(4, "\1\0\0\1\1^\0\0\2\3def\21sometable\1i\"product_images\nimage_name\nimage_name\f!\0\375\2\0\0\375\1P\0\0", 102, MSG_DONTWAIT, NULL, NULL) = 102
Oh, wunderbar! Wir haben also die fünf langsamsten Calls (respektive diejenigen mit der längsten Wartezeit vorher), alle sind recvfrom und zudem von der gleichen Datenbank (der erste Parameter entspricht dem File Handle respektive dem Socket). Bonus: Vier dieser Calls enthalten Daten der gleichen Tabelle! Jackpot!
Moment – wie sehe ich jetzt aber die Queries, welche langsam sind? Die recvfrom betreffen ja nur das Auslesen der Resultate. Wir erinnern uns – das Query wird in der Regel direkt vorher mittels sendto abgeschickt. Wir müssen also nur im (unsortierten!) Output nach den entsprechenden Zeilen suchen und den Vorgänger finden.
Ich denke, dass die relativen Timestamps über die kurze Zeit wohl eindeutig genug sind um als Suchparameter zu dienen. Also holen wir von den obigen Resultaten mal nur diese raus:
# sort -n import_db_stats.txt | tail -n5 | awk '{print $1}'
0.749176
0.769669
0.803661
0.814297
0.947148
Perfekt! Und mit grep können wir jetzt die Vorgänger-Zeilen dazu finden. Dabei hilft uns der Parameter -B. Weil wir die Resultate nicht wollen, filtern wir diese gleich wieder raus:
# sort -n import_db_stats.txt | tail -n5 | awk '{print $1}' > slowest_times.txt
> for time in $(cat slowest_times.txt); do
> grep -B1 $time import_db_stats.txt | grep -v $time
> done
0.000091 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '12345678896_1.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%12345678896'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000222 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890134_0.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890134'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000196 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890189_0.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890189'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000089 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890134_1.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890134'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
0.000167 sendto(4, "\v\1\0\0\3\n\t\t\tSELECT\n\t\t\t\t`image_name`\n\t\t\tFROM\n\t\t\t\t`product_images` AS `i`\n\t\t\tJOIN\n\t\t\t\t`products` AS `p`\n\t\t\t\t\tUSING (`product_id`)\n\t\t\tWHERE\n\t\t\t\t`image_name` LIKE '1234567890103_0.jpg'\n\t\t\t\tAND\n\t\t\t\t`p`.`product_ean` LIKE '%1234567890103'\n\t\t", 271, MSG_DONTWAIT, NULL, 0) = 271
Wunderbar. Wie bereits ganz am Anfang vermutet, ist es eines der Queries, welches eine LIKE-Suche mit einem Wildcard-Anfang macht.
Jetzt müssen wir also nur noch nach dem entsprechenden Query im Code suchen und uns überlegen, wie wir dies optimieren können. Aber das muss ich jetzt nicht mehr erklären; heute ging es darum, ein Problem einmal auf eine andere Art zu suchen.
Fazit
Wir lernen also, dass Linux mit strace ein wunderbares Werkzeug zur Verfügung stellt, um nicht nur allgemeine Probleme zu finden, sondern auch für Performance-Analysen. Das Schöne daran ist, dass man hier bereits viel über ein Programm erfahren kann, insbesondere auch wenn man auf den Quellcode keinen Zugriff hat.
Ich hatte strace bisher primär für die Fehlersuche bei hängenden Programmen verwendet oder zur Analyse was ein Programm genau tut.
Die wichtigsten Parameter von strace nochmals zusammengefasst:
-oschreibt den Output in eine Datei-rzeigt die relative Zeit seit dem letzten aufgezeichneten (!) System
Call-skann verwendet werden, um die String-Parameter-Kürzung einzustellen-cerstellt ein Call Profiling für die aufgerufenen Calls
strace kann noch viel mehr, es lohnt sich also, die Manpage einfach mal zu
überfliegen.
