Premiers pas avec Xenomai

La configuration de Xenomai est réalisée à travers la même interface que celle du noyau Linux.

Tapez les commandes suivantes 

[root@localhost src]# cd linux-2.6.24
[root@localhost linux-2.6.24]#  make menuconfig

Optimisez le noyau afin qu'il soit le plus proche possible de la configuration matérielle (29). Supprimez tout ce qui est en trop (SMP sur uniprocesseur) et traquez les parties non optimisées (choix du type de CPU...).
Vous risquez de faire de nombreuses compilations avant de trouver la bonne combinaison d'options. Supprimez les options et les drivers inutiles afin de gagner du temps !

Xenomai se trouve dans le menu Real-time sub-system.

Ce paragraphe détaille les différentes options de ce menu(30).

Xenomai

Nucleus

Nucleus est le nom du noyau interne Xenomai. Ce « Nucleus » n'a pas de rapport avec celui de Mentor Graphics.

Pervasive real-time support in user-space

Active le support temps réel depuis le mode user (processus Linux).
Activé par défaut, sinon les fonctionnalités temps réel ne sont disponibles que depuis le noyau Linux.

Interrupt shield support

Active l'Interrupt Shield comme décrit § V.B.5.
Désactivé par défaut car diminue les performances, à activer uniquement si nécessaire.

Priority coupling support

Politique de co-scheduling décrite § V.B.2, la priorité des tâches prend le pas sur le mode. En cas de désactivation, les tâches en primarymode seront alors toujours prioritaires par rapport à celles en secondary.
Activé par défaut. Configurable par la suite tâche par tâche.

Optimize as pipeline head

