php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Request #79030 Upgrade apache2handler's php_apache_sapi_get_request_time to return usec
Submitted: 2019-12-25 06:56 UTC Modified: 2020-06-24 08:02 UTC
From: herbert at groot dot jebbink dot nl Assigned:
Status: Closed Package: *General Issues
PHP Version: 7.4.1 OS: ChromeOS / Crostini / Debian 10
Private report: No CVE-ID: None
 [2019-12-25 06:56 UTC] herbert at groot dot jebbink dot nl
Description:
------------
Sometimes the $_SERVER['REQUEST_TIME_FLOAT'] and microtime(TRUE) combination gives strange results.

Below example gives about 1 in 10 times a negative result.

Test script:
---------------
<?php

  $script1 = microtime(TRUE);
  $script2 = file_get_contents('http://localhost/script2.php');

  echo $script2 - $script1;
   
?>

<?php

  echo $_SERVER['REQUEST_TIME_FLOAT'];
   
?>

Expected result:
----------------
0.00038409233093262

Actual result:
--------------
-0.00039100646972656

Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2019-12-25 09:12 UTC] requinix@php.net
-Status: Open +Status: Not a bug
 [2019-12-25 09:12 UTC] requinix@php.net
Those two are backed by gettimeofday(2), which is not suitable for measuring time intervals to sub-millisecond precision.
 [2019-12-26 06:00 UTC] herbert at groot dot jebbink dot nl
gettimeofday(2) may not be accurate at sub-millisecond level, but with 2 sequential calls the last one will not be lower then the first one.

I think it is caused by the fact that $_SERVER['REQUEST_TIME_FLOAT'] is rounded to milliseconds and microtime(TRUE) is not.
 [2019-12-26 08:23 UTC] requinix@php.net
REQUEST_TIME_FLOAT is not rounded.

To make sure, what SAPI are you using for the web side? One can define its own means of determining the request time, and if it does not then PHP falls back to gettimeofday.

https://github.com/php/php-src/blob/PHP-7.4.1/main/SAPI.c#L1083
 [2019-12-27 03:26 UTC] herbert at groot dot jebbink dot nl
The SAPI is apache2handler, that one gives indeed msec als precision.

https://github.com/php/php-src/blob/PHP-7.4.1/sapi/apache2handler/sapi_apache2.c#L360

It seems dat usec is also available 

http://apr.apache.org/docs/apr/1.5/group__apr__time.html
 [2019-12-27 03:45 UTC] bugreports at gmail dot com
> The SAPI is apache2handler, that one gives indeed msec als precision.
> It seems usec is also available

apache2handler on all of my setups is using usec

this is a microtime(TRUE) based runtime measurement from a custom header
0.0245 / 0.0152

the first number is based on $_SERVER['REQUEST_TIME_FLOAT']
the second one is based on microtime(TRUE) as first codeline

--------------------

$cms_stop_microtime = microtime(TRUE);
$runtime_total = round(($cms_stop_microtime - $_SERVER['REQUEST_TIME_FLOAT']), 4);
$tuntime_cms = round(($cms_stop_microtime - $cms_startup_microtime), 4);

--------------------

this configures a additional http header which is also usec
Header set "X-Response-Time" "%D us"

X-Response-Time: D=25726 us
 [2019-12-27 04:01 UTC] requinix@php.net
-Summary: $_SERVER['REQUEST_TIME_FLOAT'] and microtime(TRUE) combination problem +Summary: Upgrade apache2handler's php_apache_sapi_get_request_time to return usec -Status: Not a bug +Status: Re-Opened -Type: Bug +Type: Feature/Change Request
 [2019-12-27 04:01 UTC] requinix@php.net
> The SAPI is apache2handler, that one gives indeed msec als precision.
> https://github.com/php/php-src/blob/PHP-7.4.1/sapi/apache2handler/sapi_apache2.c#L360
Also https://apr.apache.org/docs/apr/1.7/group__apr__time.html which shows the time from apr_time_as_msec is truncated to milliseconds.
 [2019-12-27 05:32 UTC] herbert at groot dot jebbink dot nl
> apache2handler on all of my setups is using usec

not for REQUEST_TIME_FLOAT, the 2 numbers you give are both based on $cms_stop_microtime, filled with 'microtime(TRUE)', not coming from the sapi module.

with phpinfo(); you can see that the fraction part of REQUEST_TIME_FLOAT is 3 digits, not 6 digits.
 [2020-05-28 06:08 UTC] herbert at groot dot jebbink dot nl
What can I do to get this request into 8.0 ?
 [2020-06-24 06:23 UTC] herbert at groot dot jebbink dot nl
I have it localy working by changing line 369 of file php-src/sapi/apache2handler/sapi_apache2.c (PHP 8 master branch at github)

return ((double) apr_time_as_msec(ctx->r->request_time)) / 1000.0;

into

return ((double) ctx->r->request_time) / 1000000.0;

and now there is never a negative result anymore in the test script as given in my original post at the top of this page.

also $_SERVER['REQUEST_TIME_FLOAT'] & microtime(true) have now the same precision.

echo $_SERVER['REQUEST_TIME_FLOAT'];
echo '<br>';
echo microtime(true);

It would be great if someone can include this in the PHP 8 branch, or can I send the git diff patch to someone?
 [2020-06-24 08:02 UTC] herbert at groot dot jebbink dot nl
-Status: Re-Opened +Status: Closed
 [2020-06-24 08:02 UTC] herbert at groot dot jebbink dot nl
Pull request with the change was accepted for the PHP 8 branch at github
 [2020-06-24 12:43 UTC] nikic@php.net
Automatic comment on behalf of herbert@groot.jebbink.nl
Revision: http://git.php.net/?p=php-src.git;a=commit;h=4a26628b292b7735d1d220509eab1155346ddc6e
Log: Fixed bug #79030 Use usec from apache request time
 
PHP Copyright © 2001-2020 The PHP Group
All rights reserved.
Last updated: Mon Jul 06 22:01:03 2020 UTC