playing with increment under extreme time pressure - Arena peculiarity

[macsmol]

Hi. It's my first post here so hello everybody!

I've run into something that seems interesting so here I go..
Recently I started writing my own UCI engine (magog) from scratch.
I pit it against other engine in blitz time setting: 2min + 1s.
In one of the games my engine failed due to a bug in calculation of time dedicated for the next move.
However after looking at arena.debug more closely I've noticed that Arena actually allowed magog to get away with it (for a bit at least).

Anyway here's the relevant Arena log. I've edited it a bit. Unrelevant info is truncated and I added comments above relevant lines:

Code: Select all

2024-06-15 20:14:52,368-->1:position startpos moves [...] c4d5 c7b8 d4e5 b8a7 e5d4 a7a6 d5c6 a6a5 d4c5 a5a6 e7e6 a6a5 e6d6 a5a6 c5d4 a6a5 d6c5 a5a6 c6d5 a6a5 d4e5
// magog has 1 millisecond to move and will get another second after that move
2024-06-15 20:14:52,368-->1:go wtime 1 btime 6354 winc 1000 binc 1000
2024-06-15 20:14:52,384<--1:info depth 2 score cp -876 nps 98619 time 0 nodes 50 pv a5a4 d5e4 
2024-06-15 20:14:52,399<--1:info depth 3 score cp -870 nps 156862 time 0 nodes 104 pv a5a4 e5c3 a4a3 
2024-06-15 20:14:52,415<--1:info depth 4 score cp -885 nps 655803 time 1 nodes 1147 pv a5a4 e5c3 a4a3 c3e5 
2024-06-15 20:14:52,436<--1:info depth 5 score cp -876 nps 900220 time 2 nodes 2039 pv a5a4 e5c3 a4a3 c3e5 a3a4 
2024-06-15 20:14:52,456<--1:info depth 6 score cp -880 nps 1367706 time 30 nodes 42031 pv a5a4 d5e4 a4b3 c5b5 b3a3 b5c5 
2024-06-15 20:14:52,477<--1:info depth 7 score cp -877 nps 1370276 time 60 nodes 83084 pv a5a4 c5c4 a4a5 d5b7 a5a4 b7e4 a4a5 
2024-06-15 20:14:52,868<--1:info score cp -885 depth 8 nps 1710372 time 473 nodes 809189 pv a5a4 c5c4 a4a5 e5c7 a5a4 c4c5 a4a3 c7e5 
2024-06-15 20:14:52,889<--1:info depth 8 score cp -885 nps 1712056 time 473 nodes 809986 pv a5a4 c5c4 a4a5 e5c7 a5a4 c4c5 a4a3 c7e5 
2024-06-15 20:14:53,013<--1:info currmove a5a4 currmovenumber 1 nodes 1000000 time 617 nps 1620430
// however it can be clearly seen that it's been thinking for a second. As if Arena incremented it's time in advance
2024-06-15 20:14:53,378<--1:info score cp -885 depth 8 nps 1496163 time 987 nodes 1476989 pv a5a4 c5c4 a4a5 e5c7 a5a4 c4c5 a4a3 c7e5 
2024-06-15 20:14:53,394<--1:bestmove a5a4
2024-06-15 20:14:53,394*1*Found move:Ka5-a4
2024-06-15 20:14:53,555*2*Child Process Prio Adj:  PID 7000 conhost.exe
2024-06-15 20:14:53,555*2*Start calc, move no: 246
2024-06-15 20:14:53,555-->2:position startpos moves [...] c4d5 c7b8 d4e5 b8a7 e5d4 a7a6 d5c6 a6a5 d4c5 a5a6 e7e6 a6a5 e6d6 a5a6 c5d4 a6a5 d6c5 a5a6 c6d5 a6a5 d4e5 a5a4
2024-06-15 20:14:53,555-->2:go wtime 1 btime 6328 winc 1000 binc 1000
[...] //opponent thinking
2024-06-15 20:14:54,053<--2:info string 8: e5c3-a4a3-c5d6-a3a4-d5c4-a4a3-c4d5-fif-> (+0)
2024-06-15 20:14:55,199<--2:info string interrupted
2024-06-15 20:14:55,199<--2:info string t=1633 max_n=11
2024-06-15 20:14:55,201<--2:bestmove e5c3 ponder a4a3
2024-06-15 20:14:55,201*2*Found move:Be5-c3
2024-06-15 20:14:55,356*1*Child Process Prio Adj:  PID 12780 conhost.exe
2024-06-15 20:14:55,356*1*Start calc, move no: 247
2024-06-15 20:14:55,356-->1:position startpos moves [...] c4d5 c7b8 d4e5 b8a7 e5d4 a7a6 d5c6 a6a5 d4c5 a5a6 e7e6 a6a5 e6d6 a5a6 c5d4 a6a5 d6c5 a5a6 c6d5 a6a5 d4e5 a5a4 e5c3
// another turn for magog! Didn't get flagged! 
2024-06-15 20:14:55,356-->1:go wtime 1 btime 6328 winc 1000 binc 1000
// This time however it really interrupts the search at the very beginning - h
2024-06-15 20:14:55,366<--1:info score cp -870 depth 1 nps 1000000 time 0 nodes 1 pv a4a3 
2024-06-15 20:14:55,388<--1:bestmove a4a3
// and Arena lets it get away with it.. the game continues
2024-06-15 20:14:55,388*1*Found move:Ka4-a3
2024-06-15 20:14:55,552*2*Child Process Prio Adj:  PID 7000 conhost.exe
2024-06-15 20:14:55,552*2*Start calc, move no: 248
2024-06-15 20:14:55,552-->2:position startpos moves [...] c4d5 c7b8 d4e5 b8a7 e5d4 a7a6 d5c6 a6a5 d4c5 a5a6 e7e6 a6a5 e6d6 a5a6 c5d4 a6a5 d6c5 a5a6 c6d5 a6a5 d4e5 a5a4 e5c3 a4a3
2024-06-15 20:14:55,552-->2:go wtime 1 btime 7301 winc 1000 binc 1000
[...] //opponent thinking again
2024-06-15 20:14:57,302<--2:bestmove c5d6 ponder a3a4
2024-06-15 20:14:57,302*2*Found move:Kc5-d6
[...] //only now Arena adjudicates that magog losses on time
2024-06-15 20:14:57,459****Tour**Game end: 0-1 {0-1 White forfeits on time}
2024-06-15 20:14:57,459****Tour**Last game won by EnkoChess_290818 with Black in 125 moves

