3

プロファイルしようとしているGoバイナリがあり、驚くべき結果が得られています。コードには次の（切り捨てられた）が含まれmain.go、残りのコードはパッケージに含まれていますmonte。

package main

import (
  "monte"
  "runtime/pprof"
)

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")

func main() {
  flag.Parse()
  if *cpuprofile != "" {
    f, err := os.Create(*cpuprofile)
    if err != nil {
      log.Fatal(err)
    }
    pprof.StartCPUProfile(f)
  }

  monte.ExpensiveOperation()

  pprof.StopCPUProfile()
}

で実行可能ファイルをビルドしてから、go build src/main.goで実行し./main -cpuprofile=monte.profます。で出力を調べるとgo tool pprof main monte.prof、次の出力が得られます。 

(pprof) top10 --cum
Total: 346 samples
     280  80.9%  80.9%      343  99.1% time.Time.Format
       0   0.0%  80.9%      341  98.6% runtime.interhash
       0   0.0%  80.9%      341  98.6% runtime.main
       0   0.0%  80.9%      251  72.5% strconv.Unquote
      13   3.8%  84.7%       31   9.0% strconv.roundShortest
      11   3.2%  87.9%       18   5.2% strconv.fmtE
       9   2.6%  90.5%        9   2.6% runtime.markallocated
       1   0.3%  90.8%        8   2.3% math/rand.Float64
       2   0.6%  91.3%        8   2.3% runtime.FixAlloc_Free
       7   2.0%  93.4%        8   2.3% time.nextStdChunk

累積時間が最も長い関数はですがtime.Time.Format、これは私には間違っているように思われ（そうではないでしょうか？） 、「高価な操作」が完了するまでに約10秒かかるにもかかわらず、十分な時間についてmainは何も言及されていません。monteサンプラーがそれを見ることができます。--focus=monteフラグをに渡すとgo tool pprof、サンプルはまったく表示されません。どこかにフラグがないのではないかと思います。誰かアイデアはありますか？ありがとう！

4

2 に答える 2

2

パッケージがコンパイルされず、パッケージのソースコードが提供されませmainんmonte。したがって、結果を再現することはできません。これはデバッグの最初のステップです。

これがいくつかの実用的なソースコードと結果です。

package monte

func ExpensiveOperation() {
    var t float64
    for i := int64(0); i < 1e10; i++ {
        t += 1
    }
}

。

package main

import (
    "flag"
    "log"
    "monte"
    "os"
    "runtime/pprof"
)

var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")

func main() {
    flag.Parse()
    if *cpuprofile != "" {
        f, err := os.Create(*cpuprofile)
        if err != nil {
            log.Fatal(err)
        }
        pprof.StartCPUProfile(f)
    }

    monte.ExpensiveOperation()

    pprof.StopCPUProfile()
}

。

(pprof) top10 --cum
Total: 1166 samples
       0   0.0%   0.0%     1166 100.0% main.main
    1166 100.0% 100.0%     1166 100.0% monte.ExpensiveOperation
       0   0.0% 100.0%     1166 100.0% runtime.main
       0   0.0% 100.0%     1166 100.0% schedunlock

アップデート：

のコードはgithub.com/haldean/monte意味のある結果を提供しません。実際の時間は0m0.506sで、48サンプルしかかかりません。

(pprof) top10 --cum
Total: 48 samples
       0   0.0%   0.0%       45  93.8% main.main
       0   0.0%   0.0%       45  93.8% monte.(*Scene).Evaluate
       0   0.0%   0.0%       45  93.8% monte.(*Scene).Render
       0   0.0%   0.0%       45  93.8% monte.(*Scene).SetColor
       0   0.0%   0.0%       45  93.8% runtime.main
       0   0.0%   0.0%       45  93.8% schedunlock
       0   0.0%   0.0%       44  91.7% monte.(*Scene).RayCast
       4   8.3%   8.3%       31  64.6% runtime.new
      13  27.1%  35.4%       27  56.2% runtime.mallocgc
       3   6.2%  41.7%       26  54.2% monte.(*Scene).DirectionAt
于 2012-10-08T17:21:47.503 に答える
1

CPUのみのプロファイラーのように見えるので、ExpensiveOperationI /Oやスリープなどで時間がかかると見えなくなります。（これが「cpu」プロファイラーの問題です。）

数字の意味からすると、合計346個のサンプルがあったようです。プロファイラーの動作によっては、数値が少しスクイーズであることはそれほど驚くことではありませんが、それが真のスタックサンプラーである場合、数値は次のことを意味します。

341/346サンプルがスタック上にmainありました。すべてのサンプルがスタックにメインであるinterhashことが期待されますが、それはスクイーズな部分です。

343/346サンプルがFormatスタックにありました。（なぜ、誰が知っているよりも多くの人がいるのmainですか？）

251/346サンプルがUnquoteスタックにありました。したがって、これらの251個のサンプルのうち、おそらく、、、mainおよびinterhashスタックFormat上にあります。

この種の探偵の仕事で、あなたはサンプルがあなたに話していることをゆっくりとつなぎ合わせ始めることができます。

もちろん、実際にスタックサンプルを見ることができれば、何が起こっているのかを正確に知る前に、それらの多くを見る必要はありません。

そのすべてについての詳細。

于 2012-10-08T20:56:03.520 に答える