Timing info bug with UCI+WB engines - no updated move info

[Guenther Simon]

Hello HG,

It seems using time reported by engines cannot work correctly
for at least some UCI engines via Polyglot!
(I haven't looked up if UCI engines normally should send updated info
with the made move...)
Obviously UCI engines don't send updated infos always together
with the move made. In this case it seems Polyglot simply sends/repeats
the last made seldepth info together with the move to xboard.
This is ok for score/depth but of course not for time(and nps info),
because now it looks to xboard as if the engine hadn't used _any_ time
since last seldepth info until it really made the move!
In this case it seems the timestamp of WB itself is mandatory.
Below you can take a look at a small example move which ignores
the really used time between seldepth 14 and the time the move
was made.

Update: Now that I looked also at Naum playing as WB engine in this game it seems this also happens to WB engines, because obviously
there is no need to send updated info with the final move, thus the reported time from engines won't work at all most of the time.
I am sorry, but you need to get track of the WB clock itself again instead of what engines report.

Guenther

Debug for Naums 31...Qh3

1490413 >second: time 13551
1490413 >second: otim 17794
1490413 >second: c4d4
1490463 <second: 1 -1 0 916 Qc2
1490463 <second: 2 -3 0 2299 Qc2 f5
1490463 <second: 3 -3 0 3589 Qc2 f5 Qf2
1490463 <second: 4 -3 0 4827 Qc2 f5 Qf2 Rg2
1490463 <second: 5 -18 0 6246 Qc2 f5 Qf2 Rg2 Qe1+
1490473 <second: 5 -7 2 9238 Rfb7 Rd7 e5 Rgxg7+ Kh6
1490483 <second: 6 -9 2 12863 Rfb7 Rd7 e5 Rgxg7+ Kh6 Rh7+
1490483 <second: 7 -9 3 17725 Rfb7 Rd7 e5 Rgxg7+ Kh6 Rh7+ Kg6
1490503 <second: 8 -9 4 26143 Rfb7 Rd7 e5 Rgxg7+ Kh6 Rh7+ Kg6 Qxa4
1490523 <second: 9 -9 6 39752 Rfb7 Rd7 e5 Rgxg7+ Kh6 Rh7+ Kg6 Qxa4 Rxb2
1490553 <second: 10 -10 9 55810 Rfb7 Rd7 e5 Rgxg7+ Kh6 Qxa4 Rxd7 Rxd7 Qc2 Rd2
1490553 <second: 11 -12 9 56858 Rfb7 Rd7 e5 Rgxg7+ Kh6 Qxa4 Rxd7 Rxd7 Qc2 Rd2 Rxa3+
1490553 <second: 12 -12 9 57612 Rfb7 Rd7 e5 Rgxg7+ Kh6 Qxa4 Rxd7 Rxd7 Qc2 Rd2 Rxa3+ Qxa3
1490553 <second: 13 -12 9 58350 Rfb7 Rd7 e5 Rgxg7+ Kh6 Qxa4 Rxd7 Rxd7 Qc2 Rd2 Rxa3+ Qxa3 Qxd2
1491594 <second: 14 -38 113 980170 Rfb7 Rd7 e5 Rgxg7+ Kh6 Rh7+ Kg6 Qd1 Rxd7 Rxd7 exf4 exf4 Kh6 Rd4
1495550 <second: 14 -33 508 4115453 Qh3 Qd1 g6 Rd7 Rb7 Rxf7+ Rxf7 Qg4 Qxg4 Rxg4 Rd7 Rxh4+ Kg7 f5
1499646 <second: 15 -33 919 7533018 Qh3 Qd1 g6 Rd7 Rb7 Rxf7+ Rxf7 Qg4 Qxg4 Rxg4 Rd7 Rxh4+ Kg7 f5 exf5
1503421 <second: move Qh3

Example added including WB debug, Polyglot log for
Shredders 27. Nc5

1255805 >first : time 36147
1255805 >first : otim 18658
1255805 >first : usermove 1255805 >first : h7h5
1255886 <first : 1 -234 2 8 Qxc7 Rxd3
1255926 <first : 1 -37 2 16 e4 Qxe4
1255926 <first : 1 +113 2 37 h4
1255946 <first : 2 +95 2 158 h4 Bd6
1255946 <first : 3 +44 3 1020 h4 Qb5 Qxb5 Rxb5
1255946 <first : 3 +78 3 1832 Rgg1 Qb5 Qc2
1255946 <first : 3 +89 3 2342 Nc5 Bxc5 dxc5 c6 Qxa4
1255976 <first : 4 +101 4 4084 Nc5 Bxc5 dxc5 Rb8 e4 Qxf4 Qxe6
1255996 <first : 5 +101 4 6671 Nc5 Bxc5 dxc5 Rb8 e4 Qxf4 Qxe6
1256016 <first : 6 +85 12 29279 Nc5 Bxc5 dxc5 Rb8 h4 Kh8 Rd3 Re7 Rd2 c6
1256136 <first : 7 +62 31 86114 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 c6
1256346 <first : 8 +82 52 161883 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 g6 Rd8+ Kg7 h3
1256607 <first : 9 +94 78 255173 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 g6 Qxb3 Kg7 Qc2 Re7
1257057 <first : 10 +76 123 421772 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 Qxh2 Rd8+ Kh7 Qxb3 Qg1+ Ka2 Re7 Qd5
1260652 <first : 11 +69 483 1766018 Nc5 Bxc5 dxc5 Kh7 Rdg1 c6 Qxa4 Qd5 Qd4 Rfb7 Qxd5 exd5 R1g2 h4 Rh3 Kg8
1264238 <first : 12 +80 841 3205557 Nc5 Bxc5 dxc5 Kh7 Rdg1 Rb8 e4 Qxf4 Qxe6 Qe5 Qxe5 fxe5 Rg5 h4 Rxe5 Rf2 Re7 Rbxb2 Rgxg7+ Kh6 Rxc7 Rxh2
1272249 <first : 13 +68 1635 6425081 Nc5 Bxc5 dxc5 c6 e4 Qxf4 Rxb3 axb3 Qxe6 Qf3 Rb1 Qd3 Qxc6 Rd7 Qe6+ Kf8 Rc1 Qd2 Qc4 Rd4 Qc3 Rd3 Qxd2 Rxd2
1281993 <first : 14 +54 2617 10700168 Nc5 Bxc5 dxc5 c6 e4 Qxf4 Rxb3 axb3 Qxe6 Qf3 Rb1 Qd3 Qxc6 Rd7 Rc1 Kh8 Qe6 Qd1 Qc4 Rd4 Qc3 Rd3 Qc4
1299378 <first : 14 +54 2617 18370585 Nc5 Bxc5 dxc5 c6 e4 Qxf4 Rxb3 axb3 Qxe6 Qf3 Rb1 Qd3 Qxc6 Rd7 Rc1 Kh8 Qe6 Qd1 Qc4 Rd4 Qc3 Rd3 Qc4
1299378 <first : move d3c5
machine move 52, castling = -1 -1 -1 7 -1 -1
move to parse: d3c5
7 0 4 7 0 4 Legality test? d3c5
-1 -1 -1 7 -1 -1 Legality test? d3c5
(-1,0) (-1,0) (-1,0) (7,7) (-1,7) (-1,7) castling rights
TC string = '+40/15'
mps=40 tc=900000 inc=0
CoordsToAlgebraic, piece=1 (3,2)-(2,4) -
move: d3c5

