Codage et paresse, un exemple d'économie d'effort contre-productive.

Note liminaire Aïe ! Je me suis fait mordre par un bogue, qui pour une fois n'était pas de mon fait. Pas le genre bogue enragé, mais qui (in)visible comme le nez au milieu de la figure ne s'est pas fait remarquer immédiatement. Je dévisage rarement avec insistance l'appendice nasal de mes interlocuteurs...  Mais, d'ailleurs, peut-on dévisager un nez ?

Mise en scène

Bref. Je résume la situation. Une séquence de code (la création d'un processus) tout ce qu'il y a de plus banal dont on cherche à mesurer la durée. Un appel à gettimeofday au début, un autre à la fin. Une petite différence entre temps relevé à la fin et temps relevé au début, et hop.

Oui mais le temps résultant est négatif (très négatif!).  Ah, vous m'étonnez fort ! Auriez-vous inventé un programme à remonter le temps ?

Jetons un coup d’œil !

#include  <stdlib.h> #include  <stdio.h> int main (int argc, char **argv) {         struct timeval t0, t1;         pid_t pid;         gettimeofday(&t0, NULL);         pid = fork();         if (pid == 0) {                 return 0;         }         gettimeofday(&t1, NULL);         wait();         printf("temps: %ld µsec\n",         ((t1.tv_sec - t0.tv_sec) *1000000L) +          (t1.tv_usec - t0.tv_usec));         return 0; }

D'accord, codage minimaliste. Pas de test des codes retours, mais bon, soyons joueur !

Que donne la compilation ?

fa $ gcc lazzy_wb.c -o lazzy_wb fa $

Super, ça compile sans erreur et sans warning. D'accord, quitte à être paresseux autant l'être aussi sur la commande de compilation.

Voyons l'exécution...

fa $ ./lazzy_wb temps: -970715068 µsec fa $

Ah, effectivement, nous voilà rajeunis d'environ 970 secondes.

Est-ce qu'on peut dire "le temps passe vite", quand il passe en marche arrière? 

Investiguons

Je vous la joue courte, sinon, Jérôme, va me dire "tout ça pour ça". :-)

Vous inspectez avec toute votre concentration le code, vérifiez le calcul de la différence. Rien, pas de loup caché ici. Un coup de strace et de ltrace pour vérifier si les appels systèmes se passent correctement. Toujours rien en vue, pas de frémissement dans ma synapse.

Allez, l'arme fatale ! Roulements de tambour: gdb.

Point d'arrêt après le deuxième "gettimeofday", vérification des valeurs de t0 et de t1.
Ben elles sont correctes.
Panne sèche...

Pfiouh les 970 secondes gagnées il y a peu sont en train de s'évaporer dans le présent / futur à vitesse grand V!

Et puis d'un coup d'un seul ! Le nez, là, au milieu de la figure ! Eh, oh! Y'a pas de nez!

Un petit coup de RTFM, man wait....

Ah, ben tiens, wait prend un paramètre, intempestivement  passé aux oubliettes dans notre code.

Essayons pour voir!

fa $ sed -i -e '/wait(/s/wait(/&NULL/' lazzy_wb.c fa $ gcc lazzy_wb.c -o lazzy_wb fa $ ./lazzy_wb 35 µsec fa $

Pardon ? Passer "NULL" comme paramètre à wait suffit à corriger notre problème?

Analyse

wait, s'il reçoit un paramètre non NULL, le considère comme un pointeur sur entier et copie dans l'entier ainsi pointé la valeur de retour du processus fils décédé. Dans notre cas, 0. Ce que confirme gdb après le wait le champ t1.tv_sec est bien écrasé à 0. D'où une différence de temps négative.

Un coup d’œil à l'assembleur

Sans le paramètre     movl      $0, 4(%esp)     leal        40(%esp), %eax     movl      %eax, (%esp)     call        gettimeofday     movl      %eax, 24(%esp)     call        wait

Avec le paramètre     movl       $0, 4(%esp)     leal         40(%esp), %eax     movl       %eax, (%esp)     call         gettimeofday     movl       %eax, 24(%esp)     movl       $0, (%esp)     call         wait

Quand on invoque wait avec NULL, on empile effectivement une valeur nulle sur la pile comme paramètre de wait. Sans paramètre, on ne fait, rien... et wait qui croit qu'on a mis une valeur en pile, va utiliser ce qui se trouve en sommet de pile... et pas de chance, c'est le dernier paramètre poussé sur la pile par le compilateur... à savoir l'adresse de t1. Bingo!

Morale(s)

•  Ne pas passer de paramètre n'est pas équivalent à passer un paramètre NULL. Ma fainéantise naturelle me susurre que c'est bien dommage. 
• Une compilation avec -Wall nous aurait indiqué que les prototypes de fork, wait et gettimeofday n'étaient pas définis.
• Après ajout des directives d'inclusion idoines, nous aurions eu le message suivant  error: too few arguments to function ‘wait’

Bilan

2 à 3 minutes épargnées à ne pas effectuer les inclusions appropriées.
10 minutes perdues à 2 pour identifier et corriger.

Plus une heure pour écrire ce billet, et je ne compte pas le temps que vous venez de perdre à le lire.
Tout ça pour ça!
Désolé!