Go程序CPU消耗分析

不念不忘少年蓝@ 2022-12-26 10:29 286阅读 0赞

### CPU消耗统计 ###

在应用代码前安插如下一段代码（摘自 https://github.com/eyjian/grpcpool/blob/master/test/grpc\_client.go）：

import "runtime/pprof"
    
    func main() {
      profFilename := "test.prof"
      profFile, err := os.Create(profFilename)
      if err != nil {
          fmt.Printf("Create %s failed: %s.\n", profFilename, err.Error())
          os.Exit(1)
      } else {
          pprof.StartCPUProfile(profFile)
          profFile.Close()
          defer pprof.StopCPUProfile() // 进程退出时生成 test.prof 文件
      }
    }

进程退出时可看到文件 test.prof，执行下列命令（其中 test 为程序文件名）：

<table> 
 <thead> 
  <tr> 
   <th align="left">go tool pprof test test.prof</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

在 pprof 中执行命令 **top10** 可查看消耗 CPU 最多的 10 个函数调用。

还可将 test.prof 转换成直观的 svg 图片文件，只需在 pprof 中执行命令 **svg** 即可，但这要求安装了工具 **graphviz**，在 CentOS 等支持 yum 的系统中可执行如下命令安装 graphviz，安装好后，即可在 pprof 中执行 svg 生成图片文件：

<table> 
 <thead> 
  <tr> 
   <th align="left">yum -y install graphviz</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

上述的 **runtime/pprof** 针对的是运行后会退出的程序，如果是服务端程序，则用 **net/http/pprof** 来得到 CPU 消耗数据。

### 环境变量 GOMAXPROCS ###

用该环境变量设置进程占用的 CPU 线程数，不设置该环境变量时默认为 CPU 核数（不包含 GC 等非工作线程）。比如一个 8 核系统中，默认线程数为 14（包含了 6 个非工作线程）。

*  **示例：设置工作线程数为 1**

<table> 
 <thead> 
  <tr> 
   <th align="left">export GOMAXPROCS=1</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

这个时候总线程数为 4，其中包含 3 个非工作线程。代码中，可调用函数 runtime.GOMAXPROCS(n) 来达到同样的目的，调用函数 runtime.NumGoroutine() 可取得当前协程数。

*  **非工作线程1：**

templateThread 可参考 https://golang.org/pkg/runtime/?m=all\#templateThread。

#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
    #1  0x0000000000433b86 in runtime.futexsleep (addr=0xc22938 <runtime.newmHandoff+24>, val=0, ns=-1)
        at /usr/local/go/src/runtime/os_linux.go:45
    #2  0x000000000040dbdf in runtime.notesleep (n=0xc22938 <runtime.newmHandoff+24>) at /usr/local/go/src/runtime/lock_futex.go:159
    #3  0x000000000043e1fa in runtime.templateThread () at /usr/local/go/src/runtime/proc.go:1888
    #4  0x000000000043cd08 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1172
    #5  0x000000000043cc0e in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1137
    #6  0x0000000000401893 in runtime/cgo(.text) ()
    #7  0x00007fffffffe2a0 in ?? ()
    #8  0x00007fffcf9e3700 in ?? ()
    #9  0x00007fffcf9e39c0 in ?? ()
    #10 0x0000000000000001 in ?? ()
    #11 0x000000c000001380 in ?? ()
    #12 0x000000000043cba0 in ?? () at <autogenerated>:1
    #13 0x0000000000401493 in threadentry ()
    #14 0x00007fffcf9e3700 in ?? ()
    #15 0x0000000000000000 in ?? ()

mstart 是 GMP 模块中 M 的入口，一个 M 创建后都是从 mstart 开始执行。

*  **非工作线程2：**

协程 sysmon 是一个监控和管理协程，不参与 GMP 调度，独占一个线程。

