"go ponder"/"ponderhit" issue in UCI

[jdart]

Using cutechess-cli in UCI mode with pondering on, I see quite a few instances in the debug log where "go ponder" is immediately followed by a "ponderhit" command, with no intervening commands from cutechess or either engine.

As I understand it, this is really equivalent to a foreground (non-pondering) search because "ponderhit" is informing the engine that the predicted move was actually made, and so it is the engine's turn to move, and if it has not completed the ponder search, it should continue it but only up to a time or depth limit. Is there any reason in this case to not just send a "go" command (w/o ponder) and omit the "ponderhit"?

(I am not sure if UCI programs other than cutechess-cli have this issue).

--Jon

[elcabesa]

when does this happen? I expect it maybe for the first move after the cutechess book moves. Am I wrong?
can you post some logs? because it looks very strange to me

[phhnguyen]

“go” without “ponder” is always sent when your engine is in turn, when “go ponder” is always sent when the engine is not in turn. GUIs won’t send alternative commands since they must follow strictly input order.

From my experience that may happen when an engine has bugs about missing sending “bestmove” for command “stop” (or sending bestmove twice or after ucinewgame). That may break the synchronous status between that engine and the GUI.

[hgm]

This happens when the opponent moves immediately. CutiChess cannot know in advance that the engine is going to do that. There is a race condition there: in response to your own move it relays it to the opponent, and sends you a go-ponder. When, while it is sending this go-ponder, the opponent's move arrives, the processing of it will start immediately after sending the go-ponder command finishes. Which could result in 'ponderhit'. So it is a race condition.

[Ferdy]

Using cutechess-cli in UCI mode with pondering on, I see quite a few instances in the debug log where "go ponder" is immediately followed by a "ponderhit" command, with no intervening commands from cutechess or either engine.

As I understand it, this is really equivalent to a foreground (non-pondering) search because "ponderhit" is informing the engine that the predicted move was actually made, and so it is the engine's turn to move, and if it has not completed the ponder search, it should continue it but only up to a time or depth limit. Is there any reason in this case to not just send a "go" command (w/o ponder) and omit the "ponderhit"?

(I am not sure if UCI programs other than cutechess-cli have this issue).

--Jon

Looking at the log it looks like a bug in cutechess.

Normally the pattern is when cutechess sent position command to engine1 it will follow it with go ponder to same engine1.
Once it receives bestmove from engine2, it will send ponderhit or stop to engine1.

Code: Select all

1657899 >Deuterium v2018.1.35.514(0): position startpos moves g1f3 d7d5 d2d4 g8f6 c2c4 c7c6 e2e3 g7g6 b1c3 f8g7 f1e2 e8g8 e1g1 e7e6 d1c2 b8d7 e3e4 d5e4 c3e4 f6e4 c2e4 e6e5 d4e5 d7e5 f3e5 f8e8 f2f4 f7f6 f1d1 d8e7 g2g4 e8f8 c1e3 f6e5 d1f1 e7f6 a1d1 e5f4 f1f4 f6e6 c4c5 e6e4 f4e4 g7b2 e4e7 g8h8 e3h6 f8g8 d1d6 b2g7 e2c4 g7h6 c4g8 c8g4 e7h7 h8g8 h7h6 g4f5 h6h4 a8e8 h4b4 e8e7 d6d8 g8f7 d8b8 f7e6 b4b7 e7b7 b8b7 a7a6 b7b6 e6d5 b6a6 d5c5 a2a4 f5d3 a6a8 c5b6 g1f2 c6c5 f2e3 d3f5 a8b8 b6c7 b8b5 c7c6 b5b2 c6c7 a4a5 f5g4 a5a6 g4e6 b2b5 e6h3 a6a7 h3g2 h2h4 c5c4 b5b8 c7d6 a7a8q g2a8 b8a8 d6e6 a8c8 e6d5 c8c7 c4c3 c7c3 d5e5 c3d3 e5e6 e3f4 e6f7 d3e3 f7f6 f4g4 f6g7 g4g5 g7f7 e3e2 f7g7 e2f2
1657901 >Deuterium v2018.1.35.514(0): go ponder wtime 120148 btime 38089 winc 3000 binc 3000
1658433 <Arasan 20.4.1(1): bestmove e2f2 ponder g7h7
1658433 >Deuterium v2018.1.35.514(0): ponderhit

