Archive

Archives pour 11/2009

kernel: VM: killing process

En recherchant la solution à mon probléme sur Internet j’ai trouvé un nombre conséquent de cas similaires souvent non résolu.
Je poste donc ici mon éxpérience et ma méthode afin d’en faire profiter Google. Ma recherche m’a permis de résoudre les causes de mon probléme précis à moi que j’ai eu. Ce post s’adresse donc surtout à ceux qui ont besoin de piste pour commencer à chercher le problémes ou éventullement à ceux qui ont exactement le même probléme que moi.
**/

Bonjour,

Depuis quelques semaines l’un de mes serveurs kill des services (named, httpd, mysqld, sshd …) à des heures et jours de la semaine totalement aléatoire.

Les logs (/var/log/messages) signalaient :

17:14:47 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0xf0/0)
17:20:04 nsX kernel: grsec: From 80.9.34.136: signal 11 sent to /usr/local/apache/bin/httpd[httpd:28050] uid/euid:99/99 gid/egid:100/100, parent $
17:20:04 nsX kernel: grsec: From 80.9.34.136: signal 11 sent to /usr/local/apache/bin/httpd[httpd:28050] uid/euid:99/99 gid/egid:100/100, parent $
17:25:34 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0xf0/0)
17:25:38 nsX kernel: ENOMEM in do_get_write_access, retrying.
17:25:38 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0xf0/0)
17:25:38 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0xf0/0)
17:26:00 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:26:00 nsX kernel: VM: killing process httpd
17:26:18 nsX kernel: grsec: From 80.9.34.136: signal 11 sent to /usr/local/apache/bin/httpd[httpd:12581] uid/euid:99/99 gid/egid:100/100, parent $
17:26:19 nsX kernel: grsec: From 80.9.34.136: signal 11 sent to /usr/local/apache/bin/httpd[httpd:12581] uid/euid:99/99 gid/egid:100/100, parent $
17:27:04 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0xf0/0)
17:27:34 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:27:36 nsX kernel: VM: killing process qmail-smtpd
17:27:36 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:27:36 nsX kernel: VM: killing process httpd
17:27:36 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:27:36 nsX kernel: VM: killing process httpd
17:27:39 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1f0/0)
17:27:39 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:27:39 nsX kernel: VM: killing process httpd
17:27:59 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0xf0/0)
17:27:59 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:27:59 nsX kernel: VM: killing process vchkpw
17:27:59 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:27:59 nsX kernel: VM: killing process httpd
17:27:59 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1f0/0)
17:28:15 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0xf0/0)
17:28:33 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)
17:28:43 nsX kernel: VM: killing process httpd
17:28:50 nsX kernel: __alloc_pages: 0-order allocation failed (gfp=0x1d2/0)

Aprés une rapide recherche sur Internet je suis tombé sur un post de ce forum traitant d’un probléme équivalent :

http://forum.ovh.net/showthread.php?threadid=4550&perpage=15&pagenumber=1

Une réponse de notre chez Octave explique le phénoméne. Ne restais plus qu’a en trouver la cause.

Si comme moi vous avez une quantité considérable de script PHP (entres autres …) et de sites sur le serveur en question la recherche du probléme si elle est du à un programme qui part en sucette n’est pas gagné d’avance.

Un intervenant conseillé de couper gzip dans la configuration d’apache. Les log d’apache (/var/log/httpd/error_log) lui donnait raison :

[error] mod_gzip: TRANSMIT_ERROR:ISMEM:104

Répété plusieurs fois, mais pas vraiment aux heures des crash. J’ai donc recompilé apache sans gzip :

ftp://ftp.ovh.net/made-in-ovh/release/patch-1.61-1.62.sh
Option ./configure de la release mais en supprimant la ligne :

–add-module=src/modules/extra/mod_gzip.c \

Cette opération n’a pas réglé le probléme. Seconde piste un programme qui part en vrille. Commencons par PHP, pour trouver LE script PHP qui est la cause du probléme il me faut mettre en place un systéme simple de monitoring, transparent, qui se déploie instantanément sur tout les programmes et sans incidence sur le fonctionnement.

J’opte pour une solution à base de : auto_prepend_file et auto_append_file. Ci-dessous.
Dev
11/01/2006, 12h58
Cette « piste » consiste à chronométrer TOUT les scripts PHP exécutés sur le serveur. Le probléme venant probablement d’UN programme DANS CERTAINES CONDITIONS. (=> d’où exclusion de la recherche unitaire).

# jed /usr/local/lib/php.ini
auto_prepend_file = /home/ovh/monitoring/prepend.php
auto_append_file = /home/ovh/monitoring/append.php

# cat /home/ovh/monitoring/prepend.php
< ? $btime=microtime(); ? >

