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}