La Pandaboard au poteau de torture – 2 – Fluctuations de timers Linux

Publié par cpb
Juin 18 2012

Pandaboard au poteau de tortureDans 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 0 sur chaque CPU
  • cat /proc/interrupts en boucle sur chaque CPU
  • ps en 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/null sur chaque CPU
  • dd if=/dev/zero of=/mnt/ramdisk/file bs=1024000 count=100 alternativement sur chaque CPU
  • ls -lR / > /dev/null alternativement 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.

Fluctuations d'un timer Linux - Jour 1

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.

Fluctuations d'un timer Linux - Jour 2

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.

Fluctuations d'un timer Linux - Jour 3

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.

Fluctuations d'un timer Linux - Jour 4 (début)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)

Fluctuations d'un timer Linux - Jour 4

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.

URL de trackback pour cette page