English version

Gdb

Ou les quelques commandes gdb que j'utilise tout le temps car elles suffisent dans 95% des cas: run, backtrace, frame, print, list, break, watch, continue. Ce qui suit est un scénario réel.

Un problème classique

La synthèse vocale d'Android, pico, est de très bonne qualité, mais quand on la compile et la lance sur une machine 64bits, proutch, elle segfaulte en beauté:

€ pico2wave -w test.wav foo                                      
zsh: segmentation fault  pico2wave -w test.wav foo

Que faire ? Gdb ! Souvent la réponse que donne gdb est très éclairante !

Déjà, il faut recompiler le programme avec l'option -g, et puis éviter les optimisations qui rendent le débuggage souvent pénible, typiquement:

€ CFLAGS="-g -O0" ./configure && make

Attention par contre, parfois utiliser -O0 risque de faire disparaître le bug ! Dans ce cas on est bien obligé de garder les options d'optimisations, mais gdb risque parfois de ne pas pouvoir afficher certaines valeurs.

€ ./pico2wave -w test.wav foo
zsh: segmentation fault  pico2wave -w test.wav foo

Ouf, cela segfaulte toujours. C'est une très bonne chose: c'est systématiquement reproductible !

run, backtrace, frame, print, list

Une astuce bien pratique est d'utiliser l'option --args de gdb, qui permet de rajouter simplement gdb --args devant la commande qu'on vient d'essayer.

€ gdb --args ./pico2wave -w test.wav foo
GNU gdb (GDB) blabla
blablabla
...
(gdb)

gdb est prêt, on tape simplement r (raccourci pour run)

(gdb) r
Starting program: /tmp/svox-1.0+git20100205/pico/.libs/lt-pico2wave -w test.wav foo

Program received signal SIGSEGV, Segmentation fault.
0x00007ffff7711579 in picoos_deallocate (this=0x7ffff7285470, 
    adr=0x7ffff736d100) at lib/picoos.c:579
579	            if (cr->size > 0) {
(gdb)

En voilà une ligne intéressante ! Le segfault ne peut venir que du déréférencement de cr a priori, utilisons p (raccourci pour print) pour voir le contenu de cr:

(gdb) p cr
$1 = (MemCellHdr) 0x8000f736f9d8

Pointeur à la tronche un peu bizarre en effet (d'après /proc/$(pidof pico2wave)/maps), gdb confirme:

(gdb) p *cr
Cannot access memory at address 0x8000f736f9d8

Regardons un peu d'où cela sort à l'aide de bt (raccourci pour backtrace):

(gdb) bt
#0  0x00007ffff7711579 in picoos_deallocate (this=0x7ffff7285470, 
    adr=0x7ffff736d100) at lib/picoos.c:579
#1  0x00007ffff7730462 in sigDeallocate (mm=0x7ffff7285470, 
    sig_inObj=0x7ffff736d090) at lib/picosig2.c:367
#2  0x00007ffff772da10 in sigSubObjDeallocate (this=0x7ffff736ad78, 
    mm=0x7ffff7285470) at lib/picosig.c:238
#3  0x00007ffff76f911f in picodata_disposeProcessingUnit (mm=0x7ffff7285470, 
    this=0x7ffff7286c20) at lib/picodata.c:638
#4  0x00007ffff76f753c in ctrlSubObjDeallocate (this=0x7ffff7286b80, 
    mm=0x7ffff7285470) at lib/picoctrl.c:274
#5  0x00007ffff76f911f in picodata_disposeProcessingUnit (mm=0x7ffff7285470, 
    this=0x7ffff7285448) at lib/picodata.c:638
#6  0x00007ffff76f7c2e in picoctrl_disposeControl (mm=0x7ffff7285470, 
    this=0x7ffff7285448) at lib/picoctrl.c:487
#7  0x00007ffff76f80b5 in picoctrl_disposeEngine (mm=0x7ffff7120030, 
    rm=0x7ffff7120538, this=0x602c60) at lib/picoctrl.c:671
#8  0x00007ffff76effce in pico_disposeEngine (system=0x7ffff7120010, 
    inoutEngine=0x602c60) at lib/picoapi.c:569
#9  0x0000000000401edc in main (argc=4, argv=0x7fffffffdc68)
    at bin/pico2wave.c:319
(gdb)

Hum, c'est pour le moins cryptique. Dans de nombreux cas cr aurait pu être un simple paramètre de notre fonction en cours, et il aurait fallu remonter à l'aide de la commande up à son appelant, et continuer à utiliser des p pour voir d'où cela vient, ce n'est apparemment pas le cas ici, cr n'est pas un paramètre. Regardons autour de notre ligne fâcheuse au sein de la fonction picoos_deallocate (l raccourci pour list):

