Bug #42659 [Com]: microtime() loses time in long-running scripts
Edit report at https://bugs.php.net/bug.php?id=42659&edit=1
ID: 42659
Comment by: pv47 at yandex dot ru
Reported by: jdolecek at NetBSD dot org
Summary: microtime() loses time in long-running scripts
Status: No Feedback
Type: Bug
Package: Date/time related
Operating System: win32 only
PHP Version: 5.2.4
Block user comment: N
Private report: N
New Comment:
I have the same issue with php 5.3.6 on Windows 7.
Build Date Mar 17 2011 10:34:15
Compiler MSVC9 (Visual C++ 2008)
Architecture x86
Configure Command cscript /nologo configure.js "--enable-snapshot-build"
"--disable-isapi" "--enable-debug-pack" "--disable-isapi"
"--without-mssql" "--without-pdo-mssql" "--without-pi3web"
"--with-pdo-oci=D:\php-sdk\oracle\instantclient10\sdk,shared"
"--with-oci8=D:\php-sdk\oracle\instantclient10\sdk,shared"
"--with-oci8-11g=D:\php-sdk\oracle\instantclient11\sdk,shared"
"--enable-object-out-dir=../obj/" "--enable-com-dotnet"
"--with-mcrypt=static"
Server API Apache 2.0 Handler
(from bug 52789)> I ran the script for two hours and a half and couldn't reproduce it. Is
this XP only?
I have 1-2 second difference after ~30 min of running my script on Windows 7.
Is this a windows bug?
Previous Comments:
------------------------------------------------------------------------
[2010-09-07 09:34:32] jdolecek at NetBSD dot org
The problem is still there even with PHP 5.3.3:
PHP 5.3.3 (cli) (built: Jul 21 2010 20:36:55)
Copyright (c) 1997-2010 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2010 Zend Technologies
The test runs on physical machine (not a virtual) running Windows XP SP3.
Output after about 21 hours with 5.3.3:
msec: [2010-09-07 09:12:15.7766]
sec : [2010-09-07 09:12:18]
msec: [2010-09-07 09:17:15.7700]
sec : [2010-09-07 09:17:18]
msec: [2010-09-07 09:22:15.7634]
sec : [2010-09-07 09:22:18]
msec: [2010-09-07 09:27:15.7568]
sec : [2010-09-07 09:27:18]
For comparison, here is output from parallelly running PHP 5.2.6:
msec: [2010-09-07 09:19:51.6134]
sec : [2010-09-07 09:19:54]
msec: [2010-09-07 09:24:51.6068]
sec : [2010-09-07 09:24:54]
msec: [2010-09-07 09:29:51.6003]
sec : [2010-09-07 09:29:54]
Both show ~3 sec time difference between microtime() and time()
Unfortunately I can't re-open the PR (it says I can't change the PR to that state), so
just adding a comment.
------------------------------------------------------------------------
[2008-09-03 01:00:01] php-bugs at lists dot php dot net
No feedback was provided for this bug for over a week, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
------------------------------------------------------------------------
[2008-08-26 23:06:36] jani@php.net
Please try using this CVS snapshot:
http://snaps.php.net/php5.3-latest.tar.gz
For Windows (zip):
http://snaps.php.net/win32/php5.3-win32-latest.zip
For Windows (installer):
http://snaps.php.net/win32/php5.3-win32-installer-latest.msi
------------------------------------------------------------------------
[2007-09-13 15:30:05] jdolecek at NetBSD dot org
Description:
------------
When PHP script runs for long time, the value returned by microtime() gradually drifts away from
time(). The exact value depends on system, but we've seen 5 hour difference to current time for
script running about a week, with drift about 1 minute per 5 minutes run (system running under
VMware). The script is daemon-like process, i.e. it's blocked in select() most of time, and
only occassionally wakes up to process request.
Looking at win32/time.c, I spot one problematic spot in that the code might not notice counter
wrap-off if timer happens to be a higher value after wrap-around then the last time the function was
called. However, that shouldn't be normally problem, since the counter wraps-around very
infrequently.
Reproduce code:
---------------
<?php
ini_set('date.timezone', 'CET');
putenv("TZ=CET");
while(true) {
$sec = microtime(true);
echo "msec: ". sprintf("[%s.%04d]",
date("Y-m-d H:i:s", floor($sec)),
(float) ($sec - floor($sec)) * 10000)."\n";
echo "sec : ".date('[Y-m-d H:i:s]')."\n";
sleep(300);
}
C program which demostrates how the two times diverge (cut&paste from win32/time.c, so please
forgive whitespace/style):
#include <windows.h>
#include <winbase.h>
#include <time.h>
#include <winsock2.h>
int getfilesystemtime(struct timeval *time_Info)
{
FILETIME ft;
__int64 ff;
LARGE_INTEGER li;
GetSystemTimeAsFileTime(&ft); /* 100 ns blocks since 01-Jan-1641 */
/* resolution seems to be 0.01 sec */
li.u.LowPart = ft.dwLowDateTime;
li.u.HighPart = ft.dwHighDateTime;
ff = li.QuadPart;
time_Info->tv_sec = (int)(ff/(__int64)10000000-(__int64)11644473600ULL);
time_Info->tv_usec = (int)(ff % 10000000)/10;
return 0;
}
#define PW32G(x) (x)
int
main()
{
LARGE_INTEGER li;
__int64 freq, timer;
double dt;
struct timeval tv, *time_Info = &tv, starttime, tv2;
QueryPerformanceFrequency(&li);
freq = li.QuadPart;
getfilesystemtime(&starttime);
QueryPerformanceCounter(&li);
timer = li.QuadPart;
dt = (double)timer/PW32G(freq);
PW32G(starttime).tv_usec -= (int)((dt-(int)dt)*1000000);
if (PW32G(starttime).tv_usec < 0) {
PW32G(starttime).tv_usec += 1000000;
--PW32G(starttime).tv_sec;
}
PW32G(starttime).tv_sec -= (int)dt;
while(1) {
sleep(10);
QueryPerformanceCounter(&li);
getfilesystemtime(&tv2);
timer = li.QuadPart;
dt = (double)timer/PW32G(freq);
time_Info->tv_sec = PW32G(starttime).tv_sec + (int)dt;
time_Info->tv_usec = PW32G(starttime).tv_usec + (int)((dt-(int)dt)*1000000);
if (time_Info->tv_usec > 1000000) {
time_Info->tv_usec -= 1000000;
++time_Info->tv_sec;
}
printf("%ld.%06ld\n",
tv2.tv_sec - time_Info->tv_sec,
tv2.tv_usec - time_Info->tv_usec);
}
}
Expected result:
----------------
the time on 'msec' line should be same as for 'sec' line. Since the second
date() call fetches time after the microtime() call, the 'sec' line may print time 1
second after the 'msec' line occassionally, but the times should match most of the time.
The C program should print ~constant time difference.
Actual result:
--------------
The longer the script runs, the bigger difference between the 'msec' and 'sec'
time.
Example output (after about 12 hours):
msec: [2007-09-13 12:22:25.7074]
sec : [2007-09-13 12:22:26]
msec: [2007-09-13 12:27:25.6848]
sec : [2007-09-13 12:27:26]
msec: [2007-09-13 12:32:25.6624]
sec : [2007-09-13 12:32:26]
It _appears_ microtime() loses about 0.02 seconds on each 5 minute measurement on this machine, but
this may be just local value and the exact value could differ on different hardware.
C program output (from start):
0.002466
0.002998
0.003723
It appears performance counter based time loses about 0.0006 sec on each 10 second measurement
compared to GetSystemTimeAsFileTime(). This matches the difference observed in PHP script.
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=42659&edit=1
Thread (4 messages)