AndrewGrant wrote: ↑Wed Sep 12, 2018 11:26 pm
Here is a sample for the impacted engines, one for each.
2018-09-10 08:30:45.016<--2:id name
Nirvanachess 2.4 (64-Bit Popcount)
2018-09-10 08:33:55.385<--2:info depth 1 seldepth 19 multipv 1 score cp 64 nodes 136158436 nps 8094069 time 16822 pv b1a3 e7e5
2018-09-10 09:00:10.936<--1:id name
Nemorino
2018-09-10 09:01:12.569<--1:info depth 1 seldepth 2 multipv 1 score cp -20 nodes 1334 nps 81 hashfull 190 tbhits 0 time 16407 pv e7e5
2018-09-10 10:18:35.627<--1:id name
Laser 1.6
2018-09-10 10:21:44.105<--1:info depth 1 seldepth 48 score cp -5 time 8736 nodes 36956201 nps 4230326 tbhits 0 hashfull 25 pv g8f6
2018-09-10 11:04:00.354<--1:id name
Ethereal 10.88 (PEXT)
2018-09-10 11:07:33.288<--1:info depth 1 seldepth 1 score cp -19 time 8531 nodes 174556732 nps 20459000 tbhits 0 hashfull 0 pv f8c5
2018-09-10 13:45:44.557<--1:id name
Deep Shredder 13 x64
2018-09-10 13:46:28.001<--1:info depth 1 seldepth 6 time 1203 score cp -2 nodes 50 nps 41 hashfull 0 pv d7d5
2018-09-10 22:50:34.734<--2:id name
Senpai 2.0
2018-09-10 22:51:28.710<--2:info depth 1 seldepth 1 score cp 43 nodes 49 time 4607 nps 11 pv d1h5
Its clear that, on occasion, some threads will get blocked out by the scheduler. After doing some more reading, I have some good examples of this kind of behavior. It is common for engines to only report (printing) from the main thread. These outputs show, I believe, that some threads will get CPU time, and until the main thread is given a chance, the engine is partially stalled. The problem arises if once the main thread gets a chance to run, it immediately exits after depth 1, for fear of running out of time.
Below is taken from the logfile. Here we see the first depth taking an astounding 4672ms, and then suddenly the next 9 depths (and many more) are completed instantly.
id name Ethereal 10.88 (PEXT)
info depth 1 seldepth 2 score cp 4 time 4672 nodes 159443011 nps 34120000 tbhits 0 hashfull 0 pv c4d5 d8d5
info depth 2 seldepth 5 score cp 11 time 4672 nodes 159448935 nps 34121000 tbhits 0 hashfull 0 pv c4d5 e6d5
info depth 3 seldepth 6 score cp 18 time 4672 nodes 159455075 nps 34122000 tbhits 0 hashfull 0 pv b1c3 b8c6 c4d5 e6d5
info depth 4 seldepth 6 score cp 32 time 4672 nodes 159460619 nps 34123000 tbhits 0 hashfull 0 pv g1f3 g8f6 b1c3 f8b4
info depth 5 seldepth 6 score cp 23 time 4672 nodes 159469929 nps 34125000 tbhits 0 hashfull 0 pv g1f3 g8f6 b1c3 c7c6 c4d5 c6d5
info depth 6 seldepth 8 score cp 40 time 4672 nodes 159490636 nps 34130000 tbhits 0 hashfull 0 pv g1f3 g8f6 b1c3 f8b4 d1a4 b8c6 e2e3
info depth 7 seldepth 10 score cp 36 time 4672 nodes 159508328 nps 34134000 tbhits 0 hashfull 0 pv g1f3 g8f6 b1c3 f8b4 d1a4 b8c6 c4d5 e6d5
info depth 8 seldepth 12 score cp 34 time 4672 nodes 159535517 nps 34139000 tbhits 0 hashfull 0 pv g1f3 g8f6 b1c3 f8b4 d1a4 b8c6 e2e3 e8g8 a4c2
info depth 9 seldepth 13 score cp 25 time 4672 nodes 159633370 nps 34160000 tbhits 0 hashfull 0 pv g1f3 g8f6 b1c3 c7c6 c4d5 e6d5 c1f4 c8f5 e2e3
A somewhat less extreme example from Laser
id name Laser 1.6
info depth 1 seldepth 37 score cp -24 time 4735 nodes 19003142 nps 4013319 tbhits 0 hashfull 8 pv b8c6
info depth 2 seldepth 37 score cp -26 time 4939 nodes 20804060 nps 4212176 tbhits 0 hashfull 11 pv b8c6 f1b5
info depth 3 seldepth 41 score cp -24 time 5142 nodes 22849973 nps 4443782 tbhits 0 hashfull 12 pv b8c6 f1b5 g8f6
info depth 4 seldepth 41 score cp -29 time 5345 nodes 24856237 nps 4650351 tbhits 0 hashfull 12 pv b8c6 f1b5 g8f6 b5c6
info depth 5 seldepth 41 score cp -29 time 5595 nodes 27746921 nps 4959224 tbhits 0 hashfull 13 pv b8c6 f1b5 g8f6 b5c6 d7c6
info depth 6 seldepth 41 score cp -29 time 5673 nodes 28352153 nps 4997713 tbhits 0 hashfull 13 pv b8c6 f1b5 g8f6 b5c6 d7c6 d2d3
info depth 7 seldepth 43 score cp -29 time 6283 nodes 35605661 nps 5666955 tbhits 0 hashfull 16 pv g8f6 d2d4 f6e4 f1d3 d7d5 f3e5 b8c6
info depth 8 seldepth 43 score cp -29 time 6439 nodes 37210117 nps 5778854 tbhits 0 hashfull 16 pv g8f6 d2d4 f6e4 f1d3 d7d5 f3e5 b8c6 e5c6
info depth 9 seldepth 43 score cp -29 time 7017 nodes 43723416 nps 6231048 tbhits 0 hashfull 19 pv g8f6 d2d4 f6e4 f1d3 d7d5 f3e5 b8c6 e5c6 b7c6
Another extreme example, this one from Shredder
id name Deep Shredder 13 x64
info depth 1 seldepth 6 time 1203 score cp -2 nodes 50 nps 41 hashfull 0 pv d7d5
info depth 2 seldepth 6 time 1203 score cp -37 nodes 73 nps 60 hashfull 0 pv d7d5 b1c3
info depth 3 seldepth 10 time 1203 score cp -10 nodes 247 nps 205 hashfull 0 pv d7d5 b1c3 g8f6 e4d5
info depth 4 seldepth 10 time 1203 score cp -10 nodes 399 nps 331 hashfull 0 pv d7d5 b1c3 g8f6 e4d5
info depth 5 seldepth 10 time 1203 score cp -10 nodes 685 nps 569 hashfull 0 pv d7d5 e4d5 g8f6 b1c3 f6d5
info depth 6 seldepth 10 time 1203 score cp -17 upperbound nodes 764 nps 635 hashfull 0 pv d7d5 e4d5 d8d5
info depth 6 seldepth 10 time 1204 score cp -25 upperbound nodes 952 nps 790 hashfull 0 pv d7d5 e4d5 e7e6
info depth 6 seldepth 10 time 1204 score cp -45 upperbound nodes 2367 nps 1965 hashfull 0 pv d7d5 e4e5 d8d7
info depth 6 seldepth 10 time 1205 score cp -32 nodes 6352 nps 5271 hashfull 0 pv d7d5 e4e5 d5d4 g1f3 b8c6 b1a3
info depth 7 seldepth 12 time 1205 score cp -25 lowerbound nodes 22365 nps 18560 hashfull 0 pv d7d5 f1b5
info depth 7 seldepth 12 time 1205 score cp -27 nodes 25007 nps 20752 hashfull 0 pv d7d5 e4e5 d5d4 g1f3 b8c6 d2d3 g8h6
An example for Texel, which is a bit different, and shows not the problem of getting the initial thread access, but of holding onto it. Here we see texel lose main thread access for about half a second, and once regained the depth outputs come flying out. PV output cut by me.
id name Texel 1.07
info depth 6 score cp 34 time 3 nodes 52175 nps 17391666 pv g5e7 d4d5 ...
info depth 7 score cp 15 time 588 nodes 20128084 nps 34231435 pv g5f4 g2g3 ...
info depth 7 score cp 15 time 588 nodes 21922443 nps 37283066 pv g5f4 g2g3 ...
info depth 8 score cp 15 time 590 nodes 23060093 nps 39084903 pv g5f4 g2g3 ...
info depth 8 score cp 16 time 590 nodes 23083673 nps 39124869 pv g5g6 d1e1 ...
info depth 8 score cp 34 time 590 nodes 23116837 nps 39181079 pv h6h5 d4d5 ...
info depth 9 score cp 34 time 591 nodes 23153361 nps 39176583 pv h6h5 d4d5 ...
info depth 10 score cp 34 time 592 nodes 23199598 nps 39188510 pv h6h5 d4d5 ...
info depth 11 score cp 34 time 593 nodes 23274065 nps 39248001 pv h6h5 d4d5 ...
info depth 12 score cp 34 time 595 nodes 23362406 nps 39264547 pv h6h5 d4d5 ...
info depth 13 score cp 34 time 597 nodes 23465369 nps 39305475 pv h6h5 d4d5 ...
info depth 14 score cp 34 time 599 nodes 23568424 nps 39346283 pv h6h5 d4d5 ...
info depth 15 score cp 34 time 603 nodes 23703216 nps 39308815 pv h6h5 d4d5 ...
I have thousands of examples, for the original six, plus now for Texel.