(gdb) l
574	        this->usedSize -= c->size;
575	
576	        cr = (MemCellHdr)((picoos_objsize_t)c + c->size);
577	        cl = c->leftCell;
578	        if (cl->size > 0) {
579	            if (cr->size > 0) {
580	                crr = (MemCellHdr)((picoos_objsize_t)cr + cr->size);
581	                crr->leftCell = cl;
582	                cl->size = ((cl->size + c->size) + cr->size);
583	                cr->nextFree->prevFree = cr->prevFree;

Hum, ce code enfreint les règles usuelles de programmation, il y a du cast à tout va ! cr vient donc de c + c->size, regardons ceux-ci:

(gdb) p c
$2 = (MemCellHdr) 0x7ffff736f9d8
(gdb) p c->size
$3 = 4294967296

Re-ouille, la valeur de c a l'air raisonnable (on arrive même à la déréférencer), mais la valeur de c->size a l'air complètement incorrecte, c'est d'ailleurs exactement 0x100000000...

Quelques essais à côté

D'où vient cette valeur fantaisiste ? Soit un calcul est faux, soit on a un débordement depuis ailleurs.

Par chance, il y a peu de lignes de code qui donnent une valeur à size, on peut donc rapidement ajouter des printfs à côté de chacune d'entre elles. On n'obtient cependant que des valeurs raisonnables, et jamais 0x100000000, le problème est donc ailleurs... Comment faire ?

valgrind est un spécialiste des débordements de tampons, et d'habitude très efficace pour détecter les erreurs de pointeurs et d'allocation mémoire. Il est cependant inopérant ici: outre des tas de "Conditional jump or move depends on uninitialised value(s)", il termine lui aussi sur cette ligne cr->size sans avoir donné d'indice avant (c'est en fait parce que pico utilise son propre allocateur fait-maison, que valgrind ne peut donc pas débugguer...). Electric-Fence, un outil plus léger de détection de débordement de tampon, est inefficace ici pour la même raison.

break, watch

Il reste la solution watch: en effet, si l'on exécute plusieurs fois le programme avec la distribution aléatoire des adresses désactivée (echo 0 > /proc/sys/kernel/randomize_va_space), on constate que l'adresse de c->size est toujours la même:

(gdb) p &c->size
$1 = (long int *) 0x7ffff736f9d8

Il suffit donc de demander à gdb de s'arrêter quand cette valeur mémoire change. D'abord relancer depuis le début en s'arrêtant au début de la fonction main, avant que les choses tournent mal (b est le raccourci pour breakpoint):

(gdb) b main
Breakpoint 1 at 0x4012ef: file bin/pico2wave.c, line 73.
(gdb) r
The program being debugged has been started already.
Start it from the beginning? (y or n) y

Starting program: /tmp/svox-1.0+git20100205/pico/.libs/lt-pico2wave -w test.wav foo

Breakpoint 1, main (argc=4, argv=0x7fffffffdc58) at bin/pico2wave.c:73
73	    char * wavefile = NULL;

On appelle watch pour indiquer à gdb quelle valeur mémoire surveiller:

(gdb) watch *(long int *) 0x7ffff736f9d8
Hardware watchpoint 2: *(long int *) 0x7ffff736f9d8

Notez bien Hardware ici: on ne fait surveiller qu'un entier en mémoire, gdb a donc pu demander au processeur de faire la surveillance lui-même, ce qui ne coûte rien en performance !

Note: watch permet évidemment aussi d'observer simplement une variable existante (watch mavariable), mais ici on ne sait pas vraiment quand elle commence à exister...

On peut maintenant continuer l'exécution (oui, les valeurs de taille négatives sont "normales"...):

(gdb) c
Continuing.
Hardware watchpoint 2: *(long int *) 0x7ffff736f9d8

Old value = 0
New value = 40120
picoos_allocate (this=0x7ffff7285470, byteSize=1024) at lib/picoos.c:539
539	        c->size = cellSize;
Current language:  auto
The current source language is "auto; currently c".
(gdb) c
Continuing.
Hardware watchpoint 2: *(long int *) 0x7ffff736f9d8

Old value = 40120
New value = 1040
picoos_allocate (this=0x7ffff7285470, byteSize=1024) at lib/picoos.c:540
540	        c2->leftCell = c;
(gdb) c
Continuing.
Hardware watchpoint 4: *(long int *) 0x7ffff736f9d8

Old value = 1040
New value = -1040
picoos_allocate (this=0x7ffff7285470, byteSize=1024) at lib/picoos.c:556
556	    adr = (void *)((picoos_objsize_t)c + this->usedCellHdrSize);
(gdb) c
Continuing.
Hardware watchpoint 4: *(long int *) 0x7ffff736f9d8

Old value = -1040
New value = -4294967296
memset () at ../sysdeps/x86_64/memset.S:954
954	../sysdeps/x86_64/memset.S: Aucun fichier ou dossier de ce type.
	in ../sysdeps/x86_64/memset.S
Current language:  auto
The current source language is "auto; currently asm".

Ah, voilà quelque chose d'intéressant ! Regardons qui fait un memset et ainsi écrase notre champ size:

(gdb) bt
#0  memset () at ../sysdeps/x86_64/memset.S:954
#1  0x00007ffff77151fa in picopal_mem_set (dest=0x7ffff736f63c, byte_val=0 '\000', length=928)
    at lib/picopal.c:258
#2  0x00007ffff7710bfb in picoos_mem_set (dest=0x7ffff736f63c, byte_val=0 '\000', length=928)
    at lib/picoos.c:184
#3  0x00007ffff7730cca in mel_2_lin_lookup (sig_inObj=0x7ffff736d090, scmeanMGC=10) at lib/picosig2.c:572
#4  0x00007ffff772e3d6 in sigProcess (this=0x7ffff736ad78, inReadPos=0, numinb=64, outWritePos=0, 
    numoutb=0x7fffffffd758) at lib/picosig.c:540
