Pourquoi strace n'enregistre-t-il pas tous mes appels système ?

Question

J'essaie de déboguer une connexion série sur un BeagleBone fonctionnant sous Debian 8.7. Pour ce faire, j'ai écrit un programme de test en go. Je n'obtenais pas les résultats que j'attendais, alors j'ai lancé strace sur le programme de test.

Bien sûr, les appels système d'écriture que je m'attendais à voir n'étaient pas là. J'ai vérifié mon code source et ils devraient être là. Le programme de test est essentiellement le suivant :

loop:
   write a log message to stderr
   write a buffer of binary 0x00 to the serial port 
   write a different log message to stderr
   write a buffer of binary 0xff to the serial port 

Le programme produit une sortie sur stderr qui ressemble à ceci :

2015/11/12 21:28:45 111...
2015/11/12 21:28:46 000...
2015/11/12 21:28:48 111...
2015/11/12 21:28:49 000...
2015/11/12 21:28:51 111...
2015/11/12 21:28:52 000...
2015/11/12 21:28:54 111...
2015/11/12 21:28:55 000...
2015/11/12 21:28:57 111...
2015/11/12 21:28:58 000...
2015/11/12 21:29:00 111...
2015/11/12 21:29:01 000...
2015/11/12 21:29:03 111...
2015/11/12 21:29:04 000...
2015/11/12 21:29:06 111...
2015/11/12 21:29:07 000...
2015/11/12 21:29:09 111...
2015/11/12 21:29:10 000...
2015/11/12 21:29:12 111...
2015/11/12 21:29:13 000...
2015/11/12 21:29:15 111...
2015/11/12 21:29:16 000...
2015/11/12 21:29:18 111...
2015/11/12 21:29:19 000...
2015/11/12 21:29:21 111...

J'ai ensuite observé que toutes les écritures sur stderr n'apparaissaient pas dans la sortie de strace. Il y avait des passages du premier message de log sans aucun du second, ce qui ne peut pas arriver avec l'algorithme ci-dessus. Voici un extrait de la sortie, filtré en parcourant trace.log pour les écritures. Comme vous pouvez le voir, il y a beaucoup moins d'entrées strace que de lignes dans stderr, ce qui indique que strace n'enregistre pas tous les appels système qui sont réellement effectués.

write(2, "2015/11/12 21:28:46 000...\n", 27) = 27
write(2, "2015/11/12 21:28:49 000...\n", 27) = 27
write(2, "2015/11/12 21:28:52 000...\n", 27) = 27
write(2, "2015/11/12 21:28:55 000...\n", 27) = 27
write(2, "2015/11/12 21:28:58 000...\n", 27) = 27
write(2, "2015/11/12 21:29:01 000...\n", 27) = 27
write(2, "2015/11/12 21:29:04 000...\n", 27) = 27
write(2, "2015/11/12 21:29:07 000...\n", 27) = 27
write(2, "2015/11/12 21:29:12 111...\n", 27) = 27
write(2, "2015/11/12 21:29:15 111...\n", 27) = 27
write(2, "2015/11/12 21:29:18 111...\n", 27) = 27
write(2, "2015/11/12 21:29:21 111...\n", 27) = 27

Il n'y a pas de concurrence dans mes sources ou dans les bibliothèques Go que j'utilise, il n'y a pas de bifurcation des processus enfants.

J'ai vérifié la page de manuel de strace et il ne semble pas y avoir de moyen de spécifier un échantillonnage statistique des appels système et aucune indication qu'il ne les enregistre pas tous à moins que vous ne spécifiez une expression de filtrage (ce que je n'ai pas fait).

Je n'ai aucune idée si les appels système d'écriture dirigés vers les ports série se produisent réellement, mais pour l'instant je ne peux pas faire confiance à la sortie de strace car elle ne me montre pas tous les appels système que je sais être effectués.

Quelqu'un peut-il expliquer ce qui se passe ?

Ma ligne de commande est :

strace -o trace.log -v ./serial-test --device /dev/ttyO2 --oscillator --delay 500

mise à jour Ce qui n'est pas clair, c'est pourquoi, puisque la documentation suggère que -f n'est utile qu'en présence d'appels à fork() et qu'il n'y en a aucun dans mon programme (ou, en fait, dans la sortie de strace).

Ok, donc, la page de manuel fait également référence à clone() et les threads Linux sont créés avec clone(). go utilise les threads Linux, ce qui explique le problème.

Answer 1

Cela vient du fait que golang fait un usage libéral des threads et donc vous devez utiliser strace -f afin de suivre les fils secondaires que go a créés en votre nom.

Donc, le strace -f est requis pour les processus enfants créés par l'option fork() et également pour les threads créés par l'appel système clone() [ et aussi vfork() ]. Mon erreur était de croire qu'il n'était nécessaire que pour les processus enfants.