PDO Session Handling

Aktuell schmiert unser Testshop teilweise mit folgender Fehlermeldung ab:

 

[Fri Jun 30 13:38:34.820418 2017] [:error] [pid 14112] [client XXXXX:61968] PHP Fatal error:  Uncaught PDOException: SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction in /var/www/test/htdocs/engine/Shopware/Components/Session/PdoSessionHandler.php:536\nStack trace:\n#0 /var/www/test/htdocs/engine/Shopware/Components/Session/PdoSessionHandler.php(536): PDOStatement->execute()\n#1 /var/www/test/htdocs/engine/Shopware/Components/Session/PdoSessionHandler.php(291): Shopware\Components\Session\PdoSessionHandler->doRead(‘68tdghof2l954oj…’)\n#2 [internal function]: Shopware\Components\Session\PdoSessionHandler->read(‘68tdghof2l954oj…’)\n#3 /var/www/test/htdocs/engine/Library/Zend/Session.php(491): session_start()\n#4 /var/www/test/htdocs/engine/Shopware/Components/DependencyInjection/Bridge/Session.php(105): Zend_Session::start(Array)\n#5 /var/www/test/htdocs/var/cache/production_201704210836/proxies/ShopwareProduction60140db79c0a6921cc1bff9d5111434e54d172f5ProjectConta in /var/www/test/htdocs/engine/Shopware/Components/Session/PdoSessionHandler.php on line 536

 

Die Session ist unter s_core_sessions abgelegt - und wäre in laut DB noch bis 14 Uhr gültig. Werde allerdings aus der Fehlermeldung nicht schlau.

General error: 1205 Lock wait timeout exceeded;

Das ist die entscheidende Stelle der Fehlermeldung.  

Mit dem InndoDB Status Log kann man herausfinden, welche Prozesse eine InnoDB Table blockiert und diese nicht wieder frei gegeben haben. Ist der Prozess bekannt - z. B. weil nach einem Kill die Tabelle wieder beschreibbar ist - fährt man dort mit der Fehlersuche fort.

In der Mysql-Konfig kann der Time-Out für Locks gesetzt werden: innodb_lock_wait_timeout

Eigentlich sollte der Default Wert ausreichend sein.

@hth‍  habe gerade mit dem Hoster gesprochen in der Config wurde der Session Save Path nicht angepasst - für die Memcache Session. Wenn ich diesen in der config.php nicht setze, müsste er ja eigentlich Standardmäßig die DB nehmen.

session.save_path tcp://xx.6.xx6.7:11211?persistent=1&weight=1&timeout=1&retry_interval=2

Errorlogs, gerade der DB, sind ein pain in the arse bei dem Provider…

Ab 5.2.13 gibt es ein Session-Locking, was verhindert, dass zwei Abfragen gleichzeitig in die Session schreiben. Generell verhindert das Race-Conditions. Das kann man auch temporär über die config.php deaktivieren: config.php settings

Als Ursache würde ich jetzt zunächst mal vermuten, dass ein Querry zu lange läuft, daher die Session blockiert und Probleme macht und ihr daher in das Problem lauft. Das Deaktivieren wäre hier sicherlich nur eine Unterdrückung des Symptoms, aber nicht die Lösung des Problemes. Erfahrungsgemäß sind das häufig Querries aus Plugins - aber das müsste man dann intensiv testen.

Das Auslagern in Redis/Memcache hilft da natürlich auch, einfach weil die Querries dann schneller laufen. Das macht unabhängig ohnehin Sinn, wenn man viel Traffic auf der Seite hat.

1 Like

Interessant - das Problem hatten wir bei noch keinem Stage Setup (lokal oder beim Hoster). Kann es also nicht sein, dass es an der Config des PHP Session Save Path lag?

 

[@Moritz Naczenski](http://forum.shopware.com/profile/14574/Moritz Naczenski “Moritz Naczenski”)‍

So tief bin ich da nicht in der Materie, sorry.

Wenn man die Fehlermeldung alleine sieht, würd eich halt zunächst vermuten, dass ein Request von einem anderen blockiert wird. Das kann natürlich passieren, weil der Request an sich sehr lange braucht (bspw. Probleme mit dem Session Storage usw.) oder auch, weil eine Abfrage zu lange läuft und die Session blockiert. Letzteres wäre ja eher etwas, was in Shopware passiert und ersteres eher etwas, was am Server-Setup hängt.  Gerade bei viel Traffic mit vielen Session-Abfragen wird natürlich das Locking auch wahrscheinlicher. Da kann dann die Optimierung mit einem Session Storage wie Redis helfen oder halt die parallelen Abfragen zu erlauben.

Eine Tabelle ist von der InnoDB Engine mit einem Lock versehen und nicht wieder freigegeben worden. Der nächste Versuch eine neue Session anzulegen funktioniert dann wahrscheinlich nicht mehr. Legt zumindest das Auftreten im SessionHandler von Shopware nahe. 

Wenn der Fehler auftritt, startet man in der mysql-Konsole mit der Fehlersuche. Der Session-Lock von Shopware sollte eigentlich nicht das Problem bei den Transactions in der DB verursachen - kannst es ja testen. Schau dir mal dies hier in der Mysql-Konsole an, wenn der Fehler auftritt: SHOW ENGINE INNODB STATUS\G

Und/oder die Prozess-List.

Keine Ahnung, ob eine unvollständige Session-Handler Konfiguration Chaos verursachen kann. Wenn die gar nicht vorhanden ist, greift der Shopware-Standard automatisch mit dem DB-Zugriff. Denke, dies ist bei dir der Fall. 

Es gibt mit Sicherheit viele Einträge zu Lock-Problemen bei InnoDB in stackoverflow & Co.

Wir sind mittlerweile auf memcached umgeswitcht - leider bisher ohne viel Erfolgt.

Nun haben wir in vielen Call ein session_start() von exakt 3s / 5s und 9s

 

Der memcached wird vom Loadbalancer verwaltet und alle Appserver greifen darauf zu. Hier scheint was komplett in den binsen zu sein, die Zeiten von 3 / 5 und 9s kann ich aber nicht nachvollziehen. Timeout?