#5  0x00007ffff772f2d1 in sigStep (this=0x7ffff736ad78, mode=0, numBytesOutput=0x7fffffffd7da)
    at lib/picosig.c:1104
#6  0x00007ffff76f72ab in ctrlStep (this=0x7ffff736f63c, mode=0, bytesOutput=0x7fffffffd826)
    at lib/picoctrl.c:153
#7  0x00007ffff76f821e in picoctrl_engFetchOutputItemBytes (this=0x7ffff7285428, 
    buffer=0x7fffffffd9a0 "8\365\330\003", bufferSize=128, bytesReceived=0x7fffffffd99c)
    at lib/picoctrl.c:762
#8  0x00007ffff76f012c in pico_getData (engine=0x7ffff7285428, buffer=0x7fffffffd9a0, bufferSize=128, 
    bytesReceived=0x7fffffffd99c, outDataType=0x7fffffffd99a) at lib/picoapi.c:650
#9  0x0000000000401d10 in main (argc=4, argv=0x7fffffffdc58) at bin/pico2wave.c:278

(gdb) p/x 0x7ffff736f63c + 928
$5 = 0x7ffff736f9dc

En faisant faire un petit calcul à gdb, on s'aperçoit qu'il s'en est fallu de très peu pour que notre champ size se fasse écraser par ce memset: juste 4 octets... Ce memset est encapsulé dans des fonctions pour faire joli, il faudrait donc utiliser up plusieurs fois pour remonter à l'appelant qui est dans la fonction mel_2_lin_lookup (3e dans la pile des appels). On peut aller plus rapidement avec frame:

