mysqld macht 100% CPU-Load

[Rüdiger Kupper]

Gerade sehe ich, dass auf dem paedml ein mysqld wildgeworden ist. Ich werde den mal killen.
(Bitte im Auge behalten, ob das öfter passiert.)

[Rüdiger Kupper]

Hängt möglicherweise mit dem Timeout bei Trac zusammen (benutzt ja eine MySQL-Datenbank).
Unklar, was hier Ursache und was Wirkung ist.

[Rüdiger Kupper]

Jedenfalls kann eine Änderung im Trac diesen Fehler hervorrufen: Der mysqld macht 100% CPU-Last und antwortet niemals auf die Anfrage. Daher bleibt auch der apache dort hängen.

Eine Idee, warum der mysqld das macht?

[bau]

Hast du eine Ahnung, was das für eine Anfrage ist?
Eventuell ist einfach die MySQL-Version schlichtweg veraltet (-> Update auf paedml5)

[Rüdiger Kupper]

Trac verwaltet seine kompletten Daten (Tickets, Wiki, Timeline, etc.) in einer Datenbank. Es kann verschiedene Datenbanktreiber verwenden; MySQL ist laut Trac-Manual erst spät hinzugekommen und kann möglicheweise Probleme machen.

Daher kann es gut sein, dass ein Update des MySQL-Servers was bringt. Wir sollten schaun, dass wir den Udate auf PaedML5 bald vollziehen. (Ich hab hier schon ein OpenML5 in der virtuellen Maschine laufen, natürlich frisch hochgezogen, das geht problemlos.)

Allerdings hat Trac mit MySQL bei uns anfangs sehr gut funktioniert, vielleicht hängt's mit der Menge der Daten zusammen. (Andererseits: Ein Datenbankserver sollte ja gerade nicht von der Größe der Datenbank abhängig sein.)

Anfragen, die das auslösen können, sind z.B.

• Ändern einer Wiki-Seite (Schreibvorgang)
• Abfrage der Tickets (Lesevorgang)

Mehr hab ich nicht herausgefunden. Irgendwo habe ich gelesen, dass MySQL einen "slow transaction guard" hat, den man einschalten kann und der Informationen über Anfragen ausgibt, die sehr lange dauern. Den muss ich vielleicht mal anschalten.

[Rüdiger Kupper]

Interessanterweise sind bei mir in den letzten Tagen keine Hänger mehr aufgetreten, obwohl ich viel mit Trac arbeite. Das kann also nicht die Ursache sein. Was dann?

[bau]

Im phpMyAdmin kann man die Processlist anzeigen lassen. Da gibt es dann jede Menge nicht mehr benötigter MySQL-Prozesse. Wenn man die beendet geht der MySQLD sofort auf 0% CPU - was macht der TRAC da falsch?

[bau]

Ich habe grade dieses Ticket gesendet. Sofort hat der TRAC drei mysql-Prozesse aufgemacht, die nun alle seither schlafen. Bleibt da irgendwas persistent im Speicher???
Das sollte der TRAC aber nicht machen!

[Rüdiger Kupper]

Ich hab immer nur nach laufenden Prozessen gesucht, und da ist es im Normalfall so, dass ein Prozess auftaucht, kurz arbeitet und dann wieder verschwindet. Wenn das Trac hängt sieht man das daran, dass dieser Prozess dauerhaft 100% CPU verbraucht und erst nach langer Zeit wieder verschwindet.

Ob mysql-Prozesse im Hintergrund schlafen, habe ich nie getestet. Ich wüsste auch nicht, ob das normal ist oder nicht. Das kann ja auch normales Verhalten des mysqld sein.

[Rüdiger Kupper]

Als ich eben den Kommentar abgeschickt habe, ist ein mysql-Prozess erschienen und sofort wieder verschwunden, jetzt läuft *kein* Prozess mehr (auch nicht schlafend).

[Rüdiger Kupper]

Hm, und was sagt mir das hier:

mysql> show processlist;
+-------+------+-----------+------+---------+------+-------+------------------+
| Id    | User | Host      | db   | Command | Time | State | Info             |
+-------+------+-----------+------+---------+------+-------+------------------+
| 60656 | kup  | localhost | trac | Sleep   |  335 |       | NULL             | 
| 60671 | kup  | localhost | trac | Query   |    0 | NULL  | show processlist | 
+-------+------+-----------+------+---------+------+-------+------------------+
2 rows in set (0.00 sec)

[Rüdiger Kupper]

Nach dem letzten Kommentar (kein Hänger) sieht die porcess list jetzt so aus:

mysql> show processlist;
+-------+------+-----------+------+---------+------+-------+------------------+
| Id    | User | Host      | db   | Command | Time | State | Info             |
+-------+------+-----------+------+---------+------+-------+------------------+
| 60671 | kup  | localhost | trac | Query   |    0 | NULL  | show processlist | 
| 60672 | kup  | localhost | trac | Sleep   |   30 |       | NULL             | 
| 60673 | kup  | localhost | trac | Sleep   |   29 |       | NULL             | 
| 60674 | kup  | localhost | trac | Sleep   |   17 |       | NULL             | 
+-------+------+-----------+------+---------+------+-------+------------------+
4 rows in set (0.00 sec)

[Rüdiger Kupper]

Und jetzt so:

