xboard issue

[bob]

HGM:

Here's an oddity. I have been working on various things, and have been seeing some unexpected losses running with board. I decided to try a new opponent, and downloaded gaviota. It behaves VERY poorly. It dumps an absolute ton of garbage while it is playing. It displays multiple 8x8 boards of numbers, plus a couple of hundred array values, etc, after each move. The issue I see is that if it does that while Crafty is thinking, xboard is very sluggish in picking up Crafty's move, because it is handling all the garbage output. It becomes noticeable enough that the time updates just blank out in pretty fast games. If I turn pondering off, so that only one program displays stuff at a time, all is well.

I had not considered how a mis-behaving program can cause issues like this, and didn't notice since most of what I play is ponder off, or very long time controls where I watch the games. The misbehaving programs only dump this barrage of output either after it moves, or at the beginning of a search. I've only wasted 3 days chasing a loss in time issue that was not a real issue in my code. I wonder if it would be worthwhile to detect this since I am sure many are getting misleading results without knowing. IE perhaps an option that lets me set some counter and if a program produces more lines of output in 1 sec than that limit, I get notified "first/second program misbehaving, output rate limit exceeded" or something similar.

I limit this in crafty with the "noise setting" and setting appropriate display options to avoid sending a lot of crap to xboard. But some do not and go overboard. I found a similar problem with Scorpio, in that it starts at iteration 1 and displays every last PV. Not so bad in middle games, but in endgames? Not going to work when 50+ plies are not hard to reach. And flood xboard and introduce significant LAG in getting the moves from the other program...

In my own cluster referee, I sort of deal with this by giving priority to reading from the pipe connected to the side on move first, so that the opponent doesn't swamp things while it is my turn...

Ever run across this? How is your input/etc loop set up? Always check the programs in the same order or do you do as I do???

For Crafty, here is a sample output: (I entered these commands by hand, to make it easy to see)

Code: Select all

xboard
noise 1
level 0 1 1
post
e4
      15     12     146 4309249 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Bg5 h6 8. Be3 Be6 9. Bxe6 Bxe3
      15     12     148 4398952 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Bg5 h6 8. Be3 Be6 9. Bxe6 Bxe3
      16     13     165 4904680 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bb5 Bc5 5. O-O O-O 6. d3 d6 7. Na4 Nd4 8. Nxc5 Nxb5 9. a4
      16     13     174 5140377 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bb5 Bc5 5. O-O O-O 6. d3 d6 7. Na4 Nd4 8. Nxc5 Nxb5 9. a4
      17     18     200 5890034 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bb5 Bd6 5. O-O a6 6. Ba4 b5 7. Bb3 O-O 8. d3 Na5 9. Be3 Nxb3 10. axb3
      17     18     226 6642123 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bb5 Bd6 5. O-O a6 6. Ba4 b5 7. Bb3 O-O 8. d3 Na5 9. Be3 Nxb3 10. axb3
      18     28     367 11026440 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Na4 Na5 8. Nxc5 Nxc4 9. dxc4 dxc5 10. Be3
      18     28     437 13114444 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Na4 Na5 8. Nxc5 Nxc4 9. dxc4 dxc5 10. Be3
