Go 语言编程 — 性能分析

悠悠 2023-10-06 13:17 38阅读 0赞

## 目录 ##

#### 文章目录 ####

*  目录
 *  Profiling
 *   *  runtime
     *   *  MemStat
         *  GC
         *  pprof
         *  trace
 *  使用 GODEBUG 查看 Go Runtime Scheduler 的状态信息

## Profiling ##

Golang 提供了友好的工程化支持，其中之一就是 Profiling（分析）工具。例如：Golang 自带的 runtime 包，就可以轻松获取程序运行期间的各种内存或 CPU 的使用状态信息。

### runtime ###

#### MemStat ####

查看内存使用情况：

package main
    
    import (
    	"fmt"
    	"runtime"
    )
    
    func main() {
        
    	var m runtime.MemStats
    	runtime.ReadMemStats(&m)
    	fmt.Println(m.Alloc, m.HeapAlloc, m.HeapObjects, m.Frees)
    }

*  Alloc/HeapAlloc：表示当前 heap 的大小。
 *  HeapObjects：表示当前 heap 中有多少个对象。
 *  Frees：表示一共释放过多少的对象。程序可能会出现当前内存使用已经降下来了但过去某个时间曾经升高过的情况。

#### GC ####

// disable gc when start
    GOGC=off go run main.go
     
    
    // disable gc and manually trigger gc
    debug.SetGCPercent(-1)
    runtime.GC()

查看 GC 状态：

package main
    
    import (
        "fmt"
        "runtime/debug"
    )
    
    func main() {
        
        var d debug.GCStats
        debug.ReadGCStats(&d)
        fmt.Println(d.LastGC, d.NumGC, d.PauseTotal)
    }

*  LastGC：表示上次 GC 时间。
 *  NumGC：表示一共 GC 了过多少次。
 *  PauseTotal：总暂停时间以及 Pause 暂停历史。

#### pprof ####

pprof 可以查看程序运行过程中更加详细的 CPU、Mem 损耗信息：

package main
    
    import (
    	"os"
    	"runtime/pprof"
    )
    
    func main() {
        
        // CPU
    	pprof.StartCPUProfile(os.Stdout)
    	defer pprof.StopCPUProfile()
    }

输出 CPU Profile 文件并查看：

go run main.go > cpu.profile
    go tool pprof cpu.profile

打印内存使用信息：

package main
    
    import (
    	"os"
    	"runtime/pprof"
    )
    
    func main() {
        
        // Mem
    	pprof.WriteHeapProfile(os.Stdout)
    }

输出 Mem Profile 文件并查看：

go run main.go > memory.profile
    go tool pprof memory.profile

通常 memory.profile 记录的是当前的内存使用情况，有些时候并不适合 DEBUG，如果想知道全部的分配情况：

go tool pprof --alloc_space memory.profile

在一些问题原因不明确也不太好复现的场景中，上面输出 memory 和 cpu profile 的情况有些时候并不那么实用，这个时候一方面我们可以结合上面的 MemStats 使用，如果达到某个值就输出一份 profile，或者直接使用下面的通过 Web UI 把 profile 信息实时输出：

package main
    
    import (
    	"net/http"
    	_ "net/http/pprof"
    )
    
    func main() {
        
    	http.ListenAndServe("localhost:8082", nil)
    }

浏览器访问：http://localhost:8082/debug/pprof/  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70]

*  allocs：与 --alloc\_space 是一样的，同时还可以查看到 MemStats。
 *  block：没有在运行的时间，例如：等待 channel、等待 mutex 等。
 *  cmdline：当前程序的启动命令。
 *  goroutine：Goroutine 的信息。
 *  heap：与 Memory Profle 一样。
 *  mutex：Stack traces of holders of contended mutexes.
 *  profile：与 CPU Profile 一样。
 *  threadcreate：线程。
 *  trace：A trace of execution of the current program. You can specify the duration in the seconds GET parameter. After you get the trace file, use the go tool trace command to investigate the trace.

依旧可以使用工具来查看：

go tool pprof --alloc_space http://localhost:8082/debug/pprof/heap

#### trace ####

trace 和 pprof 的区别在于两者关注的维度不同，后者更关注代码栈层面，而 trace 更关注于 latency（延迟）。

比如说一个请求在客户端观察从发送到完成经过了 5s，做 profile 可能发现这个请求的 CPU 时间只有 2s，那剩下的 3s 就不是很清楚了， profile 更侧重的是我们代码执行了多久，至于其他的，例如：网络 IO，系统调用，Goroutine 调度，GC 时间等，很难反映出来。这是就应该使用 trace 了。

生成 trace：

