winboard time management

[xr_a_y]

Here's an output log from Weini, when using winboard (under Windows OS).

the last 3 digits of the time are milliseconds (after the sign "-")

So at 202ms Weini received from winboard a "time" command with 10centisec on the clock. Weini trigger "stop pondering" and request a "think" just after (stm 0 mode 0).
Pondering is finished after "End of search" while TimeMan is working to get next move search time ; all of this in less than 1ms. Based on its estimation, TimeMan gives 7ms to think, having 100ms on the clock and still many moves to do ... but an "emergency situation" is detected, and instead of 7ms, Weini used 49ms (which is still < 100ms). The TC ends inside the tree exactly after 49ms (251ms is the current time) and Weini starts pondering again.

Weini will then never receive the next "time" command, nor any other command saying it is Weini's turn (stm, mode) but at 323ms, the engine receive a result command saying it lose on time (when pondering !).

It seems to me that thinking/pondering switch in Weini are quite fast and I really don't understand this situation that is happening a lot when using "sudden death" clock type.

Any help will be appreciated.

Code: Select all

#INFO    - 2018-06-13 21:42:21-202: Receive command : time 10
#INFO    - 2018-06-13 21:42:21-202: XBoard: mode 0
#INFO    - 2018-06-13 21:42:21-202: XBoard: stm  1
#INFO    - 2018-06-13 21:42:21-202: Waiting for input
#INFO    - 2018-06-13 21:42:21-202: Receive command : otim 107
#WARNING - 2018-06-13 21:42:21-202: Unknown command otim 107
#INFO    - 2018-06-13 21:42:21-202: XBoard: mode 0
#INFO    - 2018-06-13 21:42:21-202: XBoard: stm  1
#INFO    - 2018-06-13 21:42:21-202: Waiting for input
#INFO    - 2018-06-13 21:42:21-202: Receive command : usermove a4a3
#INFO    - 2018-06-13 21:42:21-202: Pondering stopped
#INFO    - 2018-06-13 21:42:21-202: XBoard: mode 0
#INFO    - 2018-06-13 21:42:21-202: XBoard: stm  0
#INFO    - 2018-06-13 21:42:21-202: Think requested
#INFO    - 2018-06-13 21:42:21-202: TC type : sudden death with dynamic info
#INFO    - 2018-06-13 21:42:21-202: nodes per s : 0 knps (n:93241, q:98290 (51%), t:0ms)
#INFO    - 2018-06-13 21:42:21-202: msecPerMove 10
#INFO    - 2018-06-13 21:42:21-202: msecPerMove corrected 7
#INFO    - 2018-06-13 21:42:21-202: TC computation (Dynamics) :
#INFO    - 2018-06-13 21:42:21-202:                  msecPreviousElapsed        15
#INFO    - 2018-06-13 21:42:21-202:                  startTC                    14212384
#INFO    - 2018-06-13 21:42:21-202:                  msecRemainingTimeInTC      100
#INFO    - 2018-06-13 21:42:21-202: End of search
#INFO    - 2018-06-13 21:42:21-202:                  mps                        0
#INFO    - 2018-06-13 21:42:21-202: Searcher return move a4 a3(13994) | with score 2174 at depth 7(async)
#INFO    - 2018-06-13 21:42:21-202:                  current moves              67
#INFO    - 2018-06-13 21:42:21-202:                  remainingMoveUntilNextTC   10
#INFO    - 2018-06-13 21:42:21-202:                  msecinc                    0
#INFO    - 2018-06-13 21:42:21-202:                  msecPerMove                7
#INFO    - 2018-06-13 21:42:21-202: Next search time 7
#INFO    - 2018-06-13 21:42:21-202: SearchSync begin
#INFO    - 2018-06-13 21:42:21-202: SearchSync waiting for threads
#INFO    - 2018-06-13 21:42:21-202: SearchSync all threads ok
#INFO    - 2018-06-13 21:42:21-202: Call to Searcher Search
#INFO    - 2018-06-13 21:42:21-202: Call to Searcher Reset
#INFO    - 2018-06-13 21:42:21-202: Call to ThreadPool StartOthers
#INFO    - 2018-06-13 21:42:21-202: Emergency time -2215<-1268 ( 7 => 49 )
#INFO    - 2018-06-13 21:42:21-251: >> TC endeed in AlphaBeta
#INFO    - 2018-06-13 21:42:21-251: nodes per s : 796 knps (n:21698, q:17337 (44%), t:49ms)
#INFO    - 2018-06-13 21:42:21-251: End of search
#INFO    - 2018-06-13 21:42:21-251: Searcher return move g4 g5(16002) | with score -2215 at depth 7
#INFO    - 2018-06-13 21:42:21-251: Pondering request
#INFO    - 2018-06-13 21:42:21-251: SearchASync begin
#INFO    - 2018-06-13 21:42:21-251: SearchASync waiting for threads
#INFO    - 2018-06-13 21:42:21-251: SearchASync all threads ok
#INFO    - 2018-06-13 21:42:21-251: Pondering started async
#INFO    - 2018-06-13 21:42:21-251: Waiting for input
#INFO    - 2018-06-13 21:42:21-251: Call to Searcher Search
#INFO    - 2018-06-13 21:42:21-251: Call to Searcher Reset
#INFO    - 2018-06-13 21:42:21-251: Call to ThreadPool StartOthers
#INFO    - 2018-06-13 21:42:21-323: Receive command : result 0-1 {Black wins on time}
#INFO    - 2018-06-13 21:42:21-323: Pondering stopped
#INFO    - 2018-06-13 21:42:21-323: result 0-1 {Black wins on time}

