Time losses in mps time controls

[rwbc]

I did some testing with CuteChess for the illegal move bug with 1.10.

Surprisingly I had 35 time losses in 152 games with a mps tc of 40/120. Obviously Loki tries to strictly use all available time in such time controls and fails sometimes (up to 300ms at max, from what I have seen).

Edit: I see from your code that you already subtract 50ms safety margin per move though. It is possible that the used logging tool created some overhead, because you send all possible moves for all depths always (better only do that in analysis mode), thus I will check again w/o logging for verification.

BTW the illegal move bug popped only once up, but I could not reproduce it either, even when slowly feeding the whole game history. (sometimes FEN analysis is not enough, one should try to get similar hash entries) It was also a move played for the other side.

Guenther

Edit2: It seems not to know yet the stop command (the log from a time loss shows it was already stopped by CuteChess but still tried to output some info until it made a move and replied with 'unknown command')

773.734: < info depth 10 currmove g3g4 currmovenumber 6
773.734: > stop
773.734: < info depth 10 currmove f4e5 currmovenumber 7
773.734: < info depth 10 currmove b4b5 currmovenumber 8
773.734: < info depth 10 currmove e6d5 currmovenumber 9
773.734: < info depth 10 currmove e6d7 currmovenumber 10
773.734: < info depth 10 currmove f4f7 currmovenumber 11
773.734: < info depth 10 currmove f4c7 currmovenumber 12
773.734: < info depth 10 currmove h2h4 currmovenumber 13
773.734: < info depth 10 currmove f4h4 currmovenumber 14
773.734: < info depth 10 currmove f4f3 currmovenumber 15
773.734: < info depth 10 currmove e6f5 currmovenumber 16
773.734: < info depth 10 currmove e6f7 currmovenumber 17
773.734: < info depth 10 currmove f4e3 currmovenumber 18
773.734: < info depth 10 currmove f4d4 currmovenumber 19
773.734: < info depth 10 currmove e6h3 currmovenumber 20
773.734: < info depth 10 currmove f4f8 currmovenumber 21
773.734: < info depth 10 currmove e6b3 currmovenumber 22
773.734: < info depth 10 currmove f4g5 currmovenumber 23
773.734: < info depth 10 currmove f4e4 currmovenumber 24
773.734: < info depth 10 currmove f4f5 currmovenumber 25
773.734: < info depth 10 currmove f4c4 currmovenumber 26
773.749: < info depth 10 currmove f4g4 currmovenumber 27
773.749: < info depth 10 currmove e6a2 currmovenumber 28
773.749: < info depth 10 currmove h2h3 currmovenumber 29
773.749: < info depth 10 currmove e6g8 currmovenumber 30
773.749: < info depth 10 currmove e6c8 currmovenumber 31
773.749: < info depth 10 currmove f4d6 currmovenumber 32
773.749: < info depth 10 currmove e6g4 currmovenumber 33
773.749: < info depth 10 currmove f4h6 currmovenumber 34
773.749: < info depth 10 currmove e6c4 currmovenumber 35
773.749: < info depth 10 currmove f4c1 currmovenumber 36
773.749: < info depth 10 currmove f4b8 currmovenumber 37
773.749: < info depth 10 currmove f4d2 currmovenumber 38
773.749: < info depth 10 currmove g1f1 currmovenumber 39
773.749: < info depth 10 currmove f2f3 currmovenumber 40
773.749: < info depth 10 currmove e7e8n currmovenumber 1
773.749: < info depth 10 currmove e7e8b currmovenumber 2
773.749: < info depth 10 currmove e7e8r currmovenumber 3
773.749: < info depth 10 currmove e7e8q currmovenumber 4
773.749: < info depth 10 currmove f4f6 currmovenumber 5
773.749: < info depth 10 currmove g3g4 currmovenumber 6
773.749: < info depth 10 currmove f4e5 currmovenumber 7
773.749: < info depth 10 currmove b4b5 currmovenumber 8
773.749: < info depth 10 currmove e6d5 currmovenumber 9
773.749: < info depth 10 currmove e6d7 currmovenumber 10
773.749: < info depth 10 currmove f4f7 currmovenumber 11
773.749: < info depth 10 currmove f4c7 currmovenumber 12
773.749: < info depth 10 currmove h2h4 currmovenumber 13
773.749: < info depth 10 currmove f4h4 currmovenumber 14
773.749: < info depth 10 currmove f4f3 currmovenumber 15
773.749: < info depth 10 currmove e6f5 currmovenumber 16
773.765: < info depth 10 currmove e6f7 currmovenumber 17
773.765: < info depth 10 currmove f4e3 currmovenumber 18
773.765: < info depth 10 currmove f4d4 currmovenumber 19
773.765: < info depth 10 currmove e6h3 currmovenumber 20
773.765: < info depth 10 currmove f4f8 currmovenumber 21
773.765: < info depth 10 currmove e6b3 currmovenumber 22
773.765: < info depth 10 currmove f4g5 currmovenumber 23
773.765: < info depth 10 currmove f4e4 currmovenumber 24
773.765: < info depth 10 currmove f4f5 currmovenumber 25
773.765: < info depth 10 currmove f4c4 currmovenumber 26
773.765: < info depth 10 currmove f4g4 currmovenumber 27
773.765: < info depth 10 currmove e6a2 currmovenumber 28
773.765: < info depth 10 currmove h2h3 currmovenumber 29
773.765: < info depth 10 currmove e6g8 currmovenumber 30
773.765: < info depth 10 currmove e6c8 currmovenumber 31
773.765: < info depth 10 currmove f4d6 currmovenumber 32
773.765: < info depth 10 currmove e6g4 currmovenumber 33
773.765: < info depth 10 currmove f4h6 currmovenumber 34
773.765: < info depth 10 currmove e6c4 currmovenumber 35
773.765: < info depth 10 currmove f4c1 currmovenumber 36
773.765: < info depth 10 currmove f4b8 currmovenumber 37
773.765: < info depth 10 currmove f4d2 currmovenumber 38
773.765: < info depth 10 currmove g1f1 currmovenumber 39
773.765: < info depth 10 currmove f2f3 currmovenumber 40
773.765: < bestmove f4e5
773.765: < Unknown command: stop

