Win 7 GetTickCount() weirdness
Posted: Thu May 30, 2013 2:03 pm
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:
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()?
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 : # in (mode = 1,0): put
1977 <first : # in (mode = 1,0): time
1977 <first : # in (mode = 1,0): otim
1977 <first : # in (mode = 1,0): usermove
....
1988 <first : 0: 1:1 78 610aa c8c7 1 14 (16499944)
1988 <first : 0: 1:1 79 620ac e8e7 1 14
1988 <first : 0: 1:1 79 620ac e8e7 5 14 (16499944)
1989 <first : 0: 1:1 80 628ad f8f7 5 14
1989 <first : 0: 1:1 80 628ad f8f7 -6 14 (16499944)
1989 <first : 0: 1:1 81 630ae g8g7 -6 14
1989 <first : 0: 1:1 81 630ae g8g7 -1 14 (16499944)
1989 <first : 0: 1:1 82 638af h8h7 -1 14
1989 <first : 0: 1:1 82 638af h8h7 4 14 (16499944)
1989 <first : 0: 1:1 83 648b1 j8j7 4 14
1989 <first : 0: 1:1 83 648b1 j8j7 1 14 (16499944)
2003 <first : 0: 1:1 84 650b2 k8k7 1 14
2003 <first : 0: 1:1 84 650b2 k8k7 -4 14 (16499944)
2003 <first : 0: 1:1 85 658b3 l8l7 -4 14
2003 <first : 0: 1:1 85 658b3 l8l7 -6 14 (16500085)
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()?