了解 GoLang Profiling 输出

Posted

技术标签:

【中文标题】了解 GoLang Profiling 输出【英文标题】:Understanding GoLang Profiling output 【发布时间】:2018-02-19 23:22:30 【问题描述】:

一些上下文:

我正在尝试调试 GoGRPC 服务器,特定的 API 调用似乎需要很多时间。这个调用对 Kafka 进行了多次读取(比如说 10 到 20 次),所以我预计它需要一些时间,只是没有那么多。

1 个 API 调用大约需要 1-3 秒才能完成,但如果我在脚本中进行 40 个 api 调用,则几乎需要 30 秒才能完成所有这些。但它并没有像我预期的那样“同时”完成它们,第一个需要 5 秒,而后面的则每秒吐出 1 个左右。

需要 29 秒,一次响应所有 40 个请求。当请求时间过长时,这会导致 API 调用者超时。

我正在尝试分析 CPU 以查看我在哪里花费时间。但我是新手,go profiler 的输出没有多大意义。

我已使用 go tool pprof 生成图表,但在解释输出时遇到了一些问题。

CPU 调用图

    有一个框描述时间、类型、buildID 等。这个框中的Duration,是描述CPU 运行的总时间吗?不包括等待时间 有两种类型的边线,实线和虚线。有什么不同?边缘标记的时间是什么意思? 箭头的方向是指呼叫方向吗?例如函数 A 调用 B,在图上它将是 A -> B? 每个顶点在底部都有一个时间,例如0.01s(0.93%) out of 0.49s(45.79%),这个时间是什么意思?

阻止配置文件

    和上面的#4一样,边和顶点都有时间。这是什么意思?

编辑:

我的服务器所做的是从 kafka 流中检索一些数据。我已经确定了慢的原因,并且我编写了一个只有 kafka 调用函数的脚本。这是脚本和块分析图。

每次消费到 kafka 大约需要 50-100ms,但是由于大部分时间都花在做 IO 上,我预计 API 的吞吐量实际上是相当高的,事实并非如此。如果我打 100 个电话,大约需要 3 秒,如果我打 400 个电话,大约需要 10 秒。试图了解如何加快 API 的吞吐量

func main() 

    f, _ := os.Create("cpu.prof")
    pprof.StartCPUProfile(f)
    defer pprof.StopCPUProfile()

    block, _ := os.Create("block.prof")
    runtime.SetBlockProfileRate(1)
    p := pprof.Lookup("block")
    defer p.WriteTo(block, 0)

    var wg sync.WaitGroup
    wg.Add(messageCount)
    for i := 0; i < messageCount; i++ 
        go func() 
            // consume()
            withConsumer()
            wg.Done()
        ()

    

    wg.Wait()


var servers = []string"kafka-1", "kafka-2", "kafka-3"

var count = 0
var partition = int32(0)

func consume() 

    index := count
    t := time.Now()
    count++
    fmt.Println("starting consume", index)
    defer func() 
        fmt.Println("consume ", index, "took", time.Since(t).String())
    ()

    consumer, err := sarama.NewConsumer(servers, nil)
    if err != nil 
        panic(err)
    
    var max, min int64
    max = 1431401
    min = 2

    defer func() 
        consumer.Close()
    ()

    pc, err := consumer.ConsumePartition("source-topic", partition, rand.Int63n(max-min)+min)
    if err != nil 
        panic(err)
    

    defer func() 
        pc.Close()
    ()

    signals := make(chan os.Signal, 1)
    signal.Notify(signals, os.Interrupt)

    select 
    case msg := <-pc.Messages():
        fmt.Println("msg: ", len(msg.Value))
    case <-signals:
        return
    

谢谢,

【问题讨论】:

可以分享图表吗? 阅读blog.golang.org/profiling-go-programs。提示:始终请先咨询 golang.org,因为您会在那里找到答案。 谢谢,我在发布问题后发现了该链接,该帖子也没有详细介绍块分析器的工作原理。我将在问题中添加更多上下文 【参考方案1】:
    有一个框描述时间、类型、buildID 等。 这个框,是描述 CPU 运行的总时间吗?不是 包括等待时间

正确。 https://golang.org/doc/diagnostics#profiling 说:

cpu:CPU 配置文件确定程序在哪里花费时间 主动消耗 CPU 周期(而不是在睡眠或等待时) 用于 I/O)。

    有两种类型的边线,实线和虚线。什么是 区别?边缘标记的时间是什么意思?

https://github.com/google/pprof/issues/493 说“点/虚线表示中间节点已被删除。节点被删除以保持图形足够小以进行可视化。”

https://gperftools.github.io/gperftools/cpuprofile.html 说“每条边都标有被调用者代表调用者花费的时间。”

    箭头的方向是指呼叫方向吗?例如 函数 A 调用 B,在图上它将是 A -> B?

是的。

    每个顶点都有 底部的时间,例如0.01s(0.93%) 出 0.49s(45.79%),这个时间是什么意思?

第一次是当地时间。第二次是累计时间。 https://gperftools.github.io/gperftools/cpuprofile.html详解:

“本地”时间是直接执行指令所花费的时间 包含在程序中(以及在任何其他程序中 内联到过程中)。 “累积”时间是 “本地”时间和在任何被调用者中花费的时间。如果累计时间 与当地时间相同,不打印。

【讨论】:

以上是关于了解 GoLang Profiling 输出的主要内容,如果未能解决你的问题,请参考以下文章

golang [Go profiling snippets]用于分析目的的代码位#tags:golang,go,profiling,performance,measurement

golang调优工具 pprof

miRNA profiling啥意思

.Net Profiling - 了解托管线程的开始和结束

golang 使用编译选项-H=windowsgui后,仍然输出log到console

golang profile用法