After sending ponderhit to engine1 it will then process position and go ponder to engine2.

1658434 >Arasan 20.4.1(1): position startpos moves g1f3 d7d5 d2d4 g8f6 c2c4 c7c6 e2e3 g7g6 b1c3 f8g7 f1e2 e8g8 e1g1 e7e6 d1c2 b8d7 e3e4 d5e4 c3e4 f6e4 c2e4 e6e5 d4e5 d7e5 f3e5 f8e8 f2f4 f7f6 f1d1 d8e7 g2g4 e8f8 c1e3 f6e5 d1f1 e7f6 a1d1 e5f4 f1f4 f6e6 c4c5 e6e4 f4e4 g7b2 e4e7 g8h8 e3h6 f8g8 d1d6 b2g7 e2c4 g7h6 c4g8 c8g4 e7h7 h8g8 h7h6 g4f5 h6h4 a8e8 h4b4 e8e7 d6d8 g8f7 d8b8 f7e6 b4b7 e7b7 b8b7 a7a6 b7b6 e6d5 b6a6 d5c5 a2a4 f5d3 a6a8 c5b6 g1f2 c6c5 f2e3 d3f5 a8b8 b6c7 b8b5 c7c6 b5b2 c6c7 a4a5 f5g4 a5a6 g4e6 b2b5 e6h3 a6a7 h3g2 h2h4 c5c4 b5b8 c7d6 a7a8q g2a8 b8a8 d6e6 a8c8 e6d5 c8c7 c4c3 c7c3 d5e5 c3d3 e5e6 e3f4 e6f7 d3e3 f7f6 f4g4 f6g7 g4g5 g7f7 e3e2 f7g7 e2f2 g7h7
1658435 >Arasan 20.4.1(1): go ponder wtime 122614 btime 38089 winc 3000 binc 3000

Wait for best move of engine1 since ponderhit was already sent to it.

Code: Select all

1660593 <Deuterium v2018.1.35.514(0): bestmove g7h7 ponder f2f7

There is a case that cutechess does not follow the above pattern, see below.

Code: Select all

1661661 >Arasan 20.4.1(1): ponderhit
1661661 >Deuterium v2018.1.35.514(0): position startpos moves g1f3 d7d5 d2d4 g8f6 c2c4 c7c6 e2e3 g7g6 b1c3 f8g7 f1e2 e8g8 e1g1 e7e6 d1c2 b8d7 e3e4 d5e4 c3e4 f6e4 c2e4 e6e5 d4e5 d7e5 f3e5 f8e8 f2f4 f7f6 f1d1 d8e7 g2g4 e8f8 c1e3 f6e5 d1f1 e7f6 a1d1 e5f4 f1f4 f6e6 c4c5 e6e4 f4e4 g7b2 e4e7 g8h8 e3h6 f8g8 d1d6 b2g7 e2c4 g7h6 c4g8 c8g4 e7h7 h8g8 h7h6 g4f5 h6h4 a8e8 h4b4 e8e7 d6d8 g8f7 d8b8 f7e6 b4b7 e7b7 b8b7 a7a6 b7b6 e6d5 b6a6 d5c5 a2a4 f5d3 a6a8 c5b6 g1f2 c6c5 f2e3 d3f5 a8b8 b6c7 b8b5 c7c6 b5b2 c6c7 a4a5 f5g4 a5a6 g4e6 b2b5 e6h3 a6a7 h3g2 h2h4 c5c4 b5b8 c7d6 a7a8q g2a8 b8a8 d6e6 a8c8 e6d5 c8c7 c4c3 c7c3 d5e5 c3d3 e5e6 e3f4 e6f7 d3e3 f7f6 f4g4 f6g7 g4g5 g7f7 e3e2 f7g7 e2f2 g7h7 f2f7 h7h8 g5h6 h8g8 h6g6
1661663 <Arasan 20.4.1(1): bestmove h6g6 ponder g8h8
1661663 >Arasan 20.4.1(1): position startpos moves g1f3 d7d5 d2d4 g8f6 c2c4 c7c6 e2e3 g7g6 b1c3 f8g7 f1e2 e8g8 e1g1 e7e6 d1c2 b8d7 e3e4 d5e4 c3e4 f6e4 c2e4 e6e5 d4e5 d7e5 f3e5 f8e8 f2f4 f7f6 f1d1 d8e7 g2g4 e8f8 c1e3 f6e5 d1f1 e7f6 a1d1 e5f4 f1f4 f6e6 c4c5 e6e4 f4e4 g7b2 e4e7 g8h8 e3h6 f8g8 d1d6 b2g7 e2c4 g7h6 c4g8 c8g4 e7h7 h8g8 h7h6 g4f5 h6h4 a8e8 h4b4 e8e7 d6d8 g8f7 d8b8 f7e6 b4b7 e7b7 b8b7 a7a6 b7b6 e6d5 b6a6 d5c5 a2a4 f5d3 a6a8 c5b6 g1f2 c6c5 f2e3 d3f5 a8b8 b6c7 b8b5 c7c6 b5b2 c6c7 a4a5 f5g4 a5a6 g4e6 b2b5 e6h3 a6a7 h3g2 h2h4 c5c4 b5b8 c7d6 a7a8q g2a8 b8a8 d6e6 a8c8 e6d5 c8c7 c4c3 c7c3 d5e5 c3d3 e5e6 e3f4 e6f7 d3e3 f7f6 f4g4 f6g7 g4g5 g7f7 e3e2 f7g7 e2f2 g7h7 f2f7 h7h8 g5h6 h8g8 h6g6 g8h8
1661664 >Deuterium v2018.1.35.514(0): go ponder wtime 128338 btime 44146 winc 3000 binc 3000
1661665 >Deuterium v2018.1.35.514(0): ponderhit