[BimmerBass]

Yes, it is right that Loki tries to use all available time. Currently, it is just set to divide the remaining time (wtime/btime + winc/binc) by 30 or the amount of movestogo if that is set. This is sub-optimal since it usually gets into serious time trouble in the endgame and can't find checkmates for example, so I will implement some proper time management such as the one Hyatt experimented with (https://www.chessprogramming.org/Time_Management, section: "extra time"). By the way, I think that the illegal move bug has been fixed (I just haven't pushed the change since I am currently testing elo gains for individual pruning/reduction methods). It seemed to be caused by updating the PV even in fail-high situations... But I will have to test this further to be 100% certain (right now I've played ~800 games with no problems). The issue with the stop command is very weird because I have already written a CheckUp function that is called pretty often while searching. This checks for both the stop and quit command, so Loki should have seen it and stopped the search. I will investigate this further.

Thank you for pointing out these bugs/flaws!

[rwbc]

I just want to add that it seems it really was the logging tools' overhead with the massive output of Loki, which triggered the time losses. I have now played a few dozens (not enough yet) of games w/o logging and Loki survived often move 40 with around 20ms. I also had set piece animation to zero in the CuteChess GUI now. (default = 300ms) BTW this was the first time ever I have seen this happening with Inbetween = tool used for logging.

[BimmerBass]

I forgot to ask you something: What time control did you use for the 40/120? For testing I usually use 4s + 0.1s for 200 games (more if the change is smaller), and I am wondering if the illegal move bug is caused by big output of Loki in conjunction with a lot of GUI commands being sent. I don't know if Loki could somehow corrupt the "position startpos moves ..." string if it doesn't stop printing output immediately. I am testing that now.

[rwbc]

That was 40 moves/120 seconds

good luck!

[BimmerBass]

Since it was the logging tool that created a lot of overhead, I have reduced the output from Loki. Now it doesn't output each move, but rather just the info string containing score, pv, nodes searched etc.. This should make it easier to log.

I will therefore close this issue, and make a new one as a request for better time control mechanics.

Again, thank you for pointing out the issue!