package main
    
    import (
    	_ "net/http/pprof"
    	"os"
    	"runtime/trace"
    )
    
    func main() {
        
    	trace.Start(os.Stdout)
    	defer trace.Stop()
    }

或者上面的 pprof Web UI 也支持下载 trace 文件。

$ go tool trace app.trace
    2020/07/17 17:57:17 Parsing trace...
    2020/07/17 17:57:17 Splitting trace...
    2020/07/17 17:57:17 Opening browser. Trace viewer is listening on http://127.0.0.1:51252

在 trace 上可以清楚的看到每个 Goroutine 的起始，怎么生成的，每个 CPU 内核在做什么这些。

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70 1]

## 使用 GODEBUG 查看 Go Runtime Scheduler 的状态信息 ##

设置 GODEBUG 可以让 Golang 程序在运行时输出调试信息，包括可以直观的 GMP 调度器或垃圾回收等详细信息。GODEBUG 参数以逗号分隔，格式为：name=val。

对于 Go Runtime Scheduler，具有以下两个关键参数：

*  **schedtrace=X 参数**：可以使运行时在每 X 毫秒发出一行调度器的摘要信息到标准 err 输出中。
 *  **schedtrace=X 和 scheddetail=1 参数**：可以使运行时在每 X 毫秒发出一次详细的多行信息，信息内容主要包括调度程序、M、P、G 的状态。

示例：

package main
    
    import "sync"
    
    func main() {
        
        wg := sync.WaitGroup{
        }
        wg.Add(10)
        for i := 0; i <= 10; i++ {
        
            go func(wg *sync.WaitGroup) {
        
                var counter int
                for i := 0; i <= 10; i++ {
        
                    counter++
                }
                wg.Done()
            }(&wg)
        }
        wg.Wait()
    }

运行：

$ GODEBUG=schedtrace=1000 go run main.go
    SCHED 0ms: gomaxprocs=4 idleprocs=2 threads=4 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0]
    # command-line-arguments
    SCHED 0ms: gomaxprocs=4 idleprocs=1 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0]
    SCHED 1008ms: gomaxprocs=4 idleprocs=4 threads=9 spinningthreads=0 idlethreads=2 runqueue=0 [0 0 0 0]
    SCHED 0ms: gomaxprocs=4 idleprocs=1 threads=4 spinningthreads=1 idlethreads=0 runqueue=0 [1 0 0 0]

*  SCHED：每一行都代表调度器的调试信息，后面提示的毫秒数表示启动到现在的运行时间，输出的时间间隔受 schedtrace 值影响。
 *  gomaxprocs：当前的 CPU 核心数（GOMAXPROCS 的当前值）。
 *  idleprocs：空闲的处理器数量，后面的数字表示当前的空闲数量。
 *  threads：线程数量，后面的数字表示当前正在运行的线程数量。
 *  spinningthreads：自旋状态的线程数量。
 *  idlethreads：空闲的线程数量。
 *  runqueue：全局队列中中的 Goroutine 数量，而后面的 \[0 0 1 1\] 则分别代表这 4 个 P 的本地队列正在运行的 Goroutine 数量。

注：自旋线程（Spinning Thread）是 Go Scheduler 设计者在考虑了 “OS 的资源利用率” 以及 “频繁的线程抢占给 OS 带来的负载” 之后，提出的概念。也就是当 “自旋线程” 没有找到可供其调度执行的 Goroutine 时，并不会销毁该线程 ，而是采取 “自旋” 的操作保存了下来。虽然看起来这是浪费了一些资源，但比起 “自旋"，线程间频繁的抢占以及频繁的创建和销毁操作可能带来的损耗会更大。

如果我们想要更详细的看到调度器的完整信息时，可以增加 scheddetail 参数：

