Win 7 GetTickCount() weirdness

[hgm]

I always use the Windows call GetTickCount() to control the thinking time of my engines. But when I was working on implementing pondering for my engine HaChu, I noticed (at 40 moves/min) that on the first move it would only search 1 ply (and thus have no ponder move). The time management gives it 147 msec to start the 2-ply iteration, but after the first iteration (47 nodes!) it thinks this time has already elapsed (it reports 17 centi-sec in the thinking output).

Of course I let it print the start and stop time for debugging (immediately flushing the output), and there appears to be only a few (~10) msec between reception of these start and stop messages by WinBoard. (The clock of which now also seems to tick every msec, which is also a novelty, as on all my other machines the timestamps in the debug file always increase in steps of ~16 msec.)

The engine gives debug output for every root move, so I let it print GetTickCount() there as well, to see where this discrepancy between engine-measured time and GUI-measured time occurs. This seems to make the problem go away, however: GetTickCount() now thinks hardly any time elapses during the 1-ply and 2-ply iteration (it increments in steps of ~16 msec, so it is hard to see exactly how much), and it nicely reaches 4 ply. But in other places (where I use the search to create a list of legal moves) it seems there are ticks missing. E.g. a part of the 1-ply iteration:

Code: Select all

1844 >first : usermove 1845 >first : h3h4
1977 <first &#58; # in &#40;mode = 1,0&#41;&#58; put
1977 <first &#58; # in &#40;mode = 1,0&#41;&#58; time
1977 <first &#58; # in &#40;mode = 1,0&#41;&#58; otim
1977 <first &#58; # in &#40;mode = 1,0&#41;&#58; usermove
....
1988 <first &#58; 0&#58; 1&#58;1  78  610aa c8c7            1     14  &#40;16499944&#41;
1988 <first &#58; 0&#58; 1&#58;1  79  620ac e8e7            1     14
1988 <first &#58; 0&#58; 1&#58;1  79  620ac e8e7            5     14  &#40;16499944&#41;
1989 <first &#58; 0&#58; 1&#58;1  80  628ad f8f7            5     14
1989 <first &#58; 0&#58; 1&#58;1  80  628ad f8f7           -6     14  &#40;16499944&#41;
1989 <first &#58; 0&#58; 1&#58;1  81  630ae g8g7           -6     14
1989 <first &#58; 0&#58; 1&#58;1  81  630ae g8g7           -1     14  &#40;16499944&#41;
1989 <first &#58; 0&#58; 1&#58;1  82  638af h8h7           -1     14
1989 <first &#58; 0&#58; 1&#58;1  82  638af h8h7            4     14  &#40;16499944&#41;
1989 <first &#58; 0&#58; 1&#58;1  83  648b1 j8j7            4     14
1989 <first &#58; 0&#58; 1&#58;1  83  648b1 j8j7            1     14  &#40;16499944&#41;
2003 <first &#58; 0&#58; 1&#58;1  84  650b2 k8k7            1     14
2003 <first &#58; 0&#58; 1&#58;1  84  650b2 k8k7           -4     14  &#40;16499944&#41;
2003 <first &#58; 0&#58; 1&#58;1  85  658b3 l8l7           -4     14
2003 <first &#58; 0&#58; 1&#58;1  85  658b3 l8l7           -6     14  &#40;16500085&#41;

The first column is the WinBoard time stamp, the last number the GetTickCount(). In the last move the tick count suddenly jumps 141 msec!

There is a similar discontinuity in the GUI time stamps after sending the move that triggered all this engine activity (133 msec). It is almost like the programs can be temporarily suspended for periods > 100 msec. This is on a quad-core i7, however, with a single-threaded engine and no other explicit tasks running...

Has anyone seen similar erratic behavior with GetTickCount()?

[Henk]

In .net I use the class Stopwatch.

Maybe if many processes or threads are busy, timing is not accurate. One thread waiting for the other before it gets handled, while doing nothing but time is still counted.

[Vinvin]

I tested some years ago and I confirm the GetTickCount resolution is about 1/60th of second.

http://msdn.microsoft.com/en-us/library ... 85%29.aspx

The resolution of the GetTickCount function is limited to the resolution of the system timer, which is typically in the range of 10 milliseconds to 16 milliseconds.

[mar]

Something seems wrong here. I have never seen such behavior, GetTickCount usually has granularity of ~16 msec (depends on OS) - just tried it on shitty 64-bit Win8 and indeed, I get almost perfect 16 msec increments.
Are you 100% sure that the problem is related to GetTickCount?

[OT]
You can try multimedia timer (timeGetTime), which initially does similar thing. However, you can use timeBeginPeriod(n) and later timeEndPeriod(n) when you're done to give it any granularity you want.
You can even have a "perfect" 1msec counter.
However, timeBeginPeriod affects the frequency of timer interrupts so it may affect overall system performance (I wouldn't try it on very old hardware - which is not the case of your i7).
It would be very nice to have a reliable high performance (external) clock available. Unfortunately TSC is not the option today because of turbo boost.
[/OT]

[Joost Buijs]

The default timer resolution when using Windows is 15.6 msec.

I had issues with the stability of GetTickCount as well. When the system is heavely loaded it sometimes just forgets a tick. Also the resolution is to low for reliable timing.

You can use the high resolution timer which on most PC's will be sub usec.

Just look at QueryPerformanceFrequency(); and QueryPerformanceCounter();

[jdart]

At least GetTickCount() is efficient and I haven't had issues with it.

The most reliable high-resolution timing source is probably the High Precision Event Timer (HPET) but older motherboards may lack this feature and I believe software support came in only with Windows Vista.

Not sure what the additional overhead of using that is but it is probably higher than GetTickCount().

--Jon

[Joost Buijs]

The issue I had with GetTickCount() is that it delays the ticks when the system is busy. It' is not really forgetting them.

Anyway 15.6 msec resolution is not suitable for fast games, specially if you want to do bullet testing with games of just a few seconds total.

I use QueryPerformanceFrequency(); and QueryPerformanceCounter(); and this is very fast. Maybe this is the same as the HPET you mention, I don't know. The functions I use work under WinXP as well.

[jdart]

GetTickCount() resolution is ok for bullet. This is what many programs such as GnuChess have been using, for a long time. Also note, the Winboard protocol only passes time control info to the engine in units of 10 msec. (in UCI it is in milliseconds).

--Jon

[hgm]

Indeed it does. I am thinking of lifting this limitation, and allowing arbitrary precision, by making the time and otim parameters floating point. Engines could request the GUI to transmit the fraction through sending (say) feature time=1 (default 0) at startup.

[Patrice Duhamel]

I'm using QueryPerformanceCounter() but I will change to GetTickCount() because I read it can cause problems on multi cores machines.

But I never see problems with GetTickCount() or QueryPerformanceCounter().