Weirdness with gnuchess self-play in xboard

[vasu]

I've been trying to run slightly modified versions of gnuchess against each other using xboard to test out certain simple time-management strategies, and am running into the really alarming phenomenon of self-play not giving a 50-50 result (this obviously makes it really hard to compare two different versions).
In particular, whichever engine is specified as -fcp always has an advantage (in one case 76-18-6 for a set of 100-games). Since xboard alternates sides, I don't see any immediate reason why this should be the case. Any ideas?

[H.G.Muller]

Hard to say on so little info. Do you run these tournaments from an external book (GUI book or loadGameFile)? Do you notice any weirdness in how GNU-Chess distributes its time over the game? (Which TC are you using anyway?) Are any of the games forfeited on time or because of illegal moves or false illegal-move claims? Which version of XBoard and GNU Chess are you using anyway? I suppose you are using -matchMode for this. Or are you using a tournament manager that restarts WinBoard for every game? How long is the -matchPause between games?

[vasu]

Do you run these tournaments from an external book (GUI book or loadGameFile)?

No.

Do you notice any weirdness in how GNU-Chess distributes its time over the game? (Which TC are you using anyway?) Are any of the games forfeited on time or because of illegal moves or false illegal-move claims?

I'm running 5 second games with no increment, and there are a bunch of games forfeited on time or because of illegal move claims, but most games go to checkmate.

Which version of XBoard and GNU Chess are you using anyway?

XBoard: 4.4.2, Gnu Chess: 5.07

I suppose you are using -matchMode for this. Or are you using a tournament manager that restarts WinBoard for every game? How long is the -matchPause between games?

I am using -reuseFirst and -reuseSecond set to true.

Thanks for your help.

[H.G.Muller]

Well, illegal move claims are a bad sign. In matchMode they usually occur when one engine resigns after giving its move, so that a new game starts, and the other is still thinking about the reply move. This move might then be taken as a move of the next game. I could imagine there is some asymmetry here, as the second engine is always started last in match mode.

Does this version of GNU Chess support ping?

[Michel]

Gnuchess is indeed quite buggy. I originally started fixing those bugs but
now I have decided that it is better to entirely refactor GnuChess so that it
becomes a modern object oriented program (fruit is the model here).

I am doing this right now. The source is already much cleaner so that it is easier to work on.

When I am done refactoring I hope to tackle GnuChess's search and eval.
Of course that it is a different matter.

[Michel]

Actually I am now noticing some weirdness myself.

In the log below one sees that second gets 9.95 seconds. seconds answers immediately since it is still
in its book.

This is confirmed by the otim command to first: "otim 995".

But suddenly the next time command to second is "time 987". So 0.08 seconds seem to have vaporized
for second.

