Tubes nommés et redirections en parallèle

La ligne de commande est bien faite. Cette phrase est souvent entendue dans la bouche des informaticiens. J’en ai encore vérifié la véracité ses jours derniers.

Ma problèmatique était de constituer des statistiques sur des accès HTTP en consultant un fichier de log. La volumétrie des log étant de l’ordre de plusieurs gigaoctets et je ne disposais que de ma ligne de commande en bash.

Je me suis alors dirigé vers une serie de grep avec les bons motifs de recherche couplé à un bon vieux wc:

grep motif fichier.log | wc -l

Pour compliquer il y avait plusieurs motifs differents à compter et il fallait produire un fichier par jour avec le comptage de chaques motifs.

ACCES_COUNT=`grep -e motif_date -e motif_acces fichier.log | wc -l`

Autant de ligne de ce genre que de motif. L’inconvenient est que l’on parcourt la log autant de fois qu’il y a de motif d’acces pour une date donnée. Dans mon cas j’avais 15 motifs soit 1h30 pour obtenir les statistiques pour un jour donné.

Or, une fois que l’on est sur la bonne date dans le fichier de log c’est dommage de le reparcourir depuis le debut pour le motif d’accès suivant. D’où l’idée d’externaliser le parcours du fichier à la recherche de la bonne date puis de dispatcher la ligne aux grep qui compte les motifs d’accès.

tee

On a donc envie de faire un premier grep dont on va diriger la sortie sur d’autres grep en arborscence. La première pièce du puzzle est la commande tee. Voici l’idée :

grep -e motif_date fichier.log | tee -a entree_proc_grep1 entree_proc_grep2 … > /dev/null

Il manque la seconde piece qui est celle qui permet de definir un tube entre le premier grep et les autres qui doivent s’exécuter en parallèle. C’est là que les tube nommés interviennent.

named pipe

La commande mkfifo crée un tube nommé que l’on donne en entrée au grep de motif d’accès. Ces grep seront alors bloqués en attente de lire des donnés dans leurs tubes respectifs.

mkfifo entree_proc_grep1

grep -e motif_acces < entree_proc_grep1 | wc -l > fichier_temp1` &

PID_LIST+=” $!”

Autant de lignes de ce genre qu’il y a de motif d’accès à compter. Remarquons qu’à ce stade on à seulement créé des processus pour faire les grep de comptage et qu’ils sont tous bloqués en attentes sur leur tube. On alimente ensuite les tubes. Voici l’ordre

  1. créer les tube
  2. lancer en arrière plan les grep prenant les tubes en entrée
  3. lancer le grep sur la date pipé avec le tee vers les tubes

Subtilites

On ne peut plus récupérer la valeur des wc car c’est un sous shell qui l’exécute. On passe par un fichier temporaire.

On stocke la liste des pid des grep de comptage car le shell courant qui est leur parent doit attendre qu’ils soient tous finis avant d’aller lire les resultats dans les fichiers temporaires.

wait $PID_LIST

cat fichier_temp1

cat fichier_temp2

….

Dans mon cas particulier je suis passé de 1h30 de traitement pour avoir les statistiques d’un jour donné à seulement 3 minutes !

Finitions

Pour être propre il faut terminer en supprimant les fichiers temporaires (de comptage et les tubes).

Pour pouvoir lancer plusieurs instance du script sur des dates differentes en parallèle, ii faut ajouter le pid du script dans les noms des fichiers temporaires ( tubes nommés et comptage).

Dans mon cas particulier il me fallait les statistiques de plusieurs jours: chaque jour ayant sa propre stat. On peut lancer le script manuellement pour chaque jour ou bien intérer sur les jours, ce qui donne a peu près ceci:

for jour in 1 2 3 4

do

mkfifo entree_proc_grep1

grep -e motif_acces < entree_proc_grep1 | wc -l > fichier_temp1` &

PID_LIST+=” $!”

…..

grep -e motif_date fichier.log | tee -a entre_proc_grep1 entree_proc_grep2 … > /dev/null

wait $PID_LIST

cat fichier_temp1 >> fichier_stat_$jour

echo “” >> fichier_stat_$jour

…..

rm entree_proc_grep1

….

done

On remarque encore que pour chaque jour en parcourt l’ensemble de la log d’accès. Or dès le premier passage on a deja passé sur toutes les dates possibles. Une seule passe doit suffire ! L’idée est que le grep sur le motif de la date ne prenne plus le fichier de log en entrée mais un tube nommé…

for jour in 1 2 3 4

do

mkfifo entree_proc_grep1_$jour

grep -e motif_acces < entree_proc_grep1_$jour | wc -l > fichier_temp1_$jour` &

PID_LIST+=” $!”

…..

mkfifo entree_proc_$jour

PROC_JOUR_LIST+=” entree_proc_$jour”

grep -e motif_date entree_proc_$jour| tee -a entre_proc_grep1_$jour entree_proc_grep2_$jour … > /dev/null &

PID_LIST+=” $!”

done

cat fichier_log | tee -a $PROC_JOUR_LIST > /dev/null

wait $PID_LIST

for jour in 1 2 3 4

do

cat fichier_temp1_$jour >> fichier_stat_$jour

echo “” >> fichier_stat_$jour

…..

rm entree_proc_grep1_$jour

….

rm entree_proc_$jour

done

C’est un peu plus compliqué car pour distinguer tous ces tubes nommés on doit ajouter le numero de jour à leur nom.

Eviter ainsi de reparcourir la log depuis le début pour chaque jour permet d’aller plus vite. Dans mon cas particulier pour les statistiques de 3 jours je suis passé de 2mn50 à 0mn45s et pour les statistiques de 14 journées je suis passé de 22mn à 5mn !

Moralité de l’histoire, l’algorithmie alliée à la ligne de commande et la puissance du shell ça fait des étincelles.

Out of memory dans le kernel Linux

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.