Deuterium received position command but has not received the go ponder immediately.
It seems cutechess does this if there is successive ponderhit for both engines. But perhaps the pattern,

Code: Select all

> engine1 position ...
> engine1 go ponder ...

should have been maintained.

[elcabesa]

I believe that every communication between cutechess one engine is indipende from the other engines and that in the log you see them mixed.

in the log you sent I see 2 command , position and go ponder whit a gap of 3 ms between them. I think it's not a bug, since every engine receive the correct sequence of moves.
this is what I can understand from only 6 lines of debug log

[jdart]

I think it is a race condition as hgm says. It occurs when "bestmove" from one engine comes in right after "go ponder" is sent to the other engine. (Possibly this is somewhat obscured in the logs since i/o from the two engines could actually overlap but cutechess shows it serialized).

--Jon

[elcabesa]

Ok it maybe a race condition. But I don't understand your point. When cutechess receive a bestmove it sent position and go (ponder) to both engine. If the engine who has not to ponder answer with a bestmove very quickly then ponder hit is sent to the other engine just after and you see that the engine receive in sequence go ponder, ponder hit.

I don't think this is an issue. In ponder games cutechess sent go ponder if the engine specify the ponder move in bestmove and send ponder hit after he receive bestmove.

Do you think this is a bug?

[odomobo]

The sequencing in the example with Arasan and Deuterium seems reasonable to me; I would imagine that cutechess-cli was preparing to send the "go ponder" command when Arasan responded. However, why did it take 3ms (unreasonably long, IMO) to send the "go ponder" command? cutechess-cli should have already had the information necessary to send that command (except for, perhaps, Arasan's timer information). The question in my mind: did it actually take 3ms to send, or is that just a logging artifact?

Disclaimer: I know nothing of cutechess-cli's codebase, I'm just reasoning.

[AndrewGrant]

Using cutechess-cli in UCI mode with pondering on, I see quite a few instances in the debug log where "go ponder" is immediately followed by a "ponderhit" command, with no intervening commands from cutechess or either engine.

As I understand it, this is really equivalent to a foreground (non-pondering) search because "ponderhit" is informing the engine that the predicted move was actually made, and so it is the engine's turn to move, and if it has not completed the ponder search, it should continue it but only up to a time or depth limit. Is there any reason in this case to not just send a "go" command (w/o ponder) and omit the "ponderhit"?

(I am not sure if UCI programs other than cutechess-cli have this issue).

--Jon

Assuming the catalyst for this is the chess.com tournament.

I've told them I won't be supporting pondering, and that they should use real cores and not hyperthreads if they want good chess.