Closed Bug 124695 Opened 23 years ago Closed 19 years ago

PR_IntervalNow is slow on Windows

Categories

(NSPR :: NSPR, defect)

Product:
NSPR
Component:
NSPR
Platform:
x86
Windows 2000
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: bratell, Assigned: wtc)

References

(Blocks 1 open bug)

Details

(Keywords: perf)

Attachments

(3 files)

The testprogram. Link with winmm.lib beside the normal libs.
(deleted), text/plain
Details
Proposed patch to use timeGetTime() (carried over from bug 307527)
(deleted), patch
darin.moz
: review+
Details | Diff | Splinter Review
Patch to fix MinGW build crash in time()
(deleted), patch
Details | Diff | Splinter Review 
The documentation of PR_IntervalNow says:
"PR_IntervalNow is both very efficient and nonblocking..."
"Interval times ... are very cheap to acquire"

This is not true for Windows where QueryPerformanceCounter is used. That is the 
slowest of all timing functions making PR_IntervalNow the bad choice.

In bug 75001 I measured the speed of different timing functions and got these 
results:

Function                       Time in us
==========================================
timeGetTime                        209
ftime                              809
QueryPerfomanceCounter            4205


The one problem is that timeGetTime on NT/2000/XP have a default interval of 5ms 
which have to be set down to 1ms by using timeBeginPeriod and timeEndPeriod. 


----

If it for some reason isn't possible to change to a faster time function for 
PR_IntervalNow I want to change this bug to a request for a fast, and maybe less 
accurate timing function.
Blocks: 124697
Blocks: 75001
Thanks for the report.

Your finding is disturbing because we have always assumed
that QueryPerfomanceCounter is cheap.  PR_IntervalNow()
should be cheap, and I believe we must have verified that
QueryPerfomanceCounter is cheap before (back in NT 3.51
or 4.0).
That depends on what you mean by cheap. Since we can be calling that method so
very often it piles up.

The previous measurements were done on a Windows NT4 machine with an Intel
Pentium II 400MHz processor. 

I redid the measurements on a Windows 2000 computer (Duron 800MHz):

       QueryPerformanceCounter 10000000 times: 12473ms, 1.247300 us/call
                        _ftime 10000000 times: 6301ms, 0.630100 us/call
                   timeGetTime 10000000 times: 1700ms, 0.170000 us/call

It seems to be faster than on NT4, but still _ftime and timeGetTime is much faster.
This is the test program I used. It just calls the funtion in a tight loop.
It's probably more costly in real life since this usage will keep the timing
code in the caches, but the relative times should be right.
Keywords: mozilla1.0, perf
Keywords: mozilla1.0+
Keywords: mozilla1.0
Keywords: mozilla1.2
Do we have any updated time saving stats?

There is also a GetTickCount function that could be useful.
Blocks: 203448
Tested on WinXPsp2, IBM Thinkpad T40, 1.5Ghz Pentium M, 1GB RAM

       QueryPerformanceCounter 10000000 times: 11656ms, 1.165600 us/call
                        _ftime 10000000 times: 2254ms, 0.225400 us/call
                   timeGetTime 10000000 times: 671ms, 0.067100 us/call

Compiled with Visual C++,m version 6.0, but these are system calls and (should
be) indepent from compiler version.

So, the difference is still there and very real.
So, timeGetTime with timeBeginPeriod set to 1 should improve performance of
PR_IntervalNow

Pointers to the code:
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/nsprpub/pr/src/md/windows/ntthread.c#118
http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/md/windows/ntinrval.c#90

So, the code is even there, but disabled/replaced by QueryPerformanceCounter.

Note, Bug 176881 (PRInterval timers may be incorrect on Windows with processor
speed > 4 GHz) also notes problems with the QPC call... (see also
http://support.microsoft.com/default.aspx?scid=KB;EN-US;Q274323& for the jumping
QBC thing).

Right, summary:
Let's use timeGetTime which is about 17 times faster than QPC, and doesn't have
the jumping issues of QPC. Also because it is using 1ms accuracy it makes
conversions redundant (internally to NSPR though).
Could you also measure GetTickCount()?