POLYGLOT START SEARCH
POLYGLOT FEN 6k1/2p1brp1/4pp2/5q1p/p1QP1P2/Pr1NP1R1/1P5P/K2R4 w - - 0 27
> ENGINE position startpos moves d2d4 d7d5 c2c4 d5c4 g1f3 g8f6 d1a4 b8d7 b1c3 e7e6 g2g3 a7a6 f1g2 f8e7 c1f4 f6d5 a4c4 d5f4 g3f4 d7b6 c4b3 e8g8 e1c1 a6a5 a2a3 a5a4 b3c2 f7f6 c1b1 b6d5 e2e3 b7b5 f3e1 c8b7 c3b5 a8b8 b1a1 d5e3 f2e3 b7g2 c2g2 b8b5 h1g1 f8f7 e1d3 d8d5 g2c2 b5b3 g1g3 d5f5 c2c4 h7h5
> ENGINE go wtime 361470 btime 186580 movestogo 14
< ENGINE info depth 1 seldepth 4 time 20 score cp -234 nodes 8 nps 400 hashfull 0 pv c4c7 b3d3
> XBOARD 1 -234 2 8 Qxc7 Rxd3
< ENGINE info depth 1 seldepth 4 time 20 score cp -37 nodes 16 nps 800 hashfull 0 pv e3e4 f5e4
> XBOARD 1 -37 2 16 e4 Qxe4
< ENGINE info depth 1 seldepth 6 time 20 score cp 113 nodes 37 nps 1850 hashfull 0 pv h2h4
> XBOARD 1 +113 2 37 h4
< ENGINE info nodes 73
< ENGINE info depth 2 seldepth 7 time 20 score cp 95 nodes 158 nps 7900 hashfull 0 pv h2h4 e7d6
> XBOARD 2 +95 2 158 h4 Bd6
< ENGINE info nodes 394
< ENGINE info depth 3 seldepth 11 time 30 score cp 44 nodes 1020 nps 34000 hashfull 0 pv h2h4 f5b5 c4b5 b3b5
> XBOARD 3 +44 3 1020 h4 Qb5 Qxb5 Rxb5
< ENGINE info depth 3 seldepth 11 time 30 score cp 78 nodes 1832 nps 61066 hashfull 0 pv g3g1 f5b5 c4c2
> XBOARD 3 +78 3 1832 Rgg1 Qb5 Qc2
< ENGINE info depth 3 seldepth 11 time 30 score cp 89 nodes 2342 nps 78066 hashfull 0 pv d3c5 e7c5 d4c5 c7c6 c4a4
> XBOARD 3 +89 3 2342 Nc5 Bxc5 dxc5 c6 Qxa4
< ENGINE info nodes 3355
< ENGINE info depth 4 seldepth 11 time 40 score cp 101 nodes 4084 nps 102100 hashfull 0 pv d3c5 e7c5 d4c5 b3b8 e3e4 f5f4 c4e6
> XBOARD 4 +101 4 4084 Nc5 Bxc5 dxc5 Rb8 e4 Qxf4 Qxe6
< ENGINE info nodes 5512
< ENGINE info depth 5 seldepth 12 time 40 score cp 101 nodes 6671 nps 166775 hashfull 0 pv d3c5 e7c5 d4c5 b3b8 e3e4 f5f4 c4e6
> XBOARD 5 +101 4 6671 Nc5 Bxc5 dxc5 Rb8 e4 Qxf4 Qxe6
< ENGINE info nodes 10310
< ENGINE info depth 6 seldepth 19 time 120 score cp 85 nodes 29279 nps 243991 hashfull 0 pv d3c5 e7c5 d4c5 b3b8 h2h4 g8h8 d1d3 f7e7 d3d2 c7c6
> XBOARD 6 +85 12 29279 Nc5 Bxc5 dxc5 Rb8 h4 Kh8 Rd3 Re7 Rd2 c6
< ENGINE info nodes 44373
< ENGINE info depth 7 seldepth 23 time 310 score cp 62 nodes 86114 nps 277787 hashfull 1 pv d3c5 e7c5 d4c5 h5h4 e3e4 f5f4 g3b3 a4b3 c4e6 c7c6
> XBOARD 7 +62 31 86114 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 c6
< ENGINE info nodes 147792
< ENGINE info depth 8 seldepth 8
< ENGINE info depth 8 seldepth 19 time 520 score cp 82 nodes 161883 nps 311313 hashfull 2 pv d3c5 e7c5 d4c5 h5h4 e3e4 f5f4 g3b3 a4b3 c4e6 g7g6 d1d8 g8g7 h2h3
> XBOARD 8 +82 52 161883 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 g6 Rd8+ Kg7 h3
< ENGINE info currmovenumber 2 currmove a1a2
< ENGINE info currmovenumber 3 currmove c4a6
< ENGINE info currmovenumber 4 currmove d1d2
< ENGINE info currmovenumber 5 currmove h2h4
< ENGINE info currmovenumber 6 currmove g3g2
< ENGINE info currmovenumber 7 currmove e3e4
< ENGINE info currmovenumber 8 currmove g3g1
< ENGINE info currmovenumber 9 currmove d3c1
< ENGINE info currmovenumber 10 currmove c4a4
< ENGINE info currmovenumber 11 currmove c4c6
< ENGINE info currmovenumber 12 currmove c4c7
< ENGINE info currmovenumber 13 currmove d3e5
< ENGINE info currmovenumber 14 currmove h2h3
< ENGINE info currmovenumber 15 currmove d3f2
< ENGINE info currmovenumber 16 currmove c4c2
< ENGINE info currmovenumber 17 currmove d3e1
< ENGINE info currmovenumber 18 currmove g3g7
< ENGINE info currmovenumber 19 currmove a1b1
< ENGINE info currmovenumber 20 currmove d4d5
< ENGINE info currmovenumber 21 currmove d1g1
< ENGINE info currmovenumber 22 currmove g3f3
< ENGINE info currmovenumber 23 currmove g3g6
< ENGINE info currmovenumber 24 currmove d3b4
< ENGINE info currmovenumber 25 currmove d1e1
< ENGINE info currmovenumber 26 currmove d1c1
< ENGINE info currmovenumber 27 currmove g3g5
< ENGINE info currmovenumber 28 currmove d1h1
< ENGINE info currmovenumber 29 currmove d1f1
< ENGINE info currmovenumber 30 currmove d1b1
< ENGINE info currmovenumber 31 currmove c4c1
< ENGINE info currmovenumber 32 currmove g3g4
< ENGINE info currmovenumber 33 currmove g3h3
< ENGINE info currmovenumber 34 currmove c4c3
< ENGINE info currmovenumber 35 currmove c4b3
< ENGINE info currmovenumber 36 currmove c4b4
< ENGINE info currmovenumber 37 currmove c4c5
< ENGINE info currmovenumber 38 currmove c4b5
< ENGINE info currmovenumber 39 currmove c4d5
< ENGINE info currmovenumber 40 currmove c4e6
< ENGINE info nodes 202814
< ENGINE info depth 9 seldepth 9
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info depth 9 seldepth 22 time 781 score cp 94 nodes 255173 nps 326725 hashfull 4 pv d3c5 e7c5 d4c5 h5h4 e3e4 f5f4 g3b3 a4b3 c4e6 g7g6 e6b3 g8g7 b3c2 f7e7
> XBOARD 9 +94 78 255173 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 g6 Qxb3 Kg7 Qc2 Re7
< ENGINE info currmovenumber 2 currmove a1a2
< ENGINE info currmovenumber 3 currmove h2h4
< ENGINE info currmovenumber 4 currmove d1d2
< ENGINE info currmovenumber 5 currmove c4a6
< ENGINE info currmovenumber 6 currmove d3c1
< ENGINE info currmovenumber 7 currmove g3g2
< ENGINE info currmovenumber 8 currmove g3g1
< ENGINE info currmovenumber 9 currmove c4a4
< ENGINE info currmovenumber 10 currmove e3e4
< ENGINE info currmovenumber 11 currmove g3g7
< ENGINE info currmovenumber 12 currmove d3e5
< ENGINE info currmovenumber 13 currmove c4c6
< ENGINE info currmovenumber 14 currmove h2h3
< ENGINE info currmovenumber 15 currmove c4c7
< ENGINE info currmovenumber 16 currmove c4c2
< ENGINE info currmovenumber 17 currmove d3f2
< ENGINE info currmovenumber 18 currmove a1b1
< ENGINE info currmovenumber 19 currmove d1g1
< ENGINE info currmovenumber 20 currmove d3e1
< ENGINE info currmovenumber 21 currmove d3b4
< ENGINE info currmovenumber 22 currmove d4d5