# jed /home/ovh/monitoring/append.php
< ? $ctime=microtime(); $dtime=substr($btime, 15, 6); $etime=substr($ctime, 15, 6); $btime=substr($btime, 0, 8); $ctime=substr($ctime, 0, 8); $btime=$btime+$dtime; $ctime=$ctime+$etime; $atime=$ctime-$btime; $atime=substr($atime, 0, 8); $ftime=substr($atime, 0, 1); if ($ftime > "4") // supérieur à 4s
{

$conn = mysql_connect(XXXXXXXXXX) ;
mysql_select_db("monitoring") ;
mysql_query("INSERT INTO php_execution_time VALUES (NOW(), '" . $_SERVER["REMOTE_ADDR"] . "', '" . $_SERVER["REMOTE_HOST"] . "', '$atime', " . memory_get_usage() . ", '" . $_SERVER["HTTP_HOST"] . $_SERVER["REQUEST_URI"] . "', '" . $_SERVER["SCRIPT_FILENAME"] . "')") ;
mysql_close($conn) ;

}

? >

Les deux programmes stocke les temps d’éxcécution de TOUT les scripts supérieurs à 4 secondes (pour la forme car >20 serait déja tout à fait suffisant).

La table :

CREATE TABLE php_execution_time (
datetime datetime NOT NULL default ‘0000-00-00 00:00:00’,
ip varchar(255) NOT NULL default  »,
host varchar(255) NOT NULL default  »,
time float NOT NULL default ‘0’,
globalPHPMemory int(11) NOT NULL default ‘0’,
domain varchar(255) NOT NULL default  »,
file varchar(255) NOT NULL default  »
) TYPE=MyISAM;

NOTE : Attention cela implique un fonctionnement temporaire en mode dégradé car l’inclusion systématique consomment quelques ressources même infime mais multiplié par le nombre d’éxécution de TOUT les programme (même les CLI) !
NOTE : Pensez aussi à « vidanger » la table, soit à la main, soit via un cron, soit (déconseillé) dans l’auto_append en supprimant les entrées vieilles de + de 48h.

Toutefois les runtime des scripts n’étaient pas trés utiles seuls même pour si ils permettent de mettre en avant les scripts gourmands en ressources.
C’est pourquoi j’ai ajouté à chaque entrée la quantité de mémoire alloué à PHP à l’instant T. Pour cela il me fallait utiliser la fonction memory_get_usage() de PHP. Et pour cela recompilé PHP avec l’option : –enable-memory-limit

./configure –with-apache=../apache_1.3.33 –with-dbase –with-filepro –enable-exif –with-xml –enable-ftp –with-db –enable-bcmath –enable-calendar –with-jpeg-dir –with-png-dir –with-gd –enable-gd-native-ttf –with-freetype-dir –with-gettext –with-mysql –with-zlib-dir –enable-trans-sid –with-imap –with-kerberos –with-imap-ssl –with-openssl –enable-sysvsem –enable-sysvshm –enable-memory-limit

Il se trouve que c’est en me documentant sur cette option que j’ai découvert que la directive memory_limit de php.ini n’était pas activé par défaut mais uniquement quand PHP est compilé avec –enable-memory-limit (!?!?)

\o/ Donc évidement aprés recompilation la directive memory_limit à été prises en compte => probléme de process killés par le kernel réglé car origine du probléme était bien un programme PHP qui accaparaient trop de mémoire trop longtemps.
Dev
11/01/2006, 13h09
Toutefois cette solution laisse quand même des programmes être tués par PHP ce qui peux impliquer que certains services ne fonctionne plus.

C’est pourquoi j’ai quand même garder le chronométrage, désactivé la memory_limit :

memory_limit = -1 ; Maximum amount of memory a script may consume (8MB)

Et mis en place une page de consultation trés sommaire des logs réalisé dans la DB (le choix des logs dans la DB est nulle au passage, préféré un log en fichier plutot que dans une base de données).

La script en question donc (désolé pour les fonctions de mes librairies de code perso mais vous n’avez qu’a remplacé par des mysql_query et autres) :

Pour ma part il s’agissait de programme « webservices » qui consultait à la volée des bases de données distante via HTTP/XML chez un fournisseur à l’installation peu professionnel (un grand compte pourtant :/ ). Les programmes PHP resté en attente pendant plusieurs dizaines de secondes (voir aussi directive max_execution_time de PHP) et allez savoir pourquoi mobiliser de plus en plus de mémoire jusqu’a la fin de la transaction.

Mon probléme réglé je ne suis pas allé plus loin.

Toutefois certains programmes échappe aux chronométrage, ce qui rends la solutions ci-dessus incompléte. En effet tout les programmes tué par PHP pour max_execution_time ou
memory_limit ne voient pas l’auto_append excécuté, et ne sont donc pas chronométré (= également vrai pour les script terminé par exit()). Il faudrai donc rajouté une couche dans l’auto_append qui créer un « ticket » de début de programme que l’on surpprime dans l’auto_prepend. De cette maniére les ticket non supprimé des logs/db indiquent les programmes qui ont été tué par PHP.
Même si à la réfléxion PHP doit loguer ça quelques part nativement.

source : http://forum.ovh.com/archive/index.php/t-6454.html

Categories: Divers Tags: ,