blog.bressure.net

Sous ce titre se cache les soucis de disponibilité de mes sites web virtualisés. Depuis quelques mois ils tombent de temps en temps, surtout quand il y a un peu de charge c’est-à-dire quand j’y publie un article un peu racoleur  et que le nombre d’accès journalier dépasse l’extraordinaire nombre de quelques dizaines d’utlisateurs….

Quand cela arrive c’est souvent le SGBD qui a « crashé » et c’est signalé par un jolie « impossible d’obtenir une connexion à la base de donnée ». Le SGBD est effectivement arrêté et le redémarrer permet de remettre en fonctionnement le site. Le plus intéressant est de trouver la cause du crash.

Dans la log de démarrage on peut y voir des erreur /var/log/mysql/error.log:

181014  6:30:23 [Warning] Using unique option prefix myisam-recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
181014  6:30:23 [Note] Plugin 'FEDERATED' is disabled.
181014  6:30:27 InnoDB: The InnoDB memory heap is disabled
181014  6:30:27 InnoDB: Mutexes and rw_locks use GCC atomic builtins
181014  6:30:27 InnoDB: Compressed tables use zlib 1.2.8
181014  6:30:27 InnoDB: Using Linux native AIO
181014  6:30:29 InnoDB: Initializing buffer pool, size = 128.0M
181014  6:30:31 InnoDB: Completed initialization of buffer pool
181014  6:30:35 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 15552477668
181014  6:30:35  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...

En poussant l’investigation plus loin par un grep de « mysql » dans /var/log/syslog

Oct 14 01:14:54 wordpress kernel: [1971121.772280] INFO: task mysqld:13245 blocked for more than 120 seconds.
Oct 14 01:14:54 wordpress kernel: [1971121.772288] mysqld D ffff880019674468 0 13245 611 0x00000000
Oct 14 01:20:56 wordpress kernel: [1971481.772349] INFO: task mysqld:14574 blocked for more than 120 seconds.
Oct 14 01:20:56 wordpress kernel: [1971481.772358] mysqld D ffff880079cf8f38 0 14574 611 0x00000000
Oct 14 01:32:55 wordpress kernel: [1972201.772091] INFO: task mysqld:13240 blocked for more than 120 seconds.
Oct 14 01:32:55 wordpress kernel: [1972201.772094] mysqld D ffff8800197a4828 0 13240 611 0x00000000
Oct 14 01:34:53 wordpress kernel: [1972321.772343] INFO: task mysqld:13240 blocked for more than 120 seconds.
Oct 14 01:34:53 wordpress kernel: [1972321.772351] mysqld D ffff8800197a4828 0 13240 611 0x00000000
Oct 14 01:38:54 wordpress kernel: [1972561.772076] INFO: task mysqld:13240 blocked for more than 120 seconds.
Oct 14 01:38:54 wordpress kernel: [1972561.772078] mysqld D ffff8800197a4828 0 13240 611 0x00000000
Oct 14 01:55:40 wordpress kernel: [1973565.634464] [ 611] 0 611 1085 1 7 39 0 mysqld_safe
Oct 14 01:55:40 wordpress kernel: [1973565.634471] [ 1188] 104 1188 226779 4831 131 25556 0 mysqld
Oct 14 01:55:40 wordpress kernel: [1973565.634837] Out of memory: Kill process 1188 (mysqld) score 39 or sacrifice child
Oct 14 01:55:40 wordpress kernel: [1973565.634847] Killed process 1188 (mysqld) total-vm:907116kB, anon-rss:19324kB, file-rss:0kB
Oct 14 01:55:40 wordpress kernel: [1973568.287694] [ 611] 0 611 1085 1 7 39 0 mysqld_safe
Oct 14 01:55:40 wordpress kernel: [1973568.287706] [17643] 104 1188 226779 5726 131 24720 0 mysqld
Oct 14 01:55:40 wordpress kernel: [1973568.288313] Out of memory: Kill process 17643 (mysqld) score 39 or sacrifice child
Oct 14 01:55:40 wordpress kernel: [1973568.288317] Killed process 17643 (mysqld) total-vm:907116kB, anon-rss:22904kB, file-rss:0kB
Oct 14 03:54:02 wordpress kernel: [1980665.296368] [ 611] 0 611 1085 4 7 40 0 mysqld_safe
Oct 14 03:54:02 wordpress kernel: [1980665.296430] [17670] 104 17670 228505 5694 97 11154 0 mysqld
Oct 14 03:54:03 wordpress kernel: [1980665.296509] Out of memory: Kill process 17670 (mysqld) score 21 or sacrifice child
Oct 14 03:54:03 wordpress kernel: [1980665.296515] Killed process 17670 (mysqld) total-vm:914020kB, anon-rss:22776kB, file-rss:0kB
Oct 14 03:54:03 wordpress kernel: [1980668.526394] [ 611] 0 611 1085 3 7 40 0 mysqld_safe
Oct 14 03:54:03 wordpress kernel: [1980668.526456] [20409] 104 17670 228505 6736 97 10220 0 mysqld
Oct 14 03:54:03 wordpress kernel: [1980668.526536] Out of memory: Kill process 21984 (mysqld) score 21 or sacrifice child
Oct 14 03:54:03 wordpress kernel: [1980668.526537] Killed process 20409 (mysqld) total-vm:914020kB, anon-rss:26920kB, file-rss:24kB
Oct 14 03:55:21 wordpress kernel: [1980749.353383] [ 611] 0 611 1085 1 7 40 0 mysqld_safe
Oct 14 03:55:21 wordpress kernel: [1980749.357504] [ 611] 0 611 1085 1 7 40 0 mysqld_safe

Linux décide donc de tuer des processus quand il est à court de mémoire. Il lui arrive même de tuer des processus apache2. En faisant un grep de « apache2 » dans /var/log/syslog

Oct 14 03:55:21 wordpress kernel: [1980749.357771] Out of memory: Kill process 13173 (apache2) score 13 or sacrifice child
Oct 14 03:55:21 wordpress kernel: [1980749.357772] Killed process 13173 (apache2) total-vm:457020kB, anon-rss:1708kB, file-rss:0kB

Il ne me reste plus qu’a allouer un peu plus de mémoire à mes VM que le petit gigaoctet par défaut. Trêve de radinerie.