mysql> show processlist;
+-------+------+-----------+------+---------+------+-------+------------------+
| Id    | User | Host      | db   | Command | Time | State | Info             |
+-------+------+-----------+------+---------+------+-------+------------------+
| 60671 | kup  | localhost | trac | Query   |    0 | NULL  | show processlist | 
| 60672 | kup  | localhost | trac | Sleep   |   76 |       | NULL             | 
| 60673 | kup  | localhost | trac | Sleep   |   11 |       | NULL             | 
| 60674 | kup  | localhost | trac | Sleep   |   11 |       | NULL             | 
| 60675 | kup  | localhost | trac | Sleep   |   43 |       | NULL             | 
| 60676 | kup  | localhost | trac | Sleep   |   19 |       | NULL             | 
+-------+------+-----------+------+---------+------+-------+------------------+
6 rows in set (0.00 sec)

Es kommen jedesmal schlafende Prozesse dazu, aber es hängt nirgends. -- ?

[bau]

Ich vermute mal, dass es irgendwann einmal zu viele schlafende Hunde sind, und dann stockt das Ganze. Ich habe grade mal den Kepler-Login aufgerufen, der greift auch auf den mysql zu - man sieht noch nicht mal den Prozess, dann ist er schon wieder weg und schläft auch anschließend nicht. Also ein komisches Verhalten des TRAC. Kann man da in den Treibereinstellungen irgendwas bezüglich persistent o.Ä. einstellen?

[Rüdiger Kupper]

Da schläft aber auch manchmal noch was anderes, z.B. ein Infosys-Prozess:

mysql> show processlist;
+-------+---------+--------------------+--------+---------+------+-------+------------------+
| Id    | User    | Host               | db     | Command | Time | State | Info             |
+-------+---------+--------------------+--------+---------+------+-------+------------------+
| 60680 | kup     | localhost          | trac   | Sleep   |  623 |       | NULL             | 
| 60701 | kup     | localhost          | trac   | Sleep   |  328 |       | NULL             | 
| 60702 | kup     | localhost          | trac   | Sleep   |  327 |       | NULL             | 
| 60704 | infosys | 10.16.209.88:38344 | Schule | Sleep   |   16 |       | NULL             | 
| 60718 | kup     | localhost          | trac   | Sleep   |   66 |       | NULL             | 
| 60719 | kup     | localhost          | trac   | Sleep   |   65 |       | NULL             | 
| 60720 | kup     | localhost          | trac   | Query   |    0 | NULL  | show processlist | 
+-------+---------+--------------------+--------+---------+------+-------+------------------+
7 rows in set (0.00 sec)

Und der verschwindet ebenfalls nicht mehr.

[Rüdiger Kupper]

Hm. Jetzt ist einer der Trac-Prozesse verschwunden.
Außerdem sehe ich jede Menge apache2-Prozesse laufen, ist das normal?

08:35/0 paedml ~ # ps -ef|grep apache
root     17312     1  0 Dec18 ?        00:00:04 /usr/sbin/apache2 -k start
tomcat55 20367     1  0 Nov12 ?        01:14:46 /usr/local/java/current/bin/java -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.util.logging.config.file=/var/lib/tomcat5.5/conf/logging.properties -Djava.awt.headless=true -Xmx512M -XX:MaxPermSize=256M -Djava.endorsed.dirs=/usr/share/tomcat5.5/common/endorsed -classpath :/usr/share/tomcat5.5/bin/bootstrap.jar:/usr/share/tomcat5.5/bin/commons-logging-api.jar -Dcatalina.base=/var/lib/tomcat5.5 -Dcatalina.home=/usr/share/tomcat5.5 -Djava.io.tmpdir=/var/lib/tomcat5.5/temp org.apache.catalina.startup.Bootstrap start
www-data 30887 17312  0 08:18 ?        00:00:01 /usr/sbin/apache2 -k start
www-data 30937 17312  0 08:20 ?        00:00:02 /usr/sbin/apache2 -k start
www-data 30987 17312  0 08:21 ?        00:00:01 /usr/sbin/apache2 -k start
www-data 31285 17312  0 08:24 ?        00:00:03 /usr/sbin/apache2 -k start
www-data 31438 17312  0 08:25 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 31840 17312  1 08:29 ?        00:00:03 /usr/sbin/apache2 -k start
www-data 31890 17312  0 08:30 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 31891 17312  0 08:30 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 31892 17312  0 08:30 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 31901 17312  0 08:31 ?        00:00:01 /usr/sbin/apache2 -k start
root     32135 31849  0 08:35 pts/2    00:00:00 grep apache

[Rüdiger Kupper]

Da auch immer wieder mal Infosys-Prozesse lange schlafen, bin ich nicht überzeugt, dass das Problem wirklich bei Trac liegt, aber keine Ahnung.

Vorschlag: Wir updaten den paedml und schauen, ob es mit einer aktuelle mysql-Version noch das gleiche ist. Wenn ja: Trac unterstützt als Backend auch postresql, und da läuft ja auch ein Serve auf dem paedml, oder? Die Datenbank zu portieren ist aber etwas, was ich nciht unbedingt alle Tage tun will ;-).

[bau]

Der InfoSys-Prozess ist normal, denn InfoSys greift per ODBC auf mysql zu, da bleibt der Prozess offen, bis man InfoSys schließt. Die apache-Prozesse sind wahrscheinlich auch normal, der macht halt für die Zugriffe mehrere Prozesse auf.

OK: Umstieg auf paedml5 abwarten und eventuell auf postgres umsteigen. Portierung wäre z.B. über ODBC aus ACCESS heraus möglich.

[Rüdiger Kupper]

Das Problem scheint nach unserem Update auf PädML5 verschwunden zu sein (toi, toi, toi).