< ENGINE info currmovenumber 23 currmove d1c1
< ENGINE info currmovenumber 24 currmove g3g6
< ENGINE info currmovenumber 25 currmove g3f3
< ENGINE info currmovenumber 26 currmove d1e1
< ENGINE info currmovenumber 27 currmove d1f1
< ENGINE info currmovenumber 28 currmove d1h1
< ENGINE info currmovenumber 29 currmove d1b1
< ENGINE info currmovenumber 30 currmove g3g4
< ENGINE info currmovenumber 31 currmove g3g5
< ENGINE info currmovenumber 32 currmove g3h3
< ENGINE info currmovenumber 33 currmove c4b3
< ENGINE info currmovenumber 34 currmove c4c3
< ENGINE info currmovenumber 35 currmove c4c1
< ENGINE info currmovenumber 36 currmove c4b5
< ENGINE info currmovenumber 37 currmove c4c5
< ENGINE info currmovenumber 38 currmove c4b4
< ENGINE info currmovenumber 39 currmove c4d5
< ENGINE info currmovenumber 40 currmove c4e6
< ENGINE info nodes 310445
< ENGINE info depth 10 seldepth 10
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info depth 10 seldepth 27 time 1231 score cp 76 nodes 421772 nps 342625 hashfull 8 pv d3c5 e7c5 d4c5 h5h4 e3e4 f5f4 g3b3 a4b3 c4e6 f4h2 d1d8 g8h7 e6b3 h2g1 a1a2 f7e7 b3d5
> XBOARD 10 +76 123 421772 Nc5 Bxc5 dxc5 h4 e4 Qxf4 Rxb3 axb3 Qxe6 Qxh2 Rd8+ Kh7 Qxb3 Qg1+ Ka2 Re7 Qd5
< ENGINE info currmovenumber 2 currmove h2h4
< ENGINE info currmovenumber 3 currmove a1a2
< ENGINE info currmovenumber 4 currmove d3c1
< ENGINE info currmovenumber 5 currmove d1d2
< ENGINE info currmovenumber 6 currmove g3g2
< ENGINE info currmovenumber 7 currmove c4a6
< ENGINE info currmovenumber 8 currmove c4a4
< ENGINE info currmovenumber 9 currmove e3e4
< ENGINE info currmovenumber 10 currmove g3g1
< ENGINE info currmovenumber 11 currmove d3e5
< ENGINE info currmovenumber 12 currmove g3g7
< ENGINE info currmovenumber 13 currmove c4c6
< ENGINE info currmovenumber 14 currmove c4c7
< ENGINE info currmovenumber 15 currmove h2h3
< ENGINE info currmovenumber 16 currmove d3f2
< ENGINE info hashfull 14 nps 359922 tbhits 0
< ENGINE info currmovenumber 17 currmove d1g1
< ENGINE info currmovenumber 18 currmove d3e1
< ENGINE info currmovenumber 19 currmove c4c2
< ENGINE info currmovenumber 20 currmove d4d5
< ENGINE info currmovenumber 21 currmove a1b1
< ENGINE info currmovenumber 22 currmove d3b4
< ENGINE info currmovenumber 23 currmove d1c1
< ENGINE info currmovenumber 24 currmove c4b5
< ENGINE info currmovenumber 25 currmove g3g6
< ENGINE info currmovenumber 26 currmove d1e1
< ENGINE info currmovenumber 27 currmove g3f3
< ENGINE info currmovenumber 28 currmove c4b3
< ENGINE info currmovenumber 29 currmove d1h1
< ENGINE info currmovenumber 30 currmove g3g5
< ENGINE info currmovenumber 31 currmove d1f1
< ENGINE info currmovenumber 32 currmove d1b1
< ENGINE info currmovenumber 33 currmove g3g4
< ENGINE info currmovenumber 34 currmove c4c5
< ENGINE info currmovenumber 35 currmove c4c3
< ENGINE info currmovenumber 36 currmove c4d5
< ENGINE info currmovenumber 37 currmove g3h3
< ENGINE info currmovenumber 38 currmove c4c1
< ENGINE info currmovenumber 39 currmove c4b4
< ENGINE info currmovenumber 40 currmove c4e6
< ENGINE info nodes 755686
< ENGINE info depth 11 seldepth 11
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info hashfull 25 nps 362088 tbhits 0
< ENGINE info depth 11 seldepth 30 time 4827 score cp 69 nodes 1766018 nps 365862 hashfull 34 pv d3c5 e7c5 d4c5 g8h7 d1g1 c7c6 c4a4 f5d5 a4d4 f7b7 d4d5 e6d5 g1g2 h5h4 g3h3 h7g8
> XBOARD 11 +69 483 1766018 Nc5 Bxc5 dxc5 Kh7 Rdg1 c6 Qxa4 Qd5 Qd4 Rfb7 Qxd5 exd5 R1g2 h4 Rh3 Kg8
< ENGINE info currmovenumber 2 currmove h2h4
< ENGINE info currmovenumber 3 currmove a1a2
< ENGINE info currmovenumber 4 currmove e3e4
< ENGINE info currmovenumber 5 currmove d1d2
< ENGINE info hashfull 37 nps 369915 tbhits 0
< ENGINE info currmovenumber 6 currmove d3c1
< ENGINE info currmovenumber 7 currmove c4a4
< ENGINE info currmovenumber 8 currmove g3g2
< ENGINE info currmovenumber 9 currmove g3g1
< ENGINE info currmovenumber 10 currmove c4a6
< ENGINE info currmovenumber 11 currmove g3g7
< ENGINE info currmovenumber 12 currmove h2h3
< ENGINE info currmovenumber 13 currmove d3e5
< ENGINE info currmovenumber 14 currmove c4c6
< ENGINE info currmovenumber 15 currmove c4c7
< ENGINE info currmovenumber 16 currmove d3f2
< ENGINE info currmovenumber 17 currmove d3e1
< ENGINE info currmovenumber 18 currmove d1g1
< ENGINE info currmovenumber 19 currmove d4d5
< ENGINE info currmovenumber 20 currmove d3b4
< ENGINE info currmovenumber 21 currmove d1c1
< ENGINE info currmovenumber 22 currmove c4c2
< ENGINE info currmovenumber 23 currmove a1b1
< ENGINE info currmovenumber 24 currmove d1e1
< ENGINE info currmovenumber 25 currmove g3g5
< ENGINE info currmovenumber 26 currmove g3g6
< ENGINE info currmovenumber 27 currmove g3f3
< ENGINE info currmovenumber 28 currmove d1f1
< ENGINE info currmovenumber 29 currmove d1h1
< ENGINE info currmovenumber 30 currmove d1b1
< ENGINE info currmovenumber 31 currmove c4b3
< ENGINE info currmovenumber 32 currmove g3g4
< ENGINE info currmovenumber 33 currmove c4b5
< ENGINE info currmovenumber 34 currmove c4c5
< ENGINE info currmovenumber 35 currmove g3h3
< ENGINE info currmovenumber 36 currmove c4d5
< ENGINE info currmovenumber 37 currmove c4c3
< ENGINE info currmovenumber 38 currmove c4b4
< ENGINE info currmovenumber 39 currmove c4c1
< ENGINE info currmovenumber 40 currmove c4e6
< ENGINE info nodes 2310840
< ENGINE info depth 12 seldepth 12
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info hashfull 50 nps 377076 tbhits 0
< ENGINE info depth 12 seldepth 35 time 8412 score cp 80 nodes 3205557 nps 381069 hashfull 61 pv d3c5 e7c5 d4c5 g8h7 d1g1 b3b8 e3e4 f5f4 c4e6 f4e5 e6e5 f6e5 g3g5 h5h4 g5e5 f7f2 e5e7 b8b2 g1g7 h7h6 e7c7 f2h2
> XBOARD 12 +80 841 3205557 Nc5 Bxc5 dxc5 Kh7 Rdg1 Rb8 e4 Qxf4 Qxe6 Qe5 Qxe5 fxe5 Rg5 h4 Rxe5 Rf2 Re7 Rbxb2 Rgxg7+ Kh6 Rxc7 Rxh2
< ENGINE info currmovenumber 2 currmove h2h4
< ENGINE info currmovenumber 3 currmove a1a2
< ENGINE info currmovenumber 4 currmove c4a6
< ENGINE info hashfull 62 nps 382439 tbhits 0
< ENGINE info currmovenumber 5 currmove h2h3
< ENGINE info currmovenumber 6 currmove e3e4
< ENGINE info currmovenumber 7 currmove d3c1
< ENGINE info currmovenumber 8 currmove c4a4
< ENGINE info currmovenumber 9 currmove d1d2
< ENGINE info currmovenumber 10 currmove g3g2
< ENGINE info currmovenumber 11 currmove c4c6
< ENGINE info currmovenumber 12 currmove g3g7
< ENGINE info currmovenumber 13 currmove g3g1
< ENGINE info currmovenumber 14 currmove c4c7
< ENGINE info currmovenumber 15 currmove d3e5
< ENGINE info currmovenumber 16 currmove d3f2
< ENGINE info currmovenumber 17 currmove d3e1
< ENGINE info currmovenumber 18 currmove d4d5
< ENGINE info currmovenumber 19 currmove d1g1
< ENGINE info currmovenumber 20 currmove d1c1
< ENGINE info currmovenumber 21 currmove d3b4
< ENGINE info currmovenumber 22 currmove d1e1
< ENGINE info currmovenumber 23 currmove a1b1
< ENGINE info currmovenumber 24 currmove c4c2
< ENGINE info currmovenumber 25 currmove g3f3
< ENGINE info currmovenumber 26 currmove g3g5
< ENGINE info currmovenumber 27 currmove d1h1
< ENGINE info currmovenumber 28 currmove d1f1
< ENGINE info currmovenumber 29 currmove g3g6
< ENGINE info currmovenumber 30 currmove d1b1
< ENGINE info currmovenumber 31 currmove g3h3
< ENGINE info currmovenumber 32 currmove c4b3
< ENGINE info currmovenumber 33 currmove c4d5
< ENGINE info currmovenumber 34 currmove g3g4
< ENGINE info currmovenumber 35 currmove c4e6
< ENGINE info currmovenumber 36 currmove c4b5
< ENGINE info currmovenumber 37 currmove c4c5
< ENGINE info currmovenumber 38 currmove c4b4
< ENGINE info currmovenumber 39 currmove c4c1
< ENGINE info currmovenumber 40 currmove c4c3
< ENGINE info nodes 3641056
< ENGINE info depth 13 seldepth 13
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info hashfull 73 nps 387237 tbhits 0
< ENGINE info hashfull 84 nps 387744 tbhits 0
< ENGINE info hashfull 96 nps 391329 tbhits 0
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info hashfull 105 nps 394690 tbhits 0
< ENGINE info depth 13 seldepth 35 time 16353 score cp 68 nodes 6425081 nps 392899 hashfull 112 pv d3c5 e7c5 d4c5 c7c6 e3e4 f5f4 g3b3 a4b3 c4e6 f4f3 d1b1 f3d3 e6c6 f7d7 c6e6 g8f8 b1c1 d3d2 e6c4 d7d4 c4c3 d4d3 c3d2 d3d2
> XBOARD 13 +68 1635 6425081 Nc5 Bxc5 dxc5 c6 e4 Qxf4 Rxb3 axb3 Qxe6 Qf3 Rb1 Qd3 Qxc6 Rd7 Qe6+ Kf8 Rc1 Qd2 Qc4 Rd4 Qc3 Rd3 Qxd2 Rxd2
< ENGINE info currmovenumber 2 currmove h2h4
< ENGINE info hashfull 114 nps 394299 tbhits 0
< ENGINE info currmovenumber 3 currmove a1a2
< ENGINE info currmovenumber 4 currmove d3c1
< ENGINE info currmovenumber 5 currmove e3e4
< ENGINE info currmovenumber 6 currmove c4a4
< ENGINE info hashfull 125 nps 397902 tbhits 0
< ENGINE info currmovenumber 7 currmove c4a6
< ENGINE info currmovenumber 8 currmove h2h3
< ENGINE info currmovenumber 9 currmove d1d2
< ENGINE info currmovenumber 10 currmove c4c7
< ENGINE info currmovenumber 11 currmove g3g2
< ENGINE info currmovenumber 12 currmove c4c6
< ENGINE info currmovenumber 13 currmove g3g7
< ENGINE info currmovenumber 14 currmove g3g1
< ENGINE info currmovenumber 15 currmove d3e5
< ENGINE info currmovenumber 16 currmove d3f2
< ENGINE info currmovenumber 17 currmove d3e1
< ENGINE info currmovenumber 18 currmove d4d5
< ENGINE info currmovenumber 19 currmove d1g1
< ENGINE info currmovenumber 20 currmove d3b4
< ENGINE info currmovenumber 21 currmove d1e1
< ENGINE info currmovenumber 22 currmove d1c1
< ENGINE info currmovenumber 23 currmove g3f3
< ENGINE info currmovenumber 24 currmove a1b1
< ENGINE info currmovenumber 25 currmove g3g5
< ENGINE info currmovenumber 26 currmove d1f1
< ENGINE info currmovenumber 27 currmove d1h1
< ENGINE info currmovenumber 28 currmove d1b1
< ENGINE info currmovenumber 29 currmove c4c2
< ENGINE info currmovenumber 30 currmove g3g6
< ENGINE info currmovenumber 31 currmove c4d5
< ENGINE info currmovenumber 32 currmove c4b5
< ENGINE info currmovenumber 33 currmove g3g4
< ENGINE info currmovenumber 34 currmove g3h3
< ENGINE info currmovenumber 35 currmove c4b3
< ENGINE info currmovenumber 36 currmove c4e6
< ENGINE info currmovenumber 37 currmove c4c1
< ENGINE info currmovenumber 38 currmove c4c5
< ENGINE info currmovenumber 39 currmove c4c3
< ENGINE info currmovenumber 40 currmove c4b4
< ENGINE info nodes 7961249
< ENGINE info depth 14 seldepth 14
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info hashfull 138 nps 402121 tbhits 0
< ENGINE info hashfull 149 nps 403667 tbhits 0
< ENGINE info hashfull 161 nps 406673 tbhits 0
< ENGINE info hashfull 171 nps 407252 tbhits 0
< ENGINE info currmovenumber 1 currmove d3c5
< ENGINE info depth 14 seldepth 45 time 26167 score cp 54 nodes 10700168 nps 408918 hashfull 177 pv d3c5 e7c5 d4c5 c7c6 e3e4 f5f4 g3b3 a4b3 c4e6 f4f3 d1b1 f3d3 e6c6 f7d7 b1c1 g8h8 c6e6 d3d1 e6c4 d7d4 c4c3 d4d3 c3c4
> XBOARD 14 +54 2617 10700168 Nc5 Bxc5 dxc5 c6 e4 Qxf4 Rxb3 axb3 Qxe6 Qf3 Rb1 Qd3 Qxc6 Rd7 Rc1 Kh8 Qe6 Qd1 Qc4 Rd4 Qc3 Rd3 Qc4
< ENGINE info currmovenumber 2 currmove h2h4
< ENGINE info hashfull 181 nps 410237 tbhits 0
< ENGINE info hashfull 192 nps 410112 tbhits 0
< ENGINE info currmovenumber 3 currmove e3e4
< ENGINE info hashfull 202 nps 411240 tbhits 0
< ENGINE info currmovenumber 4 currmove c4a4
< ENGINE info currmovenumber 5 currmove d3c1
< ENGINE info hashfull 211 nps 415256 tbhits 0
< ENGINE info currmovenumber 6 currmove a1a2
< ENGINE info hashfull 222 nps 415912 tbhits 0
< ENGINE info currmovenumber 7 currmove g3g1
< ENGINE info currmovenumber 8 currmove c4a6
< ENGINE info hashfull 231 nps 415423 tbhits 0
< ENGINE info currmovenumber 9 currmove g3g7
< ENGINE info hashfull 243 nps 417107 tbhits 0
< ENGINE info currmovenumber 10 currmove h2h3
< ENGINE info currmovenumber 11 currmove c4c7
< ENGINE info hashfull 256 nps 418647 tbhits 0
< ENGINE info currmovenumber 12 currmove c4c6
< ENGINE info hashfull 268 nps 420780 tbhits 0
< ENGINE info currmovenumber 13 currmove d1d2
< ENGINE info currmovenumber 14 currmove g3g2
< ENGINE info hashfull 277 nps 421200 tbhits 0
< ENGINE info currmovenumber 15 currmove d3e5
< ENGINE info currmovenumber 16 currmove d3f2
< ENGINE info currmovenumber 17 currmove d1e1
< ENGINE info currmovenumber 18 currmove d3e1
< ENGINE info currmovenumber 19 currmove d4d5
< ENGINE info currmovenumber 20 currmove d3b4
< ENGINE info currmovenumber 21 currmove d1g1
< ENGINE info currmovenumber 22 currmove d1c1
< ENGINE info hashfull 285 nps 421591 tbhits 0
< ENGINE info currmovenumber 23 currmove g3f3
< ENGINE info currmovenumber 24 currmove d1h1
< ENGINE info currmovenumber 25 currmove a1b1
< ENGINE info currmovenumber 26 currmove g3g5
< ENGINE info currmovenumber 27 currmove d1f1
< ENGINE info currmovenumber 28 currmove d1b1
< ENGINE info currmovenumber 29 currmove c4c2
< ENGINE info currmovenumber 30 currmove c4d5
< ENGINE info currmovenumber 31 currmove c4b5
< ENGINE info currmovenumber 32 currmove g3g6
< ENGINE info currmovenumber 33 currmove c4b3
< ENGINE info currmovenumber 34 currmove c4e6
< ENGINE info currmovenumber 35 currmove g3g4
< ENGINE info currmovenumber 36 currmove c4c1
< ENGINE info currmovenumber 37 currmove g3h3
< ENGINE info currmovenumber 38 currmove c4c3
< ENGINE info currmovenumber 39 currmove c4c5
< ENGINE info currmovenumber 40 currmove c4b4
< ENGINE info nps 421808 cpuload 994 nodes 18370585 hashfull 289
< ENGINE bestmove d3c5 ponder e7c5
> XBOARD 14 +54 2617 18370585 Nc5 Bxc5 dxc5 c6 e4 Qxf4 Rxb3 axb3 Qxe6 Qf3 Rb1 Qd3 Qxc6 Rd7 Rc1 Kh8 Qe6 Qd1 Qc4 Rd4 Qc3 Rd3 Qc4
> XBOARD move d3c5
POLYGLOT MOVE Nc5

