macOS: go movetime

[twoplan]

Compiled latest demolito (search 12 = 14468903) on my mac. Then ran a test with 404 opening positions. Each with 0.1s per move, so this should give a total time of ~40s. But demolito is much faster, better say used less time:

python3 mea.py --engine "/Users/max/chess/Demolito/demolito" --name "Demolito 1.0.44" --epd "../2-moves.epd" --log --movetime 100
epd 1 / 404
..
..
epd 404 / 404 
Time allocation  : GOOD!!
at <= et + mt and at >= et - mt
ExpectedTime     : 40.4s
ActualTime       : 20.2s
MarginTime/pos   : 0.2s
MarginTime       : 80.8s

Demolito used only 50% of the time. Could this be a macOS issue?

..
[ 2019-07-26 12:48:42,798 -     INFO ] Run engine Demolito 1.0.44
[ 2019-07-26 12:48:42,800 -    DEBUG ] >> uci
[ 2019-07-26 12:48:42,808 -    DEBUG ] << id name Demolito 1.0.44
[ 2019-07-26 12:48:42,808 -    DEBUG ] << id author lucasart
[ 2019-07-26 12:48:42,808 -    DEBUG ] << option name Contempt type spin default 10 min -100 max 100
[ 2019-07-26 12:48:42,809 -    DEBUG ] << option name Hash type spin default 2 min 1 max 1048576
[ 2019-07-26 12:48:42,809 -    DEBUG ] << option name Ponder type check default false
[ 2019-07-26 12:48:42,809 -    DEBUG ] << option name Threads type spin default 1 min 1 max 63
[ 2019-07-26 12:48:42,809 -    DEBUG ] << option name Time Buffer type spin default 60 min 0 max 1000
[ 2019-07-26 12:48:42,809 -    DEBUG ] << option name UCI_Chess960 type check default false
[ 2019-07-26 12:48:42,809 -    DEBUG ] << uciok
[ 2019-07-26 12:48:42,809 -    DEBUG ] >> setoption name threads value 1
[ 2019-07-26 12:48:42,809 -    DEBUG ] >> setoption name Hash value 64
[ 2019-07-26 12:48:42,809 -    DEBUG ] >> isready
[ 2019-07-26 12:48:42,846 -    DEBUG ] << readyok
[ 2019-07-26 12:48:42,846 -     INFO ] 

