Une erreur… bien cachée

J'avais dit que je parlerais un peu des systèmes embarqués et de mes aventures dans le milieu. Aujourd'hui je voudrais relater un problème que j'avais dû résoudre au travail et qui n'était pas évident. Le prochain article sera plus générique (et celui d'après à propos d'un autre problème au boulot). Je vais essayer de varier un peu.

Ce sera sûrement un peu long, et je vais donner mon cheminement intellectuel autour de ce problème. Je respecte la chronologie des éléments dont j'avais connaissance à chaque étape.

Présentation du matériel et contexte

Pour situer un peu, je travaillais sur une plateforme Texas Instrument 8148 qui est un processeur ARM Cortex-A8 couplé avec un processeur M3 et des accélérateurs vidéos / DSP en son sein. Cette plateforme exploitait un noyau Linux 2.6.37 patchée à mort par Texas Instrument pour son processeur.

Le but du jour était d'exploiter le composant TVP5158 de… Texas Instrument encore (ce module a été conçu pour ce processeur en même temps). Pour décrire rapidement, ce composant permet de fusionner jusqu'à 4 flux vidéo analogiques (PAL / NTSC principalement) dans un seul numérisé que le processeur peut exploiter.

En soit le composant avait déjà un pilote fonctionnel pour Linux. Mais cela ne nous convenait pas. En effet, nous utilisons le TVP dans une chaîne de traitement vidéo où on faisait des décodages, redimensionnements, des remplacements d'images ou encore des encodages. Pour faire cela, non seulement il faut de la performance mais il faut aussi utiliser une API plutôt unifiée.

La performance est offerte par les accélérateurs vidéos qui sont dans les co-processeurs du système. On peut les exploiter via un firmware (dont le code source est confidentiel, désolé) et on peut communiquer avec ces accélérateurs via le noyau Linux et l'API OpenMax (OMX). Cette API est standard, éditée par le même groupe et dans les mêmes conditions qu'OpenGL, mais plutôt que de s'occuper de la 3D, il s'occupe des codecs vidéos. C'est souvent la référence libre dans ce domaine, avec GStreamer couplé avec libav.

Cette API est disponible dans le firmware de TI, cela tombe bien. Mais là où cela ce corse c'est pour récupérer des informations. En effet, il faut que durant notre traitement vidéo que nous sachions la résolution détectée par TVP du flux vidéo, et s'il existe (sur les 4 flux, des caméras peuvent être en pannes ou absentes pour diverses raisons).

Et TVP se configure via un bus assez standard et typique I2C qui est assez simple à mettre en place et largement suffisant pour lire / écrire des registres sur un composant. Il est par exemple souvent utilisé dans les cartes mères / graphiques de nos ordinateurs pour les capteurs de températures. Le soucis est que ce bus ne peut être géré par le firmware de TI (pour configurer le flux) et par le noyau Linux (pour récupérer les infos sur le flux pour l'application). Si on fait cela, il y aura conflit et le bus sera inutilisable. Modifier le firmware pour renvoyer les informations à l'espace utilisateur ou que le noyau gère la configuration du flux vidéo est plutôt complexe. Le mieux est d'utiliser un canal de communication existant entre le noyau et le firmware pour faire ceci, le firmware a donc la main sur le bus I2C et le noyau fera ses requêtes a travers lui.

On code

Partie intéressant du travail, coder. Et réfléchir à comment faire aller / revenir les informations voulues. Le noyau et le firmware, comme dans la quasi-totalité des systèmes à processeurs asymétriques, communiquent entre eux par mémoire partagée. Une partie de la RAM est allouée pour les messages, une autre pour les buffers vidéos, etc. Ceci est configurable (avec des limites) dans le code des deux côtés. Bien évidemment, les deux doivent être d'accord sur les adresses de base de chaque fonction, sinon ils ne retrouveront plus leurs petits. Cela est plutôt bien pris en charge par l'environnement de compilation fourni par TI. Vous pouvez consulter l'adressage mémoire entre les deux ici.

Bon, et le code alors ? La communication entre ces deux modules se faisant par mémoire partagée, il y a un certain protocole qui a été conçu par TI et qui s'exploite à travers une API maison nommée FVID2. Elle est déjà partiellement implémentée mais pas celle concernant le fameux TVP (qui est pourtant décrite dans l'API en question). J'ai donc écrit un pilote Linux pour combler cela. Aspect amusant, TI à la pointe de la technologie fournissait la doc de cette API dans un document .chm, un vieux format propriétaire dont le seul lecteur sous Linux potable est une application de l'ère de KDE3 : Kchmviewer. Quand je vous dis que l'embarqué c'est moderne !

Mais cela reste un peu moche, l'application en espace utilisateur demande au firmware HDVPSS de configurer le TVP. Mais, pour faire cela, il instancie le pilote interne de TVP du firmware qui ne doit pas être instancié deux fois et dont on ne peut récupérer la référence pour notre API FVID2… J'utilise donc une référence d'un autre composant dont le noyau a la référence (car il l'instancie) et j'envoie mes messages avec, le firmware a été modifié pour comprendre la situation et rediriger le message ensuite à bon port. Je n'avais pas trouvé mieux dans le délai imparti.

Et le bogue arrive… parfois

Et après le code, on teste. Après plusieurs essais difficiles, cela fini par passer. Youhou. Champomy dans les bureaux.

Mais, quand mes collègues vont tester leur application avec mon travail, cela ne fonctionne pas toujours. Le module noyau qui fait les échanges avec le coprocesseur nous signifie que certaines requêtes, en quantité variables, mettent trop de temps à revenir. On était à une moyenne de 1 à 10 échecs par minute (pour 24 requêtes). Mais il arrivait malgré tout que sur 30 minutes / 1 heure cela n'arrive pas, avant de revenir. C'est beaucoup trop problématique, et ce qui est étonnant c'est que mes tests ne présentaient aucune erreur.

