blog · git · desktop · images · contact & privacy · gopher

---

time(1) und Kindprozesse

2020-08-29

Ich habe ein Skript auf einem Server laufen lassen. Es hat diverse andere Prozesse geforkt und dann auf deren Ende gewartet. Ich war dabei, diese Skript zu optimieren, und wollte dann schauen, ob meine Optimierungen tatsächlich greifen. Also habe ich das Offensichtliche getan:

$ time my_script

Die Zahlen sahen plausibel aus. Dann kam mir die Frage: Warte mal, mein Skript macht doch gar nichts. Es startet ein paar andere Prozesse und hockt dann nur noch da, bis die fertig sind. Wieso zeigt time so hohe Zahlen für mein Skript an?

Stellt sich raus, dass die Ausgabe von time zumindest für naive Menschen wie mich etwas irreführend sein kann.

Auf meinem Server wurde übrigens zufällig das echte /usr/bin/time verwendet, also habe ich mir keine Shell-Builtins angeschaut, auch wenn die vermutlich identisch funktionieren.

Der Syscall times(2)

In der GNU-Implementierung von time gibt es (natürlich) mehrere ifdefs. Eines davon nimmt an, dass das Betriebssystem nur ein einfaches wait() kennt: Das wartet auf das Ende irgendeines Kinds. Das ist in dem Fall natürlich der vorher gestartete Prozess, also hier my_script.

wait() erzählt einem aber nur etwas über den Exit-Status des Kindes. Wie kommen wir also an dessen Ausführungszeiten? Zumal wait() den Prozess aus seinem Zombie-Status befreit, dann ist er weg und wir können nichts anderes mehr damit machen.

Man muss das Betriebssystem dann nach den Ausführungszeiten für den aktuellen Prozess fragen, also time selbst. Geht mit times():

times() stores the current process times in the struct tms that
buf points to.  The struct tms is as defined in <sys/times.h>:

struct tms {
    clock_t tms_utime;  /* user time */
    clock_t tms_stime;  /* system time */
    clock_t tms_cutime; /* user time of children */
    clock_t tms_cstime; /* system time of children */
};

Da haben wir’s, tms_cutime und tms_cstime erzählen uns die Ausführungszeiten des Kindes.

Beantwortet noch nicht meine ursprüngliche Frage, aber das ist ein paar Zeilen darunter erklärt:

The  tms_cutime  field  contains  the  sum of the tms_utime and
tms_cutime values for all waited-for terminated children.   The
tms_cstime   field  contains  the  sum  of  the  tms_stime  and
tms_cstime values for all waited-for terminated children.

Sprich, tms_cutime ist nicht nur die „user time“ des Kinds, sondern eigentlich seine „user time“ plus „user time aller Kindeskinder“. Das ist vermutlich transitiv, also bekommt man so die Zeiten des ganzen Prozessbaums.

Mit anderen Worten: time hat hier gar keine Möglichkeit, die Ausführungszeiten von my_script und die der Kinder auseinanderzuhalten.

wait3() und wait4()

Die GNU-Implementierung hat dann noch einen anderen Codepfad für den Fall, dass einer dieser beiden Syscalls vorhanden ist (eigentlich nur wait3(), aber auf meinem System benutzt das dann auch wait4()). Das tut das, worauf ich ursprünglich spekulierte:

pid_t wait3(int *wstatus, int options, struct rusage *rusage);

If  rusage  is  not  NULL, the struct rusage to which it points
will be filled with accounting  information  about  the  child.
See getrusage(2) for details.

Man kann wahrscheinlich davon ausgehen, dass das ebenfalls transitiv bzw. rekursiv arbeitet und man die Zeiten des ganzen Prozessbaums erhält.

Diese Variante ist dann deutlich flexibler, vor allem, wenn man mit mehreren Kindern zu tun hat.

Die ursprüngliche Verwirrung

Mein erster (naiver) Versuch, herauszufinden, was da los ist, sah so aus:

#!/bin/bash

for (( i = 0; i < 10000000; i++ ))
do
    true
done &
killpid=$!

sleep 1
kill $killpid

Und das Ergebnis:

$ /usr/bin/time ./a.sh 
0.00user 0.00system 0:01.00elapsed 0%CPU (0avgtext+0avgdata 3852maxresident)k
0inputs+0outputs (0major+371minor)pagefaults 0swaps

Ups, alles null.

Naja, mit dem Wissen von oben ist das trivial. Da ist kein wait.

Die ganze Sache mit wait vs. kein wait habe ich erst nach einem kleinen Moment bemerkt. Ich mein’, in der Theorie könnte das Betriebssystem ja durchaus immer die Ausführungszeiten der Kinder im Elternprozess sichtbar machen, auch ohne wait. In meinem Kopf war wait nur ein Call, um dem Betriebssystem zu sagen, dass man auf das Prozessende warten möchte – dass es auch Auswirkungen auf Ressourcenstatistiken hat, war mir nicht klar.

Und, naja, ich bin noch nicht sicher, ob es überhaupt so völlig offensichtlich ist, die Zeiten der Kinder zu inkludieren. Was, wenn ich nur die Zeit von my_script messen will, also wirklich nur meinen Prozess? Um zu sehen, wieviel Overhead der erzeugt? Das scheint „von außen“ gar nicht zu gehen und muss wohl in my_script direkt gemacht werden, aber ich lasse mich da gerne eines besseren belehren.

Thread zu diesem Blogpost auf nixers.net.

Comments?