PGN file for above debug snippets:

[Event "RWBC PSWBTM RT46"]
[Site "ESPRESSO"]
[Date "2008.08.30"]
[Round "3.3"]
[White "Shredder_11UCI"]
[Black "Naum_31"]
[Result "1-0"]
[TimeControl "40/900"]
[Annotator "11. +0.19 8... +0.09"]
[Number "105"]

1. d4 d5 2. c4 dxc4 3. Nf3 Nf6 4. Qa4+ Nbd7 5. Nc3 e6 6. g3 a6 7. Bg2 Be7
8. Bf4 Nd5 {+0.09/15 15} 9. Qxc4 Nxf4 {+0.09/15 35} 10. gxf4
Nb6 {+0.06/16 33} 11. Qb3 {+0.19/14 21} O-O {+0.07/16 58} 12.
O-O-O {+0.26/14 20} a5 {+0.23/15 30} 13. a3 {+0.16/15 25} a4 {+0.20/14 15}
14. Qc2 {+0.27/15 31} f6 {+0.15/15 54} 15. Kb1 {+0.28/14 27}
Nd5 {+0.29/13 16} 16. e3 {+0.28/13 3} b5 {+0.19/14 34} 17.
Ne1 {-0.13/13 21} Bb7 {+0.17/15 17} 18. Nxb5 {+0.37/12 3} Rb8 {+0.14/14 36}
19. Ka1 {-0.30/14 18} Nxe3 {+0.05/15 21} 20. fxe3 {+0.09/15 55}
Bxg2 {+0.09/16 52} 21. Qxg2 {-0.02/16 1:39} Rxb5 {+0.02/16 9} 22.
Rg1 {+0.01/16 10} Rf7 {+0.00/16 18} 23. Nd3 {+0.35/14 25} Qd5 {-0.01/15 8}
24. Qc2 {+0.25/14 33} Rb3 {+0.00/15 9} 25. Rg3 {+0.28/13 12}
Qf5 {+0.00/15 11} 26. Qc4 {+0.57/12 6} h5 {-0.10/15 56} 27.
Nc5 {+0.54/14 26} Bxc5 {-0.06/15 14} 28. dxc5 {+0.31/15 45} h4 {-0.03/15 8}
29. Rgg1 {+0.31/15 11} c6 {+0.00/15 10} 30. Rd8+ {+0.64/15 57}
Kh7 {-0.12/15 13} 31. Qd4 {+0.64/15 8} Qh3 {-0.33/15 9} 32.
Qd1 {+0.63/14 17} g6 {+0.00/15 11} 33. Rd7 {+0.63/15 3} Rb7 {-0.32/15 15}
34. Rxf7+ {+0.42/15 1:02} Rxf7 {-0.41/4 0} 35. e4 {+0.33/16 31}
Rg7 {+0.04/15 13} 36. Qd2 {+0.55/13 7} Ra7 {+0.01/15 10} 37.
Rd1 {+0.57/14 12} Qg4 {+0.14/16 19} 38. e5 {+0.58/13 5} fxe5 {+0.20/16 10}
39. fxe5 {+0.73/13 2} Rf7 {+0.03/16 10} 40. Qd6 {+0.35/14 9}
Kg7 {+0.20/15 8} 41. Rb1 {+0.83/16 18} Qf5 {+0.00/16 18} 42.
Qxc6 {+0.62/16 59} Qxe5 {-0.04/16 15} 43. Qxa4 {+0.87/16 37}
Qxh2 {-0.10/16 23} 44. c6 {+0.87/15 5} e5 {-0.26/15 30} 45.
Qa5 {+0.99/15 11} Kh6 {-0.32/15 45} 46. c7 {+2.52/12 13} Qc2 {-0.68/16 8}
47. Qe1 {+2.36/13 9} Qxc7 {-1.02/18 23} 48. Qxh4+ {+2.41/13 6}
Kg7 {-0.24/1 0} 49. Rh1 {+2.41/15 8} Kf8 {-1.06/18 16} 50.
Qh6+ {+2.54/15 30} Ke7 {-1.12/19 38} 51. Qg5+ {+2.54/15 10}
Kd7 {-5.82/20 1:53} 52. Rd1+ {+2.54/14 0} Kc8 {-5.82/18 11} 53.
Rc1 {+6.64/13 3} Qxc1+ {-5.82/18 12} 54. Qxc1+ {+7.25/15 5}
Kd7 {-5.82/19 7} 55. Qg5 {+7.70/15 20} Re7 {-5.82/19 8} 56.
Qxg6 {+7.68/15 6} e4 {-7.51/21 21} 57. Qf5+ {+7.68/14 23} Ke8 {-7.49/15 21}
58. Qb5+ {+8.36/15 15} Kf8 {-7.50/16 23} 59. Qb8+ {+8.36/14 15}
Kf7 {-7.95/20 8} 60. Qb3+ {+8.36/14 0} Kf6 {-6.68/13 7} 61.
Qe3 {+9.11/15 43} Kf5 {-7.84/18 9} 62. b4 {+9.46/15 28} Rh7 {-6.68/14 8}
63. a4 {+9.46/13 4} Rh1+ {-8.00/17 22} 64. Kb2 {+10.52/13 15}
Rh2+ {-22.51/19 52} 65. Kb3 {+10.52/13 0} Rh8 {-6.68/13 5} 66.
Qc5+ {+15.92/13 19} Kg4 {-299.45/17 4} 67. Qe5 {+24.38/13 12}
Rh3+ {-299.47/15 2} 68. Kc4 {+24.38/13 0}
{Black resigns} 1-0