538 >second: time 995
538 >second: otim 979
book hit = (NULL)
538 >second: d1e2
539 <second: move b7b6
machine move 19, castling = 7 0 -1 7 0 -1
move to parse: b7b6
7 0 4 7 0 4 Legality test? b7b6
7 0 -1 7 0 -1 Legality test? b7b6
(7,0) (0,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=22 (1,6)-(1,5) -
7 0 4 7 0 4 Legality test? b7b6
movetype=33, promochar=0=-
MateTest: K=1, my=16, his=16
move: b7b6
, parse: b6 (
)
MateTest: K=1, my=16, his=16
repeat test fmm=20 bmm=0 ep=-4, reps=6
20 ep=-3
19 ep=-4
18 ep=-3
17 ep=-3
16 ep=-4
15 ep=-4
14 ep=-4
13 ep=-4
12 ep=-4
11 ep=-4
10 ep=-4
9 ep=-4
8 ep=-4
7 ep=-3
6 ep=-3
5 ep=-3
4 ep=-3
3 ep=-4
2 ep=-3
1 ep=-3
0 ep=-4
time odds: 1 1
539 >first : time 979
539 >first : otim 995
book hit = (NULL)
539 >first : b7b6
541 <first : 1 12 0 130 e4
541 <first : 2 -54 0 206 e4 c4
541 <first : 2 -49 0 408 c4 Bb7 cxd5 Bxd5
541 <first : 2 -46 0 508 dxc5 Nxc5 Rb1
541 <first : 2 -46 0 515 dxc5 Nxc5 Rb1
541 <first : 3 -67 0 895 dxc5 Nxc5 e4 Bb7
541 <first : 3 -49 0 1090 c4 Bb7 cxd5 Bxd5
541 <first : 3 -36 0 1267 e4 c4 Bc2
543 <first : 3 -36 0 2257 e4 c4 Bc2
544 <first : 4 -45 0 2775 e4 c4 Bc2 Re8
546 <first : 4 -45 0 4257 e4 c4 Bc2 Re8
549 <first : 5 -10 0 5929 e4 c4 Bc2 Bb7 e5
554 <first : 5 -10 1 11282 e4 c4 Bc2 Bb7 e5
563 <first : 6 44 2 17048 e4 c4 Bc2 Bf4 exd5 exd5 Qe7
566 <first : 6 44 2 19047 e4 c4 Bc2 Bf4 exd5 exd5 Qe7
582 <first : 7 30 4 31668 e4 c4 Bc2 Bf4 e5 Nh5 h4
591 <first : 7 30 5 39207 e4 c4 Bc2 Bf4 e5 Nh5 h4
628 <first : 8 34 8 66803 e4 c4 Bc2 dxe4 Nxe4 Bb7 Nxd6 Qxd6 Qxc4 Bxf3 gxf3
650 <first : 8 34 11 82739 e4 c4 Bc2 dxe4 Nxe4 Bb7 Nxd6 Qxd6 Qxc4 Bxf3 gxf3
783 <first : 9 45 24 189184 e4 c4 Bc2 Nh5 exd5 exd5 Ne5 Nf4 Qe3 Ne6
815 <first : 9 45 27 215999 e4 c4 Bc2 Nh5 exd5 exd5 Ne5 Nf4 Qe3 Ne6
815 <first : move e3e4
machine move 20, castling = 7 0 -1 7 0 -1
move to parse: e3e4
7 0 4 7 0 4 Legality test? e3e4
7 0 -1 7 0 -1 Legality test? e3e4
(7,0) (0,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=0 (4,2)-(4,3) -
7 0 4 7 0 4 Legality test? e3e4
movetype=33, promochar=0=-
MateTest: K=1, my=16, his=16
move: e3e4
, parse: e4 (
)
MateTest: K=1, my=16, his=16
repeat test fmm=21 bmm=0 ep=-4, reps=6
21 ep=-3
20 ep=-3
19 ep=-4
18 ep=-3
17 ep=-3
16 ep=-4
15 ep=-4
14 ep=-4
13 ep=-4
12 ep=-4
11 ep=-4
10 ep=-4
9 ep=-4
8 ep=-4
7 ep=-3
6 ep=-3
5 ep=-3
4 ep=-3
3 ep=-4
2 ep=-3
1 ep=-3
0 ep=-4
time odds: 1 1
815 >second: time 987
815 >second: otim 960

GnuChess log.

1265386448.775794: Debug: parse_input() called, inputstr = *time 995
1265386448.775803: *
1265386448.775808: Debug: input_status = 1
1265386448.775815: Debug: Waking up input...
1265386448.775823: Debug: input_status = 0
1265386448.775838: Debug: Parsing input...
1265386448.775845: Debug: Waiting for input...
1265386448.775854: IN: otim 979
1265386448.775860:
1265386448.775867: Debug: Parsing input...
1265386448.775874: Debug: parse_input() called, inputstr = *otim 979
1265386448.775883: *
1265386448.775888: Debug: input_status = 1
1265386448.775895: Debug: Waking up input...
1265386448.775903: Debug: input_status = 0
1265386448.775910: Debug: Parsing input...
1265386448.775916: Debug: Waiting for input...
1265386448.775925: IN: d1e2
1265386448.775931:
1265386448.775938: Debug: Parsing input...
1265386448.775945: Debug: parse_input() called, inputstr = *d1e2
1265386448.775954: *
1265386448.775959: ParseEPD(): FEN=rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
1265386448.775979: 10. d1e2
1265386448.775990: Debug: Set 0x4
1265386448.775997: Debug: input_status = 1
1265386448.776003: Debug: Waking up input...
1265386448.776011: Debug: input_status = 0
1265386448.776018: Debug: Parsing input...
1265386448.776025: Thinking...
1265386448.776031: ParseEPD(): FEN=rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
1265386448.776059: BookMove! GenCnt=1
1265386448.776070: move b7b6
1265386448.776080: Debug: Clear 0x4
1265386448.776087: Debug: Waiting for input...
1265386449.052591: IN: time 987
1265386449.052606:
1265386449.052619: Debug: Parsing input...
1265386449.052628: Debug: parse_input() called, inputstr = *time 987

[H.G.Muller]

This is weird indeed. In general, the time is always equal to the otim of the previous ply, as it should.

The only explanation I have is that you were hit by the clock interrupt between doing the move (i.e. incrementing the move number) and pressing the clock. Which clock is decremented on a tick is decided on bases of the move number, so that would mean the time is deducted from the wrong clock. Time + otim before the move (at 539) is 1974, after the move (at 815) it is 1947. That means 270 ms was deduced from the clocks, while 276 ms passed. That sounds OK. There should have been 90 ms left on the first tick of the previous move (the time was 979, and the clock should tick at 990) which might very well show up as a decrement of 80 of the wrong clock after runding ms to cs twice.

I guess the save way to do it is to increment the move number only after switching the clock. (The first tick after the switch should always be long enough that the move number is already incremented when it comes, but the race between the incoming engine move and the next clock tick can have an arbitrarily close finish.) I already had to move the move-number increment backwards once before, to after the copying and applying of the move to the new board, to prevent adjudications to be done based on an incompletely copied board. (Which lead t false 'but bare King' corrections of time losses to draws.) But apparently I have to push it back even further.

Problem is that SwitchClocks() is called from several other places, so I would have to make sure this exchange of the order of incrementing and switching is consistently done everywhere. A really good opportunity to replace an extremely rarely occurring bug by a common one elsewhere...