Wer hat an der Uhr gedreht?

Sebastian Bergmann |

Wenn PHPUnit mit der Ausführung einer Testsuite fertig ist, werden Informationen über die benötigte Zeit sowie den benutzten Arbeitsspeicher ausgegeben:

Time: 00:02.204, Memory: 26.00 MB

Wie misst PHPUnit die benötigte Zeit? Wo kommen die 2 Sekunden und 204 Millisekunden im oben gezeigten Beispiel her?

Stundenglas

In der Vergangenheit hat PHPUnit, genauer gesagt die verwendete Komponente phpunit/php-timer hat, zu dem Zeitpunkt, an dem die oben gezeigte Ausgabe erzeugt wird, microtime(true) aufgerufen.

microtime(true) liefert die Anzahl der Sekunden seit der Unix-Epoche mit Mikrosekunden-Granularität. Da PHP die superglobale Variable $_SERVER['REQUEST_TIME_FLOAT'] auf die Anzahl der Sekunden seit der Unix-Epoche mit Mikrosekunden-Granularität zu Beginn der Skriptausführung setzt, kann mit microtime(true) - $_SERVER['REQUEST_TIME_FLOAT'] die seit dem Beginn der Skriptausführung verstrichene Zeit berechnet werden.

Im Laufe der Jahre gab es immer wieder Fehlerberichte, dass PHPUnit am Ende der Ausführung die verstrichene Zeit nicht oder nicht korrekt anzeigt. Häufig wurde hierbei von PHP die folgende Fehlermeldung ausgegeben:

`PHP Notice: Undefined index: REQUEST_TIME_FLOAT`

Der Code der von phpunit/php-timer versucht auf die Variable $_SERVER['REQUEST_TIME_FLOAT'] zuzugreifen. Da diese jedoch nicht gesetzt ist, kommt es zu dem oben gezeigten Fehler.

Nur weil $_SERVER['REQUEST_TIME_FLOAT'] von PHP zu Beginn der Skriptausführung automatisch gesetzt wird, bedeutet nicht, dass sie nicht variabel ist. Nichts hindert den von PHPUnit ausgeführten Testcode oder den von diesem ausgeführten Produktionscode daran, die Variable mithilfe von unset($_SERVER['REQUEST_TIME_FLOAT']); zu löschen.

Wenn eine Anweisung wie unset($_SERVER['REQUEST_TIME_FLOAT']); für den Test wirklich notwendig ist, so kann man diesen Test mit @backupGlobals enabled annotieren. Diese Annotation weist PHPUnit an, vor der Ausführung dieses Tests eine Kopie aller globalen und superglobalen Variablen anzulegen, um diese nach der Ausführung des Tests wieder auf ihre ursprünglichen Werte setzen zu können.

Vor einiger Zeit habe ich den Code von phpunit/php-timer dahingehend geändert, dass eine Ausnahme ausgelöst wird, wenn $_SERVER['REQUEST_TIME_FLOAT'] nicht gesetzt ist. Das löst natürlich das eigentliche Problem nicht, ist aber zumindest sauberer, als die PHP-Notice, die vorher ausgelöst wurde. Fortan gab es natürlich Fehlerberichte darüber, dass PHPUnit am Ende der Ausführung diese Ausnahme auslöst.

In letzter Zeit gab es Fehlerberichte, deren Ursache darin liegt, dass $_SERVER['REQUEST_TIME_FLOAT'] keinen Wert vom Typ float enthält. Der von PHPUnit ausgeführte Testcode oder der von diesem ausgeführte Produktionscode setzt also $_SERVER['REQUEST_TIME_FLOAT'] auf einen ungültigen Wert. Also habe ich den Code von phpunit/php-timer erweitert, eine Ausnahme auszulösen, wenn $_SERVER['REQUEST_TIME_FLOAT'] einen Wert enthält, der nicht vom Typ float ist.

Aber was passiert, wenn Test- oder Produktionscode $_SERVER['REQUEST_TIME_FLOAT'] auf einen Wert setzen, der zwar den richtigen Typ (float) hat, aber mit der aktuellen Zeit nichts zu tun hat? phpunit/php-timer kann eine solche Situation nicht erkennen und wird die verstrichene Zeit falsch berechnen. Dasselbe gilt, wenn Test- oder Produktionscode die Systemzeit tatsächlich ändern.

Es war an der Zeit, einzusehen, dass "auf die Uhr schauen", insbesondere über eine superglobale Variable wie $_SERVER['REQUEST_TIME_FLOAT'], die verändert werden kann, keine gute Idee ist. Das gilt übrigens nicht nur für die Ausgabe der verstrichenen Zeit am Ende der Testausführung, sondern auch für die Messung, wie lange die Ausführung eines einzelnen Tests gedauert hat, die beispielsweise in der TestDox-Ausgabe oder in XML-Logfiles berichtet wird.

Wenn wir also $_SERVER['REQUEST_TIME_FLOAT'] und microtime() nicht trauen können, wie sollen wir dann die Zeit messen? Die Antwort lautet: hrtime().


Hier ist ein Auszug aus unserem eBook "PHP 7 Explained", in dem unter anderem die in PHP 7.3 eingeführte Funktion hrtime() behandelt wird.


hrtime() wurde in PHP 7.3 eingeführt. Die aktuelle Version von PHPUnit setzt PHP 7.3 voraus: perfekt! Ich darf hrtime() verwenden.

Das heute veröffentlichte PHPUnit 9.2 nutzt die von Grund auf neu geschriebene Komponente phpunit/php-timer in Version 4.0. PHPUnit benutzt nun weder $_SERVER['REQUEST_TIME_FLOAT'] noch microtime(). Stattdessen wird einmal hrtime() aufgerufen, wenn der CLI Testrunner startet. Am Ende wird dann nochmal hrtime() aufgerufen. Die Differenz der beiden Rückgabewerte von hrtime() ist die Zeit, die am Ende der Testausführung ausgegeben wird. Vor und nach jedem Test wird hrtime() aufgerufen, die Differenz dieser beiden Rückgabewerte von hrtime() ist die Dauer des jeweiligen Tests.