[Guenther Simon]

Code: Select all

* bestmove  [ ponder  ]
   the engine has stopped searching and found the move  best in this position.
   the engine can send the move it likes to ponder on. The engine must not start pondering automatically.
   this command must always be sent if the engine stops searching, also in pondering mode if there is a
   "stop" command, so for every "go" command a "bestmove" command is needed!
   Directly before that the engine should send a final "info" command with the final search information,
   the the GUI has the complete statistics about the last search.


It seems that a lot of UCI engines _don't_ send the last search info directly
before they finally make their best move. Thus current WB time counting
of course cannot work, but this behaviour also screws up other useful
tools as LGDEBUG which provides more infos/stats from debugs.

An example:
(LGDEBUG 1.42 with args -t4 -s -n -k -m100. Note that t4 is sum of
used time in centisec. I desired this once from George, because it
immediately shows bad time management for games with moves/time.
It needs just one look how near engines come to 900s at my tc.)

BTW I started LGDEBUG on all debugs played in a current tourney
because I noticed that one engine -Predateur- was hanging in memory
over night. The TaskManager though showed no CPU usage and as there
was enough free memory despite the unwanted app I just wanted to
check if it had still an influence on the meanwhile played games for deciding
if the games are usable or for the trash bin.

To my big surprise I found this very weird numbers for Smash e.g.
in this game below(node count and speed in kns!!):

[Event "?"]
[Site "?"]
[Date "2008.11.06"]
[Round "1"]
[White "Cheese 1.3"]
[Black "Smash_103"]
[Result "1-0"]
[TimeControl "40/900"]
[PlyCount "134"]
[Annotator "14.8-11.8"]