move Nc6
d3
      16      9     100 3015480 2. ... e6 3. Nf3 Nf6 4. Be2 Bb4+ 5. c3 Be7 6. O-O O-O 7. Na3 d5 8. e5 Ng4 9. d4 Bd7 10. h3 Bxa3 11. bxa3
      16      5     156 4714092 2. ... Nf6 3. Nf3 e5 4. Be2 Be7 5. Nc3 O-O 6. O-O d6 7. Bd2 Bd7 8. Nd5 Nxd5 9. exd5 Nd4 10. Nxd4 exd4
      16      5     165 4966750 2. ... Nf6 3. Nf3 e5 4. Be2 Be7 5. Nc3 O-O 6. O-O d6 7. Bd2 Bd7 8. Nd5 Nxd5 9. exd5 Nd4 10. Nxd4 exd4
      17      5     209 6269124 2. ... Nf6 3. Nf3 e5 4. Be2 Be7 5. Nc3 O-O 6. O-O d6 7. Bd2 Bd7 8. Nd5 Nxd5 9. exd5 Nd4 10. Nxd4 exd4
      17      5     228 6881647 2. ... Nf6 3. Nf3 e5 4. Be2 Be7 5. Nc3 O-O 6. O-O d6 7. Bd2 Bd7 8. Nd5 Nxd5 9. exd5 Nd4 10. Nxd4 exd4
      18      0     340 10380132 2. ... Nf6 3. Nf3 e5 4. Be2 Bb4+ 5. Nc3 d5 6. O-O Bxc3 7. bxc3 dxe4 8. Ng5 exd3 9. cxd3 Nd5 10. Ne4 O-O 11. Ba3 Re8
      18      0     356 10867350 2. ... Nf6 3. Nf3 e5 4. Be2 Bb4+ 5. Nc3 d5 6. O-O Bxc3 7. bxc3 dxe4 8. Ng5 exd3 9. cxd3 Nd5 10. Ne4 O-O 11. Ba3 Re8
move Nf6

I give a "move xxx" and the usual post output and with noise 1, you will only get PVs after 1 sec of computing. And Crafty always outputs the last PV before making a move, in case the target time is less than one second which won't satisfy the noise setting.

I don't understand why others have to dump so much garbage...

Here's debug from board for Gaviota, as an example (it only seems to get into chatty-kathy mode when pondering): Note this is just a snippet, there is MUCH more of this for one move.

Code: Select all

59423 <second&#58; 14 -1027     248   1973294 &#58;-(
Impossible move a1g1^A, type = 0
60101 <second&#58; 14 -1349     316   2640242 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kd6 64.Rxa4
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
Impossible move a1g1^A, type = 24
60384 <second&#58; 14 -1349     345   2935316 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kd6 64.Rxa4
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
Impossible move a1g1^A, type = 24
62145 <second&#58; 15 -1349     521   4661556 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kd6 64.Rxa4
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
Impossible move a1g1^A, type = 24
62170 <second&#58; 15 -1349     523   4687424 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kd6 64.Rxa4
Impossible move a1g1^A, type = 24
62170 <second&#58; 15 -1349     523   4687424 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kd6 64.Rxa4
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
Impossible move a1g1^A, type = 24
66236 <second&#58; 16 -1357     930   8677892 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kb6 64.Rxa4 Kc7 65.Ra7+ Kd6 
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
Impossible move a1g1^A, type = 24
66993 <second&#58; 16 -1357    1005   9441395 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kb6 64.Rxa4 Kc7 65.Ra7+ Kd6 
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
Impossible move a1g1^A, type = 24
write FEN 50-move&#58; 0 108 0
e0. p=-4
e1. p=-4
e2. p=-4
e3. p=-4
e4. p=-4
e5. p=-4
e6. p=-4
e7. p=-4
e8. p=-3
e9. p=-4
e10. p=-3
e11. p=-4
e12. p=-3
e13. p=-4
e14. p=-4
e15. p=-4
e16. p=-3
e17. p=-4
e18. p=-3
e19. p=-2
e20. p=-4
e21. p=-2
e22. p=-2
e23. p=-4
e24. p=-4
e25. p=-4
e26. p=-3
e27. p=-3
e28. p=-4
...etc...

That REALLY swamps board in endgames when depth hits 40-50 plies and all of the chatty stuff is done once per iteration...

This is a case where the protocol has an issue. It would be nice to specify EXACTLY what a program should send, and anything else results in a loss. One program should not be able to influence the results by dumping way too much stuff. At long time controls, this is not a problem, but at 1m + 1s, one can see the effect of playing such a program, where games like crafty vs crafty proceed exactly as expected.

Any ideas???

[Sven]

