Guru Meditation

Okay. Il y a les jours avec et les jours sans. Et quand il s'agit d'un "guru meditation", on préfère généralement les jours sans :P

Mais 10 ans de programmation d'OS m'ont au moins appris une chose: quand vous tenez un bug, ne le lâchez surtout pas avant d'avoir trouvé d'où il vient. A ce moment alors, et à ce moment seulement, modifiez votre code pour l'éliminer. Ouais, je sais, c'est plus facile à dire qu'à faire. C'est un peu comme jouer à Mario sans s'autoriser à faire marche arrière, ou offrir sa glace à la vanille pour manger un yaourt nature.

Alors si vous n'êtes pas particulièrement porté sur le développement sur DS, vous risquez de trouver tout ceci complètement imbuvable. Auquel cas, je vous propose d'aller voir ma gallerie de geek à la place ... Voilà. Vous êtes prévenus.

If you've ended up here, I bet there are chances your homebrew (or someone else's) threw a "guru meditation" screen at you, which you can basically compare to window's blue-screen-of-death with a smiley reference to Amiga micro-computers. What you see on screen is hexadecimal dump of the DS' internal state: registers and stack. From these, the programmer can try and identify the root cause of the bug. So if the software isn't yours, the best you can do is shooting a screenshot of what's on screen, ensure it is readable and hand that to your favourite homebrew developer with a jar of coffee

Bon, d'abord, j'ai placé un defaultExceptionHandler() le plus tôt possible dans mon programme. Si quelque-chose tourne mal, au moins, j'aurais droit à l'équivalent d'un écran-bleu-windows, mais en rouge. Sans celà, la console se bloque purement et simplement, et on est bon pour débugger à coup de "print toto".
Ensuite, je suis passé faire un petit tour dans le code de gurumeditation.c de la libnds et j'ai trouvé ceci:

//----------------------------
static void defaultHandler() {
//----------------------------
videoSetMode(0); 
videoSetModeSub(MODE_0_2D | DISPLAY_BG0_ACTIVE);
vramSetBankC(VRAM_C_SUB_BG);

SUB_BG0_CR = BG_MAP_BASE(31);

BG_PALETTE_SUB[0] = RGB15(31,0,0);
BG_PALETTE_SUB[255] = RGB15(31,31,31);

consoleInitDefault((u16*)SCREEN_BASE_BLOCK_SUB(31), (u16*)CHAR_BASE_BLOCK_SUB(0), 16);

En clair, dès qu'un pépin est détecté, la DS va tenter de gérer l'exception et commence par retourner aux modes vidéo par défaut. C'est sympa d'y avoir pensé, mais la ligne en rouge est particulièrement agaçante: elle nous masque complètement l'écran du haut. J'aime autant la commenter: puisque c'est généralement là que se trouve ma console pleine de messages inutiles, j'aurais en vis-à-vis le programme planté et les infos sur où il s'est planté.

Maintenant, l'avantage que l'on a ici sur un écran bleu, c'est qu'on a le code du programme sous la main, de quoi interpréter tous ces chiffres cabalistiques. Voyons un peu.

In order to figure out what went wrong, it may be useful to tweak the code that generate that error report so that it doesn't "kill" your console log (what you've printed with printf). This is shown on the snippet above, which shows the start of defaultHandler, and where I suggest you remove the red line to keep one screen of the DS untouched. Note, too, that in order to have this report ever generated, you'll need defaultExceptionHandler() invoked by your main function -- the soonest possible, the best.


La première chose, c'est de savoir où le programme s'est crashé. la valeur qui suit "pc:" correspond à l'adresse fautive dans notre programme. Le plus souvent, ce qui gène le CPU, c'est un accès vers une zone mémoire non-définie (le "data abort"), et l'adresse de cette zone-mémoire est indiquée après "addr:".

La technique la plus rapide consiste à appeler arm-eabi-addr2line -e mybrew.arm9.elf 0x2001156 (merci Thoduv). Quand ça ne suffit pas, j'ajoute "-C" pour le code en C++, ou je reprends mes vieux fichiers .map et je désassemble le code pour y voir plus clair (cf la suite).

Histoire de progresser un peu, je vais passer faire un tour dans le fichier arm9/build/.map qui a été généré automatiquement lors de la compilation de mon programme et qui indique où se trouve quelle fonction/objet pour le CPU.