1. e4 {0.03s} e5 {0.43s} 2. Nf3 {0.04s} Nc6 {0.49s} 3. Bb5 {0.06s} Nf6 {0.51s} 4. O-O {0.08s} Nxe4
{0.53s} 5. d4 {0.10s} Nd6 {0.55s} 6. Bxc6 {+1.21/12 14.68s 7271338n 498.7Knps} dxc6 {0.60s} 7. dxe5
{+1.41/12 37.41s 5725172n 493.3Knps} Nf5 {0.65s} 8. Qxd8+ {+1.24/13 55.60s 9328220n 512.9Knps} Kxd8
{0.70s} 9. Nc3 {+1.25/13 78.44s 5515376n 532.1Knps} Bd7 {0.74s} 10. Rd1
{+1.57/12 101.29s 5608045n 513.7Knps} Kc8 {0.79s} 11. Ng5 {+1.57/13 124.13s 6706409n 550.3Knps} Be8
{0.84s} 12. Bf4 {+1.49/13 146.97s 4111604n 568.7Knps} h6 {-0.22/10 31.88s 3561378n 114.7Knps} 13.
Nge4 {+1.25/13 162.52s 8589110n 552.6Knps} a5 {-0.20/10 62.90s 5009343n 161.5Knps} 14. Rd3
{+1.55/13 185.59s 7164247n 584.9Knps} a4 {-0.15/9 81.51s 2509949n 134.9Knps} 15. Rad1
{+2.31/14 208.67s 6991119n 611.3Knps} Be7 {-0.13/9 113.04s 1720711n 54.6Knps} 16. Nd6+
{+1.87/14 228.95s 12421815n 612.5Knps} cxd6 {-0.11/12 129.90s 2910731n 172.6Knps} 17. exd6
{+1.77/14 252.11s 6952668n 664.4Knps} Nxd6 {-0.09/11 158.82s 1087103n 37.6Knps} 18. Bxd6
{+2.24/14 270.33s 13701813n 752.2Knps} Bxd6 {-0.08/11 187.60s 5023005n 174.5Knps} 19. Rxd6
{+2.18/13 293.66s 9135002n 854.9Knps} Kc7 {-0.09/10 219.63s 3939136n 123.0Knps} 20. R6d4
{+2.21/12 317.00s 10733929n 882.9Knps} a3 {+0.05/11 252.05s 5317866n 164.1Knps} 21. b3
{+1.81/12 333.12s 12836493n 796.1Knps} Rg8 {+0.05/9 284.51s 5446993n 167.8Knps} 22. Rc4
{+1.99/12 356.75s 8514708n 816.8Knps} Kb6 {+0.00/10 315.99s 4799251n 152.5Knps} 23. Ne4
{+2.01/11 380.38s 7507294n 809.5Knps} Kc7 {-0.03/10 345.21s 2229905n 76.3Knps} 24. Nc5
{+1.71/13 395.63s 13272555n 870.3Knps} b6 {+0.15/10 377.86s 4193978n 128.5Knps} 25. Nd3
{+1.35/13 419.67s 7162091n 848.3Knps} Rf8 {+0.14/9 406.19s 5762734n 203.4Knps} 26. Rg4
{+1.84/11 443.72s 8423639n 757.8Knps} g5 {+0.05/10 425.92s 2871960n 145.6Knps} 27. Re4
{+1.39/12 466.45s 17085296n 751.6Knps} Bd7 {+0.07/10 459.82s 4459100n 131.5Knps} 28. Ne5
{+1.35/11 490.55s 6220675n 750.2Knps} Bf5 {+0.17/10 493.70s 5713126n 168.6Knps} 29. Rc4
{+0.78/13 509.64s 14284939n 748.4Knps} c5 {+0.21/9 527.58s 1001263n 29.6Knps} 30. Rc3
{+0.90/13 534.06s 8066164n 721.1Knps} f6 {+0.22/10 551.83s 4387490n 181.0Knps} 31. Nc4
{+0.71/14 558.48s 7436356n 735.3Knps} h5 {+0.20/10 571.88s 3199842n 159.6Knps} 32. Ne3
{+0.69/12 577.24s 14012959n 747.1Knps} Be6 {+0.24/10 606.33s 6570592n 190.7Knps} 33. Rd4
{+0.60/12 602.09s 6578026n 722.6Knps} Kc6 {+0.31/10 643.33s 4439964n 120.0Knps} 34. Rd2
{+0.33/13 620.89s 15645568n 832.3Knps} Rad8 {+0.35/12 680.01s 4466846n 121.8Knps} 35. Rcd3
{-0.01/15 636.72s 13391035n 845.8Knps} Rxd3 {+0.42/12 698.60s 3794637n 204.2Knps} 36. Rxd3
{+0.00/16 663.07s 11738265n 812.8Knps} b5 {+0.38/11 738.86s 8287206n 205.9Knps} 37. f3
{+0.00/14 686.25s 18046298n 778.4Knps} h4 {+0.47/10 760.69s 3079724n 141.1Knps} 38. g3
{-0.07/14 708.31s 16909576n 766.8Knps} Rf7 {+0.45/12 807.11s 8570465n 184.6Knps} 39. gxh4
{+0.10/14 735.70s 13533620n 788.0Knps} gxh4 {+0.49/11 853.51s 3531147n 76.1Knps} 40. f4
{+0.17/14 763.10s 12349660n 793.0Knps} Rd7 {+0.40/13 899.78s 7592628n 164.1Knps} 41. Rxd7
{+0.21/17 970.49s 9639812n 875.9Knps} Bxd7 {+0.42/12 911.40s 2173381n 187.1Knps} 42. Kg2
{+0.25/18 1177.87s 36163172n 865.6Knps} Kd6 {+0.30/11 934.19s 3302153n 144.9Knps} 43. Kf3
{+0.01/17 1385.23s 73283460n 855.4Knps} Bc8 {+0.20/11 957.01s 3664324n 160.6Knps} 44. Ke4
{+0.06/17 1592.58s 13278041n 870.0Knps} h3 {+0.00/11 979.81s 2738906n 120.1Knps} 45. c3
{+0.81/17 1696.26s 9759278n 874.8Knps} Be6 {-0.62/11 1002.60s 3562235n 156.3Knps} 46. Nc2
{+1.05/13 1697.95s 1432488n 846.1Knps} Bd5+ {-0.56/12 1025.39s 2432261n 106.7Knps} 47. Kf5
{+1.16/17 1700.46s 2281363n 907.5Knps} Ke7 {-0.66/12 1041.27s 3418849n 215.3Knps} 48. Nxa3
{+1.27/16 1703.10s 1100623n 893.4Knps} Bc6 {-1.05/11 1055.02s 1674225n 121.8Knps} 49. Kg4
{+1.33/15 1705.74s 1135185n 865.2Knps} Bd7+ {-1.19/12 1078.32s 4316490n 185.2Knps} 50. Kg3
{+1.36/15 1708.38s 634578n 802.2Knps} Kf7 {-1.33/11 1095.01s 1720514n 103.1Knps} 51. Kf3
{+1.30/14 1711.01s 1022874n 873.5Knps} Kg6 {-0.92/11 1112.52s 2764377n 157.9Knps} 52. c4
{+1.41/16 1712.83s 1606617n 881.8Knps} b4 {-0.82/12 1124.66s 1949268n 160.6Knps} 53. Nb5
{+1.72/17 1714.83s 1777704n 888.0Knps} Bc6+ {-1.53/13 1148.82s 4559065n 188.7Knps} 54. Kg4
{+2.09/15 1717.05s 1992344n 896.2Knps} Bd7+ {-1.53/13 1172.95s 1416969n 58.7Knps} 55. Kg3
{+2.03/19 1719.73s 1627478n 912.8Knps} Bf5 {-1.59/13 1186.00s 1542256n 118.3Knps} 56. Nd6
{+2.43/20 1721.82s 2009767n 960.2Knps} Bb1 {-2.21/14 1207.79s 3172833n 145.6Knps} 57. Nb7
{+2.15/19 1723.65s 1856516n 1012.8Knps} Kf5 {-2.28/14 1222.53s 2486583n 168.7Knps} 58. Nxc5
{+2.25/19 1725.56s 1789296n 935.3Knps} Bxa2 {-2.26/14 1237.86s 3368021n 219.7Knps} 59. Kf3
{+2.25/18 1728.32s 1358254n 935.4Knps} Bb1 {-2.29/14 1251.67s 2364695n 171.2Knps} 60. Ke3
{+2.30/17 1730.24s 1831397n 952.4Knps} Bc2 {-1.99/12 1277.80s 3278488n 125.5Knps} 61. Kd2
{+1.50/17 1732.96s 2542567n 933.4Knps} Be4 {-1.97/13 1294.04s 4126638n 254.1Knps} 62. Nd3
{+2.37/17 1735.75s 1444944n 930.4Knps} Bxd3 {-1.88/13 1313.07s 471537n 24.8Knps} 63. Kxd3
{+8.74/20 1738.46s 3055263n 1125.7Knps} Ke6 {-4.95/17 1333.98s 5778030n 276.3Knps} 64. Kd4
{+8.76/19 1741.25s 1107398n 1084.6Knps} Kd6 {-7.13/18 1361.41s 2220369n 80.9Knps} 65. c5+
{+11.11/18 1743.11s 2037055n 1093.4Knps} Kc7 {-10.05/19 1379.51s 4517850n 249.7Knps} 66. Kc4
{+11.42/18 1745.95s 1273278n 1077.2Knps} Kc6 {-10.31/19 1402.42s 6168557n 269.3Knps} 67. f5
{+12.06/19 1748.16s 2528902n 1142.7Knps} Kd7 {-10.32/17 1430.82s 3233669n 113.9Knps}
1-0 {Xboard adjudication}

