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 Developer Edit
Welcome back! If you're the original bug submitter, here's where you can edit the bug or add additional notes.
If you forgot your password, you can retrieve your password here.
Password:
Status:
Package:
Bug Type:
Summary:
From: lennartvdd at gmail dot com
New email:
PHP Version: OS:

 

 [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

Pull Requests

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: Sat Nov 23 10:01:28 2024 UTC