I have already run Houdini in console; it output for last ply looks like this:
info depth 20
info currmove d7c6 currmovenumber 1
info time 10013 nodes 26036001 nps 2600000 tbhits 0 hashfull 945 cpuload 126 idl
e 0M
info time 11014 nodes 28675176 nps 2603000 tbhits 0 hashfull 962 cpuload 124 idl
e 0M
info time 12016 nodes 31290461 nps 2604000 tbhits 0 hashfull 973 cpuload 124 idl
e 0M
info multipv 1 depth 20 seldepth 45 score cp -28 time 12467 nodes 32428925 nps 2
601000 tbhits 0 hashfull 979 pv d7c6 e1g1 d8f6 d2d3 f8d6 c1e3 f6e6 b1d2 g8f6 d1e
2 e8g8 h2h3 h7h6 d2c4 b7b6 a2a3 a8b8 b2b4 f8d8 a1b1 a6a5 c4d6 e6d6
info currmove b7c6 currmovenumber 2
info currmove a8b8 currmovenumber 3
info currmove h7h6 currmovenumber 4
info time 13017 nodes 33845543 nps 2600000 tbhits 0 hashfull 983 cpuload 122 idl
e 0M
info currmove f7f5 currmovenumber 5
info currmove a6a5 currmovenumber 6
info currmove g8h6 currmovenumber 7
info currmove g7g6 currmovenumber 8
info currmove h7h5 currmovenumber 9
info currmove g7g5 currmovenumber 10
info currmove f8e7 currmovenumber 11
info currmove f8b4 currmovenumber 12
info currmove f8c5 currmovenumber 13
info time 14015 nodes 36430710 nps 2599000 tbhits 0 hashfull 993 cpuload 123 idl
e 0M
info currmove g8f6 currmovenumber 14
info currmove g8e7 currmovenumber 15
info currmove d8f6 currmovenumber 16
info currmove f7f6 currmovenumber 17
info currmove d8e7 currmovenumber 18
info currmove f8d6 currmovenumber 19
info currmove a8a7 currmovenumber 20
info currmove f8a3 currmovenumber 21
info currmove e8e7 currmovenumber 22
info currmove b7b5 currmovenumber 23
info currmove b7b6 currmovenumber 24
info currmove d8h4 currmovenumber 25
info currmove d8g5 currmovenumber 26
info multipv 1 depth 20 seldepth 45 score cp -28 time 14220 nodes 36962002 nps 2
599000 tbhits 0 hashfull 994 pv d7c6 e1g1 d8f6 d2d3 f8d6 c1e3 f6e6 b1d2 g8f6 d1e
2 e8g8 h2h3 h7h6 d2c4 b7b6 a2a3 a8b8 b2b4 f8d8 a1b1 a6a5 c4d6 e6d6
bestmove d7c6 ponder e1g1
There isn't timestamp emited after every currmove which makes measurement impossible just from GUI output (that's why I gave time from first timestamp after 2 main moves to the last).
GUI which logs its own timestamps is necessary.
Great, I will check it out.
Meanwhile when I increased hash to 1024MB I got approximate results:
7881ms for whole depth 20, 881ms for "bad" moves . This looks way more reasonable. I guess it makes sense that if hash is overwritten "obviousness" of first moves in the tree is forgotten thus more time is dedicated to them again and again.
I will try to make timestamps working and do some more research about how much time is spent on not promising part of the tree.
By the way: as not spending time on crappy moves is especially important at the beginning of the search wouldn't it be worthwhile to keep separate table of "refuted moves and branches" for say first 3 ply and never ever visit them again even if hash for them got overwritten (or give them reduce penalty of 2/3 of current depth or w/e) ?
OneTrickPony wrote:By the way: as not spending time on crappy moves is especially important at the beginning of the search wouldn't it be worthwhile to keep separate table of "refuted moves and branches" for say first 3 ply and never ever visit them again even if hash for them got overwritten (or give them reduce penalty of 2/3 of current depth or w/e) ?
Outright prune? No, because there is no general rule that says that moves that look bad after a 3-ply search will always look bad. That's the whole reason you do deeper searches to begin with. Reduce? Certainly, and you can be sure that Houdini already does this.
One of the first things to realise is that you should not look at a few individual positions and decide how best to search in general based on those. It's very misleading and chances are that if you optimise to search those positions, you get a program that is good at searching those positions and bad at searching others. You can certainly get inspiration from doing that, but you must always verify that it doesn't hurt in other positions (and nine times out of ten it will).
Even if it seems obvious to you that a particular move is good or bad, there may well be a reason for why a program spends more time on it than you think reasonable. Perhaps it's not as easy as you think it is. Have a look at Bob's posts about criteria for easy/hard moves. It's not easy.
OneTrickPony wrote:I have already run Houdini in console; it output for last ply looks like this:
info depth 20
...
There isn't timestamp emited after every currmove which makes measurement impossible just from GUI output (that's why I gave time from first timestamp after 2 main moves to the last).
GUI which logs its own timestamps is necessary.
Interesting test. You might consider running to larger depth (22 or 23) so that you have more time stamps between the moves in the UCI output.
From this run you can already see that the first move dxc6 was responsible for about 65% of the thinking time, bxc6 is probably like 10%, and the remaining 20 moves are probably about 25%.
This means that dxc6 gets 50 times more thinking time than the average non-capture move.
OneTrickPony wrote:There isn't timestamp emited after every currmove which makes measurement impossible just from GUI output (that's why I gave time from first timestamp after 2 main moves to the last).
GUI which logs its own timestamps is necessary.
P.S. Arena 3.0 has a full UCI log with time stamps. Just press F4 in Arena 3.0 to see the log and the exact time of each move.
How do you think people operate it? Through telepathy?
My frustration got the best of me It's a lot of copy pasting to console and somehow Critter decided not to print its usual nice infostring at the end of "go" command once I switched it to 1 thread making it impossible to measure time with my framework at the time (ie reading std output).
The info string at the end of search is required by UCI according to this: http://wbec-ridderkerk.nl/html/UCIProtocol.html .
P.S. Arena 3.0 has a full UCI log with time stamps. Just press F4 in Arena 3.0 to see the log and the exact time of each move.
Robert
Sweet.
I wrote quick script to parse the input of Arena and I got this for 1 thread search from depth 18 to depth 24:
Move d7c6 time 133933 total:81.77
Move b7c6 time 5633 total:3.44
Move a8b8 time 2874 total:1.75
Move g8h6 time 2290 total:1.40
Move f7f5 time 2264 total:1.38
Move a6a5 time 2081 total:1.27
Move h7h6 time 2062 total:1.26
Move h7h5 time 1981 total:1.21
Move f8c5 time 1774 total:1.08
Move f8b4 time 1773 total:1.08
Move g7g5 time 1609 total:0.98
Move g7g6 time 1498 total:0.91
Move a8a7 time 1299 total:0.79
Move f8e7 time 1168 total:0.71
Move g8f6 time 461 total:0.28
Move d8e7 time 364 total:0.22
Move g8e7 time 160 total:0.10
Move d8f6 time 146 total:0.09
Move d8h4 time 90 total:0.05
Move f8d6 time 73 total:0.04
Move f7f6 time 59 total:0.04
Move d8g5 time 58 total:0.04
Move e8e7 time 51 total:0.03
Move b7b5 time 34 total:0.02
Move f8a3 time 30 total:0.02
Move b7b6 time 28 total:0.02
Unfortunately measuring things before depth 18 is not possible because engine doesn't output "currmove" (just PV updates).
This looks much more reasonable than 50%+ I initially thought.
Can you explain how search in "searchmoves" mode work ? I would like to understand source of my initial wrong impression.
Also is there a way to force Houdini to print "currmove" for every depth (say starting from depth 8 or something). That would make a nice tool for comparing engines
Move d7c6 time 127335 total:71.15
Move f7f5 time 11066 total:6.18
Move b7c6 time 9127 total:5.10
Move a6a5 time 5234 total:2.92
Move g8h6 time 4757 total:2.66
Move a8b8 time 4212 total:2.35
Move g7g5 time 3641 total:2.03
Move a8a7 time 3452 total:1.93
Move f8b4 time 2828 total:1.58
Move g8f6 time 2340 total:1.31
Move f8c5 time 1144 total:0.64
Move g7g6 time 853 total:0.48
Move f8e7 time 618 total:0.35
Move d8e7 time 571 total:0.32
Move h7h6 time 561 total:0.31
Move g8e7 time 371 total:0.21
Move h7h5 time 188 total:0.11
Move d8f6 time 175 total:0.10
Move d8g5 time 113 total:0.06
Move f8d6 time 99 total:0.06
Move f7f6 time 85 total:0.05
Move e8e7 time 65 total:0.04
Move b7b6 time 44 total:0.02
Move d8h4 time 38 total:0.02
Move f8a3 time 30 total:0.02
Move b7b5 time 27 total:0.02
Rybka 2.2:
Move d7c6 time 59215 total:66.57
Move b7c6 time 3780 total:4.25
Move f8b4 time 3228 total:3.63
Move f7f5 time 3213 total:3.61
Move g8h6 time 2773 total:3.12
Move a6a5 time 2334 total:2.62
Move f8c5 time 2267 total:2.55
Move g7g6 time 1991 total:2.24
Move g7g5 time 1988 total:2.23
Move h7h5 time 1935 total:2.18
Move h7h6 time 1550 total:1.74
Move f8e7 time 718 total:0.81
Move g8f6 time 710 total:0.80
Move a8b8 time 706 total:0.79
Move a8a7 time 646 total:0.73
Move d8f6 time 285 total:0.32
Move e8e7 time 277 total:0.31
Move f8d6 time 212 total:0.24
Move d8e7 time 209 total:0.23
Move b7b6 time 205 total:0.23
Move b7b5 time 196 total:0.22
Move d8h4 time 151 total:0.17
Move f7f6 time 149 total:0.17
Move g8e7 time 103 total:0.12
Move d8g5 time 73 total:0.08
Move f8a3 time 42 total:0.05
The stronger the engine the more it focused on what's important
OneTrickPony wrote:Can you explain how search in "searchmoves" mode work ? I would like to understand source of my initial wrong impression.
Also is there a way to force Houdini to print "currmove" for every depth (say starting from depth 8 or something). That would make a nice tool for comparing engines
"searchmoves" simply limits the choice of moves at the root, other moves will no longer be considered.
It's not possible to make Houdini always print "currmove", the depth limits are hardcoded.
It's a lot of copy pasting to console and somehow Critter decided not to print its usual nice infostring at the end of "go" command once I switched it to 1 thread making it impossible to measure time with my framework at the time (ie reading std output).