php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login

go to bug id or search bugs for

Bug #63760 microtime(true) profiling is unreliable
Submitted: 2012-12-13 16:07 UTC Modified: 2013-03-11 20:51 UTC
From: lennartvdd at gmail dot com Assigned:
Status: Duplicate Package: Date/time related
PHP Version: 5.3.19 OS: Windows Server 2008 R2
Private report: No CVE-ID: None
View Add Comment Developer Edit
Anyone can comment on a bug. Have a simpler test case? Does it work for you on a different platform? Let us know!
Just going to say 'Me too!'? Don't clutter the database with that please !
Your email address:
MUST BE VALID
Solve the problem:
31 - 12 = ?
Subscribe to this entry?

 
 [2012-12-13 16:07 UTC] 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)

-------

Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2013-01-28 08:30 UTC] kraft at web-consulting dot at 
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
 [2013-03-11 20:46 UTC] sixd@php.net 
You might be interested in bug #64370
 [2013-03-11 20:51 UTC] pajoye@php.net
-Status: Open +Status: Duplicate
 [2013-03-11 20:51 UTC] pajoye@php.net 
dup  of #64370
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved. 		Last updated: Thu Apr 25 17:01:29 2024 UTC