php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #42659 microtime() loses time in long-running scripts
Submitted: 2007-09-13 15:30 UTC Modified: 2008-09-03 01:00 UTC
Votes:8
Avg. Score:3.6 ± 1.3
Reproduced:6 of 8 (75.0%)
Same Version:3 (50.0%)
Same OS:4 (66.7%)
From: jdolecek at NetBSD dot org Assigned:
Status: No Feedback Package: Date/time related
PHP Version: 5.2.4 OS: win32 only
Private report: No CVE-ID: None
View Add Comment Developer Edit
Welcome! If you don't have a Git account, you can't do anything here.
You can add a comment by following this link or if you reported this bug, you can edit this bug over here.
(description)
Block user comment
Status: Assign to:
Package:
Bug Type:
Summary:
From: jdolecek at NetBSD dot org
New email:
PHP Version: OS:

 

 [2007-09-13 15:30 UTC] 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.


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2008-09-03 01:00 UTC] 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".
 [2010-09-07 09:34 UTC] 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.
 [2011-08-24 07:11 UTC] pv47 at yandex dot ru
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?
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved.
Last updated: Fri Apr 19 15:01:28 2024 UTC