爱上开源之golang入门至实战第三章goroutine分析

inthirties

已于 2022-07-06 11:05:44 修改

阅读量613

点赞数

分类专栏： golang人门至实战 golang 爱上开源文章标签：大数据

于 2022-07-06 11:04:56 首次发布

本文链接：https://blog.csdn.net/inthirties/article/details/125635316

版权

爱上开源同时被 3 个专栏收录

61 篇文章 3 订阅

订阅专栏

golang

58 篇文章 5 订阅

订阅专栏

golang人门至实战

33 篇文章 10 订阅

订阅专栏

爱上开源之golang入门至实战第三章 - goroutine分析

Goroutine

Pprof中的Goroutine是对当前时间点的goroutine(协程)数据的采样，我们经常使用pprof对可能发送goroutine(协程)泄漏的可能点进行分析；goroutine(协程)泄漏是goroutine启动之后没有退出导致goroutine的数量不会减少，或者是在实际应用中goroutine占用了很长时间才退出导致在一段时间内goroutine的数量急剧上升；虽然goroutine(协程)相对于线程的开销来说更加的轻量级，但是对于一个高并发的对性能要求比较高的系统，一样会由于协程的持续无谓的开销而导致整体性能的降低；甚至更严重的由于协程不断的增加，最后由于资源不够充足而无法进行分配，导致整个系统宕机。

我们还是先一起来看看；pprof提供出来的goroutine是怎样的采样数据；如下图所示：

如果了解以上的采样数据和数据格式表示的什么信息；我们可以查看runtime/pprof/pprof.go的源代码

runtime/pprof/pprof.go源代码Line 709是Goroutine的pprof采样数据的输出入口

func writeRuntimeProfile(w io.Writer, debug int, name string, fetch func([]runtime.StackRecord, []unsafe.Pointer) (int, bool)) error {
    // Find out how many records there are (fetch(nil)),
    // allocate that many records, and get the data.
    // There's a race—more records might be added between
    // the two calls—so allocate a few extra records for safety
    // and also try again if we're very unlucky.
    // The loop should only execute one iteration in the common case.
    var p []runtime.StackRecord
    var labels []unsafe.Pointer
    n, ok := fetch(nil, nil)
    for {
        // Allocate room for a slightly bigger profile,
        // in case a few more entries have been added
        // since the call to ThreadProfile.
        p = make([]runtime.StackRecord, n+10)
        labels = make([]unsafe.Pointer, n+10)
        n, ok = fetch(p, labels)
        if ok {
            p = p[0:n]
            break
        }
        // Profile grew; try again.
    }

    return printCountProfile(w, debug, name, &runtimeProfile{p, labels})
}

在printCountProfile函数Line 435 可以找到goroutine的具体输出内容；入口函数如下

    if debug > 0 {
        // Print debug profile in legacy format
        tw := tabwriter.NewWriter(w, 1, 8, 1, '\t', 0)
        fmt.Fprintf(tw, "%s profile: total %d\n", name, p.Len())
        for _, k := range keys {
            fmt.Fprintf(tw, "%d %s\n", count[k], k)
            printStackRecord(tw, p.Stack(index[k]), false)
        }
        return tw.Flush()
    }

技巧

选择一个好的IDE对于语言的学习非常的有作用；golang的IDE，笔者首选intellij公司出品的Idea；Idea功能强大；体验感非常的强；用idea来研究golang的源代码非常的高效

下图为Idea里的源代码片段

技巧

在Idea里，输入ctrl+Shift+R就可以出现快捷搜索框，在搜索框里输入pprof.go就可以快速把pprof.go源文件定位出来；在Idea的左下窗口，structure window可以显示出该源文件里定义的Type, 结构体，函数。变量等等；

在源代码窗口里，点击ctrl同时鼠标移动到函数名上面，就可以直接看到该函数的具体信息；如果需要进一步查看该函数的实现内容，点击函数名，就可以直接跳转到函数的方法体；通过idea的熟练使用；在查看和分析golang的源代码的，完全可以做到事半功倍

