Arena time management bug ?!!

[Desperado]

Table:

RestTime : Time discount Arena : Time used by Engine

Code: Select all

restTime  Arena  Nemo(measured when sending bestmove)

60000    (2848)   2714
57152    (2521)   1574  !
54631    (2600)   1623  !
52031    (2616)   2434 
49415    (3100)   1903  !
46315    (2958)   1653  !
43357  

    time difference rest time -> (43357,51016)!!!

A:
==========

snippet error protocol Arena...(from another game)

2011-10-22 12:30:09,746*1*Start calc, move no: 4
2011-10-22 12:30:09,746-->1:position startpos moves e2e4 b8c6 d2d4 g8f6
2011-10-22 12:30:09,761-->1:go wtime 53285 btime 56469
2011-10-22 12:30:13,380<--1:bestmove d4d5 ponder c6e5
2011-10-22 12:30:13,380*1*Zug gefunden:d4-d5
2011-10-22 12:30:13,536*2*Start calc, move no: 5
2011-10-22 12:30:13,802-->time 5647
2011-10-22 12:30:13,802-->otim 4968
2011-10-22 12:30:13,802-->2:d4d5
2011-10-22 12:30:13,802<--2:# movesPlayed=2 movesToPlay=32 sessions=1 totalCSec=6000 totalCSec_Mod=6000 timeLeftCSec=5651 timeUsableCSec=5631 maxTimeCSec=166
2011-10-22 12:30:13,817<--2:# movesPlayed=2 movesToPlay=32 sessions=1 totalCSec=6000 totalCSec_Mod=6000 timeLeftCSec=5647 timeUsableCSec=5627 maxTimeCSec=166
2011-10-22 12:30:13,833<--2:1 53 0 183 c6e5 g1f3 e5f3 d1f3 d7d6 f1b5 c8d7 b1c3
2011-10-22 12:30:13,848<--2:1 53 0 205 c6e5 g1f3 e5f3 d1f3 d7d6 f1b5 c8d7 b1c3
2011-10-22 12:30:13,864<--2:2 25 0 251 c6e5 g1f3 e5f3 d1f3 d7d6 f1b5 c8d7 b1c3
2011-10-22 12:30:13,880<--2:2 25 0 274 c6e5 g1f3 e5f3 d1f3 d7d6 f1b5 c8d7 b1c3
2011-10-22 12:30:13,895<--2:3 5 0 413 c6e5 g1f3 d7d6 f1b5 c8d7 h2h3
2011-10-22 12:30:13,911<--2:3 5 0 518 c6e5 g1f3 d7d6 f1b5 c8d7 h2h3
2011-10-22 12:30:13,926<--2:4 5 0 874 c6e5 g1f3 d7d6 f1b5 c8d7 h2h3
2011-10-22 12:30:13,942<--2:4 5 0 2653 c6e5 g1f3 d7d6 f1b5 c8d7 h2h3
2011-10-22 12:30:13,958<--2:5 5 0 5664 c6e5 g1f3 d7d6 f3e5 d6e5 f1b5 c7c6
2011-10-22 12:30:13,973<--2:5 5 1 13430 c6e5 g1f3 d7d6 f3e5 d6e5 f1b5 c7c6
2011-10-22 12:30:13,989<--2:6 -9 3 20885 c6e5 g1f3 e5f3 d1f3 e7e6 c1e3 f8d6
2011-10-22 12:30:14,004<--2:6 -9 8 37183 c6e5 g1f3 e5f3 d1f3 e7e6 c1e3 f8d6
2011-10-22 12:30:14,020<--2:7 -16 17 76573 c6e5 g1f3 d7d6 b1c3 e5f3 g2f3 c8d7 c1e3
2011-10-22 12:30:14,145<--2:7 -16 32 147871 c6e5 g1f3 d7d6 b1c3 e5f3 g2f3 c8d7 c1e3
2011-10-22 12:30:14,457<--2:8 -21 64 266251 c6e5 g1f3 e5f3 d1f3 e7e6 b1c3 f8b4 c1e3 e8g8
2011-10-22 12:30:15,003<--2:8 -21 118 477636 c6e5 g1f3 e5f3 d1f3 e7e6 b1c3 f8b4 c1e3 e8g8
2011-10-22 12:30:15,018<--2:move c6e5
2011-10-22 12:30:15,018*2*Zug gefunden:Sc6-e5
2011-10-22 12:30:15,174*1*Start calc, move no: 6
2011-10-22 12:30:15,174-->1:position startpos moves e2e4 b8c6 d2d4 g8f6 d4d5 c6e5
2011-10-22 12:30:15,190-->1:go wtime 49671 btime 55258
2011-10-22 12:30:18,310<--1:bestmove f2f4 ponder e5g6

B:
==========

So 2 simple questions:

*

how can wTime shrink without having a move between 4,6 ???

*

what is time,oTime (myTime,opponentTime ??)
marked with blue color ? it looks like when it is
summed together that is the time which is substracted of startime,
and leads to the pseudo wtime 49671 at move 6 ?!!?

C:
==========

Has anyone experience with time management problems under Arena
(this is version Arena 3.0) ? I was able to detect the same problem
under previous versions.

Any ideas, hints, information is appreciated.

Michael

[Desperado]

Ok , forget my "first" question...

But i simply cannot find an explanation for the big differences of the
time discounts between my engine and Arena !?

Michael

[Desperado]

Ok, no more time losses! and NO bugs at all.

I am even not sure if my numbers given in the above posts are correct
at all,but because i was really dispaired because even with ultrafast
games under LittleBlitzer,Cutechess-cli i _never_ lost on time.
And i really was not able to find a bug in my timemanagement code.
But in Arena after i think 6 or 7 games lost on time in a row , i stopped the disaster...

The problem seem to be that my engine somehow produces too much
communication traffic for Arena. Although i start regularly outputs from
ply 10 (current move,pv update, searchInfo), none of the mentioned
UIs has had a problem with com-overhead. Not even in time critical
situations.

Maybe Arena should only scan for bestmove command for example when
time is less than a second or something like that.
So it does not get a problem with com-overhead in such situations.

thx for your attention...

Michael

[michiguel]

Ok , forget my "first" question...

But i simply cannot find an explanation for the big differences of the
time discounts between my engine and Arena !?

Michael

We had long discussions about it in the past.
The problem is when there is a lot of traffic going from the engine to the GUI. If you reduce the output at lower depths, you will see a clear improvement. In addition, there is one way in Arena to make sure it ignores some of it, but I do not remember the option.

If you run gaviota, you will find in the logs a measurement of the lags in the line

Code: Select all

LAG --> estimated average = 0 ms

(0 or whatever number)

Miguel
EDIT: Now I see your reply, you got it.

[tpetzke]

I have seen the same, in short time controls when my engine gets to a known endgame position and rushes through 100 plys in an instant it still sends a pv for each ply. This is more than Arena can handle. It firsts digests all the pv information and counts its own processing time against the engine.

Thomas...