Petite recherche sur "2001156". Pas de résultat. Evidemment. Par contre, en cherchant juste "2001", je tombe rapidement sur les infos suivantes:

               0x02000bb8                _ZN10SpriteAnimC2Ej
.text          0x02000d00      0x970 SpriteSet.o
     0x02000d10                _ZN9SpriteSet6setOAMEtP12sSpriteEntry
     0x02000fe4                _ZN9SpriteSet17createDefaultPageEv
     0x02000e34                _ZN9SpriteSet8SaveBackEv
            0x0200107c                _ZN9SpriteSet6unpackEPhj
      0x020012c0                _ZN9SpriteSet4LoadEPc
     0x020015f8                _ZN9SpriteSet15createEmptyPageEv
     0x02000f60                _ZN9SpriteSet7getdataEPht
.text          0x02001670      0x1e8 Wifindows.o
      0x02001788                _ZN4Wifi17create_wfc_windowEP6Wind

1. Notre erreur se trouve quelque part dans le fichier SpriteSet.o (vu qu'il démarre à une adresse inférieure au crash, et que l'unité suivante Wifindows.o commence elle trop loin).
2. la fonction SpriteSet::unpack est la seule qui pourrait contenir l'adresse fautive.
   

Bon. On peut maintenant tenter d'aller un peu plus loin en désassemblant le fameux SpriteSet.o, en utilisant "arm-eabi-objdump -drS arm9/build/SpriteSet.o | less". On obtient là un mélange plus ou moins utile de ligne de langage machine et de code C/C++ dans lequel on va chercher l'instruction numéro 456 (0x2001156-0x2000d000=0x456).

 memcpy(palette_target,fptr,pal_hdr.ncols*sizeof(u16));
fptr+=pal_hdr.ncols*sizeof(u16);
iprintf("%i colors loaded\n",pal_hdr.ncols);

44e:   0074            lsls    r4, r6, #1      ;; Log. Shift Left Short (r4:=r6*2)
450:   4651            mov     r1, sl          ;; r1:=r10 -- 'this' (sl='stack limit')
452:   9003            str     r0, [sp, #12]
454:   1c22            adds    r2, r4, #0      ;; r2==0x2c==22*2 
456:   6848            ldr     r0, [r1, #4]
458:   1c29            adds    r1, r5, #0
45a:   f7ff fffe       bl      0 
               45a: R_ARM_THM_CALL     memcpy
45e:   1c31            adds    r1, r6, #0
460:   484f            ldr     r0, [pc, #316]  (5a0 <.text+0x5a0>)  462:   192f            adds    r7, r5, r4
464:   f7ff fffe       bl      0 

Pourquoi s'être acharné jusqu'ici, me demanderez-vous ? parce qu'avec ce code désassemblé, on va pouvoir tenter de retrouver le rôle de chaque registre au moment du crash. Lors d'un appel (à memcpy ou à iprintf, par exemple), les arguments seront placés dans r0,r1,r2 ... Je me sers évidemment aussi un peu de ce que je sais des données ... il y a 22 couleurs dans ma palettes, je retrouve "r6: 0x16", ça colle : le registre r6 contient le nombre de couleurs dans la palette avant le crash, et aurait dû être passé comme argument à iprintf un peu plus tard.


Evidemment, c'est le genre de petit jeu qui demande pas mal de connaissance de la machine. Et pour le processeur ARM, j'ai encore pas mal de lacunes ... Mais c'est le genre de trucs que j'adore apprendre, alors dès que j'aurais un peu de papier devant moi, j'irai m'imprimer un le jeu d'instructions du processeur, histoire d'être mieux ARMé pour la suite (ouarf.) et je crois que je vais quand-même refaire quelques "print toto" par-ci par-là pour y voir plus clair ^_^.

oh, pour info, le registre "lr" contient généralement l'instruction ayant fait appel à la fonction en cours ... des fois qu'une erreur dans une bibliothèque vous laisserait dans le vague...

edit: Une petite discussion bien utile avec Bamba, François et Gaël m'a permis de me rendre compte que tout ça, c'était la faute à un pointeur 'this' (r10) non-initialisé avant l'appel de ma fonction SpriteSet::unpack(). Comme quoi, j'ai encore du boulot à faire avant d'être fiable en C++ :P
Read more!