#0  runtime.usleep () at /usr/local/go/src/runtime/sys_linux_amd64.s:146
    #1  0x00000000004450ad in runtime.sysmon () at /usr/local/go/src/runtime/proc.go:4633
    #2  0x000000000043cd08 in runtime.mstart1 () at /usr/local/go/src/runtime/proc.go:1172
    #3  0x000000000043cc0e in runtime.mstart () at /usr/local/go/src/runtime/proc.go:1137
    #4  0x0000000000401893 in runtime/cgo(.text) ()
    #5  0x00007fffffffe1f0 in ?? ()
    #6  0x00007fffd09e5700 in ?? ()
    #7  0x00007fffd09e59c0 in ?? ()
    #8  0x0000000000000001 in ?? ()
    #9  0x000000c000000900 in ?? ()
    #10 0x000000000043cba0 in ?? () at <autogenerated>:1
    #11 0x0000000000401493 in threadentry ()
    #12 0x00007fffd09e5700 in ?? ()
    #13 0x0000000000000000 in ?? ()

*  **非工作线程3：**

rt0\_go 是 Go 程序的入口，类似于 C/C++ 中的 \_\_libc\_start\_main。

#0  runtime.futex () at /usr/local/go/src/runtime/sys_linux_amd64.s:588
    #1  0x0000000000433b86 in runtime.futexsleep (addr=0xbf2148 <runtime.m0+328>, val=0, ns=-1) at /usr/local/go/src/runtime/os_linux.go:45
    #2  0x000000000040dbdf in runtime.notesleep (n=0xbf2148 <runtime.m0+328>) at /usr/local/go/src/runtime/lock_futex.go:159
    #3  0x000000000043e2e5 in runtime.stopm () at /usr/local/go/src/runtime/proc.go:1910
    #4  0x00000000004422bd in runtime.exitsyscall0 (gp=0xc000480900) at /usr/local/go/src/runtime/proc.go:3401
    #5  0x000000000046b17b in runtime.mcall () at /usr/local/go/src/runtime/asm_amd64.s:318
    #6  0x000000000046b074 in runtime.rt0_go () at /usr/local/go/src/runtime/asm_amd64.s:220
    #7  0x0000000000000000 in ?? ()

源代码文件 asm\_amd64.s 注释摘要：

<table> 
 <thead> 
  <tr> 
   <th align="left">_rt0_amd64 is common startup code for most amd64 systems when using internal linking. This is the entry point for the program from the kernel for an ordinary -buildmode=exe program. The stack holds the number of arguments and the C-style argv.</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

*  **工作线程：**

