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