So it's interesting that Arena does not terminate the game right at the moment when magog's time expires. It only does so a little later.
This phenomenon makes me wonder whether it could be exploited to gain some extra time.
Or maybe there's just something I don't understand in UCI or how time is measured?

[mar]

hi and welcome.

Arena is a really bad choice for engine testing, only single thread is possible and it can't really handle chess960 (even though it claims to), should you ever come to implementing that.

I'd suggest to switch to cutechess-cli or c-chess-cli for engine testing

as for the timeout: I think it's just possible that Arena measures time with more precision than what UCI allows (1msec granularity), but that's just a random guess. 1msec is plenty of time for an engine to do a depth 1 search and output bestmove in time

engines typically try to avoid such situations like this with "move overhead" - meaning they try to allocate their as if they had say 100ms less on the clock

[macsmol]

Heh. You only confirm my thoughts about changing a GUI. Arena is quite buggy and a bit cumbersome to set-up.

But the time measuring I mentioned earlier looks quite bad.. The next day I run another game.
If timestamps in Arena logs are to be trusted they showed that opponent engine spent ~1015millis on each of 5 consecutive moves. The fun part is that each of the moves was preceeded with "go btime 1". Opponent played as black. And in the end my engine lost.

But there's a happy ending. My engine lost that game due to another bug that became apparent. Bug is fixed and the new version managed to snatch a draw by 3-fold repetition in the same game

Thanks very much for testing soft recommendations!

[gordonr]

Arena is a really bad choice for engine testing, only single thread is possible and it can't really handle chess960

What do you mean by only "single thread is possible"? I'm often running matches between engines using multiple threads in Arena so I don't understanding what you mean, sorry. And the Chess960 support or not doesn't matter to many people.

I also agree that cutechess-cli is good.

[Modern Times]

I think he means that Arena has no concurrency.

[gordonr]

I think he means that Arena has no concurrency.

Fair enough. I'm curious as to what impact that has and how cutechess-cli is better in that respect.

I realise that I may only use Arena in certain ways and a subset of its functionality but it has mainly worked well for me. I largely use it for engine testing at relatively slow time controls.

[Ras]

I'm curious as to what impact that has and how cutechess-cli is better in that respect.

If you can run N games in parallel, then you need only 1/Nth of the time.

[gordonr]

I'm curious as to what impact that has and how cutechess-cli is better in that respect.

If you can run N games in parallel, then you need only 1/Nth of the time.

Yes, but you'd also need to only give each engine 1/Nth of the hardware resources which diminishes the value of the testing. I want to see how SF scales at 30 threads and large hashtables, not 30 lots of 1 thread and smaller hashtables.

Also, I've sometimes ran more than one instance of Arena to run tournaments in parallel when the hardware has been sufficient to do so.

Again, I realise cutechess-cli is good but I've not used it. I presume it's easier to run games in parallel? Is that a built-in option or do you just run multiple instances? I'm interested in trying that too.

[Ras]

Yes, but you'd also need to only give each engine 1/Nth of the hardware resources which diminishes the value of the testing.

The part of testing where more than one search thread is useful is to test the scaling itself, but most tests will be at one thread anyway.

Is that a built-in option or do you just run multiple instances?

I'm using the somewhat similar c-chess-cli, which poster "mar" already recommended earlier in this thread, and it's a built-in option. When testing, I use 14 out of my logical 16 cores to run 14 games in parallel. The remaining ones are for other activities such as web browsing.

[macsmol]

I'm curious as to what impact that has and how cutechess-cli is better in that respect.

If you can run N games in parallel, then you need only 1/Nth of the time.

Yes, but you'd also need to only give each engine 1/Nth of the hardware resources which diminishes the value of the testing.

That's true but now I'm competing with engines ranked around 650~750 on CCRL.. I don't think many of these use multithreading. Certainly mine doesn't.
And I really like the idea of speeding up testing

I've just used cutechess-cli. One advantage is that I can prepare a script that can be reused in future tournaments/engine versions.
Though I didn't figure out exactly how it works. I've set it up and expected it will play 42 games of gauntlet tournament (7 openings as white and as black against 3 opponents = 7*2*3= 42) but after I come back I see only 29 games in PGN..

Also.. does anyone know if it's possible for cutechess-cli to output results of each games grouped by opponent (much like Arena prints it?)
I mean this format:

Code: Select all

-----------------Magog.0.12.killerMoves1-----------------
Magog.0.12.killerMoves1 - DoctorB               : 5,5/14 4-7-3 (011100==00010=)  39%   -78
Magog.0.12.killerMoves1 - EnkoChess_290818      : 6,0/14 3-5-6 (==0=00==10=011)  43%   -49
Magog.0.12.killerMoves1 - Magog.0.11.addedTime4 : 9,0/14 4-0-10 (==1===111=====)  64%  +100