From: lennartvdd at gmail dot com
Operating system: Windows Server 2008 R2
PHP version: 5.3.19
Package: Date/time related
Bug Type: Bug
Bug description:microtime(true) profiling is unreliable
Description:
------------
Script executing timing (profiling) using microtime(true) can produce
unexpected
and very inaccurate results (perhaps only on windows, haven't tested on
*nix)
An often used method for execution time profiling is to substract the
result of
microtime(true) ($start) before execution of a code block from the result
of
microtime(true) ($end) after exection of the code block.
$end - $start sometimes produces values that are close to a minute, when
actual
code execution time is only a few seconds.
Note that this server is in a domain environment, so this issue could be
related
to clock drift caused by synchronization with the Domain Controller. I am
however not sure of this because I don't know the exact inner working of
this
method, and since I
haven't been able to find a viable alternative for microtime(true), in my
opinion
it was still worth submitting this issue as a bug.
Test script:
---------------
<?php
echo "PHP Version: " . phpversion() . PHP_EOL;
$iterations = 25;
for($i = 0; $i < $iterations; $i++)
{
// Sleep for 2.5 s
$sleeptime = 2500000;
$time_start = microtime(true);
echo $i . ". Sleep: " . $sleeptime . " us. ";
usleep($sleeptime);
$time = microtime(true) - $time_start;
echo "Measured: $time s.".PHP_EOL;
}
?>
Expected result:
----------------
On every iteration:
[iteration no]. Sleep: 2500000 us. Measured: [a value very close to 2.5] s.
Actual result:
--------------
C:\php-5.3.19-Win32-VC9-x86>php c:\scripts\test.php
PHP Version: 5.3.19
0. Sleep: 2500000 us. Measured: 2.5308179855347 s.
1. Sleep: 2500000 us. Measured: 2.5100009441376 s.
2. Sleep: 2500000 us. Measured: 2.5092051029205 s.
3. Sleep: 2500000 us. Measured: 2.5104570388794 s.
4. Sleep: 2500000 us. Measured: 2.555615901947 s.
5. Sleep: 2500000 us. Measured: 2.5104122161865 s.
6. Sleep: 2500000 us. Measured: 2.5099401473999 s.
7. Sleep: 2500000 us. Measured: 2.5175790786743 s.
8. Sleep: 2500000 us. Measured: 2.5002219676971 s.
9. Sleep: 2500000 us. Measured: 2.5104150772095 s.
10. Sleep: 2500000 us. Measured: 2.5105049610138 s.
11. Sleep: 2500000 us. Measured: 2.5094060897827 s.
12. Sleep: 2500000 us. Measured: 2.5106818675995 s.
13. Sleep: 2500000 us. Measured: 2.510064125061 s.
14. Sleep: 2500000 us. Measured: 2.5104229450226 s.
15. Sleep: 2500000 us. Measured: 2.5097119808197 s.
16. Sleep: 2500000 us. Measured: 45.459776878357 s.
17. Sleep: 2500000 us. Measured: 2.5101070404053 s.
18. Sleep: 2500000 us. Measured: 2.5096528530121 s.
19. Sleep: 2500000 us. Measured: 2.5101320743561 s.
20. Sleep: 2500000 us. Measured: 2.510097026825 s.
21. Sleep: 2500000 us. Measured: 2.5106229782104 s.
22. Sleep: 2500000 us. Measured: 2.5097360610962 s.
23. Sleep: 2500000 us. Measured: 2.5255708694458 s.
24. Sleep: 2500000 us. Measured: 2.5107710361481 s.
-------
C:\php-5.3.19-nts-Win32-VC9-x86>php c:\scripts\test.php
PHP Version: 5.3.19
0. Sleep: 2500000 us. Measured: 2.5030770301819 s.
1. Sleep: 2500000 us. Measured: 2.5102460384369 s.
2. Sleep: 2500000 us. Measured: 2.5099611282349 s.
3. Sleep: 2500000 us. Measured: 2.5090620517731 s.
4. Sleep: 2500000 us. Measured: 2.5101220607758 s.
5. Sleep: 2500000 us. Measured: 2.509134054184 s.
6. Sleep: 2500000 us. Measured: 2.5101330280304 s.
7. Sleep: 2500000 us. Measured: 2.510134935379 s.
8. Sleep: 2500000 us. Measured: 2.510153055191 s.
9. Sleep: 2500000 us. Measured: 2.5335099697113 s.
10. Sleep: 2500000 us. Measured: 2.4988961219788 s.
11. Sleep: 2500000 us. Measured: 2.5346119403839 s.
12. Sleep: 2500000 us. Measured: 2.5179290771484 s.
13. Sleep: 2500000 us. Measured: 2.5092740058899 s.
14. Sleep: 2500000 us. Measured: 2.5102789402008 s.
15. Sleep: 2500000 us. Measured: 45.460343122482 s.
16. Sleep: 2500000 us. Measured: 2.5100581645966 s.
17. Sleep: 2500000 us. Measured: 2.5105128288269 s.
18. Sleep: 2500000 us. Measured: 2.5105159282684 s.
19. Sleep: 2500000 us. Measured: 2.5099229812622 s.
20. Sleep: 2500000 us. Measured: 2.7429389953613 s.
21. Sleep: 2500000 us. Measured: 2.5088560581207 s.
22. Sleep: 2500000 us. Measured: 2.5094420909882 s.
23. Sleep: 2500000 us. Measured: 2.5213050842285 s.
24. Sleep: 2500000 us. Measured: 2.5118818283081 s.
Note iteration marked with no. 16. in the first result (ts version)
The timing on my watch, server and in my mind sayd it took only 2.5 s but
PHP
seems to think the sleep took longer.
Same behaviour on the nts version (iteration no. 15)
-------
--
Edit bug report at https://bugs.php.net/bug.php?id=63760&edit=1
--
Try a snapshot (PHP 5.4):
https://bugs.php.net/fix.php?id=63760&r=trysnapshot54
Try a snapshot (PHP 5.3):
https://bugs.php.net/fix.php?id=63760&r=trysnapshot53
Try a snapshot (trunk):
https://bugs.php.net/fix.php?id=63760&r=trysnapshottrunk
Fixed in SVN: https://bugs.php.net/fix.php?id=63760&r=fixed
Fixed in release: https://bugs.php.net/fix.php?id=63760&r=alreadyfixed
Need backtrace: https://bugs.php.net/fix.php?id=63760&r=needtrace
Need Reproduce Script: https://bugs.php.net/fix.php?id=63760&r=needscript
Try newer version: https://bugs.php.net/fix.php?id=63760&r=oldversion
Not developer issue: https://bugs.php.net/fix.php?id=63760&r=support
Expected behavior: https://bugs.php.net/fix.php?id=63760&r=notwrong
Not enough info:
https://bugs.php.net/fix.php?id=63760&r=notenoughinfo
Submitted twice:
https://bugs.php.net/fix.php?id=63760&r=submittedtwice
register_globals: https://bugs.php.net/fix.php?id=63760&r=globals
PHP 4 support discontinued: https://bugs.php.net/fix.php?id=63760&r=php4
Daylight Savings: https://bugs.php.net/fix.php?id=63760&r=dst
IIS Stability: https://bugs.php.net/fix.php?id=63760&r=isapi
Install GNU Sed: https://bugs.php.net/fix.php?id=63760&r=gnused
Floating point limitations: https://bugs.php.net/fix.php?id=63760&r=float
No Zend Extensions: https://bugs.php.net/fix.php?id=63760&r=nozend
MySQL Configuration Error: https://bugs.php.net/fix.php?id=63760&r=mysqlcfg