[Guenther]

The first thing you should do is creating a winboard debug file and compare
the timings for I/O with your log.

From your log it is not clear to me when the searched move really is sent to WB.

[Sven]

The first thing you should do is creating a winboard debug file and compare
the timings for I/O with your log.

From your log it is not clear to me when the searched move really is sent to WB.

Yes, absolutely necessary since one possible reason for the loss on time is that WB did not receive a proper "move ..." command so it still thought it were the engine's turn.

It might even be better to simply write all those own debug messages to standard output (instead of a separate logfile), then they will appear in the Winboard debug log together with all communication via WB protocol.

[xr_a_y]

From Weini point-of-view :

Code: Select all

#INFO    - 2018-06-14 06:50:51-746: Pondering request
#INFO    - 2018-06-14 06:50:51-747: SearchASync begin
#INFO    - 2018-06-14 06:50:51-747: SearchASync waiting for threads
#INFO    - 2018-06-14 06:50:51-747: SearchASync all threads ok
#INFO    - 2018-06-14 06:50:51-747: Pondering started async
#INFO    - 2018-06-14 06:50:51-747: Waiting for input
#INFO    - 2018-06-14 06:50:51-747: Call to Searcher Search
#INFO    - 2018-06-14 06:50:51-747: Call to Searcher Reset
#INFO    - 2018-06-14 06:50:51-747: Call to ThreadPool StartOthers
#INFO    - 2018-06-14 06:50:51-908: Receive command : time 11
#INFO    - 2018-06-14 06:50:51-908: XBoard: mode 0
#INFO    - 2018-06-14 06:50:51-908: XBoard: stm  1
#INFO    - 2018-06-14 06:50:51-908: Waiting for input
#INFO    - 2018-06-14 06:50:51-908: Receive command : otim 157
#WARNING - 2018-06-14 06:50:51-908: Unknown command otim 157
#INFO    - 2018-06-14 06:50:51-908: XBoard: mode 0
#INFO    - 2018-06-14 06:50:51-908: XBoard: stm  1
#INFO    - 2018-06-14 06:50:51-908: Waiting for input
#INFO    - 2018-06-14 06:50:51-908: Receive command : usermove c6b7
#INFO    - 2018-06-14 06:50:51-908: Pondering stopped
#INFO    - 2018-06-14 06:50:51-908: Applying move c6b7
#INFO    - 2018-06-14 06:50:51-908: XBoard: mode 0
#INFO    - 2018-06-14 06:50:51-908: XBoard: stm  0
#INFO    - 2018-06-14 06:50:51-908: Think requested
#INFO    - 2018-06-14 06:50:51-908: nodes per s : 572 knps (n:33921, q:58898 (63%), t:162ms)
#INFO    - 2018-06-14 06:50:51-908: TC type : sudden death with dynamic info
#INFO    - 2018-06-14 06:50:51-908: msecPerMove 11
#INFO    - 2018-06-14 06:50:51-908: msecPerMove corrected 8
#INFO    - 2018-06-14 06:50:51-908: TC computation (Dynamics) :
#INFO    - 2018-06-14 06:50:51-908:                  msecPreviousElapsed        203
#INFO    - 2018-06-14 06:50:51-908:                  startTC                    47132585
#INFO    - 2018-06-14 06:50:51-908:                  msecRemainingTimeInTC      110
#INFO    - 2018-06-14 06:50:51-908:                  mps                        0
#INFO    - 2018-06-14 06:50:51-908:                  current moves              68
#INFO    - 2018-06-14 06:50:51-908: End of search
#INFO    - 2018-06-14 06:50:51-908:                  remainingMoveUntilNextTC   10
#INFO    - 2018-06-14 06:50:51-908:                  msecinc                    0
#INFO    - 2018-06-14 06:50:51-908:                  msecPerMove                8
#INFO    - 2018-06-14 06:50:51-908: Next search time 8
#INFO    - 2018-06-14 06:50:51-908: SearchSync begin
#INFO    - 2018-06-14 06:50:51-908: SearchSync waiting for threads
#INFO    - 2018-06-14 06:50:51-908: Searcher return move c6 b7(20490) | with score -1291 at depth 8(async)
#INFO    - 2018-06-14 06:50:51-908: SearchSync all threads ok
#INFO    - 2018-06-14 06:50:51-908: Call to Searcher Search
#INFO    - 2018-06-14 06:50:51-908: Call to Searcher Reset
#INFO    - 2018-06-14 06:50:51-908: Call to ThreadPool StartOthers
#INFO    - 2018-06-14 06:50:51-916: >> TC endeed in AlphaBeta
#INFO    - 2018-06-14 06:50:51-916: nodes per s : 485 knps (n:1644, q:2243 (57%), t:8ms)
#INFO    - 2018-06-14 06:50:51-916: End of search
#INFO    - 2018-06-14 06:50:51-916: Searcher return move d8 e7(14011) | with score 1291 at depth 6
#INFO    - 2018-06-14 06:50:51-916: Sending move d8e7
#INFO    - 2018-06-14 06:50:51-916: Pondering request
#INFO    - 2018-06-14 06:50:51-916: SearchASync begin
#INFO    - 2018-06-14 06:50:51-916: SearchASync waiting for threads
#INFO    - 2018-06-14 06:50:51-916: SearchASync all threads ok
#INFO    - 2018-06-14 06:50:51-916: Pondering started async
#INFO    - 2018-06-14 06:50:51-916: Waiting for input
#INFO    - 2018-06-14 06:50:51-916: Call to Searcher Search
#INFO    - 2018-06-14 06:50:51-916: Call to Searcher Reset
#INFO    - 2018-06-14 06:50:51-916: Call to ThreadPool StartOthers
#INFO    - 2018-06-14 06:50:51-038: Receive command : result 0-1 {Black wins on time}
#INFO    - 2018-06-14 06:50:51-038: Pondering stopped
#INFO    - 2018-06-14 06:50:51-038: result 0-1 {Black wins on time}

