Warum protokolliert strace nicht alle meine Systemanrufe?

Question

Ich versuche eine serielle Verbindung auf einem BeagleBone zu debuggen, auf dem Debian 8.7 läuft. Dazu habe ich ein Testprogramm in go geschrieben. Ich habe die Ergebnisse, die ich erwartet hatte, nicht bekommen, also habe ich mich strikt auf das Testprogramm gefeuert.

Sicher genug, die Systemaufrufe, die ich erwartet hatte, waren nicht da. Ich habe meinen Quellcode überprüft und sie sollten definitiv da sein. Das Testprogramm ist im Wesentlichen diese:

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 

Das Programm erzeugt eine Ausgabe auf stderr, die wie folgt aussieht:

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... 

beobachtete ich dann, dass nicht alle Schreibvorgänge auf stderr wurden in der Strace Ausgabe erscheinen. Es würde Runs der ersten Log-Nachricht ohne die Sekunde geben, was mit dem obigen Algorithmus nicht passieren kann. Hier ist ein Auszug der Ausgabe, gefiltert durch grepping trace.log zum Schreiben. Wie Sie sehen können, gibt es weit weniger Strace-Einträge als Zeilen in stderr, was darauf hinweist, dass strace nicht alle Systemaufrufe protokolliert, die tatsächlich ausgeführt werden.

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 

Es gibt keine Parallelität in meiner Quelle oder einen der Go-Bibliotheken ich verwende, gibt es kein Forking von untergeordneten Prozessen.

Ich habe die strace man-Seite überprüft und es scheint keine Möglichkeit zu geben, statistische Stichproben von Systemaufrufen zu spezifizieren und keine Anzeige, dass nicht alle protokolliert werden, außer Sie einen Filterausdruck angeben t).

Ich habe keine Ahnung, ob die Schreibsystemaufrufe, die auf die seriellen Anschlüsse gerichtet sind, tatsächlich stattfinden, aber im Moment kann ich der strace-Ausgabe nicht vertrauen, weil sie mir nicht alle Systemaufrufe anzeigt, die ich kenne .

Kann jemand erklären, was vor sich geht?

Meine Befehlszeile ist:

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

Update: ein Freund schlug ein Flag -f Zugabe, die zu helfen schien. Was nicht klar ist, warum, da die Dokumentation schlägt vor, -f ist nur nützlich in Gegenwart von Aufrufen zu fork() und es gibt keine von denen in meinem Programm (oder tatsächlich, in der Strace-Ausgabe).

Ok, so bezieht sich die Manpage auch auf clone() und Linux-Threads werden mit clone() erstellt. go verwendet Linux-Threads, das erklärt das Problem.

Answer 1

Das kommt auf die Tatsache, dass Golang liberal Verwendung von Threads und so müssen Sie strace -f Flag verwenden, um die sekundären Threads verfolgen, die in Ihrem Namen erstellt hat.

Also, die strace -f Flag für Kindprozesse erforderlich durch den fork() Systemaufruf erstellt und auch für von clone() erstellt Threads [und auch vfork()]. Mein Fehler war zu glauben, dass es nur für Kinderprozesse benötigt wurde.