Curious behavior of Houdini search

[OneTrickPony]

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.

[hgm]

Indeed. But WinBoard does put timestamps in its log file, so it should be no problem. Like (running Fruit 2.1):

Code: Select all

3846 >first : time 30000
3846 >first : otim 30000
book hit = (NULL)
3846 >first : usermove 3846 >first : e2e4
3856 <first : # start search
3856 <first : # position startpos moves e2e4
3856 <first : # go btime 300000 wtime 300000 movestogo 40
3857 <first : # engine said: info depth 1
3857 <first : # engine said: info depth 1 seldepth 1 score cp -40 time 0 nodes 2 pv a7a5
3858 <first :   1     -40      0          2 a7a5
3860 <first : # engine said: info depth 1 seldepth 2 score cp -34 time 0 nodes 6 pv b7b6
3860 <first :   1     -34      0          6 b7b6
3861 <first : # engine said: info depth 1 seldepth 7 score cp 8 time 0 nodes 42 pv d7d5
3862 <first :   1       8      0         42 d7d5
3863 <first : # engine said: info depth 1 seldepth 7 score cp 10 time 0 nodes 77 pv b8c6
3863 <first :   1      10      0         77 b8c6
3864 <first : # engine said: info depth 1 seldepth 7 time 0 nodes 79 nps 0
3865 <first : # engine said: info depth 2
3865 <first : # engine said: info depth 2 seldepth 7 score cp -44 time 0 nodes 120 pv b8c6 b1c3
3865 <first :   2     -44      0        120 b8c6 b1c3
3866 <first : # engine said: info depth 2 seldepth 7 time 0 nodes 164 nps 0
3866 <first : # engine said: info depth 3
3867 <first : # engine said: info depth 3 seldepth 7 score cp 10 time 0 nodes 252 pv b8c6 b1c3 g8f6
3867 <first :   3      10      0        252 b8c6 b1c3 g8f6
3868 <first : # engine said: info depth 3 seldepth 7 time 0 nodes 368 nps 0
3868 <first : # engine said: info depth 4
3868 <first : # engine said: info depth 4 seldepth 7 score cp -37 time 0 nodes 519 pv b8c6 b1c3 g8f6 g1f3
3869 <first :   4     -37      0        519 b8c6 b1c3 g8f6 g1f3
3870 <first : # engine said: info depth 4 seldepth 11 score cp -9 time 0 nodes 1348 pv g8f6 e4e5 f6e4 b1c3
3870 <first :   4      -9      0       1348 g8f6 e4e5 f6e4 b1c3
3870 <first : # engine said: info depth 4 seldepth 11 time 0 nodes 1755 nps 0
3871 <first : # engine said: info depth 5
3871 <first : # engine said: info depth 5 seldepth 19 score cp 0 time 0 nodes 5028 pv g8f6 e4e5 f6e4 b1c3 d7d5 c3e4 d5e4
3871 <first :   5       0      0       5028 g8f6 e4e5 f6e4 b1c3 d7d5 c3e4 d5e4
3872 <first : # engine said: info depth 5 seldepth 19 score cp 11 time 16 nodes 7917 pv b8c6 b1c3 g8f6 g1f3 d7d5
3872 <first :   5      11      1       7917 b8c6 b1c3 g8f6 g1f3 d7d5
3872 <first : # engine said: info depth 5 seldepth 19 score cp 15 time 16 nodes 17318 pv d7d5 e4d5 g8f6 f1b5 c7c6 d5c6 b8c6
3873 <first :   5      15      1      17318 d7d5 e4d5 g8f6 f1b5 c7c6 d5c6 b8c6
3873 <first : # engine said: info depth 5 seldepth 19 time 16 nodes 17498 nps 0
3873 <first : # engine said: info depth 6
3876 <first : # engine said: info depth 6 seldepth 19 score cp -16 time 32 nodes 29730 pv d7d5 e4d5 g8f6 b1c3 f6d5 g1f3
3876 <first :   6     -16      3      29730 d7d5 e4d5 g8f6 b1c3 f6d5 g1f3
3878 <first : # engine said: info depth 6 seldepth 19 score cp -3 time 32 nodes 33650 pv b8c6 b1c3 g8f6 g1f3 d7d5 d2d3
3878 <first :   6      -3      3      33650 b8c6 b1c3 g8f6 g1f3 d7d5 d2d3
3880 <first : # engine said: info depth 6 seldepth 19 time 32 nodes 36951 nps 0
3880 <first : # engine said: info depth 7
3891 <first : # engine said: info depth 7 seldepth 19 score cp 17 time 47 nodes 55361 pv b8c6 b1c3 g8f6 g1f3 d7d5 e4e5 f6g4
3891 <first :   7      17      4      55361 b8c6 b1c3 g8f6 g1f3 d7d5 e4e5 f6g4
3894 <first : # engine said: info depth 7 seldepth 19 time 47 nodes 60702 nps 0
3894 <first : # engine said: info depth 8
3901 <first : # engine said: info depth 8 seldepth 19 score cp -14 time 47 nodes 74044 pv b8c6 b1c3 g8f6 g1f3 d7d5 d2d3 e7e5 c1e3
3902 <first :   8     -14      4      74044 b8c6 b1c3 g8f6 g1f3 d7d5 d2d3 e7e5 c1e3
3946 <first : # engine said: info depth 8 seldepth 19 score cp -8 time 94 nodes 165363 pv d7d5 e4d5 g8f6 b1c3 f6d5 g1f3 b8c6 d2d4
3947 <first :   8      -8      9     165363 d7d5 e4d5 g8f6 b1c3 f6d5 g1f3 b8c6 d2d4
3966 <first : # engine said: info depth 8 seldepth 19 time 110 nodes 200559 nps 0
3966 <first : # engine said: info depth 9
4101 <first : # engine said: info depth 9 seldepth 23 score cp 4 time 250 nodes 465042 pv d7d5 e4d5 g8f6 f1b5 c8d7 b5c4 b7b5 c4b3 d7g4 f2f3
4101 <first :   9       4     25     465042 d7d5 e4d5 g8f6 f1b5 c8d7 b5c4 b7b5 c4b3 d7g4 f2f3
4122 <first : # engine said: info depth 9 seldepth 23 time 266 nodes 503623 nps 0
4122 <first : # engine said: info depth 10
4310 <first : # engine said: info depth 10 seldepth 23 score cp -9 time 453 nodes 878139 pv d7d5 e4d5 g8f6 g1f3 f6d5 d2d4 b8c6 c2c4 d5f6 b1c3
4310 <first :  10      -9     45     878139 d7d5 e4d5 g8f6 g1f3 f6d5 d2d4 b8c6 c2c4 d5f6 b1c3
4395 <first : # engine said: info depth 10 seldepth 23 time 546 nodes 1035866 nps 0
4395 <first : # engine said: info depth 11
4761 <first : # engine said: info depth 11 seldepth 29 score cp -28 time 905 nodes 1757944 pv d7d5 e4d5 g8f6 f1b5 c8d7 b5c4 c7c6 d5c6 b8c6 g1f3 c6a5 b1a3 a5c4 a3c4
4762 <first :  11     -28     90    1757944 d7d5 e4d5 g8f6 f1b5 c8d7 b5c4 c7c6 d5c6 b8c6 g1f3 c6a5 b1a3 a5c4 a3c4
4860 <first : # engine said: info time 1014 nodes 1940000 nps 1913215 cpuload 999
4860 <first : # engine said: info hashfull 68
5181 <first : # engine said: info currmove g8f6 currmovenumber 3
5344 <first : # engine said: info currmove g8f6 currmovenumber 3
5802 <first : # engine said: info depth 11 seldepth 43 score cp -12 time 1950 nodes 3752829 pv g8f6 e4e5 f6d5 d2d4 b8c6 c2c4 d5b6 c4c5 b6d5 b1c3 c6b4
5803 <first :  11     -12    195    3752829 g8f6 e4e5 f6d5 d2d4 b8c6 c2c4 d5b6 c4c5 b6d5 b1c3 c6b4
5803 <first : # engine said: info currmove e7e5 currmovenumber 4
5824 <first : # engine said: info currmove d7d6 currmovenumber 5
5834 <first : # engine said: info currmove e7e6 currmovenumber 6
5854 <first : # engine said: info currmove b8a6 currmovenumber 7
5866 <first : # engine said: info currmove g8h6 currmovenumber 8
5870 <first : # engine said: info currmove b7b6 currmovenumber 9
5871 <first : # engine said: info time 2028 nodes 3880000 nps 1913215 cpuload 998
5871 <first : # engine said: info hashfull 137
5881 <first : # engine said: info currmove g7g5 currmovenumber 10
5888 <first : # engine said: info currmove g7g6 currmovenumber 11
5894 <first : # engine said: info currmove a7a5 currmovenumber 12
5901 <first : # engine said: info currmove h7h5 currmovenumber 13
5908 <first : # engine said: info currmove c7c5 currmovenumber 14
5914 <first : # engine said: info currmove c7c6 currmovenumber 15
5918 <first : # engine said: info currmove a7a6 currmovenumber 16
5920 <first : # engine said: info currmove h7h6 currmovenumber 17
5928 <first : # engine said: info currmove f7f6 currmovenumber 18
5928 <first : # engine said: info currmove f7f5 currmovenumber 19
5947 <first : # engine said: info currmove b7b5 currmovenumber 20
5952 <first : # engine said: info depth 11 seldepth 43 time 2106 nodes 4026262 nps 1911805
5952 <first : # engine said: info depth 12
5952 <first : # engine said: info currmove g8f6 currmovenumber 1
6628 <first : # engine said: info depth 12 seldepth 43 score cp -18 time 2777 nodes 5363253 pv g8f6 e4e5 f6d5 d2d4 b8c6 c2c4 d5b6 g1f3 d7d6 b1c3 c8f5 c1g5
6628 <first :  12     -18    277    5363253 g8f6 e4e5 f6d5 d2d4 b8c6 c2c4 d5b6 g1f3 d7d6 b1c3 c8f5 c1g5
6629 <first : # engine said: info currmove d7d5 currmovenumber 2
6705 <first : # engine said: info currmove b8c6 currmovenumber 3
6817 <first : # engine said: info currmove e7e5 currmovenumber 4
6889 <first : # engine said: info time 3042 nodes 5850000 nps 1923077 cpuload 999
6889 <first : # engine said: info hashfull 198
6902 <first : # engine said: info currmove d7d6 currmovenumber 5
6945 <first : # engine said: info currmove e7e6 currmovenumber 6
7041 <first : # engine said: info currmove b8a6 currmovenumber 7
7081 <first : # engine said: info currmove g8h6 currmovenumber 8
7128 <first : # engine said: info currmove b7b6 currmovenumber 9
7175 <first : # engine said: info currmove g7g5 currmovenumber 10
7198 <first : # engine said: info currmove g7g6 currmovenumber 11
7220 <first : # engine said: info currmove a7a5 currmovenumber 12
7265 <first : # engine said: info currmove h7h5 currmovenumber 13
7312 <first : # engine said: info currmove c7c5 currmovenumber 14
7337 <first : # engine said: info currmove c7c6 currmovenumber 15
7351 <first : # engine said: info currmove a7a6 currmovenumber 16
7383 <first : # engine said: info currmove h7h6 currmovenumber 17
7425 <first : # engine said: info currmove f7f6 currmovenumber 18
7428 <first : # engine said: info currmove f7f5 currmovenumber 19
7521 <first : # engine said: info currmove b7b5 currmovenumber 20
7535 <first : # engine said: info depth 12 seldepth 43 time 3682 nodes 7047012 nps 1913909
7535 <first : # engine said: info depth 13
7535 <first : # engine said: info currmove g8f6 currmovenumber 1
7900 <first : # engine said: info time 4056 nodes 7740000 nps 1908284 cpuload 999
7901 <first : # engine said: info hashfull 268
8913 <first : # engine said: info time 5070 nodes 9640000 nps 1901381 cpuload 999
8913 <first : # engine said: info hashfull 337
9928 <first : # engine said: info time 6084 nodes 11670000 nps 1918146 cpuload 999
9928 <first : # engine said: info hashfull 399
10243 <first : # engine said: info depth 13 seldepth 43 score cp -19 time 6396 nodes 12285507 pv g8f6 e4e5 f6d5 g1f3 b8c6 d2d4 e7e6 c2c4 f8b4 c1d2 d5b6 f1d3 d7d5 c4c5
10243 <first :  13     -19    639   12285507 g8f6 e4e5 f6d5 g1f3 b8c6 d2d4 e7e6 c2c4 f8b4 c1d2 d5b6 f1d3 d7d5 c4c5
10244 <first : # engine said: info currmove d7d5 currmovenumber 2
10592 <first : # engine said: info currmove b8c6 currmovenumber 3
10945 <first : # engine said: info time 7098 nodes 13610000 nps 1917442 cpuload 1000
10945 <first : # engine said: info hashfull 462
11076 <first : # engine said: info currmove e7e5 currmovenumber 4
11956 <first : # engine said: info time 8112 nodes 15440000 nps 1903353 cpuload 1000
11956 <first : # engine said: info hashfull 525
12971 <first : # engine said: info time 9126 nodes 17270000 nps 1892395 cpuload 1000
12971 <first : # engine said: info hashfull 585
13003 <first : # engine said: info currmove e7e5 currmovenumber 4
13986 <first : # engine said: info time 10140 nodes 19120000 nps 1885602 cpuload 1000
13986 <first : # engine said: info hashfull 634
14888 <first : # engine said: info depth 13 seldepth 43 score cp -15 time 11045 nodes 20797940 pv e7e5 b1c3 g8f6 g1f3 b8c6 f1b5 f8b4 d2d3 e8g8 b5c6 d7c6 f3e5 d8d4 e5c4 b4c3 b2c3 d4c3 c1d2
14889 <first :  13     -15   1104   20797940 e7e5 b1c3 g8f6 g1f3 b8c6 f1b5 f8b4 d2d3 e8g8 b5c6 d7c6 f3e5 d8d4 e5c4 b4c3 b2c3 d4c3 c1d2
14891 <first : # engine said: info currmove d7d6 currmovenumber 5
14931 <first : # engine said: info currmove e7e6 currmovenumber 6
15002 <first : # engine said: info time 11154 nodes 21010000 nps 1883629 cpuload 1000
15003 <first : # engine said: info hashfull 679
15065 <first : # engine said: info currmove b8a6 currmovenumber 7
15185 <first : # engine said: info currmove g8h6 currmovenumber 8
15218 <first : # engine said: info currmove b7b6 currmovenumber 9
15279 <first : # engine said: info currmove g7g5 currmovenumber 10
15338 <first : # engine said: info currmove g7g6 currmovenumber 11
15381 <first : # engine said: info currmove a7a5 currmovenumber 12
15441 <first : # engine said: info currmove h7h5 currmovenumber 13
15488 <first : # engine said: info currmove c7c5 currmovenumber 14
15572 <first : # engine said: info currmove c7c6 currmovenumber 15
15607 <first : # engine said: info currmove a7a6 currmovenumber 16
15648 <first : # engine said: info currmove h7h6 currmovenumber 17
15691 <first : # engine said: info currmove f7f6 currmovenumber 18
15693 <first : # engine said: info currmove f7f5 currmovenumber 19
15802 <first : # engine said: info currmove b7b5 currmovenumber 20
15841 <first : # engine said: info depth 13 seldepth 43 time 11997 nodes 22575135 nps 1881732
15841 <first : # engine said: info time 11997 nodes 22575135 nps 1881732 cpuload 1000
15841 <first : # engine said: info hashfull 716
15841 <first : # engine said: bestmove e7e5 ponder b1c3
15842 <first : # ponder on b1c3
15842 <first : # position startpos moves e2e4 e7e5 b1c3
15842 <first : # go btime 287763 wtime 300000 movestogo 39 ponder
15842 <first : move e7e5

[OneTrickPony]

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) ?

[Evert]

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.

[Houdini]

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.

Robert

[Houdini]

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.

Robert

[rvida]

Critter 1.6 doesn't implement UCI as well

How do you think people operate it? Through telepathy?

[OneTrickPony]

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

[OneTrickPony]

For the same position (the first one in my post):

Critter:

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

[Houdini]

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.

Robert