blog · git · desktop · images · contact

time(1) und CPU-Taktänderungen

2021-07-14

Das hier ist nicht neu, aber mir ist es erst heute wirklich klar geworden. Ja, bin langsam.

Ich mache oft sowas:

$ time -p some_long_running_command

Und dann schaue ich mir das user-Feld an, um herauszufinden, wieviel „CPU-Time im Userspace“ der Befehl gebraucht hat.

Ein Beispiel:

$ time -p echo 'scale=4000; a(1)*4' | bc -l >/dev/null
real 8.37
user 8.36
sys 0.00

Das berechnet Pi auf ein paar tausend Stellen. Laut time(1) hat die CPU dafür 8.36 Sekunden gebraucht und in der Realität („Wallclock“) sind dafür 8.37 Sekunden verstrichen. sys ist Null, also verbrachte der Prozess quasi keine Zeit im Kernel. Okay.

Etwas mehr Kontext: Wir benutzen auf der Arbeit Config-Management und ich wollte wissen, wie lange es dauert, die Configs für eine bestimmte Maschine zu berechnen. Das wollte ich als täglichen Cronjob einrichten und dann diese Daten sammeln und zeitlich als Graphen darstellen. Das Ziel war, herauszufinden, ob wir irgendwann Unsinn machen und unser Code langsam wird. Mit anderen Worten, das sollte komplett im Hintergrund laufen, unabhängig davon, was sonst noch auf der Kiste passiert. Ich wollte wissen, wieviel „Arbeit“ die CPU verrichten muss, um die Config zu berechnen. Wenn unser Code nicht optimal ist, muss die CPU mehr „Arbeit“ verrichten und verschwendet damit Zeit.

Benutzen wir das obige bc mal als Ersatz für meinen eigentlichen Task. Es ist einfach etwas, das etwas berechnet. Gut.

Dann schauen wir uns mal an, was passiert, wenn ich im Hintergrund ein paar while true; do true; done laufen lasse – das soll einfach irgendeine Form von Hintergrundlast erzeugen. Ich hatte immer erwartet, dass sich dadurch der Wert von user nicht ändert, weil user die CPU-Zeit meines Prozesses sein soll. Egal, was sonst also passiert, der Wert sollte etwa gleich bleiben. real darf sich ruhig erhöhen, spielt für mich in diesem Fall aber eh keine Rolle.

Zu meiner Überraschung geschah das:

$ time -p echo 'scale=4000; a(1)*4' | bc -l >/dev/null
real 11.75
user 11.55
sys 0.00

real hat sich erhöht, aber user auch. Warum?

Nach ein bisschen Stochern im Nebel habe ich begriffen, dass die dynamischen Taktänderungen der CPU der Grund sind.

Wenn ich watch -n 0.1 grep MHz /proc/cpuinfo in einem anderen Terminal laufen lasse, sehe ich, dass meine CPU (Intel i7-8665U) im Idle bei 2.1 GHz läuft. Ab und zu auch niedriger. Sobald ich bc starte, springt das auf 4.3 GHz auf einem Kern hoch. Belasse ich es dabei, dann ist bc nach etwa 8.5 Sekunden fertig.

Mit all den while true; do true; done im Hintergrund schafft die CPU aber nicht dauerhaft 4.3 GHz. Sie bleibt dann bei ungefähr 3.3 GHz. Das entspricht einem Abfall von ungefähr 25%, was auch so ganz grob dem Anstieg der user-Zeit entspricht.

Jenachdem, was auf der Maschine sonst noch los ist, schafft die CPU vielleicht sogar nur 2.3 GHz auf allen Kernen. Das ist … nicht so viel.

CPU-Zeit vs. CPU-Zyklen

Das Kernproblem ist, dass im user-Feld von time(1) die Zeit auf der CPU genannt wird. Das ist aber gar nicht das, was ich wissen wollte. Was ich wissen wollte:

Was time(1) mir sagt, ist aber:

Kleiner, aber feiner Unterschied.