(gdb) frame 3
#3  0x00007ffff7730cca in mel_2_lin_lookup (sig_inObj=0x7ffff736d090, scmeanMGC=10) at lib/picosig2.c:572
572	    picoos_mem_set(XXr + m1, 0, i);
Current language:  auto
The current source language is "auto; currently c".
(gdb) l
567	    XXr[0] = (picoos_int32) ((picoos_single) c1[0] * K1);
568	    for (nI = 1; nI < m1; nI++) {
569	        XXr[nI] = c1[nI] << shift;
570	    }
571	    i = sizeof(picoos_int32) * (PICODSP_FFTSIZE + 1 - m1);
572	    picoos_mem_set(XXr + m1, 0, i);
573	    dfct_nmf(m4, XXr); /* DFCT directly in fixed point */
574	
575	    /* *****************************************************************************************
576	     Linear frequency scale envelope through interpolation.

C'est donc là le fautif, qui déborde chez nous. On a vu plus haut qu'il débordait de 4 octets. Si l'on regarde en détail, le memset efface le tampon XXr depuis l'octet 4*m1 jusqu'à l'octet 4*(PICODSP_FFTSIZE + 1). Est-ce que le +1 n'est pas superflu ?! Si l'on va voir le code qui alloue ce pointeur (en suivant les code source avec les tags, on trouve des définitions successives qui nous amènent à un champ wcep_pI, qui est en fait appelé int_vec28):

    d32 = (picoos_int32 *) picoos_allocate(mm, sizeof(picoos_int32)
            * PICODSP_FFTSIZE);
    if (NULL == d32) {
        sigDeallocate(mm, sig_inObj);
        return PICO_ERR_OTHER;
    }
    sig_inObj->int_vec28 = d32;

Le +1 est effectivement a priori de trop ! Ou alors c'est l'allocation qui n'est pas assez grande ?! Là il faut discuter avec l'auteur, mais en tous cas on a trouvé un fautif clair ! Merci gdb !

Conclusion

Il n'y a en fait pas besoin de connaître beaucoup de commandes dans gdb. La première étape: r, bt, l et p, est en fait suffisante dans la plupart des cas ! Pour la plupart des autres cas, quelques b et watch peuvent aider beaucoup à trouver des bugs. On peut aussi essayer de les combiner avec reverse-continue.

Annexe

Threads

Lorsque l'on débuggue un programme multithreadé, il est utile de pouvoir passer d'un thread à un autre:

(gdb) r
Starting program: /tmp/test 
[Thread debugging using libthread_db enabled]
[New Thread 0x7ffff7861710 (LWP 10981)]
[New Thread 0x7ffff7060710 (LWP 10982)]
^C
Program received signal SIGINT, Interrupt.
0x00007ffff7bcabe5 in pthread_join (threadid=140737346148112, 
    thread_return=0x0) at pthread_join.c:89
89	pthread_join.c: Aucun fichier ou dossier de ce type.
	in pthread_join.c
(gdb) bt
#0  0x00007ffff7bcabe5 in pthread_join (threadid=140737346148112, 
    thread_return=0x0) at pthread_join.c:89
#1  0x00000000004005fd in main ()
(gdb)

On est ici dans le thread main, qui est simplement en train d'attendre les threads qu'il a créés. On va voir la liste des threads:

(gdb) info thread
  3 Thread 0x7ffff7060710 (LWP 10982)  0x00000000004005ac in f ()
  2 Thread 0x7ffff7861710 (LWP 10981)  0x00000000004005ac in f ()
* 1 Thread 0x7ffff7fce700 (LWP 10968)  0x00007ffff7bcabe5 in pthread_join (
    threadid=140737346148112, thread_return=0x0) at pthread_join.c:89
(gdb)

Et on peut passer de l'un à l'autre:

(gdb) thread 2
[Switching to thread 2 (Thread 0x7ffff7861710 (LWP 10981))]#0  0x00000000004005ac in f ()
(gdb) bt
#0  0x00000000004005ac in f ()
#1  0x00007ffff7bc98ba in start_thread (arg=)
    at pthread_create.c:300
#2  0x00007ffff793102d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#3  0x0000000000000000 in ?? ()
(gdb) thread 3
[Switching to thread 3 (Thread 0x7ffff7060710 (LWP 10982))]#0  0x00000000004005ac in f ()
(gdb) bt
#0  0x00000000004005ac in f ()
#1  0x00007ffff7bc98ba in start_thread (arg=)
    at pthread_create.c:300
#2  0x00007ffff793102d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#3  0x0000000000000000 in ?? ()
(gdb) 

On peut aussi utiliser thread apply all pour aller plus vite:


(gdb) thread apply all bt

Thread 3 (Thread 0x7ffff7060710 (LWP 10982)):
#0  0x00000000004005ac in f ()
#1  0x00007ffff7bc98ba in start_thread (arg=)
    at pthread_create.c:300
#2  0x00007ffff793102d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#3  0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7ffff7861710 (LWP 10981)):
#0  0x00000000004005ac in f ()
#1  0x00007ffff7bc98ba in start_thread (arg=)
    at pthread_create.c:300
#2  0x00007ffff793102d in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#3  0x0000000000000000 in ?? ()

Thread 1 (Thread 0x7ffff7fce700 (LWP 10968)):
#0  0x00007ffff7bcabe5 in pthread_join (threadid=140737346148112, 
    thread_return=0x0) at pthread_join.c:89
#1  0x00000000004005fd in main ()
(gdb) 

Heisenbugs

Un Heisenbug est un bug qui disparaît dès qu'on essaie de le débugguer. On a parlé plus haut du problème des options d'optimisation du compilateur. Dans le cas d'un programme multithreadé, il arrive souvent que le simple fait de lancer dans gdb fait disparaître le bug.

Soit le programme crashe, on peut utiliser le core qu'il dépose (utiliser ulimit -c unlimited si le programme n'a pas déposé de core).

$ gdb ./monprog core
...

Et on peut examiner l'ensemble du processus de la même manière que s'il était vivant, on ne peut juste pas reprendre l'exécution.

Soit le programme plante. On peut forcer la création d'un core en utilisant control-\ (c'est comme control-C, sauf que cela crée un core en plus). On peut aussi s'attacher au processus vivant:

$ gdb ./monprog $(pidof monprog)
...

Astuces diverses

Voici quelques trucs que j'utilise souvent


Copyright (c) 2011-2013, 2015-2016 Samuel Thibault

Ce texte est fourni sous la licence Creative Commons Attribution-ShareAlike (V3.0), ainsi que décrite sur http://creativecommons.org/licenses/by-sa/3.0/ et dont le texte complet est disponible sur http://creativecommons.org/licenses/by-sa/3.0/legalcode . Me contacter si la clause ShareAlike pose souci.