From the WB debugs and Polyglot logs I can see that it is again the case
of taking the last search info by Polyglot even if the move was made
much later! (A pity BTW that Polyglot has no timestamp)
Either the UCI engine sends no info at all with the final move or it sends
the info _after_ bestmove. Both practices seem to be against the
UCI protocol. I guess that Polyglot in the second case of sending last
seach info _after_ bestmove simply ignores it according to the protocol.
I will do a test with inbetween to see the full communication between
engine and Polyglot to verify either case one or two.
I have no idea though what Polglot could do if it doesnt want to break
the protocol? In case one though should it really duplicate the last info
even for a quite different _real_time used? At least it is clear that WB
cannot rely on those timing/nodes infos, but I guess at least it calculates
the nps info by its own timestamp, because Smash doesn't show
that strange times in the WB output window if starting after 17. exd6 from
above game.

The logs for that move:

Polyglot

Code: Select all

POLYGLOT THINK -> WAIT
< XBOARD time 77004
< XBOARD otim 64779
< XBOARD usermove e5d6
POLYGLOT MOVE exd6
POLYGLOT WAIT -> THINK
POLYGLOT START SEARCH
POLYGLOT FEN r1k1b2r/1p2bpp1/2pP3p/5n2/p4B2/2NR4/PPP2PPP/3R2K1 b - - 0 17
> ENGINE position startpos moves e2e4 e7e5 g1f3 b8c6 f1b5 g8f6 e1g1 f6e4 d2d4 e4d6 b5c6 d7c6 d4e5 d6f5 d1d8 e8d8 b1c3 c8d7 f1d1 d8c8 f3g5 d7e8 c1f4 h7h6 g5e4 a7a5 d1d3 a5a4 a1d1 f8e7 e4d6 c7d6 e5d6
> ENGINE go wtime 647790 btime 770040 movestogo 24
< ENGINE info depth 1 seldepth 10
< ENGINE info nps 800
< ENGINE info score cp 2 depth 1 nodes 8 time 10 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 1 +2 1 8 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info depth 1 seldepth 11
< ENGINE info nps 4300
< ENGINE info score cp 26 depth 1 nodes 43 time 10 pv e7f8 d6d7 e8d7 d3d7 a4a3 d7f7 a3b2 f7f5 b2b1q d1b1 a8a2
> XBOARD 1 +26 1 43 Bf8 d7+ Bxd7 Rxd7 a3 Rxf7 axb2 Rxf5 b1=Q Rxb1 Rxa2
< ENGINE info depth 1 seldepth 12
< ENGINE info nps 4500
< ENGINE info score cp 37 depth 1 nodes 45 time 10 pv e7d8 d6d7 e8d7 d3d7 d8f6 d7f7 f6c3 b2c3 a4a3 f7f5 h6h5 g1h1
> XBOARD 1 +37 1 45 Bd8 d7+ Bxd7 Rxd7 Bf6 Rxf7 Bxc3 bxc3 a3 Rxf5 h5 Kh1
< ENGINE info depth 1 seldepth 12
< ENGINE info nps 4700
< ENGINE info score cp 46 depth 1 nodes 47 time 10 pv e7f6 d6d7 e8d7 d3d7 f6c3 d7c7 c8b8 b2c3 h6h5 c7f7 f5d6 d1d6
> XBOARD 1 +46 1 47 Bf6 d7+ Bxd7 Rxd7 Bxc3 Rc7+ Kb8 bxc3 h5 Rxf7+ Nd6 Rxd6
< ENGINE info depth 2 seldepth 12
< ENGINE info nps 10400
< ENGINE info score cp -26 depth 2 nodes 104 time 10 pv e7f6 d6d7 e8d7 d3d7 f6c3 d7c7 c8b8 b2c3 h6h5 c7f7 f5d6 d1d6
> XBOARD 2 -26 1 104 Bf6 d7+ Bxd7 Rxd7 Bxc3 Rc7+ Kb8 bxc3 h5 Rxf7+ Nd6 Rxd6
< ENGINE info depth 2 seldepth 10
< ENGINE info nps 21200
< ENGINE info score cp 2 depth 2 nodes 212 time 10 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 2 +2 1 212 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 2.83051
< ENGINE info depth 3 seldepth 10
< ENGINE info nps 31700
< ENGINE info score cp 9 depth 3 nodes 317 time 10 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 3 +9 1 317 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 0.718563
< ENGINE info depth 4 seldepth 10
< ENGINE info nps 99000
< ENGINE info score cp 5 depth 4 nodes 990 time 10 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 4 +5 1 990 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 5.60833
< ENGINE info depth 5 seldepth 10
< ENGINE info nps 207800
< ENGINE info score cp -7 depth 5 nodes 2078 time 10 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 5 -7 1 2078 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 1.61664
< ENGINE info depth 6 seldepth 10
< ENGINE info nps 212500
< ENGINE info score cp -20 depth 6 nodes 4250 time 20 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 6 -20 2 4250 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 18.6627
< ENGINE info depth 7 seldepth 10
< ENGINE info nps 176261
< ENGINE info score cp -11 depth 7 nodes 22914 time 130 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 7 -11 13 22914 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 0.0261512
< ENGINE info depth 8 seldepth 10
< ENGINE info nps 191246
< ENGINE info score cp -12 depth 8 nodes 28687 time 150 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 8 -12 15 28687 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 428.043
< ENGINE info depth 9 seldepth 10
< ENGINE info nps 213456
< ENGINE info score cp -10 depth 9 nodes 335126 time 1570 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 9 -10 157 335126 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 0.373622
< ENGINE info depth 10 seldepth 10
< ENGINE info nps 213716
< ENGINE info score cp -11 depth 10 nodes 335535 time 1570 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d6
> XBOARD 10 -11 157 335535 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
< ENGINE info string branching factor = 0.00481624
< ENGINE info depth 11 seldepth 11
< ENGINE info nps 202817
< ENGINE info score cp -9 depth 11 nodes 1087103 time 5360 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4g4 f8g8
> XBOARD 11 -9 536 1087103 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rg4 Rg8
< ENGINE info string branching factor = 13174.8
< ENGINE bestmove f5d6
> XBOARD 11 -9 536 1087103 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rg4 Rg8
> XBOARD move f5d6
POLYGLOT MOVE Nxd6

Winboard debug

Code: Select all

386145 >second: time 77004
386145 >second: otim 64779
386145 >second: usermove 386145 >second: e5d6
390071 <second: 1 +2 1 8 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390071 <second: 1 +26 1 43 Bf8 d7+ Bxd7 Rxd7 a3 Rxf7 axb2 Rxf5 b1=Q Rxb1 Rxa2
390091 <second: 1 +37 1 45 Bd8 d7+ Bxd7 Rxd7 Bf6 Rxf7 Bxc3 bxc3 a3 Rxf5 h5 Kh1
390111 <second: 1 +46 1 47 Bf6 d7+ Bxd7 Rxd7 Bxc3 Rc7+ Kb8 bxc3 h5 Rxf7+ Nd6 Rxd6
390131 <second: 2 -26 1 104 Bf6 d7+ Bxd7 Rxd7 Bxc3 Rc7+ Kb8 bxc3 h5 Rxf7+ Nd6 Rxd6
390151 <second: 2 +2 1 212 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390171 <second: 3 +9 1 317 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390191 <second: 4 +5 1 990 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390211 <second: 5 -7 1 2078 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390231 <second: 6 -20 2 4250 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390231 <second: 7 -11 13 22914 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390231 <second: 8 -12 15 28687 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390231 <second: 9 -10 157 335126 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
390231 <second: 10 -11 157 335535 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rd6
391583 <second: 11 -9 536 1087103 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rg4 Rg8
415067 <second: 11 -9 536 1087103 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rg4 Rg8
415067 <second: move f5d6
machine move 33, castling = 7 -1 -1 7 0 -1
move to parse: f5d6

If FEN feeded in WB

Code: Select all

