Abbrechende MariaDB/MySQL Verbindungen

Wer sich etwas vertieft mit den MariaDB Status Zählern (SHOW GLOBAL STATUS;) auseinander setzt, wird früher oder später auf den Zähler Aborted_clients stossen:

mariadb> SHOW GLOBAL STATUS LIKE 'aborted_clients';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| Aborted_clients | 5392  |
+-----------------+-------+

Wenn man sich dann die MariaDB Dokumentation anschaut, steht da folgendes:

Number of aborted client connections. This can be due to the client not calling mysql_close() before exiting, the client sleeping without issuing a request to the server for more seconds than specified by wait_timeout or interactive_timeout, or by the client program ending in the midst of transferring data.

Also:

• Vergessener Aufruf von mysql_close().
• Inaktive Verbindung (Sleep) für mehr als wait_timeout oder interactive_timeout Sekunden.
• Unerwartete Beendigung der Applikation.

Der erste Punkt geht unter die Kategorie: Unsauber programmiert und somit ein Fehler in der Anwendung.

Der zweite Punkt ist eher ein Konfigurationsproblem sei es auf Datenbankseite oder auf Applikationsseite.

Hier stellt sich die Frage: Warum sind die Timeouts so eingestellt, wenn die Timeouts kurz sind? Default für beide Timeouts ist 28800 Sekunden, also 8 Stunden.

mariadb> SHOW GLOBAL VARIABLES LIKE '%timeout';
+---------------------------+-------+
| Variable_name             | Value |
+---------------------------+-------+
| interactive_timeout       | 28800 |
| wait_timeout              | 28800 |
+---------------------------+-------+

Oder aber: Warum schickt die Anwendung so lange keine Daten über eine geöffnete Verbindung (hat die Anwendung die Verbindung verloren)?

Der zweite Fall trifft üblicherweise dann ein, wenn persistente Verbindungen verwendet werden (Java Connection Pool, Ruby on Rails, PHP Persistent Database Connections, etc.). Dann sollten die Entwickler den Connector so konfigurieren, dass er alle paar Sekunden einen Ping über die Verbindung schickt.

Der dritte Fall hat sehr viel Ähnlichkeit mit dem ersten Fall: Die Applikation beendet sich früher als erwartet. Das kann zum Beispiel auftreten, wenn:

• exit() vor mysql_close() (Fall 1 von oben)
• Applikation wurde unerwartet von aussen beendet (kill, OOM Killer, systemd, etc.)
• Firewalls oder Load Balancer die eine idelnde Verbindung nach einer bestimmten Zeit terminieren (z.B. 300 Sekunden).

Feststellen, wen es betrifft

Eigentlich sollte die Applikation in den meisten Fällen selber merken, wenn sie unerwartet beendet wurde (Fall 2 und 3). Sehr oft tut sie dies aber nicht. Daher müssen wir als Datenbankverantwortliche der Applikation manchmal auf die Sprünge helfen, und Ihr mitteilen, dass unerwartete Abbrüche überhaupt vorkommen und wo im Applikationscode das ungefähr geschieht.

Das erste Anzeichen dafür ist, wie oben Beschrieben, ein Status Zähler von Aborted_clients grösser 0. Spannend wir das ganze aber erst wenn wir Aborted_clients in Relation zur Uptime setzen. Wenn wir nur 10 Aborted_clients über die letzten 100 Tage haben, dann kann man diesen Zähler getrost vernachlässigen. Wenn Aborted_clients im Minutentakt hochgezählt wird, sollte man sich das Ganze schon genauer anschauen:

mariadb> SHOW GLOBAL STATUS WHERE Variable_name = 'aborted_clients' OR Variable_name = 'uptime';
+-----------------+--------+
| Variable_name   | Value  |
+-----------------+--------+
| Aborted_clients | 5438   |
| Uptime          | 257991 |
+-----------------+--------+

mariadb> SELECT 257991/5438 AS Abort_every_s;
+---------------+
| Abort_every_s |
+---------------+
|       47.4423 |
+---------------+

Die nächste Frage, die sich stellt, ist, welcher Applikationsuser ist davon betroffen? Diese Frage kann auf 2 verschiedene Wege beantwortet werden. Entweder über das PERFORMANCE_SCHEMA mit der Abfrage nach Accounts, welche die Verbindung nicht sauber schliessen:

mariadb> SELECT ess.user, ess.host
     , (a.total_connections - a.current_connections) - ess.count_star as not_closed
     , ((a.total_connections - a.current_connections) - ess.count_star) * 100 /
       (a.total_connections - a.current_connections) as pct_not_closed
  FROM performance_schema.events_statements_summary_by_account_by_event_name ess
  JOIN performance_schema.accounts a on (ess.user = a.user and ess.host = a.host)
 WHERE ess.event_name = 'statement/com/quit'
   AND (a.total_connections - a.current_connections) > ess.count_star
;
+-----------+---------------+------------+----------------+
| user      | host          | not_closed | pct_not_closed |
+-----------+---------------+------------+----------------+
| applicat  |   10.0.246.74 |         31 |         0.0001 |
| applicat  |   10.0.246.73 |         59 |         0.0003 |
| replicate |   10.0.246.72 |          1 |       100.0000 |
| applicat  |   10.0.246.76 |          4 |         0.0024 |
| root      | localhost     |          3 |         0.0053 |
| applicat  | localhost     |      51880 |         0.2991 |
| applicat  |   10.0.246.77 |          1 |       100.0000 |
+-----------+---------------+------------+----------------+