在golang的源代码里，可以看到很多文档或者网上资料都没有见到过的东西；毕竟相对于java或者其他语言；golang还相对年轻；并且由于golang相对于java的优点，更让golang适合去做一些云原生生态里的底仓服务；本身对开发者要求高；涉众没有java那么广泛，生态圈和社区都没有特别全面；一些底仓的东西；有时候我们必须学会去翻源代码已确定实现的细节

下面来看看goroutine pprof中使用

goroutine: Stack traces of all current goroutines

所以首先要明确的就是； goroutine pprof是程序栈里当前的所有协程；这里强调的当前的；即这个也是一个快照量；反映的是当前采集时间点上的协程状况

Goroutine的手工埋点

在很多的文档和网上资料里，往往只介绍了如何通过net/http/pprof的方式进行web服务的pprof埋点；关于手工在程序里进行埋点的方式也只介绍了CPU Profiling和Heap的埋点方式，其他的埋点方式网上和文档都没有介绍，在pprof包里可以export的方法也只有StartCPUProfile和WriteHeapProfile两个，其他都没有提供export的方法，笔者通过pprof的源代码找到了其他的埋点方法，goroutine的埋点方法如下：

    routineProfile := pprof.Lookup("goroutine")

    if err := routineProfile.WriteTo(f2, 0); err != nil {
        panic("could not start goroutine-1 profile: ")
    }

通过在这段代码，就可以把当前程序栈中的协程采样数据记录到指定的文件里；然后通过go tool pprof goroutine-prof-1 命令；就可以进行goroutine的pprof分析了。

下面通过一个实例，来演示一下goroutine pprof分析；演示程序在主协程里启动多个协程，协程在收到指定的通道信号后，退出协程；没有收到通道的退出信号前；协程处于阻塞状态；然后在主协程里，进行goroutine采样；采样结束后；往指定的通道发送退出信号；子协程全部退出后，在主协程再次进行goroutine采样；

代码如下


func TestGoroutinePprof(t *testing.T) {
    var profileEnd = "goroutine-prof-1"  // 指定保存的文件路径，当前目录的goroutine-prof-1文件
    var profileEnd2 = "goroutine-prof-2" // 指定保存的文件路径，当前目录的goroutine-prof-2文件

    f2, err := os.Create(profileEnd)
    if err != nil {
        panic(err)
    }
    defer f2.Close()

    f3, err := os.Create(profileEnd2)
    if err != nil {
        panic(err)
    }
    defer f3.Close()

    var goroutine = 100
    var wg sync.WaitGroup
    wg.Add(goroutine)

    var exit = make(chan bool)

    for idx := 1; idx <= goroutine; idx++ {
        func(i int) {
            go func() {
                <-exit
                fmt.Printf("No %d exit\n", i)
                wg.Done()
            }()
        }(idx)
    }

    time.Sleep(500 * time.Millisecond)

    //var profileEnd3 = "heap-prof-3" // 指定保存的文件路径，当前目录的test-prof文件

    routineProfile := pprof.Lookup("goroutine")

    if err := routineProfile.WriteTo(f2, 0); err != nil {
        panic("could not start goroutine-1 profile: ")
    }

    close(exit)

    wg.Wait()

    if err := routineProfile.WriteTo(f3, 0); err != nil {
        panic("could not start goroutine-2 profile: ")
    }

    fmt.Printf("sum=%d\n", goroutine)
}

技巧

golang具有多并发编程的良好基因，通过上面的go func(){}的方式，就可以非常方便的启动一个比线程轻量很多的routine；同时通过chan的实现；进行不同routine里的消息通信；通过WaitGroup的方式实现主子协程同步的操作

执行上面的代码，产生goroutine-prof-1和goroutine-prof-2两个goroutine的采样数据； goroutine-prof-1对应的是启动了所欲的子协程以后的goroutine的采样数据，goroutine-prof-2对应的是所有子协程收到退出信号后；子协程全部都确保退出后以后的goroutine采样数据。

通过pprof对采样数据进行分析

PS E:\WORK\PROJECT\git\go\go-in-practice\code\charpter-01> go tool pprof goroutine-prof-1
warning: GOPATH set to GOROOT (E:\WORK\SOFT\go1.18.windows-amd64\go) has no effect
Type: goroutine                  
Time: Jul 6, 2022 at 8:43am (CST)
Entering interactive mode (type "help" for commands, "o" for options)