#0  syscall.Syscall () at /usr/local/go/src/syscall/asm_linux_amd64.s:24
    #1  0x000000000047ca7a in syscall.read (fd=640, p=<error reading variable: access outside bounds of object referenced via synthetic pointer>, 
        n=<optimized out>, err=...) at /usr/local/go/src/syscall/zsyscall_linux_amd64.go:686
    #2  0x00000000004d688c in syscall.Read (fd=90, p=..., n=<optimized out>, err=...) at /usr/local/go/src/syscall/syscall_unix.go:187
    #3  internal/poll.(*FD).Read.func1 (~r0=<optimized out>, ~r1=...) at /usr/local/go/src/internal/poll/fd_unix.go:155
    #4  0x00000000004d42a7 in internal/poll.ignoringEINTR (fn={void (int *, error *)} 0xc007cc8be8, ~r1=<optimized out>, ~r2=...)
        at /usr/local/go/src/internal/poll/fd_unix.go:567
    #5  0x00000000004d14be in internal/poll.(*FD).Read (fd=0xc003141300, p=..., ~r1=<optimized out>, ~r2=...)
        at /usr/local/go/src/internal/poll/fd_unix.go:155
    #6  0x000000000055ebcf in net.(*netFD).Read (fd=0xc003141300, p=..., n=<optimized out>, err=...) at /usr/local/go/src/net/fd_posix.go:55
    #7  0x000000000057202e in net.(*conn).Read (c=0xc005829e10, b=..., ~r1=<optimized out>, ~r2=...) at /usr/local/go/src/net/net.go:182
    #8  0x0000000000501f62 in bufio.(*Reader).Read (b=0xc0072c41e0, p=..., n=<optimized out>, err=...) at /usr/local/go/src/bufio/bufio.go:227
    #9  0x00000000004cd467 in io.ReadAtLeast (r=..., buf=..., min=9, n=<optimized out>, err=...) at /usr/local/go/src/io/io.go:309
    #10 0x000000000074b029 in io.ReadFull (r=..., buf=..., err=..., n=<optimized out>) at /usr/local/go/src/io/io.go:333
    #11 golang.org/x/net/http2.readFrameHeader (buf=..., r=..., ~r2=..., ~r3=...)
        at /root/go/pkg/mod/golang.org/x/net@v0.0.0-20190311183353-d8887717615a/http2/frame.go:237
    #12 0x000000000074b8a5 in golang.org/x/net/http2.(*Framer).ReadFrame (fr=0xc0072a82a0, ~r0=..., ~r1=...)
        at /root/go/pkg/mod/golang.org/x/net@v0.0.0-20190311183353-d8887717615a/http2/frame.go:492
    #13 0x000000000076e919 in google.golang.org/grpc/internal/transport.(*http2Client).reader (t=0x5a)
        at /root/go/pkg/mod/google.golang.org/grpc@v1.33.2/internal/transport/http2_client.go:1294
    #14 0x000000000046cf81 in runtime.goexit () at /usr/local/go/src/runtime/asm_amd64.s:1374
    #15 0x000000c007199880 in ?? ()
    #16 0x0000000000000000 in ?? ()

### 垃圾回收 GC 之 “GODEBUG=gctrace=1” ###

GC 经常是消耗 CPU 的大户，可使用工具 GODEBUG 来观察 GC。只需在启动程序之前，设置如下环境变量：

<table> 
 <thead> 
  <tr> 
   <th align="left">export GODEBUG=gctrace=1</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

这样就会在屏幕上输出 GC 运行数据，如：

gc 1 @4.598s 0%: 0.057+1.0+0.034 ms clock, 0.22+0.77/0.94/0+0.13 ms cpu, 7->7->6 MB, 8 MB goal, 4 P
    gc 2 @4.601s 0%: 0.033+1.2+0.004 ms clock, 0.13+1.2/1.0/0+0.019 ms cpu, 11->11->11 MB, 12 MB goal, 4 P
    gc 3 @4.604s 0%: 0.083+1.1+0.074 ms clock, 0.33+2.5/1.0/0+0.29 ms cpu, 20->21->21 MB, 23 MB goal, 4 P
    gc 4 @4.618s 0%: 0.091+2.8+0.042 ms clock, 0.36+6.5/2.8/0+0.16 ms cpu, 38->38->38 MB, 42 MB goal, 4 P
    gc 5 @4.659s 0%: 0.13+7.7+0.057 ms clock, 0.54+18/6.9/0+0.23 ms cpu, 70->71->69 MB, 76 MB goal, 4 P

每一行的格式为（参考 https://golang.org/pkg/runtime/ ）：

<table> 
 <thead> 
  <tr> 
   <th align="left">gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #-&gt;#-&gt;# MB, # MB goal, # P</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

各部分含义：

<table> 
 <thead> 
  <tr> 
   <th align="left"></th> 
   <th align="left">含义</th> 
  </tr> 
 </thead> 
 <tbody> 
  <tr> 
   <td align="left">gc #</td> 
   <td align="left">GC 执行次数，每执行一次增一</td> 
  </tr> 
  <tr> 
   <td align="left">@#s</td> 
   <td align="left">自程序启动以来经过的秒数</td> 
  </tr> 
  <tr> 
   <td align="left">#%</td> 
   <td align="left">自程序启动以来，GC 花费的时间所在百分比</td> 
  </tr> 
  <tr> 
   <td align="left">#+…+#</td> 
   <td align="left">GC 占用的 CPU 时间百分比，如果有 forced 则表示 runtime.GC() 程序强制 GC</td> 
  </tr> 
  <tr> 
   <td align="left">#-&gt;#-&gt;# MB</td> 
   <td align="left">GC 启动、GC 结束和 被标记为活跃的堆大小</td> 
  </tr> 
  <tr> 
   <td align="left"># MB goal</td> 
   <td align="left">下一次 GC 启动的堆大小，即达到这个值触发 GC</td> 
  </tr> 
  <tr> 
   <td align="left"># P</td> 
   <td align="left">使用的 CPU 核数</td> 
  </tr> 
 </tbody> 
