Using profiler on linux

[Look]

Hi,

As I remember , one could use Visual Studio profiler on Windows OS. What about that on Linux OS ? I found this link , any better idea ?

[abulmo2]

As your link show, gprof is a possible solution.
Another one is using perf: https://perf.wiki.kernel.org/index.php/Main_Page

[Joost Buijs]

If you have an Intel CPU another option would be Intel Vtune.

https://software.intel.com/en-us/vtune/ ... standalone

[dragontamer5788]

If you have an Intel CPU another option would be Intel Vtune.

https://software.intel.com/en-us/vtune/ ... standalone

And if you have an AMD CPU, AMD uProf is okay. Not anywhere as good as VTune, but access to hardware-level counters is always useful.

[Look]

I played around with gcc profiler and produced the text output. It was fun. In future I may try heavier projects to see what happens.

[JohnWoe]

For Sapeli I use gprof.

Here's the magic command: https://github.com/SamuraiDangyo/Sapeli ... kefile#L50

No profile:

Code: Select all

./sapeli -bench
...
info depth 11 nodes 4128807 time 1025 nps 4028104 score cp 1191 pv b7a8q
info depth 12 nodes 9455540 time 3001 nps 3150796 score cp 1191 pv b7a8q
[ 10: 8/PPPk4/8/8/8/8/4Kppp/8 w - - ]
info depth 1 nodes 38 time 0 nps 0 score cp 997 pv c7c8q
info depth 2 nodes 222 time 0 nps 0 score cp 1000 pv c7c8q
info depth 3 nodes 2688 time 1 nps 2688000 score cp 999 pv c7c8q
info depth 4 nodes 4035 time 1 nps 4035000 score cp 1169 pv c7c8q
info depth 5 nodes 6973 time 2 nps 3486500 score cp 1169 pv c7c8q
info depth 6 nodes 12130 time 5 nps 2426000 score cp 1175 pv c7c8q
info depth 7 nodes 26361 time 10 nps 2636100 score cp 1175 pv c7c8q
info depth 8 nodes 71248 time 28 nps 2544571 score cp 1369 pv c7c8q
info depth 9 nodes 180647 time 65 nps 2779184 score cp 1369 pv c7c8q
info depth 10 nodes 522728 time 199 nps 2626773 score cp 1565 pv c7c8q
info depth 11 nodes 1627458 time 553 nps 2942962 score cp 1565 pv c7c8q
info depth 12 nodes 4365900 time 1725 nps 2530956 score cp 2557 pv c7c8q
info depth 13 nodes 8305790 time 3001 nps 2767674 score cp 2557 pv c7c8q
= nodes 105497904 mnps 3.515 time 30.010

Profiled:

Code: Select all

./sapeli -bench
...
info depth 10 nodes 2319639 time 623 nps 3723337 score cp 1193 pv b7a8q
info depth 11 nodes 11674940 time 1841 nps 6341629 score cp 1191 pv b7a8q
info depth 12 nodes 15281968 time 3001 nps 5092291 score cp 1191 pv b7a8q
[ 10: 8/PPPk4/8/8/8/8/4Kppp/8 w - - ]
info depth 1 nodes 38 time 0 nps 0 score cp 997 pv c7c8q
info depth 2 nodes 222 time 0 nps 0 score cp 1000 pv c7c8q
info depth 3 nodes 2691 time 1 nps 2691000 score cp 999 pv c7c8q
info depth 4 nodes 4035 time 1 nps 4035000 score cp 1169 pv c7c8q
info depth 5 nodes 6973 time 2 nps 3486500 score cp 1169 pv c7c8q
info depth 6 nodes 12130 time 5 nps 2426000 score cp 1175 pv c7c8q
info depth 7 nodes 25142 time 9 nps 2793555 score cp 1175 pv c7c8q
info depth 8 nodes 69203 time 26 nps 2661653 score cp 1369 pv c7c8q
info depth 9 nodes 169909 time 56 nps 3034089 score cp 1369 pv c7c8q
info depth 10 nodes 529086 time 184 nps 2875467 score cp 1565 pv c7c8q
info depth 11 nodes 1630000 time 496 nps 3286290 score cp 1565 pv c7c8q
info depth 12 nodes 4370136 time 1541 nps 2835909 score cp 2557 pv c7c8q
info depth 13 nodes 10190590 time 3002 nps 3394600 score cp 2557 pv c7c8q
= nodes 124867893 mnps 4.161 time 30.011

