Engines losing on time in won/drew games

Discussion of anything and everything relating to chess playing software and machines.

Moderators: hgm, Rebel, chrisw

User avatar
michiguel
Posts: 6401
Joined: Thu Mar 09, 2006 8:30 pm
Location: Chicago, Illinois, USA

Re: Engines losing on time in won/drew games

Post by michiguel »

Aaron Becker wrote:Having taken a closer look at the debugging output you posted, I'm a little confused about what's actually happening. Looking at just daydreamer's last 2 moves, here are the move commands and its final output for each:

Code: Select all

7.169.454-->1:go wtime 9511 btime 1871 winc 1000 binc 1000 
7.170.314<--1&#58;info depth 15 time 170 nodes 57823 score cp 0 pv b4b5 d4c3 c4c5 d6c5 b5c5 c3d3 c5b4 d3c2 b4a4 c2b1 a4b4 b1a1 b4a4 a1b1 
7.170.345<--1&#58;bestmove b4b5 

7.175.017-->2&#58;go wtime 9724 btime 487 winc 1000 binc 1000 
7.177.486<--2&#58;info multipv 1 depth 81 seldepth 0 score cp 0 time 376 nodes 10 nps 0 hashfull 0 tbhits 633 pv e4d4 
7.177.486-->2&#58;stop 
7.178.001*moveerror*black moved but it is white's turn !Ke4-d4! 
I read the number that starts each line as a millisecond timer. Black starts the first move with 1871ms on its clock at time 7.169.454, and produces a move at 7.170.345, 891ms later. By my count it should have 980+1000 = 1980ms on its clock to start the next move.

However, it actually starts the next move with 487ms on the clock. If we had positive time left on the clock after the last move, and the GUI added our increment of 1000ms, it should be impossible to start this move with only 487ms. Then daydreamer outputs an info line at time 7.177.486 (2469ms later), but it reports its time consumed as only 376ms.

Maybe I'm misreading the output, and the first number isn't actually a timestamp. But in any case, I don't understand how daydreamer started the last move with under 1000ms on the clock. I also have a hard time figuring out why daydreamer and the gui disagree by over 2s on the time of its info line in the second move. Maybe some disagreement can be explained by errors in my timing code, but an error of 2s on a reported time of 376ms is hard for me to figure out.

Does anyone have some suggestions for understanding this situation? I'd like to get this problem fixed, but it seems like there may be some underlying issue that I don't understand yet.
Very simple: Arena steals time from the engines and it may not be the only GUI who do that in windows (Ilari said he needed to replace some libraries to avoid similar problems with cutechess in windows). I measured it and posted about it some time ago. On average, in one computer I tested Arena steals from 0.2 to 0.4 seconds / move, and for some reason, that gets much bigger when the engine is probing the hard drive. In some cases, I measured a delay of 4 seconds, but it was not so rare to see delays of 0.5 to 2 seconds. You just need one event like that once in a while, and the engine loses on time.

Aaron, do not try to debug this because most likely has nothing to do with the engine. There are some ways to defensively deal with this issue, but you need to know that the source of the problem is the GUI.

Carlos, you cannot reliably run bullet games in Arena. I have no idea about other windows GUI, but they may suffer from the same problems with the possible exceptions of winboard and cutechess.

Miguel
Edmund
Posts: 670
Joined: Mon Dec 03, 2007 3:01 pm
Location: Barcelona, Spain

Re: Engines losing on time in won/drew games

Post by Edmund »

michiguel wrote:Very simple: Arena steals time from the engines and it may not be the only GUI who do that in windows (Ilari said he needed to replace some libraries to avoid similar problems with cutechess in windows). I measured it and posted about it some time ago. On average, in one computer I tested Arena steals from 0.2 to 0.4 seconds / move, and for some reason, that gets much bigger when the engine is probing the hard drive. In some cases, I measured a delay of 4 seconds, but it was not so rare to see delays of 0.5 to 2 seconds. You just need one event like that once in a while, and the engine loses on time.

