Edit report at https://bugs.php.net/bug.php?id=63760&edit=1
ID: 63760 Comment by: kraft at web-consulting dot at Reported by: lennartvdd at gmail dot com Summary: microtime(true) profiling is unreliable Status: Open Type: Bug Package: Date/time related Operating System: Windows Server 2008 R2 PHP Version: 5.3.19 Block user comment: N Private report: N New Comment: Maybe the problem ist task swapping. Altough the measured instruction was a sleep(2.5 seconds) it could be that before or after the sleep a task swap took place and another application with higher priority got executed. At least you are in a multi tasking environment and you can't expect your application to show real-time behaviour. Altough extending a 2.5seconds loop to almost 45 seconds looks strange. On my work laptop which is MacBook Black running Ubuntu your script yields the following output: PHP Version: 5.3.10-1ubuntu3.5 0. Sleep: 2500000 us. Measured: 2.5002579689026 s. 1. Sleep: 2500000 us. Measured: 2.5001587867737 s. 2. Sleep: 2500000 us. Measured: 2.5001730918884 s. 3. Sleep: 2500000 us. Measured: 2.5001239776611 s. 4. Sleep: 2500000 us. Measured: 2.5001139640808 s. 5. Sleep: 2500000 us. Measured: 2.5001068115234 s. 6. Sleep: 2500000 us. Measured: 2.5001077651978 s. 7. Sleep: 2500000 us. Measured: 2.5002279281616 s. 8. Sleep: 2500000 us. Measured: 2.5001499652863 s. 9. Sleep: 2500000 us. Measured: 2.5002629756927 s. 10. Sleep: 2500000 us. Measured: 2.5001599788666 s. 11. Sleep: 2500000 us. Measured: 2.5001139640808 s. 12. Sleep: 2500000 us. Measured: 2.5001239776611 s. 13. Sleep: 2500000 us. Measured: 2.5001049041748 s. 14. Sleep: 2500000 us. Measured: 2.5001349449158 s. 15. Sleep: 2500000 us. Measured: 2.5001358985901 s. 16. Sleep: 2500000 us. Measured: 2.5001120567322 s. 17. Sleep: 2500000 us. Measured: 2.5002059936523 s. 18. Sleep: 2500000 us. Measured: 2.5001180171967 s. 19. Sleep: 2500000 us. Measured: 2.5001227855682 s. 20. Sleep: 2500000 us. Measured: 2.5001170635223 s. 21. Sleep: 2500000 us. Measured: 2.5001339912415 s. 22. Sleep: 2500000 us. Measured: 2.5001168251038 s. 23. Sleep: 2500000 us. Measured: 2.500118970871 s. 24. Sleep: 2500000 us. Measured: 2.5001111030579 s. I assume it has to do with some Windows issue! greetings, Bernhard Previous Comments: ------------------------------------------------------------------------ [2012-12-13 16:07:33] lennartvdd at gmail dot com 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 this bug report at https://bugs.php.net/bug.php?id=63760&edit=1