[bob]

Lots wrong there. Nodes should NOT change with optimization levels/types. They should remain constant. Suggests the usual undefined/unitialized variable sort of bug that you should try to find.

[JohnWoe]

With Sapeli -bench means benching the chess engine.
-benchm benches mgen and the the same nodes are expented.

Valgrind report of Sapeli 1.48. No leaks are possible. Not surprising as I have written Sapeli in the most simplest way.

Code: Select all

...
--9434-- REDIR: 0x5174c70 (libc.so.6:__strcpy_chk) redirected to 0x4c37090 (__strcpy_chk)
--9434-- REDIR: 0x50fe460 (libc.so.6:memcpy@GLIBC_2.2.5) redirected to 0x4c34060 (memcpy@GLIBC_2.2.5)
--9434-- REDIR: 0x50da950 (libc.so.6:free) redirected to 0x4c30cd0 (free)
==9434== Warning: set address range perms: large range [0xd858028, 0x1d858058) (noaccess)
==9434== 
==9434== HEAP SUMMARY:
==9434==     in use at exit: 0 bytes in 0 blocks
==9434==   total heap usage: 3 allocs, 3 frees, 402,654,208 bytes allocated
==9434== 
==9434== All heap blocks were freed -- no leaks are possible
==9434== 
==9434== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
==9434== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

Here is the gprof report of Sapeli 1.48 (-bench).
Sapeli actually spends majority of time generating moves.
Eval_all() only takes 4%. Tho -bench isn't very accurate measure. Should play games instead.

Code: Select all

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 22.80      4.09     4.09 106851405     0.00     0.00  Add_b
 19.85      7.65     3.56 29386200     0.00     0.00  QSearch_w
 19.40     11.13     3.48 95672570     0.00     0.00  Add_w
  6.91     12.37     1.24 19637831     0.00     0.00  Search_b
  5.46     13.35     0.98 13840520     0.00     0.00  Search_w
  4.46     14.15     0.80 11345481     0.00     0.00  Sort_mgen
  3.57     14.79     0.64  5650069     0.00     0.00  Eval_all
  2.34     15.21     0.42  5922394     0.00     0.00  Mgen_all_b
  2.31     15.63     0.42 26340581     0.00     0.00  Eval_pawns_b
  1.95     15.98     0.35  6622064     0.00     0.00  Mgen_all_w
  1.78     16.30     0.32 25520991     0.00     0.00  Eval_pawns_w
  1.31     16.53     0.24 164434737     0.00     0.00  Handle_castle_rights
  1.20     16.75     0.22  8758406     0.00     0.00  Sort_captures
  0.75     16.88     0.14  7100763     0.00     0.00  Eval_rooks_b
  0.70     17.01     0.13 54935937     0.00     0.00  Sort_almost_captures
  0.61     17.12     0.11  7737267     0.00     0.00  Eval_rooks_w
  0.59     17.22     0.11  3704782     0.00     0.00  Eval_queens_b
  0.50     17.31     0.09  4700446     0.00     0.00  Eval_bishops_b
  0.50     17.40     0.09  3940535     0.00     0.00  Eval_queens_w
  0.47     17.49     0.09 12770529     0.00     0.00  Checks_w
  0.39     17.56     0.07  4897345     0.00     0.00  Eval_bishops_w
  0.39     17.63     0.07                             Chess960
  0.31     17.68     0.06 11590184     0.00     0.00  Checks_b
  0.31     17.74     0.06  5483751     0.00     0.00  Eval_knights_b
  0.28     17.79     0.05  5650069     0.00     0.00  Eval_kings_b
  0.28     17.84     0.05  5650069     0.00     0.00  Eval_kings_w
  0.22     17.88     0.04  5650069     0.00     0.00  Eval_setup_globals
  0.20     17.91     0.04        9     3.89     3.89  Build_castle_bb
  0.11     17.93     0.02  5376634     0.00     0.00  Eval_knights_w
  0.06     17.94     0.01                             Suite
  0.00     17.94     0.00   174168     0.00     0.00  Checks2_b
  0.00     17.94     0.00      173     0.00     0.00  Checks2_w
  0.00     17.94     0.00      126     0.00     0.00  P
  0.00     17.94     0.00       74     0.00   199.46  Best_w
  0.00     17.94     0.00       52     0.00    58.97  Best_b
  0.00     17.94     0.00       11     0.00     0.00  Legal
  0.00     17.94     0.00       10     0.00     0.01  Mgen_root
  0.00     17.94     0.00       10     0.00     0.00  Move_name
  0.00     17.94     0.00        9     0.00     0.00  Build_castle_brd