$ GODEBUG=scheddetail=1,schedtrace=1000 go run main.go
    ...
    SCHED 10ms: gomaxprocs=4 idleprocs=2 threads=5 spinningthreads=0 idlethreads=2 runqueue=0 gcwaiting=1 nmidlelocked=0 stopwait=2147483647 sysmonwait=0
      P0: status=1 schedtick=6 syscalltick=0 m=0 runqsize=0 gfreecnt=6 timerslen=0
      P1: status=0 schedtick=2 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
      P2: status=1 schedtick=5 syscalltick=0 m=4 runqsize=0 gfreecnt=4 timerslen=0
      P3: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
      M4: p=2 curg=10 mallocing=1 throwing=0 preemptoff= locks=2 dying=1 spinning=false blocked=false lockedg=-1
      M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
      M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
      M1: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
      M0: p=0 curg=1 mallocing=1 throwing=0 preemptoff= locks=2 dying=1 spinning=false blocked=false lockedg=-1
      G1: status=2(semacquire) m=0 lockedm=-1
      G2: status=4(force gc (idle)) m=-1 lockedm=-1
      G3: status=4(GC sweep wait) m=-1 lockedm=-1
      G4: status=4(GC scavenge wait) m=-1 lockedm=-1
      G5: status=6() m=-1 lockedm=-1
      G6: status=6() m=-1 lockedm=-1
      G7: status=6() m=-1 lockedm=-1
      G8: status=6() m=-1 lockedm=-1
      G9: status=6() m=-1 lockedm=-1
      G10: status=2() m=4 lockedm=-1
      G11: status=6() m=-1 lockedm=-1
      G12: status=6() m=-1 lockedm=-1
      G13: status=6() m=-1 lockedm=-1
      G14: status=6() m=-1 lockedm=-1
      G15: status=6() m=-1 lockedm=-1
    ...

**M**：

*  p：隶属哪一个 P。
 *  curg：当前正在使用哪个 G。
 *  runqsize：运行队列中的 G 数量。
 *  gfreecnt：可用的 G（状态为 Gdead）。
 *  mallocing：是否正在分配内存。
 *  throwing：是否抛出异常。
 *  preemptoff：不等于空字符串的话，保持 curg 在这个 m 上运行。

**P**：

*  status：P 的运行状态。
 *  schedtick：P 的调度次数。
 *  syscalltick：P 的系统调用次数。
 *  m：隶属哪一个 M。
 *  runqsize：运行队列中的 G 数量。
 *  gfreecnt：可用的 G（状态为 Gdead）。

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70 2]

**G**：

*  status：G 的运行状态。
 *  m：隶属哪一个 M。
 *  lockedm：是否有锁定 M。

G 共涉及如下 9 种状态：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70 3]

结合上述案例看看，如下：

G1: status=4(semacquire) m=-1 lockedm=-1
    G2: status=4(force gc (idle)) m=-1 lockedm=-1
    G3: status=4(GC sweep wait) m=-1 lockedm=-1
    G17: status=1() m=-1 lockedm=-1
    G18: status=2() m=4 lockedm=-1

在这个片段中，G1 的运行状态为 \_Gwaiting，并没有分配 M 和锁定，表示 Goroutine 在运行时时被阻止，而阻止它的就是 semacquire 事件，是因为 semacquire 会检查信号量的情况，在合适的时机就调用 goparkunlock 函数，把当前 Goroutine 放进等待队列，并把它设为 \_Gwaiting 状态。

实际运行中还有以下原因会导致这种现象：

waitReasonZero                                    // ""
        waitReasonGCAssistMarking                         // "GC assist marking"
        waitReasonIOWait                                  // "IO wait"
        waitReasonChanReceiveNilChan                      // "chan receive (nil chan)"
        waitReasonChanSendNilChan                         // "chan send (nil chan)"
        waitReasonDumpingHeap                             // "dumping heap"
        waitReasonGarbageCollection                       // "garbage collection"
        waitReasonGarbageCollectionScan                   // "garbage collection scan"
        waitReasonPanicWait                               // "panicwait"
        waitReasonSelect                                  // "select"
        waitReasonSelectNoCases                           // "select (no cases)"
        waitReasonGCAssistWait                            // "GC assist wait"
        waitReasonGCSweepWait                             // "GC sweep wait"
        waitReasonChanReceive                             // "chan receive"
        waitReasonChanSend                                // "chan send"
        waitReasonFinalizerWait                           // "finalizer wait"
        waitReasonForceGGIdle                             // "force gc (idle)"
        waitReasonSemacquire                              // "semacquire"
        waitReasonSleep                                   // "sleep"
        waitReasonSyncCondWait                            // "sync.Cond.Wait"
        waitReasonTimerGoroutineIdle                      // "timer goroutine (idle)"
        waitReasonTraceReaderBlocked                      // "trace reader (blocked)"
        waitReasonWaitForGCCycle                          // "wait for GC cycle"
        waitReasonGCWorkerIdle                            // "GC worker (idle)"

通过以上 waitReason 可以了解到 Goroutine 会被暂停运行的原因，也就是会出现在括号中的事件。

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70]: https://img-blog.csdnimg.cn/20200717174624385.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70 1]: https://img-blog.csdnimg.cn/20200717175858967.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70 2]: https://img-blog.csdnimg.cn/2020071821261633.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr_size_16_color_FFFFFF_t_70 3]: https://img-blog.csdnimg.cn/20200718212251765.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0ptaWxr,size_16,color_FFFFFF,t_70