missing samples in pprof profile

[hs]

Hello,

I am using the pprof profiler. This worked well until recently.

Now I run a program with profiling enabled and it runs about 11 minutes:

real    11m52.329s

user    11m45.497s

sys     0m1.423s

pprof output in interative mode looks like this:

Total: 24679 samples

    7338  29.7%  29.7%     7498  30.4% code.google.com/p/gochess/search.GenerateBadCaptures

    2909  11.8%  41.5%     2987  12.1% code.google.com/p/gochess/search.GenerateGoodCaptures

    1875   7.6%  49.1%     1875   7.6% code.google.com/p/gochess/search.UnderAttack

    1617   6.6%  55.7%    21632  87.7% code.google.com/p/gochess/search.quiescenceSearch

    1547   6.3%  61.9%     1591   6.4% code.google.com/p/gochess/search.GenerateEvenCaptures

    1425   5.8%  67.7%     1493   6.0% code.google.com/p/gochess/position.(*Position).move

    1110   4.5%  72.2%     2949  11.9% code.google.com/p/gochess/position.(*Position).MakeMove

     912   3.7%  75.9%     1009   4.1% code.google.com/p/gochess/position.(*Position).Remove

     884   3.6%  79.5%      889   3.6% runtime.lessstack

     794   3.2%  82.7%      819   3.3% code.google.com/p/gochess/position.(*Position).reset

     660   2.7%  85.4%     2158   8.7% code.google.com/p/gochess/position.(*Position).UnmakeMove

     628   2.5%  87.9%      652   2.6% code.google.com/p/gochess/search.GeneratePawnPromotions

     486   2.0%  89.9%      516   2.1% code.google.com/p/gochess/search.(*FifoMoveList).Next

     332   1.3%  91.2%      332   1.3% runtime.gogo

     328   1.3%  92.6%     2286   9.3% code.google.com/p/gochess/search.IsCheck

     300   1.2%  93.8%      359   1.5% runtime.morestack

     260   1.1%  94.8%      300   1.2% code.google.com/p/gochess/position.(*Position).setEnPassantSquare

     211   0.9%  95.7%      251   1.0% code.google.com/p/gochess/evaluation.CalculateScore

     197   0.8%  96.5%      244   1.0% code.google.com/p/gochess/search.(*FifoMoveList).Add

     174   0.7%  97.2%      174   0.7% runtime.morestack24

     162   0.7%  97.9%      162   0.7% morestack

     112   0.5%  98.3%      112   0.5% code.google.com/p/gochess/search.(*TranspositionTable).Get

     102   0.4%  98.7%      102   0.4% code.google.com/p/gochess/search.(*FifoMoveList).Empty

      92   0.4%  99.1%       92   0.4% runtime.morestack16

      64   0.3%  99.4%       64   0.3% runtime.gogocall

      33   0.1%  99.5%       33   0.1% code.google.com/p/gochess/search.(*TranspositionTable).Save

      29   0.1%  99.6%    21799  88.3% code.google.com/p/gochess/search.negaSearch

      22   0.1%  99.7%       24   0.1% code.google.com/p/gochess/position.(*Position).removeCastlingRights

      15   0.1%  99.8%       15   0.1% code.google.com/p/gochess/position.(*Position).Set

      13   0.1%  99.8%       13   0.1% code.google.com/p/gochess/search.(*SortedMoveList).Sort

Each sample is 1/100 s, so I have profiling data for about 4 minutes only. I wonder why.

The program uses a recursive algorithm, maybe this is important.

I you need any more information let me know. Thanks in advance,

Heiko

[hs]

I run into the same issue again, this time i used perf and i see some interesting differences to pprof

I run my benchmark with

perf record -g -- go test -test.run="jjj" -test.bench="10" -cpuprofile cpu.prof

it takes around 80s to finnish:


PASS
BenchmarkFindBestMoveMidgamePositionDepth10
ok      code.google.com/p/gochess/search        79.920s


pprof gives me

