Gestern vormittag war der Server bereits relativ langsam, am Nachmittag war er dann zeitweise kaum noch reaktionsfähig, und hat Fehlermeldungen geworfen.

Was war passiert?

Eigentlich nichts besonderes, davon aber zu viel.
So, wie ich die Logfiles verstehe, waren gestern die üblichen Suchmaschinenroboter (Google, Bing, Baidu, ...) etwas aktiver als sonst - jedenfalls waren 15% mehr Zugriffe von denen zwischen 10 und 18 Uhr zu bemerken.

Außerdem liefen noch ein paar andere Roboter über die Seite. Zwar lief einer von denen offensichtlich Amok, aber auch das hätte der Server sonst überstanden. Insgesamt waren das 50% mehr als sonst.

Die Zahl der Zugriffe durch Menschen hielt sich im Rahmen des üblichen - sie war nur leicht erhöht.
Aber ein paar von denen haben intensiver nach Bildern gesucht, und Volltextsuche und Ähnlichkeitssuche strapaziert. Die gibt's sonst auch, aber in jenem Zeitraum waren es knapp 20% mehr als sonst.

Insgesamt hätte der Server das ganz, ganz locker überstanden - es gab zwar auffällig viele Zugriffe zwischen 10 und 18 Uhr, aber immer noch deutlich weniger als sonst zwischen 18 und 22 Uhr...

Hinzu kam noch eine Kleinigkeit: Seit einigen Tagen läuft um 11 Uhr morgens ein Script, was so eine Art Rangliste der Objekte in der Datenbank berechnet. Das war nicht unbedingt elegant geschrieben, lief aber sonst immer in 30 bis 80 Sekunden durch.

Gestern allerdings nicht - gestern brauchte es mal eben 6 Stunden.

Warum? Tja, gute Frage. Ich war in dem Moment nicht dabei... und insofern ist das, was ich vermute, nicht durch harte Fakten untermauert.

1. Die Hardware an sich ist mittlerweile zwischenzeitlich recht gut ausgelastet. Naja, im Tagesmittel ist sie immer noch nicht ausgelastet, aber in Spitzenzeiten eben doch.
   
2. Das Script hat massiv in einer Tabelle geschrieben, in die auch das Forum schreibt. Wahrscheinlich haben sich beide gegenseitig blockiert.
   
3. Das Script hat, ein einer Tabelle mit unter 450000 Einträgen, das hier verursacht:
   

   
   INFO:  Index »object_stats_pkey« gelesen und 10406419 Zeilenversionen entfernt
   DETAIL:  CPU 0.14s/0.68u sec elapsed 3.49 sec.
   INFO:  Index »object_stats_hitcount« gelesen und 10406419 Zeilenversionen entfernt
   DETAIL:  CPU 1.27s/4.53u sec elapsed 94.49 sec.
   INFO:  Index »object_stats_x_rank« gelesen und 10406419 Zeilenversionen entfernt
   DETAIL:  CPU 1.02s/5.11u sec elapsed 116.61 sec.
   INFO:  »object_stats«: 10406419 Zeilenversionen in 108642 Seiten entfernt
   DETAIL:  CPU 2.24s/0.88u sec elapsed 65.14 sec.
   INFO:  Index »object_stats_pkey« enthält 433052 Zeilenversionen in 4875 Seiten
   DETAIL:  977373 Indexzeilenversionen wurde entfernt.
   0 Indexseiten wurden gelöscht, 0 sind gegenwärtig wiederverwendbar.
   CPU 0.00s/0.00u sec elapsed 0.00 sec.
   INFO:  Index »object_stats_hitcount« enthält 433052 Zeilenversionen in 41556 Seiten
   DETAIL:  7559454 Indexzeilenversionen wurde entfernt.
   37454 Indexseiten wurden gelöscht, 12849 sind gegenwärtig wiederverwendbar.
   CPU 0.00s/0.00u sec elapsed 0.00 sec.
   INFO:  Index »object_stats_x_rank« enthält 433052 Zeilenversionen in 41511 Seiten
   DETAIL:  7559454 Indexzeilenversionen wurde entfernt.
   37568 Indexseiten wurden gelöscht, 12914 sind gegenwärtig wiederverwendbar.
   CPU 0.00s/0.00u sec elapsed 0.00 sec.
   INFO:  »object_stats«: 903453 entfernbare, 433052 nicht entfernbare Zeilenversionen in 125492 Seiten gefunden
   DETAIL:  2 tote Zeilenversionen können noch nicht entfernt werden.
   Es gibt 1501976 unbenutzte Itemzeiger.
   121718 Seiten enthalten nützlichen freien Platz.
   0 Seiten sind vollkommen leer.
   CPU 5.44s/11.81u sec elapsed 285.58 sec.
   

   
   Mit anderen Worten, es hat die Tabelle dank MVCC stark aufgebläht. Einschließlich der Indexdaten hatte die Tabelle 1.6 Gigabyte Umfang. Nach Aufräumen ("CLUSTER") waren es wieder 62 MB.
   
   
   Wahrscheinlich hat das dazu geführt, daß der Plattencache überfordert war ("0 Seiten sind vollkommen leer" kann man auch lesen als "jede Seite enthielt ein kleines bisschen nützlicher Information").
   

Ich hab' das Script dann gestern abend mal umgeschrieben, daß es deutlich weniger auf die Datenbank schreibt, und sich außerdem schreibenderweise von allen Tabellen fernhält, in denen das Forum schreibt.
Und siehe da, seitdem läuft es zwischen 35 und 55 Sekunden.

Gruß, Uwe