Aaron, do not try to debug this because most likely has nothing to do with the engine. There are some ways to defensively deal with this issue, but you need to know that the source of the problem is the GUI.

Carlos, you cannot reliably run bullet games in Arena. I have no idea about other windows GUI, but they may suffer from the same problems with the possible exceptions of winboard and cutechess.

Miguel
Am I right to assume using GetProcessTimes() instead of any wall-time meassures solves the problem?

regards,
Edmund
User avatar
michiguel
Posts: 6401
Joined: Thu Mar 09, 2006 8:30 pm
Location: Chicago, Illinois, USA

Re: Engines losing on time in won/drew games

Post by michiguel »

Edmund wrote:
michiguel wrote:Very simple: Arena steals time from the engines and it may not be the only GUI who do that in windows (Ilari said he needed to replace some libraries to avoid similar problems with cutechess in windows). I measured it and posted about it some time ago. On average, in one computer I tested Arena steals from 0.2 to 0.4 seconds / move, and for some reason, that gets much bigger when the engine is probing the hard drive. In some cases, I measured a delay of 4 seconds, but it was not so rare to see delays of 0.5 to 2 seconds. You just need one event like that once in a while, and the engine loses on time.

Aaron, do not try to debug this because most likely has nothing to do with the engine. There are some ways to defensively deal with this issue, but you need to know that the source of the problem is the GUI.

Carlos, you cannot reliably run bullet games in Arena. I have no idea about other windows GUI, but they may suffer from the same problems with the possible exceptions of winboard and cutechess.

Miguel
Am I right to assume using GetProcessTimes() instead of any wall-time meassures solves the problem?

regards,
Edmund
If you mean to use that in the engine, I do not think so. If you mean in the GUI, I don't know.

The GUI relies the move to the engine informing that the engine has less time on the clock. The GUI spent that time somewhere and there is nothing the engine can do about it.

Miguel
User avatar
hgm
Posts: 27789
Joined: Fri Mar 10, 2006 10:06 am
Location: Amsterdam
Full name: H G Muller

Re: Engines losing on time in won/drew games

Post by hgm »

Edmund wrote:Am I right to assume using GetProcessTimes() instead of any wall-time meassures solves the problem?
In WinBoard I created nps 0 mode for this. This still relies on the engines not cheating when they report the (process) time they used, though.

Stealing time because of scheduling delays and hanging in some library routine is one thing, but it seems very strange that Arena still would do it while being aware of it. It tells the engine it has less than 1000 msec in a TTC with a 1000 msec increment. I don't think there can be any excuse for that. This suggests to me it has started the engines clock before it started something else which was time consuming, and then waited for the latter to complete, read the clock again, to see how much it had to take from the engine's time before sending it to the engine. That seems just wrong design...
Edmund
Posts: 670
Joined: Mon Dec 03, 2007 3:01 pm
Location: Barcelona, Spain

Re: Engines losing on time in won/drew games

Post by Edmund »

hgm wrote:
Edmund wrote:Am I right to assume using GetProcessTimes() instead of any wall-time meassures solves the problem?
In WinBoard I created nps 0 mode for this. This still relies on the engines not cheating when they report the (process) time they used, though.
[...]
But why would you rely on the engines report in this context? Sure they must be informed to switch to process-time mode, but the gui could still get its information from GetProcessTimes(), which can report process-time from any process currently running.
Carlos777
Posts: 1728
Joined: Sun Dec 13, 2009 6:09 pm

Re: Engines losing on time in won/drew games

Post by Carlos777 »

michiguel wrote:
Aaron Becker wrote:Having taken a closer look at the debugging output you posted, I'm a little confused about what's actually happening. Looking at just daydreamer's last 2 moves, here are the move commands and its final output for each:

Code: Select all