Durch dieses dynamische CPU-Frequency-Scaling ist es so, als würde man permanent die CPU mit einem anderen Modell ersetzen. Natürlich braucht eine andere CPU, die vielleicht schneller oder langsamer ist, dann auch nicht so lange oder länger, um dieselbe Aufgabe zu erfüllen. Es ist völlig richtig und in Ordnung von time(1), wenn es unterschiedliche Zeiten ausgibt.

Wie misst man denn die „Arbeit“, die die CPU erledigt hat? Da gibt es nicht unbedingt eine einfache Antwort. Eine Idee wäre, die Zahl der Instruktionen (wie mov, cmp und so weiter) zu messen, aber nicht jede Instruktion läuft gleich lange … naja, nicht gleich „lange“ per so, sondern sie brauchen eine unterschiedliche Anzahl an CPU-Zyklen. Und jetzt kommen wir ein Stückchen weiter.

Das hier liefert so ziemlich dasselbe Ergebnis, unabhängig von Hintergrundlast oder CPU-Takt:

$ perf stat -e cycles:u sh -c "echo 'scale=4000; a(1)*4' | bc -l >/dev/null"

 Performance counter stats for 'sh -c ...'

    35,246,938,315      cycles:u             <---- hierum geht’s

       8.395594299 seconds time elapsed

       8.366890000 seconds user
       0.010255000 seconds sys

Gemessen wird die Zahl der CPU-Zyklen im Userspace (daher das :u).

Das ist auch kein vollständiges Bild. Es gibt viele Variablen, so ein Computer besteht ja auch aus mehr als nur der CPU, und deswegen ist die ursprüngliche Idee des Messens der Zeit als kumulativer Metrik gar nicht so falsch gewesen. Wenn man das so macht, muss man nur dafür sorgen, dass die CPU-Frequenz nicht wie verrückt springt (also, ich musste das in meinem Fall machen).

Ein Weg, um sie zu stabilisieren, ist, den „Turbo“-Modus temporär abzuschalten:

cd /sys/devices/system/cpu/
for i in $(seq $(nproc) )
do
    cpuid=$((i - 1))
    sudo sh -c "echo 1900000 >cpu${cpuid}/cpufreq/scaling_max_freq"
done

Das begrenzt meine CPU auf 1.9 GHz. Jetzt passt das Timing. Aber natürlich ist auch alles furchtbar langsam.

Es hängt alles davon ab …

Später habe ich dann gemerkt, dass diese konkrete CPU das Problem besonders deutlich zutagefördert. Es ist ein Laptop. Es ist eine besonders stromsparende CPU, die alles tun will, um die Akkulaufzeit zu maximieren. Und vielleicht ist auch die Kühlung einfach nicht gut genug.

Meine anderen Rechner zeigen das Problem kaum. Mein i7-3770 von 2013 springt auf 3.9 GHz im „Turbo“-Modus und fällt dann vielleicht auf 3.7 GHz runter, wenn es viel Hintergrundlast gibt. Der Celeron N3050 in meinem Intel NUC springt auf 2.1 GHz im „Turbo“ – und bleibt dann einfach da, unabhängig von der Last. Auf diesen beiden Kisten tritt das Problem gar nicht so wirklich auf.

Ist es jetzt falsch, Prozesse mit time(1) zu messen? In meinem konkreten Anwendungsfall war es falsch. Aber es hängt wirklich davon ab, was man wissen will. Man kann es auch so betrachten: Die Tatsache, dass die user-Zeit hochging und die CPU-Frequenz runter, ist eigentlich ein Indiz dafür, dass das vielleicht ein bisschen zu viel Last für diese Maschine ist.

So oder so ist es gut zu wissen, dass die Ausgabe von time(1) nicht unbedingt so „stabil“ ist, wie man vielleicht erwartet.

Anhang

In den Kommentaren auf Hacker News zu diesem Blogpost wird auf diesen Blogpost von Raymond Chen hingewiesen: What should the CPU usage be of a fully-loaded CPU that has been throttled? Tja, gute Frage. :-)

Comments?