phpunix-timestampmicrotime

Why does PHP's microtime() sometimes go backwards?


Have a strange issue where PHP's microtime() sometimes goes back in time when doing http requests. And it's not a "floating point error" either, it can be as much as 0.8 seconds seconds backwards!

I have this reproduce code (PS I'm the owner of the domain and the webserver):

<?php

declare(strict_types=1);
error_reporting(E_ALL);
set_error_handler(function ($errno, $errstr, $errfile, $errline) {
    throw new ErrorException($errstr, 0, $errno, $errfile, $errline);
});
function DoStuff()
{
    $ch = curl_init();
    curl_setopt_array($ch, array(
        CURLOPT_URL => 'http://x2.ratma.net/',
        CURLOPT_RETURNTRANSFER => true,
    ));
    $data = curl_exec($ch);
    curl_close($ch);
}
$attempts_before_going_backwards = 0;
for (;;) {
    $t1 = microtime(true);
    DoStuff();
    $t2 = microtime(true);
    $t = $t2 - $t1;
    $str = number_format($t, 3, '.', '');
    if (str_contains($str, '-')) {
        var_dump([
            "WTF",
            "attempts_before_going_backwards" => $attempts_before_going_backwards,
            "t" => $t,
            "t_100" => number_format($t, 100, '.', ''),
            "str" => $str,
            "t1" => $t1,
            "t1_100" => number_format($t1, 100, '.', ''),
            "t2" => $t2,
            "t2_100" => number_format($t2, 100, '.', ''),
        ]);
        die();
    }
    ++$attempts_before_going_backwards;
}

And when it runs long enough, eventually something like this happens:

$ time php repro2.php 
array(9) {
  [0]=>
  string(3) "WTF"
  ["attempts_before_going_backwards"]=>
  int(126)
  ["t"]=>
  float(-0.7924120426177979)
  ["t_100"]=>
  string(103) "-0.7924120426177978515625000000000000000000000000000000000000000000000000000000000000000000000000000000"
  ["str"]=>
  string(6) "-0.792"
  ["t1"]=>
  float(1736293804.892522)
  ["t1_100"]=>
  string(111) "1736293804.8925220966339111328125000000000000000000000000000000000000000000000000000000000000000000000000000000"
  ["t2"]=>
  float(1736293804.10011)
  ["t2_100"]=>
  string(111) "1736293804.1001100540161132812500000000000000000000000000000000000000000000000000000000000000000000000000000000"
}

real    0m29.164s
user    0m0.025s
sys 0m0.041s

In this example, microtime() somehow went 0.792 seconds back in time after 126 attempts.

How is that possible?

Environment:

Btw seems someone observed similar behavior on NetBSD in 2002: https://mail-index.netbsd.org/port-i386/2002/07/31/0002.html


Solution

  • microtime reports the system time. The system time is subject to change at any time, either explicitly by an administrator or automatically for clock synchronization (with an NTP server, for instance, or for leap second adjustments). You can therefore never rely on the system clock to measure durations -- at least not at low resolution.

    Instead, use a monotonic clock. In PHP, one is provided by hrtime.

    $t1 = hrtime(true);
    DoStuff();
    $t2 = hrtime(true);
    
    $deltaNanos = $t2 - $t1;
    $deltaSeconds = $deltaNanos / 1e9;