7.169.454-->1&#58;go wtime 9511 btime 1871 winc 1000 binc 1000 
7.170.314<--1&#58;info depth 15 time 170 nodes 57823 score cp 0 pv b4b5 d4c3 c4c5 d6c5 b5c5 c3d3 c5b4 d3c2 b4a4 c2b1 a4b4 b1a1 b4a4 a1b1 
7.170.345<--1&#58;bestmove b4b5 

7.175.017-->2&#58;go wtime 9724 btime 487 winc 1000 binc 1000 
7.177.486<--2&#58;info multipv 1 depth 81 seldepth 0 score cp 0 time 376 nodes 10 nps 0 hashfull 0 tbhits 633 pv e4d4 
7.177.486-->2&#58;stop 
7.178.001*moveerror*black moved but it is white's turn !Ke4-d4! 
I read the number that starts each line as a millisecond timer. Black starts the first move with 1871ms on its clock at time 7.169.454, and produces a move at 7.170.345, 891ms later. By my count it should have 980+1000 = 1980ms on its clock to start the next move.

However, it actually starts the next move with 487ms on the clock. If we had positive time left on the clock after the last move, and the GUI added our increment of 1000ms, it should be impossible to start this move with only 487ms. Then daydreamer outputs an info line at time 7.177.486 (2469ms later), but it reports its time consumed as only 376ms.

Maybe I'm misreading the output, and the first number isn't actually a timestamp. But in any case, I don't understand how daydreamer started the last move with under 1000ms on the clock. I also have a hard time figuring out why daydreamer and the gui disagree by over 2s on the time of its info line in the second move. Maybe some disagreement can be explained by errors in my timing code, but an error of 2s on a reported time of 376ms is hard for me to figure out.

Does anyone have some suggestions for understanding this situation? I'd like to get this problem fixed, but it seems like there may be some underlying issue that I don't understand yet.
Very simple: Arena steals time from the engines and it may not be the only GUI who do that in windows (Ilari said he needed to replace some libraries to avoid similar problems with cutechess in windows). I measured it and posted about it some time ago. On average, in one computer I tested Arena steals from 0.2 to 0.4 seconds / move, and for some reason, that gets much bigger when the engine is probing the hard drive. In some cases, I measured a delay of 4 seconds, but it was not so rare to see delays of 0.5 to 2 seconds. You just need one event like that once in a while, and the engine loses on time.

Aaron, do not try to debug this because most likely has nothing to do with the engine. There are some ways to defensively deal with this issue, but you need to know that the source of the problem is the GUI.

Carlos, you cannot reliably run bullet games in Arena. I have no idea about other windows GUI, but they may suffer from the same problems with the possible exceptions of winboard and cutechess.

Miguel
Hi Miguel and Aaaron,

Thanks for the explanation. This confirms that Arena is the problem here. As I said before, there were reports from programmers and users about Arena stealing time from engines. I will try WB + PSWBTM next, it seems more reliable about time allocating. I'd like that these issues were solved in the next version of Arena, because (as I stated before) it is my favorite GUI.

Best regards,
Carlos

PS: Also thanks to HGM for his informative posts.
User avatar
Matthias Gemuh
Posts: 3245
Joined: Thu Mar 09, 2006 9:10 am

Re: Engines losing on time in won/drew games

Post by Matthias Gemuh »

michiguel wrote:
Very simple: Arena steals time from the engines and it may not be the only GUI who do that in windows (Ilari said he needed to replace some libraries to avoid similar problems with cutechess in windows). I measured it and posted about it some time ago. On average, in one computer I tested Arena steals from 0.2 to 0.4 seconds / move, and for some reason, that gets much bigger when the engine is probing the hard drive. In some cases, I measured a delay of 4 seconds, but it was not so rare to see delays of 0.5 to 2 seconds. You just need one event like that once in a while, and the engine loses on time.

Aaron, do not try to debug this because most likely has nothing to do with the engine. There are some ways to defensively deal with this issue, but you need to know that the source of the problem is the GUI.

Carlos, you cannot reliably run bullet games in Arena. I have no idea about other windows GUI, but they may suffer from the same problems with the possible exceptions of winboard and cutechess.