POLYGLOT FEN r1k1b2r/1p2bpp1/2pP3p/5n2/p4B2/2NR4/PPP2PPP/3R2K1 b - - 0 1
> ENGINE position fen r1k1b2r/1p2bpp1/2pP3p/5n2/p4B2/2NR4/PPP2PPP/3R2K1 b - - 0 1
> ENGINE go infinite
< ENGINE info depth 1 seldepth 1
< ENGINE info nps 800
< ENGINE info score cp 2 depth 1 nodes 8 time 10 pv f5d6
> XBOARD 1 +2 1 8 Nxd6
< ENGINE info depth 1 seldepth 1
< ENGINE info nps 4300
< ENGINE info score cp 26 depth 1 nodes 43 time 10 pv e7f8
> XBOARD 1 +26 1 43 Bf8
< ENGINE info depth 1 seldepth 1
< ENGINE info nps 4500
< ENGINE info score cp 37 depth 1 nodes 45 time 10 pv e7d8
> XBOARD 1 +37 1 45 Bd8
< ENGINE info depth 1 seldepth 1
< ENGINE info nps 4700
< ENGINE info score cp 46 depth 1 nodes 47 time 10 pv e7f6
> XBOARD 1 +46 1 47 Bf6
< ENGINE info depth 2 seldepth 3
< ENGINE info nps 11000
< ENGINE info score cp -26 depth 2 nodes 110 time 10 pv e7f6 d6d7 e8d7
> XBOARD 2 -26 1 110 Bf6 d7+ Bxd7
< ENGINE info depth 2 seldepth 2
< ENGINE info nps 26800
< ENGINE info score cp 2 depth 2 nodes 268 time 10 pv f5d6 f4d6
> XBOARD 2 +2 1 268 Nxd6 Bxd6
< ENGINE info string branching factor = 4.1017
< ENGINE info depth 3 seldepth 3
< ENGINE info nps 45200
< ENGINE info score cp 9 depth 3 nodes 452 time 10 pv f5d6 f4d6 e7f6
> XBOARD 3 +9 1 452 Nxd6 Bxd6 Bf6
< ENGINE info string branching factor = 3.33884
< ENGINE info depth 4 seldepth 4
< ENGINE info nps 253300
< ENGINE info score cp 5 depth 4 nodes 2533 time 10 pv f5d6 f4d6 e7f6 d6c5
> XBOARD 4 +5 1 2533 Nxd6 Bxd6 Bf6 Bc5
< ENGINE info string branching factor = 4.54579
< ENGINE info depth 5 seldepth 5
< ENGINE info nps 191680
< ENGINE info score cp 11 depth 5 nodes 9584 time 50 pv f5d6 f4d6 e7f6 d6c5 f6e5
> XBOARD 5 +11 5 9584 Nxd6 Bxd6 Bf6 Bc5 Be5
< ENGINE info string branching factor = 1.98884
< ENGINE info depth 6 seldepth 6
< ENGINE info nps 183415
< ENGINE info score cp -8 depth 6 nodes 23844 time 130 pv f5d6 f4d6 e7g5 c3e4 g5h4 d6e5
> XBOARD 6 -8 13 23844 Nxd6 Bxd6 Bg5 Ne4 Bh4 Be5
< ENGINE info string branching factor = 4.01752
< ENGINE info depth 7 seldepth 7
< ENGINE info nps 170400
< ENGINE info score cp -7 depth 7 nodes 54528 time 320 pv f5d6 f4d6 e7g5 c3e4 g5h4 d6e5 h8g8
> XBOARD 7 -7 32 54528 Nxd6 Bxd6 Bg5 Ne4 Bh4 Be5 Rg8
< ENGINE info string branching factor = 2.14819
< ENGINE info depth 8 seldepth 8
< ENGINE info nps 190136
< ENGINE info score cp -12 depth 8 nodes 167320 time 880 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 b7b6 c3e4
> XBOARD 8 -12 88 167320 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 b6 Ne4
< ENGINE info string branching factor = 3.62129
< ENGINE info depth 9 seldepth 9
< ENGINE info nps 186563
< ENGINE info score cp -10 depth 9 nodes 447752 time 2400 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 b7b5
> XBOARD 9 -10 240 447752 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 b5
< ENGINE info string branching factor = 1.99702
< ENGINE info depth 10 seldepth 10
< ENGINE info nps 189844
< ENGINE info score cp -11 depth 10 nodes 1120082 time 5900 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4d2
> XBOARD 10 -11 590 1120082 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 R4d2
< ENGINE info string branching factor = 3.15672
< ENGINE info depth 11 seldepth 11
< ENGINE info nps 189664
< ENGINE info score cp -9 depth 11 nodes 4049333 time 21350 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 h8f8 d6d4 c6c5 d4g4 f8g8
> XBOARD 11 -9 2135 4049333 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 Rf8 R6d4 c5 Rg4 Rg8
< ENGINE info string branching factor = 3.92572
< ENGINE info depth 12 seldepth 13
< ENGINE info nps 188975
< ENGINE info score cp -10 depth 12 nodes 11353648 time 60080 pv f5d6 f4d6 e7d6 d3d6 c8c7 a2a3 c6c5 d6d5 b7b6 d5e5 a8d8 e5e7 c7c8
> XBOARD 12 -10 6008 11353648 Nxd6 Bxd6 Bxd6 Rxd6 Kc7 a3 c5 R6d5 b6 Re5 Rd8 Re7+ Kc8
< ENGINE info string branching factor = 2.45005
< ENGINE EOF

[Michel]

This is a well know problem to anyone who does benchmarking.

You should never rely on the times reported by an engine.

I assume WinBoard/XBoard keep track of the time themselves. The time/otim commands are there to inform the engine how much time is left.

Michel

[H.G.Muller]

OK, I finally had the time to retrn to this problem. WinBoard does save the time left on the clock before every move, for both sides. This in order to easily backup through the game being played: if you undo a number of moves, you will also undo the time associated with these moves. In my firstt attempt to print the time in the PGN I did make use of these stored times, by printing the difference of time left before and after the move.

Problem was that this did not work satisfactorily, as the GUI sometimes awards extra time. (On every move in incremental TCs, after a session otherwise.) This spoiled the computation for the thinking time on these moves. It was not easy to figure out how much time was added, as for sdifferent TC types, this happened in different places in the code.

So I switched to the engine reported times, which are recorded (if /showThinking=true) for each move as well (in WB_x and later). This was not satisfactory either, as too many engines apparently report erroneous times. (Some Joker versions are guilty of this too... )

The latest WB now has a centralized routine for awarding new time quota, as a function of move number, which is used in any TC mode. (I made this in preparation for more complex, multi-session time controls, which already work in 4.3.14 as far as manipulating the GUI clock is concerned, but for which no protocol exists yet to communicate the number of moves in the next session to the engine.) This makes it easy to correct the before-after time difference on the GUI clock to a thinking time. I have a WB version now that does this. (Not posted on my website yet, as unfortunately I have no ftp access at the moment.)

I am confronted now with a logical problem, though, that I am not sure how to solve. The score/depth+time are recorded in PGNs as comments. WB ignores such comments on reading the PGN, except for remembering them and displaying them with the move in a pop-up window. WB_x and earlier completely messed up the layout of a PGN file with comments, on storing it, because they tried to get the comments on separate lines. So writing a PGN with pgnExtendedInfo, reading it back, and writing it again, gives a horrible result there.

I tried to fix this in WB 4.3.14 by making the WB PGN reader aware that the extended info is not a true comment, stripping it off, and only treat the remainder (if any) as a comment. To make sure it is not permanently lost, I wrote this info back to the WB array that normally would hold this information obtained directly from the engine. The comments pop-up window already displayed such info before any true comments, directly from this 'pvInfoList', to make sure it appears in this window even before saving and loading the PGN, when stepping through the current game.

This works fine for score and depth. On saving PGN they are taken from the pvInfoList, on loading they are put back there. So you can save and load as often as you want. But for the times it does not work! On saving the PGN the time is calculated from the remaining clock times. But before saving the PGN, when stepping though the old moves, the comments window displays the time reported by the engine, not this calculated GUI time. When reading the PGN back, I put the times in the pvInfoList, but loading a PGN is not supposed to affct the timeRemaining in WB. If I load a PGN, e.g. to use as opening moves in an engine-engine game, I don't want the TC tag of the PGN, or the possibly included search times to affect the time the engines see on their clock when they start playing. This time should be simply the time for which the WB TC was set by the user.

So I cannot reconstruct the the timeReamaining at each move from the PGN thinking time on loading. But as on saving the time is calculated from there, loading and saving a PGN with extended info loses the times. (It resets them to the time quota recieved for that move in the user-selected TC, i.e. the increment on every move, or zero on most and timePerSession on some.) I do copy the times read from the PGN to the pvInfoList, though, so they are displayed in the comments window after the first load. (But before saving and loading the engine-reported times are displayed there, not those that will end up in the PGN.)

I am not sure how to solve this, or even how we would like WinBoard to behave. Are there any suggestions for this? The current behavior strikes me as really ugly. This problem did not exist when I was still using the times reported by the engines from the pvInfoList to print in the PGN, then they went back where they came from.