The reason we prefer GetTickCount() to timeGetTime()
is that timeGetTime() requires linking with winmm.lib.
In fact NSPR used timeGetTime() before and we had to
switch to GetTickCount() to eliminate the winmm.lib
dependency.
How about this?
       QueryPerformanceCounter 10000000 times: 11603ms, 1.160300 us/call
                        _ftime 10000000 times: 2542ms, 0.254200 us/call
                   timeGetTime 10000000 times: 575ms, 0.057500 us/call
                  GetTickCount 10000000 times: 63ms, 0.006300 us/call

So, GetTickCount is even faster than timeGetTime.
However, GetTickCount only provides 10mseconds (or worse) accuracy, even with '
timeBeginPeriod(1);'

So GetTickCount is useless?
More info at:
http://gpwiki.org/index.php/VB:Timers

timeGetTime seams really be the only solution on windows to get 1msecond
accurate timing.
I wrote a test program to obtain the resolution of
GetTickCount and timeGetTime.  On my Windows XP SP2
machine, the resolution of GetTickCount is 15-16 ms
while the resolution of timeGetTime is 1 ms.  So I
am in favor of timeGetTime.  Can anyone help me measure
the startup time penalty due to loading winmm.dll?

Here is my test program and a few sample outputs.

C:\temp>cat tick.c
#include <windows.h>
#include <stdio.h>

int main()
{
    DWORD tick0;
    DWORD tick;

    tick0 = GetTickCount();
    for (;;) {
        tick = GetTickCount();
        if (tick != tick0) {
            break;
        }
    }
    printf("GetTickCount: tick0=%d tick=%d resolution=%d\n", tick0, tick, (tick-
tick0));

    tick0 = timeGetTime();
    for (;;) {
        tick = timeGetTime();
        if (tick != tick0) {
            break;
        }
    }
    printf("timeGetTime: tick0=%d tick=%d resolution=%d\n", tick0, tick, (tick-t
ick0));

    return 0;
}

C:\temp>.\tick.exe
GetTickCount: tick0=18564656 tick=18564671 resolution=15
timeGetTime: tick0=18564663 tick=18564664 resolution=1

C:\temp>.\tick.exe
GetTickCount: tick0=18565390 tick=18565406 resolution=16
timeGetTime: tick0=18565395 tick=18565396 resolution=1

C:\temp>.\tick.exe
GetTickCount: tick0=18566062 tick=18566078 resolution=16
timeGetTime: tick0=18566069 tick=18566070 resolution=1

C:\temp>.\tick.exe
GetTickCount: tick0=18603031 tick=18603046 resolution=15
timeGetTime: tick0=18603031 tick=18603032 resolution=1
Note, bug 307527 has a patch (and which is recently 2006/02/06) also submitted to some tree's) to switch to timeGetTime.  
So, if that patch is accepted and the bug 307527 is closed, then this one is also implicetely closed?

Let's depend this bug on bug 307527 for the time being...
Depends on: 307527
It's more correct to make this NSPR bug block the Thunderbird
bug 307527.

Here is a summary for developers of other NSPR-based products
who will be affected by this change.

Right now, on Windows, PR_IntervalNow() calls QueryPerformanceCounter().
QueryPerformanceCounter() may return the wrong value because of bugs
in the BIOS or motherboard device drivers, and it may have problems
with multiprocessor systems (including the dual-core and multi-core
processors) and processors with variable clock speeds (for low
power consumption).  Microsoft considers these problems outside
the boundary of Windows and refers the consumers to the processor
or motherboard vendors for help.

Recently, older versions of AMD's drivers for dual-core Athlon64
X2 processors cause QueryPerformanceCounter() to return the wrong
value again and cause connection timeout in Thunderbird (bug 307527).
So I decided it's time to use a different implementation for
PR_IntervalNow() on Windows.  There are only two alternatives,
but they each have their own problem with resolution.
1. timeGetTime(): the resolution can be adjusted by the application.
   On most systems, you can set the resolution to 1 ms.  However,
   the documentation about setting the resolution of timeGetTime()
   seems to suggest that the resolution is a process-global property.
   As a library, NSPR is not in a good position to set any process-global
   property.
2. GetTickCount(): the resolution is fixed and is too coarse. For
   example, on one of my Windows XP SP2 machine, the resolution of
   GetTickCount() is 16 ms.  This is 60% coarser than the traditional
   Unix time resolution of 10 ms.

