Statistiques system & software

• Ce petit script est interessant à être cronné toutes les 5 minutes, il récupère des stats sur la mémoire, process httpd, cpu

#!/bin/bash

DATE=`date +%Y%m%d%H%M`
MEM=`free -o | grep Mem: | sed -e 's/Mem: //'`
SWAP=`free -o | grep Swap: | sed -e 's/Swap: //'`
HTTPD=`ps -ef | grep apache | wc -l`
CPU=`ps -u mysql -o %cpu | grep -v CPU`

if [ ! -r /home/claranet/stat.txt ]
then
  echo DATE MEMTOTAL MEMUSED MEMFREE MEMSHARED MEMBUF MEMCACHED SWAPTOTAL SWAPUSED SWAPFREE PROCHTTP HTTPREQ MYSQLCPU CONNMYSQL >/home/claranet/stat.txt
  fi
  echo $DATE $MEM $SWAP $HTTPD $CPU  >>/home/claranet/stat.txt

• Ci-dessous une petite étude de log apache

out d'abord, regardons les fichiers de logs laissés par le serveur
apache pour www.rmcinfos.fr:

un77@rmc2:/var/log/apache$ ls -al rmcinfo.fr-access.log*
-rw-r-----  1 root adm    93722767 2005-10-26 18:50 rmcinfo.fr-access.log
-rw-r-----  1 root adm  8325298686 2005-10-26 17:59 rmcinfo.fr-access.log.1
-rw-r-----  1 root adm   191472769 2005-10-24 06:28 rmcinfo.fr-access.log.2.gz
-rw-r--r--  1 root root  101403486 2005-10-22 06:26 rmcinfo.fr-access.log.3.gz

-> le fichier de log rmcinfo.fr-access.log.1 actif avant le redémarrage d'apache
  fait plus de 8 Go ! C'est beaucoup trop grop pour pouvoir être traité
  efficacement par le système et le serveur web et contribue probablement à
  dégrader la performance du serveur.

Element le plus ancien dans le fichier de log:

un77@rmc2:/var/log/apache$ head rmcinfo.fr-access.log.1
86.195.163.152 - - [23/Oct/2005:06:25:43 +0200] "GET
/fileadmin/templates/images/point_gris.gif HTTP/1.1" 304 -
"http://www.rmcinfo.fr/index.php?id=pagenews&tx_rmcafpnews_pi1[newsid]=051022162240.8te22ubi&tx_rmcafpnews_pi1[dirtype]=une"
"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)"
<snip>

-> le fichier de logs commence au 23/10/05 à 6:25, c'est à dire dimanche
  dernier.

Regardons le nombre de requetes reçues sur cette période:

un77@rmc2:/var/log/apache$ time cat rmcinfo.fr-access.log.1 | wc -l
38827304

real    1m54.071s
user    0m4.212s
sys     0m38.006s

un77@rmc2:/var/log/apache$ cat rmcinfo.fr-access.log.1 | grep '26/Oct/2005' | wc -l
7775872

-> Nous avons reçus 39 millions de hits en 3,5 jours dont 7,8 millions
  aujourd'hui avant le redémarrage du serveur. A priori, rien d'exceptionnel
  sur la charge d'aujourd'hui donc. Au passage, il a fallu presque *2 minutes*
  au serveur pour lire le fichier et compter les lignes !

Voyons un peu la décomposition des requêtes sur les dernières heures :

un77@rmc2:/var/log/apache$ for heure in 12 13 14 15 16 17; do echo -n "$heure ";
cat rmcinfo.fr-access.log.1 | grep "26/Oct/2005:$heure" | wc -l; done
12 852378
13 587189
14 616721
15 687293
16 610127
17 640391

-> 640000 hits entre 17:00 et 18:00, cela ressemble à une charge moyenne et en
  tout cas inférieure à ce que le serveur peut tenir puisque 12:00 - 13:00
  génère plus de hits

En décomposant la même période en hits/minute:

un77@rmc2:/var/log/apache$ cat rmcinfo.fr-access.log.1 | perl -e 'while (<>) {
m#26/Oct/2005:(\d+:\d+):#; $min{$1}++; } for $stamp (keys %min) { print
$stamp,"\t",$min{$stamp},"\n"; }' > /tmp/minutes.txt
un77@rmc2:/var/log/apache$ cat /tmp/minutes.txt | sort -nr -k 1,2 | head -30
17:59   29
17:58   16
17:57   47
17:56   60
17:55   48
17:54   16
17:53   71
17:52   50
17:51   102
17:50   68
17:49   137
17:48   436
17:47   2455
17:46   2817
17:45   4610
17:44   3624
17:43   3481
17:42   12090
17:41   14031
17:40   16276
17:39   15216
17:38   14942
17:37   16998
17:36   14046
17:35   15979
17:34   14604
17:33   15343
17:32   15457
17:31   14369

-> On constate que le serveur avait une charge "normale" avant de s'écrouler
complètement entre 17h43 et 17h48.

En cherchant les minutes les plus chargées de la journée:

un77@rmc2:/var/log/apache$ cat /tmp/minutes.txt | sort -nr -k 2,3 | head
17:17   17027
17:37   16998
12:14   16673
12:06   16635
17:29   16410
17:40   16276
11:53   16272
11:45   16191
11:58   16183
12:44   16138

-> On se rend compte que la charge n'avait rien d'exceptionnel a priori.

Par contre en regardant l'état du système :

un77@rmc2:/var/log/apache2$ vmstat 1 5
procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa
0  0 753848  89636  21112 808568    5    4     2    17    1    18 12  4 83  0
1  0 753848  89364  21112 808704    0    0     0     0 1028  3144 11  4 85  0
0  0 753848  87324  21112 808704    0    0     0     0  779  1991  5  2 93  0
0  0 753848  87076  21116 808700    0    0     0   632  858  2134  5  2 93  0
1  0 753848  86836  21124 808896    0    0     0    16  846  2618 10  2 87  0

-> on voit que l'on utilise 753 Mo de swap (sur 1 Go dispo) et 800 Mo de cache !
  Les 2 valeurs semblent excessives et peuvent expliquer une perte de
  performance. Il reste à trouver la raison pour laquelle le serveur a
  consommé son swap de cette façon.