I decided to try a new opponent, and downloaded gaviota. [...] It displays multiple 8x8 boards of numbers, plus a couple of hundred array values, etc, after each move.
[...]
For Crafty, here is a sample output: (I entered these commands by hand, to make it easy to see)

Code: Select all

xboard
noise 1
level 0 1 1
post
e4
      15     12     146 4309249 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Bg5 h6 8. Be3 Be6 9. Bxe6 Bxe3
      15     12     148 4398952 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Bg5 h6 8. Be3 Be6 9. Bxe6 Bxe3
[...]

[...]
Here's debug from board for Gaviota, as an example (it only seems to get into chatty-kathy mode when pondering): Note this is just a snippet, there is MUCH more of this for one move.

Code: Select all

59423 <second&#58; 14 -1027     248   1973294 &#58;-(
Impossible move a1g1^A, type = 0
60101 <second&#58; 14 -1349     316   2640242 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kd6 64.Rxa4
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
&#91;...&#93;

The 8x8 boards of numbers as well as the long array output are xboard output in /debug mode, not from Gaviota (otherwise it would have the "xxxxx <second " prefix in each single line). The Crafty output you have shown is from console mode. So I think you should compare the debug output when playing "Crafty vs. FixedOpponent" against debug output when playing "Gaviota vs. FixedOpponent". The difference will probably be not too big, apart from the obvious advantage of Crafty due to its "noise" setting (but other engines may have a similar setting, or suppress PV output for a fixed number of first N iterations).

Apart from that, the xboard/WinBoard output in debug mode appears too huge for my taste as well. Maybe a concept of a verbosity level (e.g. 0,1,2) would be helpful, where 0 would be the default for non-debug mode, 1 for debug mode, and only verbosity 2 would add all the internal xboard stuff as mentioned above that would be needed to actually debug xboard.

Another issue is the

Code: Select all

Impossible move a1g1^A, type = 0

stuff, that looks really fishy. Have you checked where that comes from?

[michiguel]

HGM:

Here's an oddity. I have been working on various things, and have been seeing some unexpected losses running with board. I decided to try a new opponent, and downloaded gaviota. It behaves VERY poorly. It dumps an absolute ton of garbage while it is playing. It displays multiple 8x8 boards of numbers, plus a couple of hundred array values, etc, after each move.

Gaviota does not do any of that. Sven explains it in another post (it seems you are looking at the wrong lines). If you want to limit Gaviota output even more, check the ini file (or the options in the xboard gui), you have there a couple of parameters to control the noise.

Miguel

[jdart]

I haven't seen an issue and Gaviota is one of the programs in my usual opponent pool. It is nice and stable.