So, there is no ideal solution to this problem that I must fix.
I decided to go with timeGetTime() and rely on its default
resolution.  An NSPR-based application can call timeBeginPeriod()
and timeEndPeriod() to set the timeGetTime() resolution to a desired
value. I considered calling timeBeginPeriod() and timeEndPeriod()
in NSPR's DllMain function, but Microsoft's DllMain documentation
warns that only kernel32.dll functions should be called in DllMain,
and those two functions are defined in winmm.dll.
Blocks: 307527
Status: NEW → ASSIGNED
No longer depends on: 307527
Target Milestone: --- → 4.6.2
FYI, I ran the program from comment #11 on my WinXP sp2 IBM T41p notebook, and I found that timeGetTime has a resolution of 1ms.  That seems to contradict the theory that the default resolution of timeGetTime is higher (e.g., 5 - 10 ms).
Darin, a resolution of 5-10 ms is acceptable because it
is as good as the traditional Unix resolution of 10 ms.
Microsoft only documents that on Windows NT/2000 the
default resolution of timeGetTime can be >= 5 ms.  On
my Windows XP SP2 machine, the resolution of timeGetTime()
is also 1 ms.
Comment on attachment 211084 [details] [diff] [review]
Proposed patch to use timeGetTime() (carried over from bug 307527)

r=darin
Attachment #211084 - Flags: review+
I should clarify the issue with the resolution of timeGetTime().

It is not that the default resolution of 5-10 ms (on some
versions of Windows) is too coarse.  It is that the resolution
may be set by the application to a very coarse value, say
20 ms, which may be too coarse for certain NSPR customers.
It seems inappropriate for NSPR to set the resolution. Also,
Microsoft documentation doesn't say what happens if the
application and NSPR try to set the resolution to different
values.
Hello,

I'm building Mozilla Sunbird on Windows 2000 from trunk using cygwin/mingw.

I did not build for some days but when I tried today the build succeeded but Sunbird crashed during startup. I did a debug build from scratch and got the following stack trace:

Program received signal SIGSEGV, Segmentation fault.

#0  0x780290d6 in time () from /cygdrive/c/WINNT/system32/msvcrt.dll

#1  0x30026060 in _PR_MD_GET_INTERVAL () 
    at c:/dev/mozilla/nsprpub/pr/src/md/windows/ntinrval.c:54

#2  0x30012c28 in PR_IntervalNow () 
    at c:/dev/mozilla/nsprpub/pr/src/misc/prinrval.c:77

#3  0x0d58fc92 in nsSocketTransportService::Poll (this=0x2547040, interval=0x13eeff04)
    at c:/dev/mozilla/netwerk/base/src/nsSocketTransportService2.cpp:357

#4  0x0d5906e1 in nsSocketTransportService::Run (this=0x2547040)
    at c:/dev/mozilla/netwerk/base/src/nsSocketTransportService2.cpp:568

#5  0x00742fba in nsThread::Main (arg=0x2547758) 
    at c:/dev/mozilla/xpcom/threads/nsThread.cpp:118
(More stack frames follow...)

Looking at the stack I think the check in for this bug could be the cause.

Any ideas?
Stefan, could you try this patch?

The crash in time() is most likely because we aren't
passing an argument to time().  But I think it is
wrong to use the time() function anyway; its resolution
is too coarse (1 second).  I don't understand why the
MinGW code was using time() here.
(In reply to comment #19)
> Stefan, could you try this patch?

Sunbird build with this patch was successful and no longer crashes during startup.
Comment on attachment 211433 [details] [diff] [review]
Patch to fix MinGW build crash in time()

I checked in the MinGW build fix on the NSPR trunk
(NSPR 4.7), NSPRPUB_PRE_4_2_CLIENT_BRANCH (mozilla
1.9 alpha), MOZILLA_1_8_BRANCH (mozilla 1.8.1), and
MOZILLA_1_8_0_BRANCH (mozilla 1.8.0.2).
Can we mark this fixed now?
Patch has been committed, and after the MinGW followup patch, everything seems ok.
Marking fixed.
Status: ASSIGNED → RESOLVED
Closed: 19 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: