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