执行Top命令

(pprof) top                                                          
Showing nodes accounting for 102, 100% of 102 total                                                   
Showing top 10 nodes out of 16                                                                        
      flat  flat%   sum%        cum   cum%                                                            
       101 99.02% 99.02%        101 99.02%  runtime.gopark                                            
         1  0.98%   100%          1  0.98%  runtime/pprof.runtime_goroutineProfileWithLabels          
         0     0%   100%          1  0.98%  go-in-practice/code/charpter-01.TestGoroutinePprof        
         0     0%   100%        100 98.04%  go-in-practice/code/charpter-01.TestGoroutinePprof.func1.1
         0     0%   100%          1  0.98%  main.main                                                 
         0     0%   100%        101 99.02%  runtime.chanrecv                                          
         0     0%   100%        101 99.02%  runtime.chanrecv1                                         
         0     0%   100%          1  0.98%  runtime.main
         0     0%   100%          1  0.98%  runtime/pprof.(*Profile).WriteTo
         0     0%   100%          1  0.98%  runtime/pprof.writeGoroutine

Showing nodes accounting for 102, 100% of 102 total

此时共有102个协程

其中

101 99.02% 99.02% 101 99.02% runtime.gopark 1 0.98% 100% 
  1 0.98% runtime/pprof.runtime_goroutineProfileWithLabels

查看第一行的101个协程的具体调用栈信息

(pprof) traces gopark
Type: goroutine     
Time: Jul 6, 2022 at 8:43am (CST)                                  
-----------+-------------------------------------------------------
       100   runtime.gopark                                        
             runtime.chanrecv                                      
             runtime.chanrecv1                                     
             go-in-practice/code/charpter-01.TestGoroutinePprof.func1.1
-----------+-------------------------------------------------------
         1   runtime.gopark
             runtime.chanrecv
             runtime.chanrecv1
             testing.(*T).Run
             testing.runTests.func1
             testing.tRunner
             testing.runTests
             testing.(*M).Run
             main.main
             runtime.main
-----------+-------------------------------------------------------

通过这里大致可以看到101分为两个部分 100 来着于charpter-01.TestGoroutinePprof.func1.1 和 1来自于 runtime.main主协程(本演示案例使用go test进行运行的，所有主协程即为testing.(*M).Run)

具体查看100个协程的相关源头

(pprof) list func1.1
Total: 102
ROUTINE ======================== go-in-practice/code/charpter-01.TestGoroutinePprof.func1.1 in E:\WORK\PROJECT\git\go\go-in-practice\code\charpter-01\lesson02_test.go
         0        100 (flat, cum) 98.04% of Total
         .          .    232:   var exit = make(chan bool)
         .          .    233:
         .          .    234:   for idx := 1; idx <= goroutine; idx++ {
         .          .    235:           func(i int) {
         .          .    236:                   go func() {
         .        100    237:                           <-exit
         .          .    238:                           wg.Done()
         .          .    239:                           fmt.Printf("No %d exit\n", i)
         .          .    240:                   }()
         .          .    241:           }(idx)
         .          .    242:   }

在第一个分析段落里，我们共看到了102个协程，以上由我们的测试代码已经找到了101个协程的来历；还有一个在哪里呢？

继续分析；找到第一个分析段落里的1个协程的

1 0.98% 100% 1 0.98% runtime/pprof.runtime_goroutineProfileWithLabels

在pprof交互命令行里执行traces runtime_goroutineProfileWithLabels

(pprof) traces runtime_goroutineProfileWithLabels
Type: goroutine
Time: Jul 6, 2022 at 8:43am (CST)
-----------+-------------------------------------------------------
         1   runtime/pprof.runtime_goroutineProfileWithLabels
             runtime/pprof.writeRuntimeProfile
             runtime/pprof.writeGoroutine
             runtime/pprof.(*Profile).WriteTo
             go-in-practice/code/charpter-01.TestGoroutinePprof
             testing.tRunner
-----------+-------------------------------------------------------

通过这里可以看到，是在我们执行routine采样的代码，产生了一个新的协程

