Edit report at http://bugs.php.net/bug.php?id=42659&edit=1
ID: 42659 Comment by: jdolecek at NetBSD dot org 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 New Comment: 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. Previous Comments: ------------------------------------------------------------------------ [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] j...@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 http://bugs.php.net/bug.php?id=42659&edit=1