(pprof) top30
Total: 6939 samples
     943  13.6%  13.6%      943  13.6% code.google.com/p/gochess/movement.GeneratePieceCaptures
     815  11.7%  25.3%      815  11.7% code.google.com/p/gochess/search.(*TranspositionTable).Get
     789  11.4%  36.7%     1477  21.3% code.google.com/p/gochess/search.(*Position).MakeMove
     591   8.5%  45.2%      889  12.8% code.google.com/p/gochess/search.(*Position).move
     537   7.7%  53.0%     6555  94.5% code.google.com/p/gochess/search.negaSearch
     444   6.4%  59.4%      446   6.4% code.google.com/p/gochess/movement.GeneratePawnCapturesAndPromotions
     328   4.7%  64.1%      328   4.7% code.google.com/p/gochess/movement.(*SortableMoveList).Sort
     325   4.7%  68.8%      347   5.0% code.google.com/p/gochess/position.(*piecePlacement).Move
     209   3.0%  71.8%      882  12.7% code.google.com/p/gochess/search.(*Position).UnmakeMove
     196   2.8%  74.6%      196   2.8% code.google.com/p/gochess/movement.isPinned
     158   2.3%  76.9%      193   2.8% code.google.com/p/gochess/movement.GeneratePieceMoves
     153   2.2%  79.1%      153   2.2% code.google.com/p/gochess/search.(*TTDepthPreferred).Save
     128   1.8%  80.9%      128   1.8% code.google.com/p/gochess/movement.UnderAttack
     124   1.8%  82.7%      126   1.8% code.google.com/p/gochess/movement.DetectCheckByLastMove
     109   1.6%  84.3%      146   2.1% code.google.com/p/gochess/movement.GenerateCheckEvasions
     101   1.5%  85.7%      101   1.5% code.google.com/p/gochess/search.(*Position).setEnPassantSquare
      93   1.3%  87.1%       93   1.3% code.google.com/p/gochess/search.(*Position).setCastlingRights
      84   1.2%  88.3%      376   5.4% code.google.com/p/gochess/movement.IsLegalMoveWhileNotInCheck
      81   1.2%  89.5%      148   2.1% code.google.com/p/gochess/search.(*Position).Remove
      73   1.1%  90.5%      138   2.0% code.google.com/p/gochess/search.(*Position).Reset
      71   1.0%  91.5%       79   1.1% code.google.com/p/gochess/position.(*piecePlacement).Remove
      71   1.0%  92.6%       71   1.0% code.google.com/p/gochess/position.(*piecePlacement).Reset
      70   1.0%  93.6%       70   1.0% code.google.com/p/gochess/movement.(*SortableMoveList).Next
      66   1.0%  94.5%      111   1.6% code.google.com/p/gochess/search.(*Position).switchSides
      62   0.9%  95.4%       62   0.9% code.google.com/p/gochess/position.(*Position).SwitchSides
      44   0.6%  96.1%       46   0.7% runtime.lessstack
      43   0.6%  96.7%       47   0.7% code.google.com/p/gochess/movement.GeneratePawnMoves
      42   0.6%  97.3%       42   0.6% code.google.com/p/gochess/search.CalculateScore
      40   0.6%  97.9%       40   0.6% code.google.com/p/gochess/movement.(*SortableMoveList).Add
      32   0.5%  98.3%       39   0.6% runtime.morestack

so 10s are missing, now perf report:

Events: 80K cpu-clock
+  11.72%  search.test  search.test        [.] code.google.com/p/gochess/movement.GeneratePieceCaptures
+  10.27%  search.test  search.test        [.] code.google.com/p/gochess/search.(*TranspositionTable).Get
+  10.17%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).MakeMove
+   7.16%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).move
+   6.45%  search.test  search.test        [.] code.google.com/p/gochess/search.negaSearch
+   5.65%  search.test  search.test        [.] code.google.com/p/gochess/movement.GeneratePawnCapturesAndPromotions
+   4.40%  search.test  search.test        [.] runtime.newstack
+   4.07%  search.test  search.test        [.] code.google.com/p/gochess/movement.(*SortableMoveList).Sort
+   3.89%  search.test  search.test        [.] code.google.com/p/gochess/position.(*piecePlacement).Move
+   3.08%  search.test  search.test        [.] runtime.oldstack
+   2.51%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).UnmakeMove
+   2.16%  search.test  search.test        [.] code.google.com/p/gochess/movement.isPinned
+   2.08%  search.test  search.test        [.] code.google.com/p/gochess/search.(*TTDepthPreferred).Save
+   2.05%  search.test  search.test        [.] code.google.com/p/gochess/movement.GeneratePieceMoves
+   1.42%  search.test  search.test        [.] code.google.com/p/gochess/movement.UnderAttack
+   1.34%  search.test  search.test        [.] code.google.com/p/gochess/movement.DetectCheckByLastMove
+   1.32%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).setEnPassantSquare
+   1.20%  search.test  search.test        [.] runtime.stackfree
+   1.18%  search.test  search.test        [.] code.google.com/p/gochess/movement.GenerateCheckEvasions
+   1.11%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).setCastlingRights
+   1.04%  search.test  search.test        [.] runtime.stackalloc
+   1.00%  search.test  search.test        [.] code.google.com/p/gochess/movement.IsLegalMoveWhileNotInCheck
+   0.99%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).Remove
+   0.89%  search.test  search.test        [.] code.google.com/p/gochess/position.(*piecePlacement).Remove
+   0.87%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).Reset
+   0.86%  search.test  search.test        [.] code.google.com/p/gochess/movement.(*SortableMoveList).Next
+   0.75%  search.test  search.test        [.] code.google.com/p/gochess/position.(*piecePlacement).Reset
+   0.73%  search.test  search.test        [.] code.google.com/p/gochess/search.(*Position).switchSides
+   0.72%  search.test  search.test        [.] code.google.com/p/gochess/position.(*Position).SwitchSides
+   0.66%  search.test  search.test        [.] runtime.lessstack
+   0.57%  search.test  search.test        [.] code.google.com/p/gochess/movement.GeneratePawnMoves
+   0.54%  search.test  search.test        [.] runtime.morestack
+   0.53%  search.test  search.test        [.] code.google.com/p/gochess/search.CalculateScore
+   0.46%  search.test  search.test        [.] code.google.com/p/gochess/search.quiescenceSearch
+   0.45%  search.test  search.test        [.] code.google.com/p/gochess/movement.(*SortableMoveList).Add

according to the perf report a significant amount of time is spent in runtime.newsstack and runtime.oldstack. pprof does not report this time at all, which explains the missing time in pprof. this is odd.

and: i don't know what causes the program to spent so much time in runtime.newsstack, this behaviour occurred after making a rather small change (saving some values into an array along the way). going back to an old version make pprof and perf report look equal. maybe this information is important, because i can imagine the problem lies deep somewhere in the go runtime code. just guessing.

any help appriciated. regards

heiko

[Dmitry Vyukov]

Hi,

Thanks!

There is indeed an issue in pprof profiler in Go runtime, it ignores samples in newstack/oldstack.

I've filed an issue for this:

https://code.google.com/p/go/issues/detail?id=5544

 

[hs]

ok, thanks, sorry that i didn't report back (because nobody answered), but I found an issue for that problem:

http://code.google.com/p/go/issues/detail?can=2&q=2197&id=2197

And in my case the problem is the deep recursive function and the way segmented stacks are working, which is described here:

https://groups.google.com/forum/#!msg/golang-dev/vxRuA-gbwdw/xiaDzM586VMJ

So what I do right now is turning my recursive function into an iterative one. Seems I end up in spaghetti code this way.

[Dmitry Vyukov]

Thanks!
I've merged and updated the issues.

> --
> You received this message because you are subscribed to the Google Groups
> "golang-nuts" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to golang-nuts...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>