Miguel
Hi Miguel,

if you ever have time for it, can you test ChessGUI's time management (even in bullet games).
I try to account for every millisecond.
BTW, ChessGUI has a time overstep margin (set to zero by default).

Matthias.
My engine was quite strong till I added knowledge to it.
http://www.chess.hylogic.de
User avatar
michiguel
Posts: 6401
Joined: Thu Mar 09, 2006 8:30 pm
Location: Chicago, Illinois, USA

Re: Engines losing on time in won/drew games

Post by michiguel »

Matthias Gemuh wrote:
michiguel wrote:
Very simple: Arena steals time from the engines and it may not be the only GUI who do that in windows (Ilari said he needed to replace some libraries to avoid similar problems with cutechess in windows). I measured it and posted about it some time ago. On average, in one computer I tested Arena steals from 0.2 to 0.4 seconds / move, and for some reason, that gets much bigger when the engine is probing the hard drive. In some cases, I measured a delay of 4 seconds, but it was not so rare to see delays of 0.5 to 2 seconds. You just need one event like that once in a while, and the engine loses on time.

Aaron, do not try to debug this because most likely has nothing to do with the engine. There are some ways to defensively deal with this issue, but you need to know that the source of the problem is the GUI.

Carlos, you cannot reliably run bullet games in Arena. I have no idea about other windows GUI, but they may suffer from the same problems with the possible exceptions of winboard and cutechess.

Miguel
Hi Miguel,

if you ever have time for it, can you test ChessGUI's time management (even in bullet games).
I try to account for every millisecond.
BTW, ChessGUI has a time overstep margin (set to zero by default).

Matthias.
I will.

In the meantime, before I put my hands on a windows machine (I am using Linux, mostly), if you play few games with Gaviota, send me the log files (my gmail account is mballicora) and I can extract the information from there.

Miguel
User avatar
Matthias Gemuh
Posts: 3245
Joined: Thu Mar 09, 2006 9:10 am

Re: Engines losing on time in won/drew games

Post by Matthias Gemuh »

michiguel wrote:
Matthias Gemuh wrote: Hi Miguel,

if you ever have time for it, can you test ChessGUI's time management (even in bullet games).
I try to account for every millisecond.
BTW, ChessGUI has a time overstep margin (set to zero by default).

Matthias.
I will.

In the meantime, before I put my hands on a windows machine (I am using Linux, mostly), if you play few games with Gaviota, send me the log files (my gmail account is mballicora) and I can extract the information from there.

Miguel

Which fast time control should I use ?
I tried "Game/30sec" and Gaviota lost one game (8 games played) on time at move 90.
It produced no logs.

Code: Select all

log         = on
max_logs    = 8
My engine was quite strong till I added knowledge to it.
http://www.chess.hylogic.de
User avatar
Matthias Gemuh
Posts: 3245
Joined: Thu Mar 09, 2006 9:10 am

Re: Engines losing on time in won/drew games

Post by Matthias Gemuh »

Matthias Gemuh wrote:
michiguel wrote:
Matthias Gemuh wrote: Hi Miguel,

if you ever have time for it, can you test ChessGUI's time management (even in bullet games).
I try to account for every millisecond.
BTW, ChessGUI has a time overstep margin (set to zero by default).

Matthias.
I will.

In the meantime, before I put my hands on a windows machine (I am using Linux, mostly), if you play few games with Gaviota, send me the log files (my gmail account is mballicora) and I can extract the information from there.

Miguel

Which fast time control should I use ?
I tried "Game/30sec" and Gaviota lost one game (8 games played) on time at move 90.
It produced no logs.

Code: Select all

log         = on
max_logs    = 8
Is the ini file really gaviota.ini.txt ?
No logs created at 1+1 either.

Renaming to gaviota.ini did not help.

I am using a later Gaviota renamed to Gaviota 0.74.12

Matthias.
My engine was quite strong till I added knowledge to it.
http://www.chess.hylogic.de