Quite big delay on first move at TCEC

[Matthies]

562 >RubiChess 20230121(0): setoption name Hash value 65536
562 >RubiChess 20230121(0): setoption name Move_Overhead value 1000
562 >RubiChess 20230121(0): setoption name SyzygyPath value /home/syzygy7
562 >RubiChess 20230121(0): isready
17927 <RubiChess 20230121(0): info string Found 1511 (650 pawn-less / 861 with pawn) tablebases.
17972 <RubiChess 20230121(0): readyok
Started game 41 of 10400 (RubiChess 20230121 vs Stockfish_15_100M)
62406 >RubiChess 20230121(0): ucinewgame
62407 >RubiChess 20230121(0): setoption name Ponder value false
62407 >RubiChess 20230121(0): setoption name UCI_RatingAdv value -33
62407 >RubiChess 20230121(0): position startpos
62407 >RubiChess 20230121(0): isready
63785 <RubiChess 20230121(0): info string Using contempt -8
63830 <RubiChess 20230121(0): readyok
63830 >RubiChess 20230121(0): position startpos moves e2e4
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4 f8e7
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4 f8e7 c1e3
63830 >RubiChess 20230121(0): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4 f8e7 c1e3 b8c6
63830 >RubiChess 20230121(0): go wtime 1800000 btime 36000000 winc 3000 binc 1
64542 <RubiChess 20230121(0): info depth 1 seldepth 2 multipv 1 time 0 score cp 45 nodes 193 nps 0 tbhits 0 hashfull 0 pv d4c6 b7c6 
64542 <RubiChess 20230121(0): info depth 2 seldepth 3 multipv 1 time 0 score cp 261 nodes 466 nps 0 tbhits 0 hashfull 0 pv g4g5 c6d4 g5f6 
...
96225 <RubiChess 20230121(0): bestmove g4g5 ponder f6d7
...
99133 >RubiChess 20230121(0): go wtime 1770606 btime 35997094 winc 3000 binc 1
99181 <RubiChess 20230121(0): info string Measured GUI overhead is 712ms (> 50% of allowed via Move_Overhead option).

So from cutechess pov it takes 712ms from go to first output. From RubiChess pov this is a GUI lag.

[Matthies]

Maybe ucinewgame action takes a while? ... No, that should be handled in the isready ... readyok sequence that follows the ucinewgame and takes 1423ms.

[Matthies]

Next idea: Flooding the engine with positions may be the reason. ... No. In the reverse game only the last position ... is sent directly before the go and we still see delay:

61485 >RubiChess 20230121(1): ucinewgame
61485 >RubiChess 20230121(1): setoption name Ponder value false
61485 >RubiChess 20230121(1): setoption name UCI_RatingAdv value -33
61485 >RubiChess 20230121(1): position startpos
61485 >RubiChess 20230121(1): isready
63309 <RubiChess 20230121(1): info string Using contempt -8
63356 <RubiChess 20230121(1): readyok
63356 >RubiChess 20230121(1): position startpos moves e2e4
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4 f8e7
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4 f8e7 c1e3
63356 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4 f8e7 c1e3 b8c6
65487 >RubiChess 20230121(1): position startpos moves e2e4 c7c5 g1f3 d7d6 d2d4 c5d4 f3d4 g8f6 b1c3 a7a6 h2h3 e7e6 g2g4 f8e7 c1e3 b8c6 g4g5
65487 >RubiChess 20230121(1): go wtime 35997715 btime 1800000 winc 1 binc 3000
65533 <RubiChess 20230121(1): info depth 1 seldepth 2 multipv 1 time 0 score cp -118 nodes 230 nps 0 tbhits 0 hashfull 0 pv f6d7 

[Matthies]

startSearchTime() which fixes the starting time is called immediately after the "go" is seen and even before threads are started etc. so if starting > 100 threads takes some time, the engine should see this and would not give ... time 0 ... on first depth.

[Matthies]

Every 'position ... ' triggers a prepareThreads() which moves quite an amount of data for every thread. So maybe it is the flooding of position that causes the delay. Needs more logs to investigate...