[ 2019-07-26 12:48:42,846 -     INFO ] Pos 1
[ 2019-07-26 12:48:42,846 -     INFO ] EPD: r1bqkb1r/pppppppp/2n2n2/8/2PP4/8/PP2PPPP/RNBQKBNR w KQkq - c0 "Nc3=53, Nf3=46";
[ 2019-07-26 12:48:42,846 -     INFO ] id None
[ 2019-07-26 12:48:42,846 -     INFO ] FEN: r1bqkb1r/pppppppp/2n2n2/8/2PP4/8/PP2PPPP/RNBQKBNR w KQkq - 0 1
[ 2019-07-26 12:48:42,846 -     INFO ] Solutions: Nc3=53, Nf3=46
[ 2019-07-26 12:48:42,846 -    DEBUG ] >> ucinewgame
[ 2019-07-26 12:48:42,847 -    DEBUG ] >> position fen r1bqkb1r/pppppppp/2n2n2/8/2PP4/8/PP2PPPP/RNBQKBNR w KQkq - 0 1
[ 2019-07-26 12:48:42,847 -    DEBUG ] >> go movetime 100
[ 2019-07-26 12:48:42,852 -    DEBUG ] << info depth 1 score cp 36 time 0 nodes 33 hashfull 0 pv b1c3
[ 2019-07-26 12:48:42,852 -    DEBUG ] << info depth 2 score cp -5 time 0 nodes 255 hashfull 0 pv b1c3 d7d5
[ 2019-07-26 12:48:42,852 -    DEBUG ] << info depth 3 score cp 8 time 0 nodes 598 hashfull 0 pv e2e3
[ 2019-07-26 12:48:42,852 -    DEBUG ] << info depth 3 score cp 8 time 0 nodes 684 hashfull 0 pv e2e3 d7d5 b1c3
[ 2019-07-26 12:48:42,852 -    DEBUG ] << info depth 4 score cp -14 time 0 nodes 967 hashfull 0 pv b1c3 d7d5 c4d5 f6d5
[ 2019-07-26 12:48:42,852 -    DEBUG ] << info depth 4 score cp -14 time 0 nodes 975 hashfull 0 pv b1c3 d7d5 c4d5 f6d5
[ 2019-07-26 12:48:42,852 -    DEBUG ] << info depth 5 score cp 16 time 1 nodes 1755 hashfull 0 pv b1c3 d7d6 e2e3 c8f5 f1d3
[ 2019-07-26 12:48:42,854 -    DEBUG ] << info depth 6 score cp 0 time 2 nodes 4211 hashfull 0 pv g1f3
[ 2019-07-26 12:48:42,854 -    DEBUG ] << info depth 6 score cp 8 time 3 nodes 5178 hashfull 0 pv g1f3 d7d6 d4d5 c6e5 f3e5 d6e5
[ 2019-07-26 12:48:42,856 -    DEBUG ] << info depth 7 score cp 27 time 4 nodes 7859 hashfull 0 pv g1f3 d7d6 b1c3 c8f5 d4d5 c6e5 d1b3
[ 2019-07-26 12:48:42,860 -    DEBUG ] << info depth 8 score cp 22 time 8 nodes 15667 hashfull 0 pv g1f3 d7d6 b1c3 e7e5 d4d5 c6e7 e2e4 c8d7 f1e2
[ 2019-07-26 12:48:42,886 -    DEBUG ] << info depth 9 score cp 9 time 34 nodes 58462 hashfull 1 pv b1c3 e7e6 e2e3 f8b4 g1e2 d7d5 a2a3 b4c3 e2c3 e8g8
[ 2019-07-26 12:48:42,886 -    DEBUG ] << info depth 9 score cp 9 time 34 nodes 59450 hashfull 1 pv b1c3 e7e6 e2e3 f8b4 g1e2 d7d5 a2a3 b4c3 e2c3 e8g8
[ 2019-07-26 12:48:42,894 -    DEBUG ] << bestmove b1c3 ponder e7e6
[ 2019-07-26 12:48:42,894 -     INFO ] elapsed(ms) since go: 48
[ 2019-07-26 12:48:42,895 -     INFO ] bestmove: Nc3
[ 2019-07-26 12:48:42,895 -     INFO ] Top 1 move!!
[ 2019-07-26 12:48:42,895 -     INFO ] Score for this test: 53
[ 2019-07-26 12:48:42,895 -     INFO ] Total Score update: 53 / 53 (1.000)
[ 2019-07-26 12:48:42,896 -     INFO ] r1bqkb1r/pppppppp/2n2n2/8/2PP4/8/PP2PPPP/RNBQKBNR w KQkq - bm Nc3; ce 9; acd 9;
[ 2019-07-26 12:48:42,896 -     INFO ] 
..

[erbsenzaehler]

Demolito does a 80ms search on my machine, when I set Time Buffer to 0.

Not sure what is expected from engines in this scenario

[twoplan]

Thanks erbsenzehler, didn't notice this option. Now it's all perfect:

python3 mea.py --engine "/Users/max/chess/Demolito/demolito-1.0.44" --name "Demolito 1.0.44" --eoption "Time Buffer=0" --epd "../2-moves.epd" --log --movetime 100

Time allocation  : GOOD!!
at <= et + mt and at >= et - mt
ExpectedTime     : 40.4s
ActualTime       : 44.5s
MarginTime/pos   : 0.2s
MarginTime       : 80.8s