</table>

以

<table> 
 <thead> 
  <tr> 
   <th align="left">gc 1 @4.598s 0%: 0.057+1.0+0.034 ms clock, 0.22+0.77/0.94/0+0.13 ms cpu, 7-&gt;7-&gt;6 MB, 8 MB goal, 4 P</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

为例：

<table> 
 <thead> 
  <tr> 
   <th align="left"></th> 
   <th align="left">说明</th> 
  </tr> 
 </thead> 
 <tbody> 
  <tr> 
   <td align="left">gc 1</td> 
   <td align="left">程序启动以来的第 1 次 GC</td> 
  </tr> 
  <tr> 
   <td align="left"></td> 
   <td align="left"></td> 
  </tr> 
  <tr> 
   <td align="left">@4.598s</td> 
   <td align="left">程序自启动以来，已运行 4.598 秒</td> 
  </tr> 
  <tr> 
   <td align="left">0%</td> 
   <td align="left">自程序启动以来，GC 耗费了 0% 的 CPU 时间</td> 
  </tr> 
  <tr> 
   <td align="left"><strong>wall-clock</strong></td> 
   <td align="left"></td> 
  </tr> 
  <tr> 
   <td align="left">0.057</td> 
   <td align="left">标记阶段的 STW 时长（单 P）</td> 
  </tr> 
  <tr> 
   <td align="left">1.0</td> 
   <td align="left">并发标记的时长（所有 P）</td> 
  </tr> 
  <tr> 
   <td align="left">0.034</td> 
   <td align="left">标记结束阶段的 STW 时长（单 P）</td> 
  </tr> 
  <tr> 
   <td align="left"><strong>CPU time</strong></td> 
   <td align="left"></td> 
  </tr> 
  <tr> 
   <td align="left">0.22</td> 
   <td align="left">整个进程在标记阶段 STW 时长</td> 
  </tr> 
  <tr> 
   <td align="left">0.77</td> 
   <td align="left">标记准备时长</td> 
  </tr> 
  <tr> 
   <td align="left">0.94</td> 
   <td align="left">回收时长</td> 
  </tr> 
  <tr> 
   <td align="left">0</td> 
   <td align="left">空闲时长</td> 
  </tr> 
  <tr> 
   <td align="left">0.13</td> 
   <td align="left">整个进程在标记结束阶段 STW 时长</td> 
  </tr> 
  <tr> 
   <td align="left"></td> 
   <td align="left"></td> 
  </tr> 
  <tr> 
   <td align="left">7</td> 
   <td align="left">开始标记前使用的堆大小</td> 
  </tr> 
  <tr> 
   <td align="left">7</td> 
   <td align="left">标记结束后使用的堆大小</td> 
  </tr> 
  <tr> 
   <td align="left">6</td> 
   <td align="left">标记结束后，被标记为活跃的堆大小</td> 
  </tr> 
  <tr> 
   <td align="left">8</td> 
   <td align="left">下一次触发 GC 的堆大小</td> 
  </tr> 
  <tr> 
   <td align="left"><strong>Threads</strong></td> 
   <td align="left"></td> 
  </tr> 
  <tr> 
   <td align="left">4 P</td> 
   <td align="left">使用了 4 个 CPU 核</td> 
  </tr> 
 </tbody> 
</table>