在pprof交互命令行里执行list runtime_goroutineProfileWithLabels查看源码调用

(pprof) list runtime_goroutineProfileWithLabels   
Total: 102
ROUTINE ======================== runtime/pprof.runtime_goroutineProfileWithLabels in E:\WORK\SOFT\go1.18.windows-amd64\go\src\runtime\mprof.go
         1          1 (flat, cum)  0.98% of Total
         .          .    748:   return
         .          .    749:}
         .          .    750:
         .          .    751://go:linkname runtime_goroutineProfileWithLabels runtime/pprof.runtime_goroutineProfileWithLabels
         .          .    752:func runtime_goroutineProfileWithLabels(p []StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
         1          1    753:   return goroutineProfileWithLabels(p, labels)
         .          .    754:}
         .          .    755:
         .          .    756:// labels may be nil. If labels is non-nil, it must have the same length as p.
         .          .    757:func goroutineProfileWithLabels(p []StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
         .          .    758:   if labels != nil && len(labels) != len(p) {

在这里启动了新的协程；

以上是对第一个采样点的分析；第一个分析点，是在退出信号没有发出的时候，进行采样的，我们创建的100个协程都没有退出；下面来看看第二个分析点，第二个分析点，是在主协程已经给所有的子协程发出退出信号后，并且等待并确保所有100子协程都全部退出后，在主协程里进行goroutine采样；

通过pprof对第二个采样数据进行分析

PS E:\WORK\PROJECT\git\go\go-in-practice\code\charpter-01> go tool pprof goroutine-prof-2
warning: GOPATH set to GOROOT (E:\WORK\SOFT\go1.18.windows-amd64\go) has no effect
Type: goroutine                  
Time: Jul 6, 2022 at 8:43am (CST)
Entering interactive mode (type "help" for commands, "o" for options)

执行Top命令

(pprof) top                                                          
Showing nodes accounting for 2, 100% of 2 total           
Showing top 10 nodes out of 15                            
      flat  flat%   sum%        cum   cum%                
         1 50.00% 50.00%          1 50.00%  runtime.gopark
         1 50.00%   100%          1 50.00%  runtime/pprof.runtime_goroutineProfileWithLabels
         0     0%   100%          1 50.00%  go-in-practice/code/charpter-01.TestGoroutinePprof
         0     0%   100%          1 50.00%  main.main
         0     0%   100%          1 50.00%  runtime.chanrecv
         0     0%   100%          1 50.00%  runtime.chanrecv1
         0     0%   100%          1 50.00%  runtime.main
         0     0%   100%          1 50.00%  runtime/pprof.(*Profile).WriteTo
         0     0%   100%          1 50.00%  runtime/pprof.writeGoroutine
         0     0%   100%          1 50.00%  runtime/pprof.writeRuntimeProfile

Showing nodes accounting for 2, 100% of 2 total

此时共有2个协程

其中

         1 50.00% 50.00%          1 50.00%  runtime.gopark
         1 50.00%   100%          1 50.00%  runtime/pprof.runtime_goroutineProfileWithLabels

按照第一轮的分析方法；我们可以看到一个是主协程，一个是采样数据的新启动的协程

使用图形化web命令进行分析

在pprof的交互模式里输入web命令

下图为第一次采样点对应的图形化

下图为第二次采样点对应的图形化

图形化的结果很直观，和trace的结果是一致的；在无法安装图形化的情况下；可以通过traces来查看类似图形调用树的结果

使用traces命令查看采样数据

(pprof) traces gopark
Type: goroutine
Time: Jul 6, 2022 at 10:35am (CST)
-----------+-------------------------------------------------------
         1   runtime.gopark
             runtime.chanrecv
             runtime.chanrecv1
             testing.(*T).Run
             testing.runTests.func1
             testing.tRunner
             testing.runTests
             testing.(*M).Run
             main.main
             runtime.main
-----------+-------------------------------------------------------

通过pprof我们进行goroutine的分析；本文中的例子；仅仅是笔者用来演示分析过程只用，在项目过程中，都是通过压力测试的场景下，查看goroutine的资源情况，然后采样，在进行分析数据；用以上的分析过程，同样的适用于这样的场景。