Oder über das Error Log, wenn die die Variable log_warnings auf 2 gesetzt ist:

mariadb> SHOW GLOBAL VARIABLES LIKE 'log_warn%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_warnings  | 2     |
+---------------+-------+

Bei MySQL 5.7 und neuer wird hierzu die Variable log_error_verbosity auf 3 gesetzt:

mysql> SHOW GLOBAL VARIABLES LIKE '%verbosity%';
+---------------------+-------+
| Variable_name       | Value |
+---------------------+-------+
| log_error_verbosity | 3     |
+---------------------+-------+

Ein Eintrag ins Error Log sieht dann in etwa wie folgt aus:

[Warning] Aborted connection 411 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets)
[Warning] Aborted connection 417 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error writing communication packets)
[Warning] Aborted connection 424 to db: 'billing' user: 'billing' host: 'mysql_LB' (Got an error reading communication packets)
[Warning] Aborted connection 433 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets)
[Warning] Aborted connection 449 to db: 'app_production' user: 'app_prod' host: 'mysql_LB' (Got an error reading communication packets)

Somit wissen wir jetzt also bereits etwas genauer, welchen User von welchem Host mit Zugriff auf welches Schema es erwischt hat. Zudem haben wir noch die Connection ID welche eindeutig und aufsteigen ist.

Feststellen wo im Code es ungefähr passiert

Um festzustellen, wo im Applikationscode der unerwartete Abbruch ungefähr passiert haben wir wiederum 2 Möglichkeiten.

Wir können dazu das General Query Log einschalten (Achtung: kann sehr rasant anwachsen!) und dann die enstprechende Verbindung suchen:

mariadb> SET GLOBAL general_log = 1;

mariadb> SHOW GLOBAL VARIABLES LIKE '%general%';
+------------------+----------------------------------------------------------------------+
| Variable_name    | Value                                                                |
+------------------+----------------------------------------------------------------------+
| general_log      | ON                                                                   |
| general_log_file | /home/mysql/database/mariadb-10.2/log/chef_mariadb-10.2_general.log |
+------------------+----------------------------------------------------------------------+

Eine sauber abgebaute Verbindung sieht darin wie folgt aus:

Time                               Id Command    Argument
2017-04-20T10:26:05.613569Z        26 Connect   app@localhost on test using TCP/IP
2017-04-20T10:26:05.613629Z        26 Query     SELECT ...
2017-04-20T10:26:05.613681Z        26 Quit

Eine unsauber abgebaute oder noch offene Verbindung wie folgt:

Time                               Id Command    Argument
2017-04-20T10:26:17.165585Z        27 Connect   app@localhost on test using TCP/IP
2017-04-20T10:26:17.165785Z        27 Query     SELECT ...
                                      Fehlendes Quit

Die zweite Möglichkeit besteht darin, die Sequenz von Abfragen über das PERFORMANCE_SCHEMA zu ermitteln. Hierzu müssen wir als erstes herausfinden, wie gross der Unterschied zwischen der Processlist ID und der Datenbankserver internen Thread ID ist:

mariadb> SELECT thread_id, processlist_id, thread_id-processlist_id AS diff
  FROM performance_schema.threads WHERE processlist_id IS NOT NULL
 ORDER BY thread_id DESC LIMIT 3;
+-----------+----------------+------+
| thread_id | processlist_id | diff |
+-----------+----------------+------+
|       436 |            433 |    3 |
|       427 |            424 |    3 |
|       420 |            417 |    3 |
+-----------+----------------+------+

In einem zweiten Schritt können wir über das PERFORMANCE_SCHEMA herausfinden welche Befehle von der Applikation ausgeführt wurden:

UPDATE performance_schema.setup_consumers SET enabled = 1
 WHERE name = 'events_statements_history_long';

mariadb> SELECT thread_id, event_name, sql_text, current_schema
  FROM performance_schema.events_statements_history_long
 WHERE thread_id = 433 + 3;
+-----------+---------------------------------+----------------------------------------------------------+----------------+
| THREAD_ID | EVENT_NAME                      | SQL_TEXT                                                 | CURRENT_SCHEMA |
+-----------+---------------------------------+----------------------------------------------------------+----------------+
|       436 | statement/sql/set_option        | SET NAMES utf8, @@SESSION.sql_mode = 'STRICT_ALL_TABLES' | app_production |
|       436 | statement/com/Ping              | NULL                                                     | app_production |
|       436 | statement/sql/select            | select @@character_set_database as 'Value'               | app_production |
|       436 | statement/sql/show_tables       | SHOW TABLES LIKE 'schema_migrations'                     | app_production |
|       436 | statement/sql/show_tables       | SHOW TABLES LIKE 'schema_migrations'                     | app_production |
|       436 | statement/sql/select            | SELECT `schema_migrations`.* FROM `schema_migrations`    | app_production |
|       436 | statement/sql/show_fields       | SHOW FULL FIELDS FROM `schema_migrations`                | app_production |
|       436 | statement/sql/show_fields       | SHOW FULL FIELDS FROM `settings`                         | app_production |
+-----------+---------------------------------+----------------------------------------------------------+----------------+

Nun sollte es in Zusammenarbeit mit den Entwicklern nicht mehr allzu schwer fallen, die entsprechenden Stellen im Applikationscode zu finden und die Fehler zu beheben.