I run my program in "debug mode" all the time on chess servers and if using xboard for matches. In that mode it outputs all kinds of "unnecessary" stuff (prefixed with # so xboard knows it is an info line). But that should just go into the log file, not to the server. For offline test matches though I use cutechess-cli and don't turn on debug, because I don't think cutechess has any way to capture the output.

--Jon

[bob]

I decided to try a new opponent, and downloaded gaviota. [...] It displays multiple 8x8 boards of numbers, plus a couple of hundred array values, etc, after each move.
[...]
For Crafty, here is a sample output: (I entered these commands by hand, to make it easy to see)

Code: Select all

xboard
noise 1
level 0 1 1
post
e4
      15     12     146 4309249 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Bg5 h6 8. Be3 Be6 9. Bxe6 Bxe3
      15     12     148 4398952 1. ... Nc6 2. Nf3 e5 3. Nc3 Nf6 4. Bc4 Bc5 5. d3 O-O 6. O-O d6 7. Bg5 h6 8. Be3 Be6 9. Bxe6 Bxe3
[...]

[...]
Here's debug from board for Gaviota, as an example (it only seems to get into chatty-kathy mode when pondering): Note this is just a snippet, there is MUCH more of this for one move.

Code: Select all

59423 <second&#58; 14 -1027     248   1973294 &#58;-(
Impossible move a1g1^A, type = 0
60101 <second&#58; 14 -1349     316   2640242 Ng7 56.Rd6+ Kh5 57.Kf3 Nf5 58.Ng3+ Kg5 59.Rd5 Kf6 60.Rxf5+ Ke6 61.Ke4 Kd6 62.f4 Kc6 63.Ra5 Kd6 64.Rxa4
 44 44 44  3 23 44 44 44
 44 44 44 44 44 44 44 44
 44 44 44 44 44 44 44 43
 44 44 44 44 44 44  1 44
 22 44 44 44 44 44 44 44
  0 44 44 44 44 44 44 44
 44 44 44 44 44  0 21 44
 44 44 44 44 44 44 44 44
&#91;...&#93;

The 8x8 boards of numbers as well as the long array output are xboard output in /debug mode, not from Gaviota (otherwise it would have the "xxxxx <second " prefix in each single line). The Crafty output you have shown is from console mode. So I think you should compare the debug output when playing "Crafty vs. FixedOpponent" against debug output when playing "Gaviota vs. FixedOpponent". The difference will probably be not too big, apart from the obvious advantage of Crafty due to its "noise" setting (but other engines may have a similar setting, or suppress PV output for a fixed number of first N iterations).

Apart from that, the xboard/WinBoard output in debug mode appears too huge for my taste as well. Maybe a concept of a verbosity level (e.g. 0,1,2) would be helpful, where 0 would be the default for non-debug mode, 1 for debug mode, and only verbosity 2 would add all the internal xboard stuff as mentioned above that would be needed to actually debug xboard.

Another issue is the

Code: Select all

Impossible move a1g1^A, type = 0

stuff, that looks really fishy. Have you checked where that comes from?

I checked your theory. the odd e1/e2 stuff _is_ coming from xboard but the 8x8 arrays are not. That specific output appears at the end of a game it seems. I just ran the same test with crafty vs crafty and I am not seeing any of that odd output except for the end of game stuff, whatever it is supposed to mean. The odd thing is it goes only to the debug output. Unless you theorize that somehow gaviota is triggering that in xboard. For the "impossible move" stuff I do not see it when playing Crafty vs Crafty. Only with Crafty vs Giovatta. Note that this is an OS X giovatta that is pre-compiled.

In any case, the excessive output problem is quite real and quite serious for shorter games. Not so much for long games or ponder-off games... It has a significant influence in the endgame where time is already getting low, and then a program outputs a PV and such for every iteration up to 50 or whatever.

[bob]

HGM:

Here's an oddity. I have been working on various things, and have been seeing some unexpected losses running with board. I decided to try a new opponent, and downloaded gaviota. It behaves VERY poorly. It dumps an absolute ton of garbage while it is playing. It displays multiple 8x8 boards of numbers, plus a couple of hundred array values, etc, after each move.

Gaviota does not do any of that. Sven explains it in another post (it seems you are looking at the wrong lines). If you want to limit Gaviota output even more, check the ini file (or the options in the xboard gui), you have there a couple of parameters to control the noise.

Miguel

I looked in the as-distributed .ini file (this is an os x pre-compiled version). I didn't see anything that addresses this... Is it possible for Giovatta to send something to board that puts it in some oddball mode? I don't see ANY of those 8x8 dumps when I play Crafty vs Crafty. Nor with Crafty vs Scorpio (or stockfish, arisen 17.x, etc...)

[bob]

I haven't seen an issue and Gaviota is one of the programs in my usual opponent pool. It is nice and stable.

I run my program in "debug mode" all the time on chess servers and if using xboard for matches. In that mode it outputs all kinds of "unnecessary" stuff (prefixed with # so xboard knows it is an info line). But that should just go into the log file, not to the server. For offline test matches though I use cutechess-cli and don't turn on debug, because I don't think cutechess has any way to capture the output.

--Jon

My issue happens in A vs B. Excessive output from A penalizes B due to xboard internal lag...

I write my debug stuff to the log file only, xboard never sees it. Seemed like the right approach when I first did this back in 1994 or so.

[hgm]

As already pointed out, this is debug output from XBoard. It would not be generated when you don't run XBoard in -debug mode, so normally it couldnot cause any slowdown. The move parser prints the board every time it fails to disambiguate a SAN move. In this case that probably happens because it tries to parse the first move of Gaviota's PV, and it is a move for the wrong side (as Gaviota is pondering), and thus illegal. This might be Gaviota or XBoard's fault, for trying to parse the move in the wrong position, by not sending or not performing the ponder move.

XBoard tries to identify the first PV move for sorting PVs of the same depth by score (for good multi-PV output), but it should not re-order PVs that start with the same move, irrespective of score (as they are probably re-searches of non-indicated fail highs).

It is debatable if I should do all that for ponder output; suppressing the sorting during ponder would be a simple way to avoid the problem. I doubt that this would eat very much time when not in debug mode; the printing to the debug file could take some time.

Note that the debug file is primarily intended as a tool to debug XBoard.

It is true that engine input is handled in XBoard by generating events in the event loop of the widget set (Xaw or GTK), and that events cannot interrupt each other. An input event handles all input received in a single read operation, even if it is multi-line. So it is in theory possible for one engine to lock out the other, by flooding XBoard with difficult-to-process output.

I guess the simples way to avoid is, is to poll for input of the other engine in the low-level input event handler that splits up the engine input in lines. It could then recursively start to handle events for that other engine before handling the remaining lines from the pondering engine. This is a bit tricky, because a flooding engine might interrupt the processing even of its own input.

[D Sceviour]

My issue happens in A vs B. Excessive output from A penalizes B due to xboard internal lag...

This sounds like a serious issue but it is not clear how lag can happen. Can engine A actually hog xboard resources to create a time lag penalty for engine B? If so, then this should be an interface problem. Xboard should not print engine A error output while engine B is thinking and polling for input.

However, that is still not clear. My engine only polls for CECP output received from xboard (i.e. engine> ). The 8x8 output should not be a time problem unless Crafty is actually reading all of the information from the debug file, and not just the information intended for CECP.

[bob]

My issue happens in A vs B. Excessive output from A penalizes B due to xboard internal lag...

This sounds like a serious issue but it is not clear how lag can happen. Can engine A actually hog xboard resources to create a time lag penalty for engine B? If so, then this should be an interface problem. Xboard should not print engine A error output while engine B is thinking and polling for input.

However, that is still not clear. My engine only polls for CECP output received from xboard (i.e. engine> ). The 8x8 output should not be a time problem unless Crafty is actually reading all of the information from the debug file, and not just the information intended for CECP.

The problem works like this:

Bad program makes a move, and then starts sending lots of garbage, which continually unblocks xboard for it to read that input. Meanwhile good program finally gets the move, thinks, and sends its move back, but xboard is backlogged processing all the bad program output, so if it is not careful, it will spend all of its time reading that input first, and only reading the good move later, and that program gets charged for all of that time.

This is caused by a polling issue. In unix, we use select() to determine when data is available on any of a set of descriptors. But once select() returns, you have to process the input in some order, and if you always check the first program's socket first, you always get that input first.

In my cluster referee, I use select(), but I always read from the descriptor connected to the side on move first, since that should be a priority... With only two sockets to worry with, this is trivial to do. It takes a confluence of events to make this an issue, the most notable is a short time control, so that the lag costs you dearly. I saw a sequence like this last night:

time 1400 (crafty has 14 seconds left)

Crafty moved and the search log shows 1.9 seconds used.

time 980 (crafty has 9.8 seconds left at the start of the next move, even though it clearly only used 1.9 seconds.)

I have been working on a new adaptive time allocation idea, but there is no way you can do anything adaptive when the time charged is much larger than the target time that was actually used...