### 附1：不依赖 libc 库 ###

如果不想编译出的程序依赖 libc，可加上如下参数：

<table> 
 <thead> 
  <tr> 
   <th align="left">-ldflags ‘-linkmode “external” -extldflags “-static”’</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

示例：

<table> 
 <thead> 
  <tr> 
   <th align="left">go build -o grpc_server -ldflags ‘-linkmode “external” -extldflags “-static”’ grpc_server.go hello.pb.go</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>

### 附2：三色标记法垃圾回收（GC） ###

*  **白色**

对象未被标记，在本次 GC 中将被清理掉（回收）。

*  **黑色**

对象已被标记，且所包含的子对象也已被标记，不会在本次 GC 中被清理掉（回收）。

*  **灰色**

对象已被标记，但所包含的子对象未被标记。灰色是种中间状态，GC 完成后，要么是将被清理掉的白色对象，要么是继续保留的黑色对象。

**标记过程**

1）暂停所有工作协程的运行（stop the world）

2）初始时所有对象都是**白色**的

3）恢复所有工作协程的运行（start the world）

4）首先将根对象 **root** 标记为**灰色**

5）从根对象（包含所有全局变量、栈变量）开始找到所有可达对象，标记为灰色后放入待处理灰色对象队列

6）遍历灰色对象队列，将灰对象引用的对象标记为**灰色**，将被引用的对象放入待处理灰色对象队列，将灰对象自身标记为**黑色**

7）重复步骤 4，直到待处理灰色对象队列为空

8）暂停所有工作协程的运行（stop the world）

9）清理掉**白色**对象

10）恢复所有工作协程的运行（start the world）

### 附3：GMP 模型 ###

*  **G**

G 即 Goroutine，协程。

*  **M**

M 即 Machine，系统线程，执行 P。可调用 debug.SetMaxThreads(n) 来设置 M 的数量。

*  **P**

P 即 Processor，执行 G 的逻辑处理器，每一个 P 都维护了一个非共享的 G 运行队列（另外还有一个全局共享的 G 队列），决定了并发任务数，调度 G 在 M 上的执行。注意，并不是物理 CPU 核。可通过 GOMAXPROCS 来设置 P 的数量，默认为可用物理 CPU 核数，可大于物理 CPU 核数。

### 附4：程序入口 ###

以程序 grpc\_client 为例。

*  **找到入口地址**

# objdump -f grpc_client
    
    grpc_client：     文件格式 elf64-x86-64
    体系结构：i386:x86-64，标志 0x00000112：
    EXEC_P, HAS_SYMS, D_PAGED
    起始地址 0x000000000046e5e0

从上可看到入口地址为“0x000000000046e5e0”，反汇编找入口函数：

# objdump -d grpc_client > c.txt
    # grep 46e5e0 c.txt             
    000000000046e5e0 <_rt0_amd64_linux>:
      46e5e0:       e9 3b c9 ff ff          jmpq   46af20 <_rt0_amd64>

从上可看到入口函数为“\_rt0\_amd64\_linux”，所在源代码文件为 /usr/local/go/src/runtime/rt0\_linux\_amd64.s。

### 附5：go tool trace ###

可用来了解运行时信息，需要在程序中安装如下一段代码：

import "runtime/trace"
    
    traceFilename := "grpc_client.trace"
    traceFile, err := os.Create(traceFilename)
    if err != nil {
        fmt.Printf("Create trace://%s failed: %s.\n", traceFilename, err.Error())
        os.Exit(1)
    } else {
        trace.Start(traceFile)
        defer traceFile.Close()
        defer trace.Stop()
    }

当 trace.Stop() 完成后，会生成 trace 数据文件 grpc\_client.trace。然后可借助命令“go tool trace”以 HTTP 方式查看结果：

<table> 
 <thead> 
  <tr> 
   <th align="left">go tool trace -http=:80 grpc_client.trace</th> 
  </tr> 
 </thead> 
 <tbody></tbody> 
</table>