Du coup, comme pour toute chaine de communication, on va déboguer étape par étape pour identifier où cela coince. Je précise que la seule section dont je pouvais difficilement déboguer c'est l'échange des messages entre Linux et le firmware qui est assez mal documenté et le code assez obscur en plus d'être gros.

Matériel

Le plus simple à tester, c'est le matériel (recompiler le firmware vidéo pour y ajouter du débogue c'est 40 minutes de compilation, c'est pénible et long, on évite au maximum de le faire). Je vérifie donc que le TVP reçoit les bonnes requêtes et y répond. Le bus I2C étant très simple, un petit oscilloscope sur un fil et on peut rapidement conclure que les signaux sont bons dans les deux sens que la requête échoue ou non à la fin.

Mais je me dis que le temps d'attente côté Linux pour recevoir ce message est trop court, je l'allonge volontairement à un délai absurde comme 30 secondes, cela ne change rien. Soit ça réussi vite, soit au bout des 30 secondes j'ai l'erreur. Pas d'entre deux, pas de hausse ou baisse de ces erreurs.

Du coup on sait que la chaîne d'envoi est bonne, et le matériel aussi, le soucis se situe bien au retour.

Firmware vidéo

Donc forcément je remonte un peu la chaîne côté firmware vidéo et à chaque étape en son sein, l'information est correcte à tous les coups. Comme le soucis n'est pas côté Linux après l'API FVID2, le soucis se situe forcément dans le transfert des messages entre les deux mondes comme on dit. Côté retour uniquement.

Plongeons au cœur de la mémoire

À ce stade là, cela devient assez étrange. Comment cela peut planter de cette manière là ? J’émets quelques hypothèses, manque de place pour l'échange de messages (il y a d'autres messages que ceux du TVP là dedans) ou éventuellement un conflit de lecture / écriture simultanée par les deux sur un même message.

Pendant que je cherchais comment l'ensemble fonctionnait, des collègues m'ont rapporté des informations pertinentes (bah oui, ils continuent de testeur leur travail de leur côté et disent ce qui est pertinent quand ils constatent le problème). Il y a une corrélation entre le nombre de caméras branchées au TVP (et exploitées par notre programme) et la fréquence du bogue. Plus il y a avait de caméras, moins cela plantait. Cela paraît contre intuitif.

J'ai maintenant une idée plus claire de ce qui semble être le cas, mais je dois vérifier. J'essaye de voir donc comment l'échange de message fonctionne, et la fonction que j'appelle a quelques lignes intrigantes dont je copie la boucle intéressante :

while (fctrl->fctrlprms->returnvalue == VPS_FVID2_M3_INIT_VALUE) {
       usleep_range(100, 300);
       if (vps_timeout) {
              do_gettimeofday(&etime);
              td = time_diff(stime, etime);
              if (vps_timeout < td) {
                    VPSSERR("contrl event 0x%x timeout\\n",  cmd);
                     return -ETIMEDOUT;
               }
        }
}

En gros, Linux initialise une valeur précise à une adresse précise dans la RAM. Quand le firmware a fini son boulot et renvoie les infos demandés, il signifie au noyau qu'il a fini en changeant la valeur initialisée précédemment. Le noyau regarde sa valeur régulièrement par tranches de 100 à 300 microsecondes pendant 2 secondes maximum.

Et comme par hasard, si je mets dans la boucle un printk de débogue (l'équivalent de printf pour le noyau, pour afficher des chaînes de caractères visibles en espace utilisateur, cette fonction est plutôt grosse), le bogue disparaît. Quelques soient les conditions.

Cela me renforce dans mon hypothèse : nous sommes face à un soucis d'accès à la valeur de cette variable. Le noyau Linux relit la variable depuis le cache ou le registre du processeur qui bien sûr ne change pas (car le processeur n'a pas changé cette valeur, c'est au coprocesseur de le faire !), du coup il voit éternellement la variable comme au départ et il croit que le firmware vidéo ne fout rien. Le printk ou l'activité du système (plus il y a de caméras, moins cela arrive, n'oublions pas) permettant à Linux de bien voir la véritable valeur en la rechargeant depuis la RAM.

Le problème vient du fait que ce genre de vérification ne doit pas se faire directement, surtout que la zone mémoire concernée a été allouée avec "ioremap()".

Il suffit donc de remplacer la ligne

 while (fctrl->fctrlprms->returnvalue == VPS_FVID2_M3_INIT_VALUE) {

Par

 while (ioread32(&fctrl->fctrlprms->returnvalue) == VPS_FVID2_M3_INIT_VALUE) {

Les accès par "ioread*()" mettent des barrières mémoires et indiquent que la variable peut être modifiée de l'extérieur. Obligeant donc une nouvelle lecture de la valeur en toute circonstance.

Conclusion

Je suis tombé sur ce bogue après quelques mois dans la vie active seulement. C'était un défi intéressant, je n'avais pas trouvé cela évident. C'est vraiment le genre de choses que l'on a tendance à oublier, on accorde trop de confiances aux couches d'en dessous (matériel / noyau / compilateur / bibliothèque / langage) qu'on en oublie qu'ils peuvent présenter des problèmes et qu'on doit faire attention en les utilisant.

Après, cela met en évidence un énième bogue / oubli stupide de la part de Texas Instrument (ils en font du code horrible, je vous le dis) qui aurait pu être évité s'ils travaillaient un peu plus avec le noyau officiel. Nul doute qu'avec plus de relecteurs de leur code, quelqu'un l'aurait vu. Mais bon, tant pis, je me suis bien amusé.