Hi Mirko,
leider scheitert bei uns das Upgrade immer noch. Hier mal eine Analyse was wir bis jetzt beobachten konnten:
# Startbedingungen
MySQL
Server version: 8.4.7 MySQL Community Server - GPL
PHP 8.1 + Apache
SML 9.52 Updatedateien sind bereits aufgespielt, upgrade.php jedoch noch nicht ausgeführt.
# Schritt 1:
Isolieren der SML-App, Reverse-Proxy wird mit Basic-Auth bestückt, Passwort ist nur Admin bekannt.
# Schritt 2:
MySQL General Log clearen und neu aktivieren. Ab jetzt wird JEDER Datenbankzugriff geloggt.
mysql> SET GLOBAL general_log = OFF;
Query OK, 0 rows affected (0.00 sec)
mysql> SET GLOBAL log_output = 'TABLE';
Query OK, 0 rows affected (0.00 sec)
mysql> TRUNCATE TABLE mysql.general_log;
Query OK, 0 rows affected (0.00 sec)
mysql> SET GLOBAL general_log = ON;
Query OK, 0 rows affected (0.00 sec)
# Schritt 3:
Ein paar Minuten warten, sodass offensichtlich wird, dass kein Cronjob oder irgendein anderer Prozess auf die Datenbank zugreift.
mysql> SELECT NOW() AS start_time;
+---------------------+
| start_time |
+---------------------+
| 2026-04-01 11:53:23 |
+---------------------+
1 row in set (0.00 sec)
mysql> SELECT NOW() AS start_time;
+---------------------+
| start_time |
+---------------------+
| 2026-04-01 12:01:24 |
+---------------------+
1 row in set (0.00 sec)
Übersicht über die Datenbankzugriffe bisher:
mysql> SELECT event_time, user_host, command_type
-> FROM mysql.general_log
-> ORDER BY event_time DESC
-> LIMIT 20;
+----------------------------+---------------------------+--------------+
| event_time | user_host | command_type |
+----------------------------+---------------------------+--------------+
| 2026-04-01 12:01:48.087522 | root[root] @ localhost [] | Query |
| 2026-04-01 12:01:24.845378 | root[root] @ localhost [] | Query |
| 2026-04-01 11:53:23.289373 | root[root] @ localhost [] | Query |
+----------------------------+---------------------------+--------------+
3 rows in set (0.00 sec)
Die drei Queries sind meine Uhrzeit-Abfragen und die General-Log Abfrage, was man auch am user "root" sieht.
# Schritt 4:
Jetzt wird das Upgrade durchgeführt. Deadlock tritt auf:
SQL-Fehler: Deadlock found when trying to get lock; try restarting transaction 1213
SQL-Anweisung: SHOW COLUMNS FROM `jamaicanflavours_forms`
Hier sind die letzten Zeilen des General-Logs vor dem Fehler. Man sieht den ROLLBACK, und auch, dass es scheinbar mehrere Thread IDs gibt, die "kreuz und queer" (also nicht sequenziell) auf die Datenbank zugreifen. Das vollständige General Log stellen wir bei Bedarf gerne privat zur Verfügung.
+----------------------------+---------------------------+-----------+--------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| event_time | user_host | thread_id | command_type | sql_text |
+----------------------------+---------------------------+-----------+--------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ |
| 2026-04-01 12:02:25.989353 | sml[sml] @ [172.17.4.3] | 17 | Quit | |
| 2026-04-01 12:02:25.989128 | sml[sml] @ [172.17.4.3] | 17 | Query | ROLLBACK |
| 2026-04-01 12:02:25.988458 | sml[sml] @ [172.17.4.3] | 17 | Query | SELECT `GoogleTranslate` FROM `options` |
| 2026-04-01 12:02:25.982452 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `jamaicanflavours_forms` |
| 2026-04-01 12:02:25.982430 | sml[sml] @ [172.17.4.3] | 18 | Query | ALTER DATABASE sml CHARACTER SET utf8 |
| 2026-04-01 12:02:25.982191 | sml[sml] @ [172.17.4.3] | 18 | Query | SET SQL_MODE="" |
| 2026-04-01 12:02:25.982082 | sml[sml] @ [172.17.4.3] | 18 | Query | SET CHARACTER SET 'utf8' |
| 2026-04-01 12:02:25.981991 | sml[sml] @ [172.17.4.3] | 18 | Query | SET NAMES 'utf8' |
| 2026-04-01 12:02:25.981912 | sml[sml] @ [172.17.4.3] | 18 | Init DB | sml |
| 2026-04-01 12:02:25.981795 | sml[sml] @ [172.17.4.3] | 18 | Query | SET SQL_MODE="" |
| 2026-04-01 12:02:25.981677 | sml[sml] @ [172.17.4.3] | 18 | Query | SET CHARACTER SET 'utf8' |
| 2026-04-01 12:02:25.981502 | sml[sml] @ [172.17.4.3] | 18 | Query | SET NAMES 'utf8' |
| 2026-04-01 12:02:25.980095 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `jamaicanflavours_members` |
| 2026-04-01 12:02:25.977633 | [sml] @ [172.17.4.3] | 18 | Connect | sml@172.17.4.3 on using TCP/IP |
| 2026-04-01 12:02:25.977269 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste1_forms` |
| 2026-04-01 12:02:25.975305 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste1_members` |
| 2026-04-01 12:02:25.972922 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste2_forms` |
| 2026-04-01 12:02:25.970917 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste2_members` |
| 2026-04-01 12:02:25.968228 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste3_forms` |
| 2026-04-01 12:02:25.966258 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste3_members` |
| 2026-04-01 12:02:25.963698 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste4_forms` |
| 2026-04-01 12:02:25.961207 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste4_members` |
| 2026-04-01 12:02:25.958928 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste5_forms` |
| 2026-04-01 12:02:25.957056 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste5_members` |
| 2026-04-01 12:02:25.954702 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste6_forms` |
| 2026-04-01 12:02:25.951965 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste6_members` |
| 2026-04-01 12:02:25.949579 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste7_forms` |
| 2026-04-01 12:02:25.942379 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste8_members` |
| 2026-04-01 12:02:25.947658 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste7_members` |
| 2026-04-01 12:02:25.939611 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste9_members` |
| 2026-04-01 12:02:25.945206 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste8_forms` |
| 2026-04-01 12:02:25.936991 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `maillists` |
| 2026-04-01 12:02:25.940893 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `liste9_forms` |
| 2026-04-01 12:02:25.931945 | sml[sml] @ [172.17.4.3] | 17 | Query | SELECT `JobType` FROM `cronoptions` WHERE JobType='AutoImport' |
| 2026-04-01 12:02:25.939284 | sml[sml] @ [172.17.4.3] | 17 | Query | SELECT `MaillistTableName`, `FormsTableName` FROM maillists |
| 2026-04-01 12:02:25.932821 | sml[sml] @ [172.17.4.3] | 17 | Query | SELECT `id` FROM `fieldnames` WHERE `fieldname`='u_Profession' |
| 2026-04-01 12:02:25.930647 | sml[sml] @ [172.17.4.3] | 17 | Query | SHOW COLUMNS FROM `options`
Hier ist das Access-Log während des Upgrades. Die drei "Besuche" auf upgrade.php sind das Weiterklicken durch die Dialoge.
sml | [Wed Apr 01 11:48:49.587417 2026] [mpm_prefork:notice] [pid 1:tid 1] AH00163: Apache/2.4.65 (Debian) PHP/8.1.34 configured -- resuming normal operations
sml | [Wed Apr 01 11:48:49.587460 2026] [core:notice] [pid 1:tid 1] AH00094: Command line: 'apache2 -D FOREGROUND'
sml | 172.17.2.4 - - [01/Apr/2026:12:02:20 +0000] "GET /upgrade.php HTTP/1.1" 200 2312 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
sml | 172.17.2.4 - - [01/Apr/2026:12:02:21 +0000] "GET /js_localization.php HTTP/1.1" 200 553 "https://sml.ctdasradio.de/upgrade.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
sml | 172.17.2.4 - - [01/Apr/2026:12:02:23 +0000] "POST /upgrade.php HTTP/1.1" 200 2377 "https://sml.ctdasradio.de/upgrade.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
sml | 172.17.2.4 - - [01/Apr/2026:12:02:23 +0000] "GET /images/loading.gif HTTP/1.1" 200 2997 "https://sml.ctdasradio.de/upgrade.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
sml | 172.17.2.4 - - [01/Apr/2026:12:02:23 +0000] "GET /js_localization.php HTTP/1.1" 200 553 "https://sml.ctdasradio.de/upgrade.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
sml | 172.17.2.4 - - [01/Apr/2026:12:02:25 +0000] "POST /upgrade.php HTTP/1.1" 200 2565 "https://sml.ctdasradio.de/upgrade.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
sml | 172.17.2.4 - - [01/Apr/2026:12:02:25 +0000] "GET /js_localization.php HTTP/1.1" 200 553 "https://sml.ctdasradio.de/upgrade.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
sml | 172.17.2.4 - - [01/Apr/2026:12:02:26 +0000] "GET /js_localization.php HTTP/1.1" 200 553 "https://sml.ctdasradio.de/upgrade.php" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:149.0) Gecko/20100101 Firefox/149.0"
Upgrade schlägt mit Deadlock fehl
Moderator: mirko
Re: Upgrade schlägt mit Deadlock fehl
Das CronJob-Script ausschalten/Script umbenennen, kein anderer sollte während der Zeit zugreifen. Das Script upgrade.php öffnet nur eine MySQL-Verbindung, also muss jemand anders zugreifen, z.B. das CronJob-Script.
Upgrade schlägt mit Deadlock fehl
Hallo,
beim Upgrade unserer SML-Installation kommt es reproduzierbar zu einem Abbruch mit folgendem Fehler:
Deadlock found when trying to get lock; try restarting transaction (1213)
SQL-Anweisung: SHOW COLUMNS FROM <tabellenname>
Umgebung:
SML 9.40.0.01447
MySQL 8.4.7
PHP 8.1, Apache
Installation in Docker, mit jeweils offiziellen PHP / MySQL images.
für das Upgrade isolierte Umgebung, keine externen Zugriffe, geprüft via access log
Im MySQL-General-Log ist ersichtlich, dass während des Upgrades mehrere sehr kurzlebige DB-Verbindungen geöffnet werden, die parallel ALTER TABLE-Statements und SHOW COLUMNS-Abfragen ausführen. Dies führt offenbar zu Metadata-Lock-Deadlocks (MDL), wodurch das Upgrade auch nach 20–30 Versuchen stets an unterschiedlichen Stellen mit Fehler 1213 abbricht.
Wir sehen diese Deadlock-Fehler zwischenzeitlich auch bei Admin-Aktivitäten wie dem Anlegen von neuen Verteilerlisten. Dort sind sie allerdings durch mehrfaches Versuchen umgehbar.
Die Docker-Umgebung wurde testweise auf einen anderen Server in einer anderen Umgebung umgezogen, auch dort treten die Fehler auf. Beide Umgebungen sind üblicherweise performant (SSD, 8GB RAM, 4 Kerne).
Gerne stelle ich bei Bedarf relevante Log-Auszüge zur Verfügung.
Viele Grüße
Claas
beim Upgrade unserer SML-Installation kommt es reproduzierbar zu einem Abbruch mit folgendem Fehler:
Deadlock found when trying to get lock; try restarting transaction (1213)
SQL-Anweisung: SHOW COLUMNS FROM <tabellenname>
Umgebung:
SML 9.40.0.01447
MySQL 8.4.7
PHP 8.1, Apache
Installation in Docker, mit jeweils offiziellen PHP / MySQL images.
für das Upgrade isolierte Umgebung, keine externen Zugriffe, geprüft via access log
Im MySQL-General-Log ist ersichtlich, dass während des Upgrades mehrere sehr kurzlebige DB-Verbindungen geöffnet werden, die parallel ALTER TABLE-Statements und SHOW COLUMNS-Abfragen ausführen. Dies führt offenbar zu Metadata-Lock-Deadlocks (MDL), wodurch das Upgrade auch nach 20–30 Versuchen stets an unterschiedlichen Stellen mit Fehler 1213 abbricht.
Wir sehen diese Deadlock-Fehler zwischenzeitlich auch bei Admin-Aktivitäten wie dem Anlegen von neuen Verteilerlisten. Dort sind sie allerdings durch mehrfaches Versuchen umgehbar.
Die Docker-Umgebung wurde testweise auf einen anderen Server in einer anderen Umgebung umgezogen, auch dort treten die Fehler auf. Beide Umgebungen sind üblicherweise performant (SSD, 8GB RAM, 4 Kerne).
Gerne stelle ich bei Bedarf relevante Log-Auszüge zur Verfügung.
Viele Grüße
Claas