Dans le précédent article, nous avons examiné les possibilités de fonctionnement en continu d’une carte Pandaboard. Il s’est avéré que l’ajout d’un dissipateur thermique était indispensable pour maintenir un régime permanent à 100% du CPU.
Nous allons dans cet article observer le comportement d’un timer logiciel Linux sur cette carte sous une haute charge – tant logicielle qu’en interruptions – et mesurer les fluctuations maximales.
Méthode de mesure
Timers Linux
Le programme suivant utilise l’API des timers Posix timer_create() et timer_settime() proposée par le noyau Linux. Il programme la réception périodique d’un signal. Dans les expériences ci-dessous, j’ai utilisé un timer de 100 micro-secondes. Cette valeur est choisie de manière à ce que la période soit sensiblement plus courte que celle du tick système (pour les noyaux compilés sans l’option tickless). Sur les systèmes ARM, le tick est généralement réglé à une fréquence de 128Hz, parfois 1000Hz. En utilisant un déclenchement à 10kHz, nous obligeons le kernel à utiliser des timers de précision élevée (High Resolution Timers). En contrepartie, nous choisissons une période relativement longue par rapport à la durée du traitement à réaliser lors de la réception du signal (quelques microsecondes).
Lorsque le timer se déclenche, notre programme mesure la durée écoulée depuis l’occurrence précédente grâce à l’API clock_gettime(). Il affiche toutes les cinq secondes les durées minimale, maximale et moyenne observées. En outre, il conserve la pire valeur (intitulée « Max Max » dans les résultats) rencontrée depuis le début de son exécution.
fluctuations-timer.c: #include <signal.h> #include <stdio.h> #include <stdlib.h> #include <time.h> #include <unistd.h> static int nb_mesures = 0; void handler_alarm(int unused) { static long long int min; static long long int max; static double sum; static long long int max_max = 0; static struct timespec precedent; static int mesure = -1; long long int duree; struct timespec ts; // Reinitialisation des mesures intermediaires if (mesure == -1) { min = -1; max = 0; sum = 0; clock_gettime(CLOCK_REALTIME, & precedent); mesure ++; return; } clock_gettime(CLOCK_REALTIME, & ts); duree = ts.tv_sec - precedent.tv_sec; duree *= 1000000000; // en nanosecondes duree += ts.tv_nsec - precedent.tv_nsec; duree /= 1000; // en microsecondes if ((min == -1) || (duree < min)) min = duree; if (duree > max) { max = duree; if (max_max < max) max_max = duree; } sum += duree; precedent = ts; mesure ++; if (mesure == nb_mesures) { fprintf(stdout, "[%ld] Min.= %lld, Moy.= %.1lf, Max.= %lld, Max.Max.= %lldn", time(NULL), min, sum / nb_mesures, max, max_max); fflush(stdout); mesure = -1; } } int main (int argc, char * argv[]) { long int periode; timer_t tmr; struct sigevent notification; struct itimerspec itimer; if ((argc != 2) || (sscanf(argv[1], "%ld", & periode) != 1)) { fprintf(stderr, "usage: %s periode_usn", argv[0]); exit(EXIT_FAILURE); } if ((periode <= 0) || (periode > 2000000)) { fprintf(stderr, "%s: La periode doit etre dans [1, 2000000]n", argv[0]); exit(EXIT_FAILURE); } nb_mesures = 5000000 / periode; if (nb_mesures == 0) { fprintf(stderr, "periode trop longuen"); exit(EXIT_FAILURE); } signal(SIGALRM, handler_alarm); notification.sigev_notify = SIGEV_SIGNAL; notification.sigev_signo = SIGALRM; if (timer_create(CLOCK_REALTIME, & notification, & tmr) != 0) { perror("timer_create"); exit(EXIT_FAILURE); } itimer.it_value.tv_sec = itimer.it_interval.tv_sec = periode / 1000000; // en secondes itimer.it_value.tv_nsec = itimer.it_interval.tv_nsec = (periode % 1000000) * 1000; // en nanosecondes if (timer_settime(tmr, 0, & itimer, NULL) != 0) { perror("timer_settime"); exit(EXIT_FAILURE); } while(1) pause(); return EXIT_SUCCESS; }
Voici le type de résultats que nous fournit ce programme. Naturellement nous l’exécutons sous un ordonnancement temps-réel afin de s’affranchir des fluctuations liées à l’ordonnancement en temps partagé.
# chrt -f 80 ./fluctuations-timer 100 [1339860164] Min.= 00, Moy.= 99.7, Max.= 305, Max.Max.= 305 [1339860169] Min.= 30, Moy.= 99.7, Max.= 274, Max.Max.= 305 [1339860174] Min.= 30, Moy.= 99.7, Max.= 366, Max.Max.= 366 [1339860179] Min.= 0, Moy.= 99.7, Max.= 274, Max.Max.= 366 [1339860184] Min.= 30, Moy.= 99.7, Max.= 305, Max.Max.= 366 [1339860189] Min.= 0, Moy.= 99.7, Max.= 305, Max.Max.= 366 (Contrôle-C) #
Mesures de longues durées
Lorsque l’on désire connaître les pires fluctuations auxquelles on peut s’attendre sur un système donné, il est nécessaire de réaliser ce genre d’expérience de manière prolongée, avec une charge très élevée, tant en ce qui concerne les processus et l’ordonnancement qu’en termes d’interruptions et d’appels système.
Pour cela, nous allons écrire un script qui fait tourner ce programme en boucle en remplissant des fichiers de mesure. Chaque exécution (chaque fichier) durera une journée. Nous mesurerons les secondes à partir de zéro en ramenant chaque fois l’heure système au 1er janvier 1970.
Le principe est donc en substance représenté par le squelette de script suivant.
#! /bin/sh
# Trouver le premier nom de fichier inutilise.
COMPTEUR=0
while true
do
COMPTEUR=$((COMPTEUR + 1))
FICHIER_RESULTATS=/root/resultat-fluctuations-timer-linux-${COMPTEUR}.txt
if ! [ -f "${FICHIER_RESULTATS}" ]; then break; fi
done
while true
do
# Retour dans le passe !
date -s 1970.01.01-00:00
# Lancer la mesure
date +"##[%s] Debut de l'experience" > "${FICHIER_RESULTATS}"
txt=$(uname -a)
date +"##[%s] $txt" >> "${FICHIER_RESULTATS}"
chrt -f 99 /usr/local/bin/fluctuations-timer 100 >> "${FICHIER_RESULTATS}" &
while true
do
# Charger le systeme
[...]
sleep 300
SECONDES=$(date +%s)
if [ $SECONDES -ge 86400 ]; then break; fi
done
killall fluctuations-timer
echo "##[$SECONDES] Fin de l'experience" >> "${FICHIER_RESULTATS}"
COMPTEUR=$((COMPTEUR + 1))
FICHIER_RESULTATS=/root/resultat-fluctuations-timer-linux-${COMPTEUR}.txt
done
Charge système importante
Pour avoir des chances de rencontrer assez rapidement les pires fluctuations, il est très important de charger excessivement le système. Pour ce faire, je me suis inspiré du script dohell qui est livré avec Xenomai. Celui-ci multiplie les commandes pour surcharger tous les aspects du système.
J’ai décidé d’alterner les périodes de très fortes charge pendant cinq minutes avec des périodes de repos de trente secondes. Ceci permet d’augmenter les phases de transition, pendant lesquelles surviennent souvent les pires conditions plutôt que durant les phases de fonctionnement en régime permanent.
Pendant les périodes de charge, nous lançons des tâches qui réalisent de très nombreux appels-système.
top -d 0sur chaque CPUcat /proc/interruptsen boucle sur chaque CPUpsen boucle sur chaque CPU
D’autres tâches vont réaliser beaucoup d’opérations d’entrées-sorties.
dd if=/dev/zero of=/dev/nullsur chaque CPUdd if=/dev/zero of=/mnt/ramdisk/file bs=1024000 count=100alternativement sur chaque CPUls -lR / > /dev/nullalternativement sur chaque CPU
Enfin, nous provoquons des interruptions externes en utilisant nc afin de faire des transferts volumineux par le réseau à destination d’une machine hôte : nc $HOTE $PORT < /tmp/netcat.data le fichier transféré faisant environ 2.5Mo.
Au bout de quelques jours, j’ai decidé d’augmenter la charge en interruptions réseau avec un ping « flood » depuis un hôte qui envoie des paquets ICMP le plus rapidement possible en direction de la cible. Les paquets non acquittés apparaissent sous forme de points qui évoluent dynamiquement pendant l’exécution du ping.
# ping -f 192.168.3.152 PING 192.168.3.152 (192.168.3.152) 56(84) bytes of data. ...
Script de test
Voici le script complet de test que j’ai lancé sur la cible Pandaboard
lance-test-fluctuations-timer-linux.sh #! /bin/sh # Trouver le premier nom de fichier inutilise. COMPTEUR=0 while true do COMPTEUR=$((COMPTEUR + 1)) FICHIER_RESULTATS=/root/resultat-fluctuations-timer-linux-${COMPTEUR}.txt if ! [ -f "${FICHIER_RESULTATS}" ]; then break; fi done while true do # Retour dans le passe ! date -s 1970.01.01-00:00 # Lancer la mesure date +"##[%s] Debut de l'experience" > "${FICHIER_RESULTATS}" txt=$(uname -a) date +"##[%s] $txt" >> "${FICHIER_RESULTATS}" chrt -f 99 /usr/local/bin/fluctuations-timer 100 >> "${FICHIER_RESULTATS}" & mkdir -p /mnt/ramdisk mount none /mnt/ramdisk -t ramfs if [ -e /proc/sys/kernel/hung_task_timeout_secs ] then echo 0 > /proc/sys/kernel/hung_task_timeout_secs fi while true do txt=$(uptime) date +"##[%s] $txt" >> "${FICHIER_RESULTATS}" txt=$(/usr/local/bin/omap4_temp) date +"##[%s] temperature : $txt" >> "${FICHIER_RESULTATS}" date +"##[%s] Periode de repos" >> "${FICHIER_RESULTATS}" sleep 60 date +"##[%s] Periode de charge" >> "${FICHIER_RESULTATS}" PIDS="" # -------------------------------------------------------- # Charge importante en appels systeme sur les deux CPU taskset 1 top -d 0 > /dev/null 2>&1 & PIDS="$PIDS $!" taskset 2 top -d 0 > /dev/null 2>&1 & PIDS="$PIDS $!" while true; do taskset 1 cat /proc/interrupts; done > /dev/null 2>&1 & PIDS="$PIDS $!" while true; do taskset 2 cat /proc/interrupts; done > /dev/null 2>&1 & PIDS="$PIDS $!" while true; do taskset 1 ps ; done > /dev/null 2>&1 & PIDS="$PIDS $!" while true; do taskset 2 ps ; done > /dev/null 2>&1 & PIDS="$PIDS $!" # ------------------------------------------------------- # Charge importante en I/O fichiers sur les deux CPUs taskset 1 dd if=/dev/zero of=/dev/null & PIDS="$PIDS $!" taskset 2 dd if=/dev/zero of=/dev/null & PIDS="$PIDS $!" cpu=1 while true ; do taskset $cpu dd if=/dev/zero of=/mnt/ramdisk/file bs=1024000 count=100; i=$((3-i)); done & PIDS="$PIDS $!" cpu=2 while true ; do taskset $cpu ls -lR / > /dev/null 2>&1; i=$((3-i)); done & PIDS="$PIDS $!" # ------------------------------------------------------ # Charge importante en interruptions sur les deux CPU CIBLE=192.168.3.1 PORT=2012 # Il faut lancer auparavant # nc $CIBLE $PORT -l -k > /dev/null # sur la machine cible du transfert reseau seq 1 399999 > /tmp/netcat.data while true ; do nc $CIBLE $PORT < /tmp/netcat.data ; sleep 15; done & PIDS="$PIDS $!" sleep 300 kill -KILL $PIDS 2>/dev/null killall -KILL dd ls nc sleep 2>/dev/null SECONDES=$(date +%s) if [ $SECONDES -ge 86400 ]; then break; fi done killall fluctuations-timer echo "##[$SECONDES] Fin de l'experience" >> "${FICHIER_RESULTATS}" COMPTEUR=$((COMPTEUR + 1)) FICHIER_RESULTATS=/root/resultat-fluctuations-timer-linux-${COMPTEUR}.txt done
Le programme stocke donc ses résultats dans des fichiers quotidiens numérotés successivement. Au vu du script ci-dessus, il est évident que le système vit un véritable enfer en charge système et interruptive. La température du processeur est vérifiée régulièrement, et il se maintient (avec l’aide d’un dissipateur) dans une zone thermique très raisonnable.
Résultats
J’ai obtenu quelques résultats, mais j’ai mis au point le script ci-dessous en le complétant au vu des premiers essais. Il y a donc des évolutions au cours des journées de test.
Les mesures ont été réalisées sur un noyau Linux « vanilla » 3.4.1, dont voici le fichier de configuration.
Jour 1
[Panda]# tail resultat-fluctuations-timer-linux-1.txt [86566] Min.= 0, Moy.= 99.7, Max.= 213, Max.Max.= 3173 [86571] Min.= 30, Moy.= 99.7, Max.= 213, Max.Max.= 3173 [86576] Min.= 0, Moy.= 99.7, Max.= 244, Max.Max.= 3173 [86581] Min.= 0, Moy.= 99.7, Max.= 244, Max.Max.= 3173 [86586] Min.= 0, Moy.= 99.7, Max.= 244, Max.Max.= 3173 [86591] Min.= 0, Moy.= 99.7, Max.= 274, Max.Max.= 3173 [86596] Min.= 0, Moy.= 99.7, Max.= 244, Max.Max.= 3173 [86601] Min.= 0, Moy.= 99.7, Max.= 213, Max.Max.= 3173 [86606] Min.= 0, Moy.= 99.6, Max.= 213, Max.Max.= 3173 ##[86608] Fin de l'experience
Plusieurs observations peuvent être faites d’ors et déjà.
- La moyenne des intervalles entre les déclenchements des timers est toujours très proche des 100 microsecondes demandées. C’est le comportement que l’on attend d’un système temps réel souple comme Linux.
- Sur chaque période de cinq secondes (donc 50000 déclenchements de timers), il y a des fluctuations suffisament importantes pour que l’on « rate » un déclenchement théorique, ce qui nécessite un rattrapage avec deux déclenchements consécutifs avant que l’heure système ne soit mise à jour. C’est ce que traduit la valeur minimale à zéro.
- Sur la journée, nous avons rencontré des préemptions de plus de 3 millisecondes. C’est le genre de valeurs que je souhaite connaître avec des tests de longue durée.
J’ai mis au point un petit script qui présente graphiquement les valeurs maximales sur chaque itération (sous forme de points) et le maximum rencontré jusqu’alors (sous forme de ligne).
./affiche-fluctuations-max.sh #! /bin/sh if [ $# -ne 1 ] then echo "usage: $0 fichier-fluctuations..." >&2 exit 1 fi for fichier in "$@" do if [ ! -f "$fichier" ] then echo "$fichier: inexistant" >&2 continue fi # Supprimer les lignes de commentaires (commencant par un diese) sed -e '/^#/d;' < "$fichier" > fichier-tmp-1 # Isoler les valeurs max sur cinq secondes sed -e 's/[//; s/].* Max.=//; s/,.*$//' < fichier-tmp-1 > fichier-tmp-2 # Isoler les valeurs max de la journée sed -e 's/[//; s/].*Max.=//' < fichier-tmp-1 > fichier-tmp-3 # Creer le graphique gnuplot <<-EOF set terminal png size 800,600 set title "$fichier" set output '${fichier}.png' set multiplot plot "fichier-tmp-2" notitle with dots lc rgb "#000080" replot "fichier-tmp-3" notitle with lines lc rgb "#800000" EOF done
Je l’invoque ainsi :
$ ./affiche-fluctuations-max.sh resultat-fluctuations-timer-linux-1.txt $
Il crée alors un fichier resultat-fluctuations-timer-linux-1.txt.png avec la représentation graphique.
A l’issue du premier jour de test, je me suis aperçu que les tâches décrites ci-dessus ne chargeaient pas totalement les deux CPU simultanément. La fluctuation maximale sur la journée de test avait été de plus de 3 millisecondes. Elle avait été obtenue au bout de 16718 secondes, soit un peu plus de quatre heures et demi.
[Panda]# grep "3173, " resultat-fluctuations-timer-linux-1.txt [16718] Min.= 0, Moy.= 99.9, Max.= 3173, Max.Max.= 3173 [Panda]#
Nous pouvons remarquer les pires fluctuations rencontrées furent les suivantes
- 946 microsecondes après 156 secondes (2 minutes et demi) d’expérience
- 1129 microsecondes au bout d’une heure (3602 sec.) d’expérience
- 1464 microsecondes après une heure et demi d’expérience
- 2105 microsecondes au bout de quatre heures d’expérience
- 3173 microsecondes après quatre heures et demi d’expérience
Autrement dit, comme on pouvait s’y attendre, il est nécessaire de réaliser des tests pendant plusieurs heures avant de pouvoir approcher des fluctuations maximales.
Jour 2
J’ai relancé le test modifié (avec une charge importante sur les deux CPU), mais j’ai dû l’interrompre au bout de 8 heures environ pour vérifier mon script. Le fichier se termine donc un peu abruptement.
[Panda]# tail resultat-fluctuations-timer-linux-2.txt [29230] Min.= 30, Moy.= 99.7, Max.= 305, Max.Max.= 6072 [29235] Min.= 30, Moy.= 99.7, Max.= 305, Max.Max.= 6072 [29240] Min.= 30, Moy.= 99.7, Max.= 305, Max.Max.= 6072 [29245] Min.= 30, Moy.= 99.7, Max.= 274, Max.Max.= 6072 [29250] Min.= 30, Moy.= 99.7, Max.= 274, Max.Max.= 6072 [29255] Min.= 30, Moy.= 99.7, Max.= 274, Max.Max.= 6072 ##[29257] Periode de charge [29260] Min.= 0, Moy.= 99.9, Max.= 396, Max.Max.= 6072 [29265] Min.= 0, Moy.= 99.9, Max.= 396, Max.Max.= 6072 [29270] Min.= 0, Moy.= 99.9, Max.= 366, Max.Max.= 6072
La fluctuation maximale est beaucoup plus importante. Elle a été obtenue quelques instants avant l’arrêt du programme (peut-être un artefact de la connexion par SSH sur la cible). La précédente (5126 microsecondes) était survenue après trois heures et demi de mesure.
Nous pouvons remarquer une plus grande dispersion des fluctuations maximales vers le haut.
Jour 3
J’ai pu relancer le programme et le laisser s’exécuter une journée sans interruption, dans les mêmes conditions que précédemment.
[Panda]# tail resultat-fluctuations-timer-linux-3.txt [86506] Min.= 0, Moy.= 101.1, Max.= 2777, Max.Max.= 5523 [86511] Min.= 0, Moy.= 100.3, Max.= 1770, Max.Max.= 5523 [86517] Min.= 0, Moy.= 99.9, Max.= 396, Max.Max.= 5523 [86522] Min.= 0, Moy.= 99.9, Max.= 457, Max.Max.= 5523 [86527] Min.= 0, Moy.= 101.4, Max.= 3814, Max.Max.= 5523 [86532] Min.= 0, Moy.= 99.9, Max.= 427, Max.Max.= 5523 [86537] Min.= 0, Moy.= 99.9, Max.= 396, Max.Max.= 5523 [86542] Min.= 0, Moy.= 100.5, Max.= 2288, Max.Max.= 5523 [86547] Min.= 0, Moy.= 100.8, Max.= 3601, Max.Max.= 5523 ##[86550] Fin de l'experience
Nous sommes dans le même ordre de fluctuation maximale. La pire valeur a été observée après plus de 21 heures de test.
Jour 4
Lors du quatrième jour, j’ai décidé d’augmenter sensiblement en ajoutant un ping « flood » depuis un autre poste, afin de déclencher de nombreuses interruptions réseau.
Quelle ne fût pas ma surprise, en regardant des résultats temporaires au bout de 21 heures, de voir que les fluctuations étaient beaucoup plus faibles que celles observées précédemment ! En voici une représentation graphique.
C’est en voulant vérifier dans le pseudo fichier /proc/interrupts si la charge en interruptions était aussi élevée que prévu que j’ai compris où se situait le problème.
[Panda]# cat /proc/interrupts
CPU0 CPU1
29: 1624296339 1089370474 GIC twd
39: 0 0 GIC TWL6030-PIH
41: 0 0 GIC l3-dbg-irq
42: 0 0 GIC l3-app-irq
44: 401065 0 GIC DMA
52: 0 0 GIC gpmc
57: 6 0 GIC OMAP DISPC
69: 9 0 GIC gp timer
85: 0 0 GIC omapdss_dsi.0
88: 240 0 GIC omap_i2c
89: 0 0 GIC omap_i2c
91: 13 0 GIC mmc1
93: 0 0 GIC omap_i2c
94: 0 0 GIC omap_i2c
108: 1 0 GIC ohci_hcd:usb2
109: 160087021 0 GIC ehci_hcd:usb1
115: 435894 0 GIC mmc0
116: 0 0 GIC omapdss_dsi.1
363: 0 0 twl6030 rtc0
419: 0 0 PRCM hwmod_io
IPI0: 0 0 Timer broadcast interrupts
IPI1: 1771432 2429790 Rescheduling interrupts
IPI2: 0 0 Function call interrupts
IPI3: 95149 68083 Single function call interrupts
IPI4: 0 0 CPU stop interrupts
Err: 0
[Panda]#
Visiblement toutes les interruptions DMA (44), réseau (109) et celles de la carte micro-SD (115) ne sont traitées que sur le cœur 0, pas sur le 1. Si le programme de test s’exécute sur ce CPU 0, il sera fortement perturbé par les interruptions et les fluctuations plus importantes que s’il tourne sur le CPU 1.
Pour en avoir le cœur net, j’ai déplacé le programme de test (avec la commande taskset pour le faire fonctionner sur le CPU 0. Les performances ce sont instantanément dégradées comme nous le voyons sur ce second graphique. (resultat-fluctuations-timer-linux-4.txt)
Conclusion
Pour continuer cette expérience, il est important de répartir correctement les traitements des interruptions et les mesures sur les deux coeurs disponibles. Ceci fera l’objet du prochain article.
