libFAT : hide and fseek ...

Well, initially I thought that the performance issue of TCP transfers would be worth another investigation-novel-styled post, but being somewhere between Christmas and New Year's Eve didn't allowed me to do so. Or maybe just digesting the source code of libfat, figuring out what kind of access pattern made it so slow and what more subtle access pattern was making my new cache policy go wrong was already demanding enough.

The patch is not ready for inclusion in libfat according to devkitpro's standards. Yet, having a look at it is the only way for you to have an idea of what can be changed to fix the performance issue.

The core idea of this patch is to allow pages in the cache to reflect only partially what is (should be) on disk. The new readable field gives the position in the page where we leave 'valid' data and enter uncharted, here-be-dragons, area which content shouldn't be relied upon. I proceeded with additional extensive checks (64M movies transfers, md5 checksum verification and fsck on the media card) and fixed one last bug affecting end of files. The patch released on Tuesday is thus invalidated.

Remember, kids: FAT is the worst filesystem ever.

Oh, and btw, server.pl, the PC-side data source for a PC-to-DS wifi transfer can now be invoked so that it will cycle within a list of files, allowing one to efficitently transfer the files one after the other, e.g. :

server.pl neoflash/*.nds [DS_IP_ADDR [PC_IP_ADDR]]

libFAT cache-cache

Après avoir instrumenté un brin le gestionnaire de cache de la libFAT, j'ai droit à une belle série de statistiques qui montrent que pour réécrire ~400K sur ma carte mémoire, il me faut au préalable lire à peu près autant (968 secteurs) ... En fait, puisque j'écris chaque paquet (~550 bytes) au fur et à mesure dans le fichier, et puisque le cache travaille par "page" de 4K, toutes les écritures sont partielles et le cache lit d'abord le contenu du disque avant de commencer à écrire la bonne valeur). Le hic, c'est bien sûr que dans mon cas, les anciennes données ne seront jamais utiles, puisque je les écraserai toutes :-P

J'essaie donc de modifier "cache.c" pour forcer une politique de "lecture paresseuse" où l'on ne remplirait une entrée du cache avec le contenu du disque que si une tentative de lecture a lieu. Il est donc possible de "préparer" progressivement un contenu à écrire et ne l'écrire qu'une fois complété. Bon, maintenant, il va falloir débugguer ça. A moi desmume, ddd et strace ...

Tout semble fonctionner sur émulateur, mais sur la DS "Phat" de ma fée, j'ai juste droit à un "FATinit failed" ... qui s'avère être dû à un petit problème de DLDI sur SuperCard SD. Après quelques hexdump et diff supplémentaires, je peux enfin vous proposer ma libfat revue et corrigée, jusqu'à 3 fois plus rapide sur les écritures de fichier.

PS: il restait un bug, donc voyez le post du 31 pour la version définitive.

Speed Limit: 32

Now, that's fairly annoying. It looks like the TCP WiFi transfers with the "devkitpro r32" is roughly 3 times slowlier than its r21 counterpart (in purple) for the same receiving code. That's especially annoying since it significantly increase the duration of a self-upgrade cycle during development.

The new performance (in black, as reported by wireshark) is impaired by regular "waits" of ~200ms before the PC retransmits some data. And I'm doing the test with a local server here. A larger RTT would likely reduce the performance even more. Retransmissions happen form the start, and that's fairly normal for a wireless transmission. I ran some early code comparison between the ARM9 TCP code of the two dswifi versions, but I couldn't spot any major change that could explain this behaviour.

J'ai finalement suffisament rafistolé runMe pour qu'il puisse de nouveau faire sa mise à jour automatique -- la clé de voûte de mon cycle de développement sur DS. Je pouvais déjà jouer à redémarrer sous Moonshell, puis passer dans le menu R4, utiliser le vieux runMe "21" pour télécharger le nouveau tryMe "32", retourner à Moonshell puis au menu R4 pour démarrer le programme tryMe. Pas extraordinaire. Problème: les transfers par WiFi sont devenus nettement plus lents. Jusqu'à 3x plus lents si j'en crois mes captures wireshark (ci dessus, runme-21 en mauve, runme-32 en noir).

Pourtant, à en croire le code de TCP dans libdswifi9, rien n'a changé ... ou presque. Rien en tout cas qui puisse expliquer ces pauses de 200ms récurrentes dans le deuxième scénario. J'investigue un peu plus grâce au zoom infini de WireShark pour découvrir que la DS annonce juste avant cette pause une fenêtre de réception de plus en plus petite, qui finit par atteindre une taille nulle. Et ça, en langage TCP, c'est le signe que le récepteur ne suit plus: les buffers saturent.

One intriguing thing is that, somewhat prior one of these long wait is that the receiver's window size is reduced from 1400 bytes to 1127, then 591 and finally 55 bytes ... It will then remain with a 0 receiver window for a few packets and then move back to 1400. In TCP language, this is an indication that the receiver struggles to process the received data on time. But the code that invokes "recv()" hasn't changed either ... that sounds like a problem coming from the "write-to-filesystem" side of the program ... from the libFAT.

It looks like libFAT has received more substantial changes, especially regarding the cache management. I used runMe's "receive to memory" mode, which is limitted in file size, but still operated at the usual peak speed. If a sequence number graph doesn't talk to you, the performance monitor just on the right should. The first "bridge" bar is the transfer to disk, the second "tower" bar is the transfer to memory. I haven't figured how to fix that yet, but at least I am in position to say that TCP is clear of charges.

Puisque le code qui transfère les données de dswifi à libfat n'a pas changé d'un iota, le problème est plus que probablement dans la libfat, qui a subi des modifications relativement importantes -- notamment au niveau de la gestion de son cache. Et vu que les données arrivent par le réseau à une taille qui n'est pas la taille "naturelle" pour écrire sur disque, un petit défaut dans la libFAT pourrait facilement avoir un effet conséquent sur les performances. Dernier petit test pour me convaincre de continuer dans cette direction : un transfer Wifi en mémoire (et non pas vers un fichier), fonctionalité un peu désuète de runMe mais qui tombe à pic ici. Résultat sans appel: on retrouve la vitesse à laquelle runMe m'avait habitué.

C'est donc un dswifi blanchi qui quitte la garde à vue tandis que je m'apprète à jouer une âpre partie de cache-cache avec le gros lard louche connu sous le nom de libFAT.

* Merry Christmas *

Joyeux Noël. je vous invite à prendre livraison des sources du jeu de l'année 2010 : Apple Assault.

Merry Christmas, everyone. I managed to clean up and comment the source code for Apple Assault, which you're now welcome to download. See you in 2011 ^_^

* Merry Christmas *

Pendant que Bilou et Bouli se font une bataille de boules de neige, je vous invite à prendre livraison des sources du jeu de l'année 2010 : Apple Assault.

Merry Christmas, everyone. Bilou and Bouli are currently having a relaxing snowball battle on planet 2412.0 ... Meanwhile, I managed to clean up and comment the source code for Apple Assault, which you're now welcome to download. See you in 2011 ^_^

PS: les p'tits graphismes de Bilou et Bouli viennent d'un vieux PCX datant de ... hooouuuu ... 1999 ? Je voulais faire un Worms avec des boules de neige ;)

So long, exec.cpp

Since August 2007 the exec.cpp file from GrizzlyAdams has been a corner stone of my activities on the Nintendo DS. It allowed me to launch NDS files from other NDS files -- a functionality that was missing of the "standard" features of libnds by then. Combined with dswifi and a small HTTP retriever, it allowed me to introduce a "self-update" feature that replaced the media card mounting/unmounting that was previously taking most of my development time. Since I mostly work on my DS project on lunch time or in the evening, it had a major impact on my ability to keep going on.
En août 2007, mes projets sur DS ont pris un grand tournant avec l'ajout d'un morceau de code de DsChannel de GrizzlyAdams, qui permettait d'enchaîner un NDS vers un autre. Combiné à un petit code HTTP, je devenais capable d'écrire des programmes se mettant à jour eux-même. Et il n'y a pas à dire, celà a nettement boosté le travail sur le Sprite Editor, le Level Editor, la lecture de modules et plus tard, le moteur de jeu à la base d'Apple Assault ...

But here we are, 3 years later, at devkitArm revision 32, with all the libraries changed. The handling of FIFO code, among other things, received a major revision, that breaks the compatibility with the custom loader. Meanwhile, too, Wintermute included a similar feature in HBMenu and made several part of the libnds dependent of its own approach. Reseting the ARM7 on request from the ARM9, for instance, is directly located in fifosystem.c, and a C++ exception will try to return to the launcher of a program. Rather than fighting against this, I decided to try and see to what extent the bare bones of "HBmenu" can be converted to support runME.

Mais voilà. Ce code utilisait le FIFO -- pratiquement inutilisé du temps du devkitArm 21 -- qui entretemps a subit une refonte importante, et Wintermute et ses accolytes ont cherché à intégrer une fonction similaire dans la libnds. L'astuce, en fait, c'est que la fonction n'est pas directement offerte aux programmes, mais intégrée dans HBmenu, qui laisse une partie de son code à un emplacement "persistant" qui (si je comprends bien) est uniquement capable de revenir au programme qui a installé ce programme persistant. Plutôt que de me battre à essayer de faire cohabiter le code de GrizzlyAdams dans le nouvel environnement, j'ai donc repris la base de HBMenu pour reconstruire runMe par-dessus. Ca marche plutôt bien, dirait-on, même si je n'ai pas encore fini le portage ... mais curieusement, ça me fait un peu chose de laisser tomber cet "exec.cpp" qui m'a soutenu tout ce temps ...

The result is encouraging, although I've got a small tear in my eye for that piece of software that I analysed and debugged to make it fully support DLDI ... Although the code from the devkitpro project shares many similarities with "my" previous approach, a larger part of the stub executes from the ARM7 (as far as I understood), meaning that it's not possible to perform debugging for it. The new code consists of

• nds_loader_arm9.c, acting as a library and directly linked to your program (runme or HBMenu), that mainly ensure software reset of the two processors and DLDI patching of the loader
• bootstub.bin, installed from the end of the ARM9 memory (the upper 48K of the 4MB area) by installBootStub() function in the "library" file
• loader.bin, copied in VRAM by runNdsFile(). It contains its own (stripped-down) FAT access, the DLDI patcher.

PS: loader.bin and bootstub.bin are thus by-products of HBMenu compilation. To get them, you need to gather the latest sources from SVN, compile them (make all is enough provided that you have devkitpro installed with the appropriate libraries), and find them in the hbmenu/data directory.

Debugging sessions darker than night

Beyond Infinity, a fellow OS hobby developer back in 2002 used to twist Gandalf's quote into "I see debugging sessions coming, darker than night itself" ... I guess that could apply to the last week. After identifying the reason why DDD wasn't operating properly (not showing machine code) anymore and quickly applying a patch, I started investigating the internals of desmume's gdb stub ... the part of the emulator that allows one to perform source-level debugging as if it was a locally running program. With zeromus, we identified a couple of curious things in the emulator-debugger communication, and although we don't agree yet on how it should best be fixed, I managed to patch the emulator as well so that it behave the way I need.

J'aimais bien être développeur d'OS sur mega-tokyo. Une chose sympa avec les développeurs d'OS, c'est que comme on en prend tous pour 20 ans, on apprend à se connaître, à construire ensemble, etc. "Beyond Infinity" était l'un de ceux-là, geek de première dans sa manière de détourner les 'quotes' des grands films et livres. C'est à lui que je dois le parallèle entre les "jours plus sombres que la nuit elle-même" du Seigneur des Anneaux et ces scéances obscures de debugging ou plus rien ne semble marcher comme il se doit au point qu'on finit par débugguer la machine virtuelle et/ou le débuggueur lui-même.

D'une certaine manière, voilà qui colle parfaitement à mes activités homebrew de la semaine dernière ... Et après avoir surmonté des lignes de code sans nombre, triomphant de bugs inouïs, de haute lutte j'ai frayé mon chemin jusqu'au stub par-delà localhost:9999 pour reprendre la condition de course qui s'était infiltrée. Vouaip. Et du coup, je suis enfin en mesure de chercher pourquoi certains décors ne s'affichent pas dans Apple Assault sous "dkp-r32". Vous vous tenez bien les côtes ?

Bon, bin voilà: le comportement de fread() a changé. Il n'est désormais plus possible de transférer des données directement entre un fichier et la VRAM si la position dans le fichier n'est pas un multiple de 4. Quand on sait que la VRAM ne peut pas être adressée par bytes (mais uniquement par mot de 16 ou 32 bits) et qu'on a désassemblé quelques memcpy dans sa vie, on se dit "bon sang, mais c'est bien sûr" ... mais on a quand-même passé des heures dessus >_<

I am thus (at last) in position to think about why some of the background in AppleAssault don't show up anymore. It looks like something has changed either in newlib or in libfat that altered the way non-aligned memory transfers are handled by fread(). The problem is I regularly transfer tiles data straight from the file into the VRAM, but that the VRAM only support 16-bit or 32-bit wide writes. It is typical for a memcpy implementation to fall back to byte-per-byte copies as soon as a mis-alignment condition is detected, but in this case, it kills the whole transfer. I need to patch some pictures so that they have an even number of colours.


Là-dessus, maintenant que mon code est revenu à un état plus rassurant, il va falloir que je réattaque vaisselle et ménage ... Ma fée a beau avoir une patience d'ange, 'y'a des choses qui ne se font pas toutes seules.

cd /home/kitchen
make mrproper
/etc/init.d/dishwasher reload
cat /tmp/laundry > /dev/drier

It works ! I can't believe it !! ...

Wo, dudes. It sure has been an odd week at work, but it was even weirder after office hours when I tried to figure out what prevented Apple Assault to work... I wish I had actually typed "svn copy trunk branch/dkp-r32" before I started "fixing" the code for the new release of devkitarm.

After spending hours contemplating fifosystem.c and other hours digging into the source of DesMuME, I found no heroïc bug to fix, gained more confidence in the new tools and finally figured out that some of the assumptions I was working with (e.g. "thou shall call irqInit() before you invoke swiWaitForVBlank") were no longer true in the latest release ... and actually weren't true anymore for a while.

Migrating to the new libnds requires you to switch to the new everything ... including the latest desmume where the way to support "emulated filesystem" had changed. After I inserted a fake register whose content is dumped immediately on both ARM processors (I'm pretty sure there is similar features already, but it's faster to redo it than to locate it :P), I got capable of tracking the execution of the program ... Another modification enabled register dump after haltemu was called, which "explained" that the emulator shutdown was due to a new policy for handling not only exit(), but also abort() -- and C++ exceptions, which I had used in a tweaked way with the "devkitarm-21-based" setup I used so far.

The good news is that I now have Apple Assault running -- in a degraded mode, but running. And I have plenty of developer-friendly stuff added to my emulator to help me fix (hopefully) quickly the remaining things... It was about time : I nearly got discouraged yesterday.

Vous avez vu ? j'ai réussi à réavoir de l'Apple Assault qui s'affiche. C'est pas encore complètement rétabli, mais ça remarche de nouveau. Tout le reste, vous l'avez déjà lu dans les posts précédents :P

edit: I even managed to get sound running, although TrackSequences aren't working yet (missing the get-current-position ? no : curpos() do not rely on FIFO : it's just shared memory ... Or maybe I should ensure the oops[] array is accessed through un-cached addresses it looks to work fine the way it is, but it constantly compares against "pos == 0" ... ) That means the "trunk" is now definitely for "devkitpro-r32" (whatever it means) and that the devkitpro-r21 old things are archived once for all in tags/apple-assault-release.

SYSTEM POWERED OFF VIA ARM7 SPI POWER DEVICE

sauf erreur de ma part, je parviens maintenant à avoir le code de runme qui tourne sur desmume (version 0.9.6-SVN) quand il est compilé avec en mode "dkp-r32". Par contre, si j'essaie d'utiliser les même outils pour AppleAssault, j'ai droit à un magnifique "SYSTEM POWERED OFF VIA ARM7 SPI POWER DEVICE". Je soupçonne desmume de couper froidement toute communication avec GDB quand ça se produit, ce qui, du coup, m'empêche d'en chercher la cause >_<

IPC9@201564a send FIFO < 0x480A725C -- size 000 (l 0x8505, tail 00) (r 0x8501, tail 05)
-- IRQ delivering.
IPC7@37ff16a recv FIFO > 0x480A725C -- size 000 (l 0x8401, tail 05) (r 0x8504, tail 01)
IPC9@201564a send FIFO < 0x04010040 -- size 000 (l 0x8505, tail 01) (r 0x8501, tail 08)
-- IRQ delivering.
IPC7@37ff16a recv FIFO > 0x04010040 -- size 000 (l 0x8401, tail 08) (r 0x8504, tail 02)

Evidemment, la version "standard" de desmume (0.9.5, livrée par Ubuntu), elle, coince à l'initialisation du Wifi, et ça ne vaut donc même pas la peine de continuer à chercher. Je vais donc devoir aller ajouter l'équivalent-émulateur d'un gurumediation dans le code de emu_halt(), voire y ajouter un DEBUG_dumpMemory() ...

I think I can now get runMe running under desmume when it is compiled with my 'dkp-r32' install. If do try to use the same tools for AppleAssault, I end up with an error message suggesting ARM7 powered off sometihng. I bet the emulator doesn't try to talk to GDB any further when that occurs. Let's see if I manage to get more information by adding something helping guru meditation in emu_halt() ... and later a 'magic' fake register that allows me to track evolution.

After exploration, it turns out that something is calling `abort()` before my exception catch-and-report code could kick in. And abort() may shut power down. All this occurs because I forgot command line argument --gbaslot-rom to let DLDI code access files.

Après modification, et si j'en crois mon nouvel outil, c'est au niveau de libnds_exit.c que le processeur ARM9 s'est arrèté, juste après un appel à powerOn, qui aurait été appelé quelque part à partir de fifosystem.c (dans la fonction waitBlock, ce qui me paraît on ne peut plus louche ...) Le processeur ARM7, lui, s'est bloqué au niveau de writePowerManagement appelé depuis powerValueHandler. Ca, au moins, c'est cohérent. Le dernier message transmis de l'ARM9 vers l'ARM7 est (poétiquement) un 0x04010040, ce que je peux décoder en:

• 0xxx.xxxx : Channel 0 : power management
• x4xx.xxxx : Immediate value (type=4)
• xxx1.xxxx : PM_REQ_ON
• xxxx.0040 : PM_SYSTEM_PWR (?...)

Ma foi, ça me semble être tout à fait la situation découlant d'un appel à systemShutdown, dernière opération de __libnds_exit() lorsque le "retour à hbmenu" a échoué :P Bref, heureusement, je m'étais donné un "faux registre" 0x04042000 pour envoyer des mots de 32 bits hors de l'émulateur ... ce qui m'amène à la conclusion que mon interception des exceptions C++ s'est fait court-circuiter par un appel "abort()" qui a ordonné la fin du programme ... grr. ... et derrière tout ça, l'oubli de --gbaslot-rom, désormais indispensable pour EFS sous desmume >_<.