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()?