Arena loss on time.

[Jan Brouwer]

Hi,

I have seen my program Rotor lose on time a few times under Arena 1.1.

On one such occasion I noticed the following in the Arena debug window:

Code: Select all

...

// Here I expect to have 1382 + 3000 = 4382 ms left:

2754791>1:go wtime 12933 btime 1382 winc 3000 binc 3000
2754811<1&#58;info string time&#58; max adjusted from 6078 to 3505
2754811<1&#58;info string time&#58; target = 3039 s, min = 1519 s, max = 3505 s
2754811<1&#58;info depth 1 seldepth 2 nodes 10 nps 100 score cp -1089 hashfull 0 pv h5g6 c2g6 
2754831<1&#58;info depth 1 seldepth 2 nodes 36 nps 360 score cp -174 hashfull 0 pv h5f7 
2754851<1&#58;info depth 1 seldepth 2 nodes 74 nps 740 score cp -171 hashfull 0 pv h5f3 
2754871<1&#58;info depth 1 seldepth 2 nodes 89 nps 890 score cp -160 hashfull 0 pv g5g4 
2754891<1&#58;info depth 1 seldepth 2 nodes 110 nps 1100 score cp -158 hashfull 0 pv h8g7 c2c3 g7g6 
2754911<1&#58;info depth 2 seldepth 3 nodes 173 nps 1730 score cp -161 hashfull 0 pv h8g7 a4b4 
2754931<1&#58;info depth 3 seldepth 5 nodes 682 nps 6820 score cp -167 hashfull 0 pv h8g7 c2c3 g7g6 c6e5 g6g7 
2754951<1&#58;info depth 3 seldepth 5 nodes 1640 nps 16400 score cp -161 hashfull 0 pv g5g4 c2c3 h8g8 a4b4 
2754971<1&#58;info depth 4 seldepth 7 nodes 3399 nps 33990 score cp -163 hashfull 0 pv g5g4 a4b4 h8g7 a3a4 
2754991<1&#58;info depth 5 seldepth 9 nodes 10686 nps 106860 score cp -167 hashfull 0 pv g5g4 c2c3 h8h7 a4b4 h5d5 a3a4 
2755011<1&#58;info depth 6 seldepth 11 nodes 44445 nps 444450 score cp -163 hashfull 1 pv g5g4 a4b4 h5d5 a3a4 g4g3 a4a5 
2755031<1&#58;info depth 7 seldepth 14 nodes 138454 nps 728705 score cp -162 hashfull 5 pv g5g4 c2c3 h8h7 c6e5 h5e8 a4b4 e8b8 b4c5 b8c7 c5d4 c7c3 d4c3 
2755291<1&#58;info depth 8 seldepth 15 nodes 369088 nps 768933 score cp -161 hashfull 13 pv g5g4 c2c3 h8h7 c3e3 h7g7 e3d4 g7g8 d4d8 g8h7 d8e7 h7g8 c6e5 
2755772<1&#58;info depth 9 seldepth 18 nodes 770411 nps 801676 score cp -163 hashfull 27 pv g5g4 c2c3 h8h7 c3e3 h5f5 a4b4 f5b1 b4c5 b1c2 c5b5 c2b1 b5c4 b1c2 c4d5 

// After 2757795 - 2754791 = 3004 ms, I'm stopped and the game is forfeited&#58;

2757795>1&#58;stop
2757855<1&#58;info input waiting
2757855<1&#58;info stop command received
2757855<1&#58;info string search stopped
2757855<1&#58;info hashfull 88
2757855<1&#58;info string nodes&#58; 2477337 q-nodes&#58; 58% pv nodes&#58; 0.23% illegal ic&#58; 3% illegal oc 12% try 6% attacks 62% check gens 6%
2757855<1&#58;info string fail-high&#58; 90% hash&#58; 50% pawn hash&#58; 100% king eval cuts&#58; 46% null cuts&#58; 51%
2757855<1&#58;bestmove g5g4 
2757855*1*---------> Arena&#58;Illegal move! &#40;bestmove g5g4 )
2757995********Game end&#58; 1-0 &#123;1-0 Black forfeits on time&#125;
2757995********Last game won by Tao 5.6 with White in 100 moves
2757995********Rotor - Tao 5.6&#58; 0-2-0
2757995********   2 W 2    1.0&#58;0.0        0.0&#58;2.0       9&#58;39&#58;51 PM     0.00   100 10.379 &#58;9.393  0-2-0
2758045********Saving file C&#58;\Program Files\Arena\Tournaments\Arena tournament.pgn
2758075>1&#58;stop
2758075>2&#58;stop
2758095<2&#58;info string discarded &#91;stop&#93;
2761370********Terminating engine 1 Rotor
2761370>1&#58;stop
2761370>1&#58;quit
2761951********Terminating engine 2 Tao 5.6
2761951>2&#58;stop
2761951>2&#58;quit
2766067********Tournament aborted

It seems that Arena stopped the match about 1.3 seconds too early.

Is this a known problem? Or am I misinterpreting the UCI time commands?

Thanks,

Jan

[hgm]

I don't know UCI, but time increments are added only after you do the move, isn't it?

Why would UCI not send the true time, but have the engine do an addition to calculate it? That seems odd.

[Jan Brouwer]

Hmm, yes, that does make sense...

Anyhow, reality must take precedence, so I'll adapt my time handling code.