This is hash debugging is Sapeli. Notice Eval hash is getting full really quick.
100ms / 1s / 10s searches.

Code: Select all

./sapeli -search 100 -hashfull
info depth 1 nodes 40 time 0 nps 0 score cp 49 pv e2e3
info depth 2 nodes 258 time 0 nps 0 score cp 5 pv e2e3
info depth 3 nodes 2608 time 4 nps 652000 score cp 32 pv d2d4
info depth 4 nodes 6727 time 11 nps 611545 score cp 9 pv d2d4
info depth 5 nodes 34759 time 56 nps 620696 score cp 10 pv d2d4
info depth 6 nodes 70768 time 102 nps 693803 score cp 10 pv d2d4
+-+ Debug Hash +-+
GOOD_MOVES / count: 8388608 / key: 8388607
= 0.03%
EVALS / count: 16777216 / key: 16777215
= 0.17%

Code: Select all

./sapeli -search 1000 -hashfull
info depth 1 nodes 40 time 0 nps 0 score cp 49 pv e2e3
info depth 2 nodes 242 time 1 nps 242000 score cp 5 pv e2e3
info depth 3 nodes 2739 time 5 nps 547800 score cp 32 pv d2d4
info depth 4 nodes 6822 time 12 nps 568500 score cp 9 pv d2d4
info depth 5 nodes 34512 time 55 nps 627490 score cp 10 pv d2d4
info depth 6 nodes 107747 time 135 nps 798125 score cp 8 pv e2e4
info depth 7 nodes 175144 time 201 nps 871363 score cp 11 pv e2e4
info depth 8 nodes 654121 time 510 nps 1282590 score cp 9 pv d2d4
info depth 9 nodes 1783860 time 1001 nps 1782077 score cp 9 pv d2d4
+-+ Debug Hash +-+
GOOD_MOVES / count: 8388608 / key: 8388607
= 0.56%
EVALS / count: 16777216 / key: 16777215
= 3.42%

Code: Select all

./sapeli -search 10000 -hashfull
info depth 1 nodes 40 time 0 nps 0 score cp 49 pv e2e3
info depth 2 nodes 242 time 0 nps 0 score cp 5 pv e2e3
info depth 3 nodes 2739 time 4 nps 684750 score cp 32 pv d2d4
info depth 4 nodes 6789 time 11 nps 617181 score cp 9 pv d2d4
info depth 5 nodes 34504 time 53 nps 651018 score cp 10 pv d2d4
info depth 6 nodes 108346 time 131 nps 827068 score cp 8 pv e2e4
info depth 7 nodes 175616 time 195 nps 900594 score cp 11 pv e2e4
info depth 8 nodes 606030 time 477 nps 1270503 score cp 9 pv e2e4
info depth 9 nodes 1888063 time 1019 nps 1852858 score cp 9 pv e2e4
info depth 10 nodes 8166745 time 4033 nps 2024980 score cp 5 pv e2e4
info depth 11 nodes 21220224 time 10001 nps 2121810 score cp 5 pv e2e4
+-+ Debug Hash +-+
GOOD_MOVES / count: 8388608 / key: 8388607
= 6.16%
EVALS / count: 16777216 / key: 16777215
= 33.18%

[Fabio Gobbato]

I use oprofile https://oprofile.sourceforge.io/news/ one advantage over gprof is that you can profile the parallel search too.