From WinBoard :

Code: Select all

45536 <second: move c6b7
45536 >first : time 11
45536 >first : otim 157
book hit = (NULL)
45536 >first : usermove 45536 >first : c6b7
silence
45661 <first : 1 1291 0 2	d8e7+ 
45661 <first : 2 1291 0 56	d8e7+ e6d7 
45661 <first : 3 1291 0 110	d8e7+ e6d7 e7d7+ 
45661 <first : 4 1291 0 164	d8e7+ e6d7 e7d7+ b7b6 
45661 <first : 5 1291 0 218	d8e7+ e6d7 e7d7+ b7b6 d7d6+ 
45661 <first : 6 1291 0 272	d8e7+ e6d7 e7d7+ b7b6 d7d6+ b6b5 
45661 <first : 7 1291 0 326	d8e7+ e6d7 e7d7+ b7b6 d7d6+ b6b5 d6h6 
45661 <first : 8 1291 0 380	d8e7+ e6d7 e7d7+ b7b6 d7d6+ b6b5 d6h6 b5c4 
45661 <first : move d8e7
GameEnds(27, Black wins on time, 4)
GE(27, Black wins on time, 4) bare king k=5 color=44

[xr_a_y]

Two interesting thoughts :
* it seems (I didn't check the source code) that winboard/xboard is thinking every string received on stdout (even starting with a #) is an issue if it contains "not found" inside. From the doc :

Code: Select all

In support of the -firstHost/-secondHost features, which allow a chess engine to be run on another machine using the rsh protocol, xboard recognizes error messages that are likely to come from rsh as fatal errors. The following messages are currently recognized:

    unknown host
    No remote directory
    not found
    No such file
    can't alloc
    Permission denied

I suspect, those checks shall not be performed on comments output.

Code: Select all

# COMMENT
    The engine can send any string of printable characters, terminated by a newline, for inclusion in the winboard.debug file, provided the line starts with a '#' character. If the engine has set feature debug=1, it is guaranteed that WinBoard (and any future version of it) will completely ignore these lines in any other respect. 

* the time control issue never ever happens on xboard (linux), only with winboard.

[hgm]

In the WinBoard log the clock showing still 100ms starts at 45.536, an thus woul flag at 45.646. The move is received 45.661, i.e. after you flagged.

[Sven]

Two interesting thoughts :
* it seems (I didn't check the source code) that winboard/xboard is thinking every string received on stdout (even starting with a #) is an issue if it contains "not found" inside. From the doc :

Code: Select all

In support of the -firstHost/-secondHost features, which allow a chess engine to be run on another machine using the rsh protocol, xboard recognizes error messages that are likely to come from rsh as fatal errors. The following messages are currently recognized:

    unknown host
    No remote directory
    not found
    No such file
    can't alloc
    Permission denied

I suspect, those checks shall not be performed on comments output.

Code: Select all

# COMMENT
    The engine can send any string of printable characters, terminated by a newline, for inclusion in the winboard.debug file, provided the line starts with a '#' character. If the engine has set feature debug=1, it is guaranteed that WinBoard (and any future version of it) will completely ignore these lines in any other respect. 

* the time control issue never ever happens on xboard (linux), only with winboard.

Maybe a problem of not flushing stdout when sending the engine move to WB (and/or maybe also other commands sent to the GUI)?

[xr_a_y]

In the WinBoard log the clock showing still 100ms starts at 45.536, an thus woul flag at 45.646. The move is received 45.661, i.e. after you flagged.

Indeed, and that is my problem. because Weini is seeing 8ms

Code: Select all

#INFO    - 2018-06-14 06:50:51-908: XBoard: mode 0
#INFO    - 2018-06-14 06:50:51-908: XBoard: stm  0
#INFO    - 2018-06-14 06:50:51-908: Think requested
....
#INFO    - 2018-06-14 06:50:51-916: nodes per s : 485 knps (n:1644, q:2243 (57%), t:8ms)
#INFO    - 2018-06-14 06:50:51-916: End of search
#INFO    - 2018-06-14 06:50:51-916: Searcher return move d8 e7(14011) | with score 1291 at depth 6
#INFO    - 2018-06-14 06:50:51-916: Sending move d8e7

Maybe a problem of not flushing stdout when sending the engine move to WB (and/or maybe also other commands sent to the GUI)?

Only the move is sent,

Code: Select all

std::cout << _buffer.str() << std::endl << std::flush;

But this code is inside the DTOR of some Logger object specifically construct inline and acting as a stream in my Logger implementation ; maybe compiled with VisualStudio the DTOR is called a little later. At least this never happens with xboard and linux (gcc6 on debian 9)...

[xr_a_y]

But this code is inside the DTOR of some Logger object specifically construct inline and acting as a stream in my Logger implementation ; maybe compiled with VisualStudio the DTOR is called a little later. At least this never happens with xboard and linux (gcc6 on debian 9)...

Ok I check that, adding more logs, and both under windows and linux I am pretty sure the move is send to GUI as soon as I wanted from both Weini and GUI point of view :

Code: Select all

37189 <first : #INFO    - 2018-06-15 08:02:04-508: End of search
37189 <first : #INFO    - 2018-06-15 08:02:04-508: Searcher return move e8 e6(14011) | with score 7842 at depth 4
37189 <first : #INFO    - 2018-06-15 08:02:04-508: Sending move e8e6
37189 <first : #COMGUI  - 2018-06-15 08:02:04-508: move e8e6
37189 <first : move e8e6

[hgm]

What TC are you using here. And if it is very fast, did you switch move animation off?