Force Xenomai comme le premier à traiter les interruptions.
Activé par défaut (est prévu pour le cas - très théorique - où il y aurait d'autres noyaux en plus de Xenomai et Linux).

Number of pipe devices

Nombres de pipes utilisables pour la communication avec Linux.
À modifier si le nombre de devices /dev/rtpn n'est pas suffisant.

Number of registry slots

Nombre total d'objets temps réel instantiables à un instant. Par objet temps réel on désigne les tâches, les sémaphores...

Size of the system heap (Kb)

Zone de mémoire allouée pour le noyau Nucleus. Si certains appels système Xenomai renvoient ENOMEM, cette valeur devra être augmentée.

Size of the private stack pool (Kb)

Pile allouée aux tâches en mode noyau (pour driver RTDM et tâche Xenomai implémentée dans un module noyau).

Statistics collection

Collecte de statistiques dans le fichier.

Debug support

Nucleus Debugging support

Active le débogage Nucleus (ajoute des traces printk) : trace les spinlocks...
Désactivé par défaut, utilisé pour le développement de Xenomai.

Queue Debugging support

Active le débogage des files de messages internes et utilisées via les skins (ajoute des traces printk et des contrôles).
Désactivé par défaut.

Registry Debugging support

Fonctionnalité sans effet dans la version 2.4.3.

Timer Debugging support

Fonctionnalité sans effet dans la version 2.4.3.

Watchdog support

Détecte si une tâche Xenomai garde le processeur plus de [Watchdog timeout] secondes sans rescheduler. Si c'est le cas, la tâche est suspendue. Utilisée lors de la mise au point d'applications, cette option évite de redémarrer la machine si une tâche ne rend pas la main.

En cas de déclenchement, un message du type :
Xenomai: watchdog triggered -- killing runaway thread '...' sera accessible par dmesg.

Watchdog timeout

Valeur de ce timeout comprise entre 1 et 60 secondes.

Shared interrupts (31)

Le partage d'interruptions est à activer si Xenomai doit prendre en charge des périphériques partageant la même interruption (exemple : carte à quatre ports série). Ce type de configuration est cependant à éviter car il introduit des latences.

Timing

Enable periodic timing

Le temps peut être manipulé à travers deux « unités » lors de l'utilisation de l'API Xenomai  :

• soit en ticks si cette option est activée, comme sous VxWorks par exemple. La durée d'un tick est alors fixée lors de la compilation du noyau et éventuellement modifiable lors de l'exécution (rt_timer_set_mode dans l'API native par exemple) ;
• soit en nanosecondes.

Scheduling latency (ns)

Délai de retour à l'exécution d'une tâche après une interruption (timer notamment). Si ce paramètre vaut 0 (défaut), une valeur par défaut sera considérée.

Ce délai est utilisé en interne pour corriger la date d'échéance des timers.

Scalability

O(1) scheduler

Active le scheduler en O(1), c'est-à-dire que le temps mis pour choisir une tâche parmi les éligibles est constant, et ce quel que soit leur nombre. Cette option présente un intérêt si ce nombre est supérieur à 10.
L'implémentation de ce scheduler est réalisée par une liste chaînée par niveau de priorité.

Timer indexing method

Le nombre de timers à gérer influe sur les performances du scheduler Xenomai, c'est pourquoi plusieurs algorithmes sont proposés.
Détermine l'algorithme utilisé pour démarrer, arrêter, échoir les timers apériodiques (les périodiques sont toujours indexés selon la méthode linéaire). Les choix ci-dessous sont les structures de données utilisées par ces algorithmes. Si l'option « Enable periodic timing » est activée, ce sera forcément la structure « Timer wheel » qui sera utilisée.

Linear

Complexité en O(N), le temps dépend du nombre de timers utilisés, recommandé jusqu'à 10 timers. Choix par défaut.

Tree

Complexité en O(log N) reposant sur un arbre binaire.

Binary heap capacity

L'arbre binaire étant alloué de manière statique, ce paramètre fixe le nombre maximum de timers simultanés.

Hash

Complexité en O(1), c'est-à-dire indépendante du nombre de timers. L'algorithme utilisé est décrit dans le paragraphe XXI.B.

Timer wheel step

Le Timer wheel step est la durée d'un slot (entrée dans la structure de donnée circulaire contenant les timers non échus). Le nombre de slots est fixé à 64 et il n'est pas modifiable.

Machine

Enable FPU support

Réservé aux processeurs sans FPU, ce qui n'est pas le cas sur les PC. Il n'y a priori aucune raison de la désactiver.

NMI watchdog

Le NMI est utilisé dans Linux pour le débogage du noyau lorsque le système est gelé.

Enable NMI watchdog

Sert au débogage du noyau Nucleus.
Active un watchdog hardware via une interruption non masquable (NMI). Le watchdog est armé à chaque programmation du timer. Si le timer n'a pas expiré après [NMI watchdog latency threshold]ns, le watchdog claque en collectant des informations de débogage.

NMI watchdog latency threshold

Tolérance du watchdog à l'égard du timer.

SMI workaround

Le SMI est un système de gestion d'interruptions utilisé par certains composants (USB...). Les interruptions générées ne sont pas masquables et introduisent des temps de latence parasites pour Xenomai.

Disable SMI detection

Pour les systèmes non équipés du SMI.

Enable SMI workaround

Détecte les composants équipés du SMI et en désactive la partie SMI.

Globally disable SMI

Inhibe le SMI de tous les périphériques lorsque Xenomai a la main. Les options ci-dessous permettent une granularité plus fine.

Enable Intel-Specific USB2 SMI

Enable legacy USB2 SMI

Enable periodic SMI

Enable TCO SMI

Enable microcontroller SMI

Enable APM SMI

Enable legacy USB SMI

Enable ACPI BIOS SMI

Number of pre-allocated kernel stacks

Spécificité Intel Itanium 64.

Interfaces

Gestion des skins. Les options les plus triviales ne sont pas décrites.
La customisation très fine des skins et des fonctionnalités utilisées à l'intérieur de celles-ci permet de réduire l'empreinte mémoire.

Native API

Base period (us)

Dans le cas où l'option « Enable periodic timing » est activée, on configure ici l'équivalence 1 tick = x microsecondes.

Message pipes

Active le support des pipes, le nombre de pipes est configuré dans Number of pipe devices. Nécessaire pour l'appel des fonctions rt_pipe_* et donc la communication avec les tâches Linux « classiques ».

Bytes in buffer space

Taille du buffer par pipe.

Registry support

Counting semaphores

Nécessaire pour l'appel des fonctions rt_sem_*.

Events flags

Nécessaire pour l'appel des fonctions rt_event_*.

Mutexes

Nécessaire pour l'appel des fonctions rt_mutex_*.

Condition variables

Nécessaire pour l'appel des fonctions rt_cond_*.

Messages queues

Nécessaire pour l'appel des fonctions rt_queue_*.

Memory heaps

Active l'allocation dynamique de mémoire depuis les tâches Xenomai. Nécessaire pour l'appel des fonctions rt_heap_*.

Alarms

Active les watchdogs. Nécessaire pour l'appel des fonctions rt_alarm_*.

Message passing support

Active l'échange de messages entre tâches. Nécessaire pour l'appel des fonctions rt_task_send/receive/reply.

Interrupts

Nécessaire pour l'appel des fonctions rt_intr_*.

Debugging support

Dans les versions antérieures de Xenomai, les objets « orphelins » (files de messages...) persistaient après la fin de l'application. Ils devaient alors être explicitement détruits (de même qu'au début de l'application supportant ainsi les cas de terminaisons brutales). Dorénavant, les destructions d'objets sont automatiques, cette option produit un message lors de celles-ci.

POSIX API

Base period (us)

Shared Memory

Interrupts

Select syscall

Debugging support

pSOS+ emulator

uITRON API

VRTX emulator

RTAI emulator

Fifos

Semaphores

Shared Memory

Real-Time Driver Model

Active le support RTDM, à utiliser pour le support des cartes série, CAN et autres.

Base period (us)

Maximum number of RTDM file descriptors

Nombre maximum de descripteurs ouverts à un instant donné. La valeur par défaut apparaît largement suffisante pour la plupart des applications.

Select support for RTDM file descriptors

Support de la fonctionnalité équivalente au select.

RTDM debugging support

Drivers

Active les drivers fournis par défaut. Ils peuvent correspondre à des interfaces physiques ou virtuelles.

Serial drivers

16550A UART driver

Ce driver supporte les chipsets 8250 et 16550x.

Hardware access mode

Port-based I/O

Option correspondant à la plupart des configurations PC (où il y a un espace d'adressage distinct pour les périphériques).

Memory-mapped I/O

Pour les configurations autres que PC.

Any access mode

Les deux modes d'accès sont supportés.

Testing drivers

Drivers virtuels établissant des benchmarks.

Timer benchmarck driver

Kernel-only latency measurement module

IRQ benchmark driver

Context switch unit testing driver

CAN drivers

RT-Socket-CAN, CAN raw socket interface

Le noyau Nucleus et les drivers peuvent être soit compilés avec le noyau Linux, soit en tant que modules.

Les modules permettent de mettre au point les options sans redémarrer et ainsi de disposer d'un système plus flexible. Dans la suite du document la configuration utilisée repose sur Xenomai intégré au noyau.

Comme nous l'avons vu, l'option « Low-Latency Desktop » améliore la latence de Linux, ce qui est important pour les tâches Xenomai en secondary mode.

Pour cela, il faut sélectionner :

Processor type and features/Preemption Model/Low-Latency Desktop.

Ce paragraphe rappelle(32) les options Linux à désactiver, pour quelle raison, et où les désactiver dans le noyau Linux. Le positionnement d'options incompatibles provoque des warnings lors de la configuration du noyau.

ACPI Support (processor) : [incompatible] gestion de l'énergie, la fréquence du processeur peut être diminuée ce qui introduit des latences lors du retour à la vitesse nominale.

Power management options/Power Management support/ACPI Support/Processor.

CPU frequency scaling :[incompatible] driver modulant la fréquence du processeur en fonction de sa charge. L'horloge TSC (compteur de cycles processeur utilisé pour les timers) peut être instable et le processeur peut mettre du temps à retrouver sa vitesse nominale.

Se trouve dans :

Power management options/CPU Frequency scaling.

PC speaker : [incompatible] risque de conflit avec le timer Xenomai pour les architectures utilisant un timer 8254

Device Drivers/Input device support/Miscellaneous devices/PC Speaker support.

Tout ce qui est graphique repose sur des timers, il peut être souhaitable de désactiver le serveur X.

En tant que root, exécutez /usr/xenomai/bin/latency.

Ce programme mesure par défaut la latence d'une tâche périodique, c'est-à-dire l'écart entre le moment où elle devrait être active et celui où elle l'est réellement.

Ce test est exécuté dans des conditions longues (plusieurs minutes voire heures) et de stress, en parallèle nous lançons la commande :

[dchabal@localhost ~]$ dd if=/dev/zero of=/dev/null

Lors de la première exécution, nous avons au bout de quelques secondes :

[root@localhost bin]# /usr/xenomai/bin/latency
== Sampling period: 100 us
== Test mode: periodic user-mode task
== All results in microseconds
warming up...
RTT|  00:00:01  (periodic user-mode task, 100 us period, priority 99)
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTD|       0.235|       0.565|       1.347|       0|       0.235|       1.347
RTD|       0.226|       0.568|       3.734|       0|       0.226|       3.734
RTD|       0.258|       0.565|       1.463|       0|       0.226|       3.734
RTD|       0.219|       0.566|       1.357|       0|       0.219|       3.734
RTD|       0.200|       0.567|       1.400|       0|       0.200|       3.734
RTD|       0.282|       0.567|       2.192|       0|       0.200|       3.734
RTD|       0.218|       0.565|       2.295|       0|       0.200|       3.734
RTD|       0.235|       0.567|       2.710|       0|       0.200|       3.734
RTD|       0.221|       0.568|       3.701|       0|       0.200|       3.734
RTD|       0.222|       0.632|       2.052|       1|       0.200|     198.581
RTD|       0.201|       0.625|       2.078|       1|       0.200|     198.581
RTD|       0.223|       0.627|       3.737|       1|       0.200|     198.581
RTD|       0.179|       0.627|       2.217|       1|       0.179|     198.581
RTD|       0.345|       0.624|       1.957|       1|       0.179|     198.581
RTD|       0.202|       0.625|       2.149|       1|       0.179|     198.581
---|------------|------------|------------|--------|-------------------------
RTS|       0.179|       0.593|     198.581|       1|    00:00:17/00:00:17

Le cas le plus défavorable (qui est toujours celui à considérer) donne une latence de 198 µs.

On considère un temps supérieur à 100 µs comme pathologique. Sur une architecture de type PC, on s'attend à trouver des valeurs comprises entre 10 et 50 µs(33).

La valeur obtenue n'est pas acceptable, le paragraphe suivant décrit la procédure d'investigation afin de l'expliquer et la diminuer.

Le fichier TROUBLESHOOTING contient des problèmes fréquemment rencontrés.

Les grandes pistes à suivre sont :

• un problème d'accélération matérielle du serveur X, relancez le programme en mode console ;
• une mauvaise configuration du noyau :
  • SMI non désactivé (vérifiez le journal de démarrage),
  • ACPI autres que processor à désactiver (sur PC : si vous percevez une variation du régime du ventilateur lors du lancement du bench, l'ACPI est probablement impliqué),
  • l'arrivée de NMI (cf. /proc/interrupts),
  • l'option idle=poll à passer sur la ligne de boot Lilo ou Grub ;
• une mauvaise configuration directement au niveau du BIOS (Power management, SMI, ACPI encore et toujours, options Legacy*).

Si malgré cela, les mauvais résultats persistent, il faut investiguer avec I-pipe Tracer.

Si vous vous sentez un peu seul face à la question « qu'est-ce qui retarde ma tâche devant s'exécuter ? », ce débogueur va vous aider. Cela passe par deux choses :

• l'instrumentation d'ADEOS, avec le traçage des interruptions et du temps passé dans leur traitement ;
• l'instrumentation du code sous test, qui demande explicitement le gel du contexte conduisant au cas le plus défavorable.

On retourne dans notre configuration du noyau :

[root@localhost src]# cd /usr/src/linux-2.6.24
[root@localhost linux-2.6.24]#  make menuconfig

Puis dans le menu Kernel hacking, on active I-pipe debugging et son sous-menu Latency tracking.

Les options sont alors les suivantes :

I-pipe debugging

L'activation du débogage introduit une latence supplémentaire ;

Check for illicit cross-domain calls ;

Latency tracing

À activer pour notre investigation sur les temps de latence. Cette option peut être activée soit ici, soit via la commande echo 1 > /proc/ipipe/trace/enable ;

Enable tracing on boot ;

Instrument fonction entries ;

Trace IRQ-off times ;

Depth of trace log ;

Use vmalloc'ed trace buffer ;

Enable panic back traces.

Le détail des options, les fichiers de configuration et les fichiers produits se trouvent dans le manuel en ligne :http://www.xenomai.org/index.php/I-pipe:Tracer.

On conserve les choix par défaut puis on recompile (d'ailleurs, aviez-vous bien allégé le noyau ?) et on reboote :

[root@localhost linux-2.6.24]#  make && make modules_install install

On active le plus de traces possible :

[root@localhost bin]# echo 1 > /proc/ipipe/trace/enable
[root@localhost bin]# echo 1 > /proc/ipipe/trace/verbose

On agrandit la fenêtre de capture des évènements.

[root@localhost bin]# echo 128 > /proc/ipipe/trace/back_trace_points

On relance notre benchmark,avec l'option -f en plus (toujours en chargeant le système) :

[root@localhost bin]# /usr/xenomai/bin/latency -f
...
RTH|-----lat min|-----lat avg|-----lat max|-overrun|----lat best|---lat worst
RTD|       1.898|       3.099|       6.090|       3|       1.829|     202.798
RTD|       1.989|       3.133|     131.559|       4|       1.829|     202.798
RTD|       1.951|       3.105|       6.104|       4|       1.829|     202.798
RTD|       2.008|       3.197|       6.504|       4|       1.829|     202.798
RTD|       2.024|       3.091|       7.040|       4|       1.829|     202.798
RTD|       1.970|       3.136|       7.937|       4|       1.829|     202.798
RTD|       1.902|       3.117|       8.278|       4|       1.829|     202.798
RTD|       1.867|       3.091|       5.965|       4|       1.829|     202.798
RTD|       2.060|       3.082|       5.823|       4|       1.829|     202.798
RTD|       2.011|       3.094|       8.030|       4|       1.829|     202.798
RTD|       1.927|       3.099|       5.772|       4|       1.829|     202.798
RTD|       2.074|       3.133|       6.432|       4|       1.829|     202.798
RTD|       2.060|       3.132|     195.732|       5|       1.829|     202.798
RTD|       2.779|       3.112|       8.222|       5|       1.829|     202.798
RTD|       2.508|       3.072|       7.934|       5|       1.829|     202.798
RTD|       2.456|       3.124|       7.784|       5|       1.829|     202.798
RTD|       2.480|       3.117|       9.660|       5|       1.829|     202.798
RTD|       2.303|       3.049|       5.657|       5|       1.829|     202.798
---|------------|------------|------------|--------|-------------------------
RTS|       1.829|       3.086|     202.798|       5|    00:06:15/00:06:15

Il est normal que les résultats soient empirés par l'instrumentation.

Le résultat de la capture se trouve dans le fichier /proc/ipipe/trace/frozen :

I-pipe frozen back-tracing service on 2.6.24/ipipe-2.0-06
------------------------------------------------------------
CPU: 0, Freeze: 567619631513 cycles, Trace Points: 100 (+10)
Calibrated minimum trace-point overhead: 0.110 us

 +----- Hard IRQs ('|': locked)
 |+---- <unused>
 ||+--- <unused>
 |||+-- Xenomai
 ||||+- Linux ('*': domain stalled, '+': current, '#': current+stalled)
 |||||                        +---------- Delay flag ('+': > 1 us, '!': > 10 us)
 |||||                        |        +- NMI noise ('N')
 |||||                        |        |
      Type    User Val.   Time    Delay  Function (Parent)
:    +func                -221    0.105  do_sync_read+0x17 (vfs_read+0xed)
:    +func                -221    0.095  generic_file_aio_read+0x21 (do_sync_read+0xf2)
:    +func                -220    0.100  generic_segment_checks+0xe (generic_file_aio_read+0x4f)
:    +func                -220    0.105  do_generic_mapping_read+0x16 (generic_file_aio_read+0xf5)
:    +func                -220    0.095  cond_resched+0x9 (do_generic_mapping_read+0x79)
:    +func                -220    0.090  find_get_page+0x19 (do_generic_mapping_read+0x12b)
:    +func                -220    0.090  _read_lock_irq+0x9 (find_get_page+0x2f)
:    +func                -220    0.085  _read_lock_irqsave+0x16 (_read_lock_irq+0xe)
:    +func                -220    0.100  ipipe_check_context+0x19 (_read_lock_irqsave+0x25)
:    +func                -220    0.115  ipipe_check_context+0x19 (_read_lock_irqsave+0x41)
:    +func                -220    0.145  ipipe_check_context+0x19 (_read_lock_irqsave+0x71)
:    #func                -220    0.135  radix_tree_lookup+0x9 (find_get_page+0x3a)
:    #func                -219    0.105  _read_unlock_irq+0x9 (find_get_page+0x61)
:    #func                -219    0.100  __ipipe_unstall_root+0x9 (_read_unlock_irq+0x11)
:|   #begin   0x80000000  -219    0.095  __ipipe_unstall_root+0x5c (_read_unlock_irq+0x11)
:|   +end     0x80000000  -219    0.100  __ipipe_unstall_root+0x4b (_read_unlock_irq+0x11)
:    +func                -219    0.115  ipipe_check_context+0x19 (_read_unlock_irq+0x1d)
:    +func                -219    0.095  file_read_actor+0x21 (do_generic_mapping_read+0x2f2)
:    +func                -219    0.240  ipipe_check_context+0x19 (file_read_actor+0x125)
:    +func                -219    0.110  ipipe_check_context+0x19 (file_read_actor+0x192)
:    +func                -218    0.115  put_page+0x20 (do_generic_mapping_read+0x31d)
:    +func                -218    0.095  touch_atime+0xe (do_generic_mapping_read+0x386)
:    +func                -218    0.085  current_fs_time+0xe (touch_atime+0x98)
:    +func                -218    0.095  current_kernel_time+0xd (current_fs_time+0x16)
:    +func                -218    0.110  timespec_trunc+0xe (current_fs_time+0x27)
:    +func                -218    0.105  dnotify_parent+0x19 (vfs_read+0x12b)
:    +func                -218    0.105  _spin_lock+0xe (dnotify_parent+0x43)
:    +func                -218    0.120  ipipe_check_context+0x19 (_spin_lock+0x1d)
:    +func                -218    0.300  _spin_unlock+0x9 (dnotify_parent+0x83)
:|   +begin   0x00000081  -217    0.115  common_interrupt+0x6d (__ipipe_trace+0x1f7)
:|   +func                -217    0.170  __ipipe_handle_irq+0x21 (common_interrupt+0x75)
:|   +func                -217    0.155  __ipipe_set_irq_pending+0xa (__ipipe_handle_irq+0x22f)
:|   +func                -217    0.130  __ipipe_ack_irq+0x9 (__ipipe_handle_irq+0x24a)
:|   +func                -217    0.125  __ipipe_ack_fasteoi_irq+0x9 (__ipipe_ack_irq+0x20)
:|   +func                -217    0.120  ack_apic_level+0x9 (__ipipe_ack_fasteoi_irq+0x10)
:|   +func                -216    0.135  __mask_IO_APIC_irq+0xc (ack_apic_level+0x24)
:|   +func                -216+   1.534  io_apic_base+0x9 (__mask_IO_APIC_irq+0x6f)
:|   +func                -215    0.165  io_apic_base+0x9 (__mask_IO_APIC_irq+0x84)
:|   +func                -215+   1.499  io_apic_base+0x9 (__mask_IO_APIC_irq+0x91)
:|   +func                -213    0.155  __ipipe_walk_pipeline+0x10 (__ipipe_handle_irq+0x96)
:|   +func                -213    0.170  __ipipe_sync_stage+0x16 (__ipipe_walk_pipeline+0x118)
:|   #end     0x80000000  -213    0.165  __ipipe_sync_stage+0x31e (__ipipe_walk_pipeline+0x118)
:    #func                -213    0.140  __ipipe_get_irq_vector+0x9 (__ipipe_sync_stage+0x3a1)
:    #func                -213    0.140  do_IRQ+0x19 (__ipipe_sync_stage+0x3ee)
:    #func                -212    0.115  exit_idle+0x9 (do_IRQ+0x44)
:    #func                -212    0.095  irq_enter+0x9 (do_IRQ+0x49)
:    #func                -212    0.095  ipipe_check_context+0x19 (irq_enter+0x15)
:    #func                -212    0.125  idle_cpu+0x9 (irq_enter+0x35)
:    #func                -212    0.100  handle_fasteoi_irq+0x20 (do_IRQ+0x8a)
:    #func                -212    0.090  _spin_lock+0xe (handle_fasteoi_irq+0x3b)
:    #func                -212    0.125  ipipe_check_context+0x19 (_spin_lock+0x1d)
:    #func                -212    0.110  _spin_unlock+0x9 (handle_fasteoi_irq+0x8d)
:    #func                -212    0.110  ipipe_check_context+0x19 (_spin_unlock+0x1b)
:    #func                -211    0.105  handle_IRQ_event+0x10 (handle_fasteoi_irq+0x98)
:    #func                -211    0.145  usb_hcd_irq+0xe [usbcore] (handle_IRQ_event+0x39)
:    #func                -211+   1.288  uhci_irq+0x21 [uhci_hcd] (usb_hcd_irq+0x3d [usbcore])
:    #func                -210    0.095  ata_interrupt+0x16 (handle_IRQ_event+0x39)
:    #func                -210    0.095  _spin_lock_irqsave+0xc (ata_interrupt+0x23)
:    #func                -210    0.105  ipipe_check_context+0x19 (_spin_lock_irqsave+0x1b)
:    #func                -210    0.120  ipipe_check_context+0x19 (_spin_lock_irqsave+0x37)
:    #func                -209    0.220  ipipe_check_context+0x19 (_spin_lock_irqsave+0x67)
:    #func                -209    0.105  ata_bmdma_status+0x9 (ata_interrupt+0x1bf)
:    #func                -209+   1.062  ioread8+0x9 (ata_bmdma_status+0x19)
:    #func                -208    0.100  ata_bmdma_stop+0x16 (ata_interrupt+0x1de)
:    #func                -208+   1.057  ioread8+0x9 (ata_bmdma_stop+0x29)
:    #func                -207! 198.631  iowrite8+0x9 (ata_bmdma_stop+0x39)
:|   #begin   0x000000f7    -8    0.125  common_interrupt+0x6d (ata_bmdma_stop+0x3c)
:|   #func                  -8    0.140  __ipipe_handle_irq+0x21 (common_interrupt+0x75)
:|   #func                  -8    0.135  __ipipe_ack_apic+0x9 (__ipipe_handle_irq+0xe2)
:|   #func                  -8    0.135  __ipipe_dispatch_wired+0x20 (__ipipe_handle_irq+0x71)
:|  #*func                  -8    0.170  xnintr_clock_handler+0x12 (__ipipe_dispatch_wired+0x178)
:|  #*func                  -8    0.275  xntimer_tick_aperiodic+0x10 (xnintr_clock_handler+0x92)
:|  #*func                  -7    0.135  xnthread_periodic_handler+0x9 (xntimer_tick_aperiodic+0xb7)
:|  #*func                  -7    0.150  xnpod_resume_thread+0x16 (xnthread_periodic_handler+0x2f)
:|  #*[ 4445] samplin 99    -7    0.265  xnpod_resume_thread+0xd3 (xnthread_periodic_handler+0x2f)
:|  #*func                  -7    0.295  xntimer_next_local_shot+0x9 (xntimer_tick_aperiodic+0x184)
:|  #*func                  -6    0.265  xnpod_schedule+0x16 (xnintr_clock_handler+0x1a2)
:|  #*[ 4442] -<?>-   -1    -6    0.421  xnpod_schedule+0x1fb (xnintr_clock_handler+0x1a2)
:|  #*func                  -6    0.300  __phys_addr+0x9 (xnpod_schedule+0x550)
:|  #*func                  -5    0.340  __switch_to+0x16 (xnpod_schedule+0x5bf)
:|  #*[ 4445] samplin 99    -5    0.371  xnpod_schedule+0x613 (xnpod_suspend_thread+0x2e4)
:|  #*func                  -5    0.195  xntimer_get_overruns+0x9 (xnpod_wait_thread_period+0x127)
:|  #*func                  -5    0.140  __ipipe_restore_pipeline_head+0x16 (xnpod_wait_thread_period+0x17f)
:|  +*end     0x80000000    -4    0.315  __ipipe_restore_pipeline_head+0xc6 (xnpod_wait_thread_period+0x17f)
:|  +*begin   0x80000001    -4    0.215  __ipipe_dispatch_event+0x23f (__ipipe_syscall_root+0x62)
:|  +*end     0x80000001    -4    0.130  __ipipe_dispatch_event+0x203 (__ipipe_syscall_root+0x62)
:|  +*begin   0x80000000    -4    0.827  __ipipe_syscall_root+0xdb (__ipipe_syscall_root_thunk+0x35)
:   +*func                  -3    0.155  __ipipe_syscall_root+0xc (__ipipe_syscall_root_thunk+0x35)
:   +*func                  -3    0.110  __ipipe_dispatch_event+0x16 (__ipipe_syscall_root+0x62)
:|  +*begin   0x80000001    -3    0.115  __ipipe_dispatch_event+0x2a8 (__ipipe_syscall_root+0x62)
:|  +*end     0x80000001    -3    0.135  __ipipe_dispatch_event+0x24f (__ipipe_syscall_root+0x62)
:   +*func                  -2    0.396  hisyscall_event+0x21 (__ipipe_dispatch_event+0x12b)
:   +*func                  -2    0.315  xnshadow_sys_trace+0x16 (hisyscall_event+0x1bf)
:   +*func                  -2    0.220  ipipe_trace_frozen_reset+0x12 (xnshadow_sys_trace+0xe1)
:   +*func                  -1    0.195  __ipipe_global_path_lock+0x9 (ipipe_trace_frozen_reset+0x17)
:   +*func                  -1    0.110  __ipipe_spin_lock_irqsave+0xc (__ipipe_global_path_lock+0x15)
:|  +*begin   0x80000001    -1+   1.323  __ipipe_spin_lock_irqsave+0x8b (__ipipe_global_path_lock+0x15)
:|  #*func                   0    0.165  __ipipe_spin_unlock_irqcomplete+0xe (__ipipe_global_path_unlock+0x7b)
:|  +*end     0x80000001     0    0.165  __ipipe_spin_unlock_irqcomplete+0x64 (__ipipe_global_path_unlock+0x7b)
<   +*freeze  0x0002e643     0    0.185  xnshadow_sys_trace+0x49 (hisyscall_event+0x1bf)
 |  +*begin   0x80000001     0    0.155  __ipipe_dispatch_event+0x23f (__ipipe_syscall_root+0x62)
 |  +*end     0x80000001     0    0.150  __ipipe_dispatch_event+0x203 (__ipipe_syscall_root+0x62)
 |  +*begin   0x80000000     0    0.255  __ipipe_syscall_root+0xdb (__ipipe_syscall_root_thunk+0x35)
    +*func                   0    0.160  __ipipe_syscall_root+0xc (__ipipe_syscall_root_thunk+0x35)
    +*func                   0    0.135  __ipipe_dispatch_event+0x16 (__ipipe_syscall_root+0x62)
 |  +*begin   0x80000001     1    0.150  __ipipe_dispatch_event+0x2a8 (__ipipe_syscall_root+0x62)
 |  +*end     0x80000001     1    0.130  __ipipe_dispatch_event+0x24f (__ipipe_syscall_root+0x62)
    +*func                   1    0.180  hisyscall_event+0x21 (__ipipe_dispatch_event+0x12b)
    +*func                   1    0.145  __rt_task_wait_period+0x19 (hisyscall_event+0x1bf)
    +*func                   1    0.000N rt_task_wait_period+0x9 (__rt_task_wait_period+0x31)

Au premier abord, ce fichier n'est pas très facile à lire, voici quelques explications qui vous aideront à le décoder.

Tout d'abord, que cherche-t-on ? Des sections anormalement longues.

La colonne Time est le temps relatif de l'évènement par rapport à capture de la trace (appel à xntrace_user_freeze dans l'outil de benchmark). La colonne suivante, Delay, est la durée qu'a prise l'évènement. Pour nous aider un petit peu, I-Pipe Tracer nous indique avec + et !, les délais les plus longs.

[pid] :indique le scheduling d'un processus, son nom (samplin) et sa priorité (-1 pour les tâches schedulées par Linux).

common_interrupt indique l'arrivée d'une interruption, la ligne d'IRQ est 0x000000f7.

L'exploitation de ce fichier reste tout de même assez délicate car elle nécessite un très bonne connaissance de l'architecture matérielle utilisée.

Sur cette configuration, il s'agissait ici de l'absence du paramètre de noyau idle=poll lié à l'économie d'énergie, c'est une piste assez logique lorsque rien ne paraît dans la fonction justifier un long temps de traitement.