Go程序CPU消耗分析

最新推荐文章于 2024-04-24 18:25:07 发布

一见

最新推荐文章于 2024-04-24 18:25:07 发布

阅读量2.1k

点赞数

分类专栏： go 文章标签： go

本文链接：https://blog.csdn.net/Aquester/article/details/110672025

版权

go 专栏收录该内容

29 篇文章 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 为程序文件名）：

go tool pprof test test.prof

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

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

yum -y install graphviz

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

环境变量 GOMAXPROCS

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

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

export GOMAXPROCS=1

这个时候总线程数为 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 注释摘要：

_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.

工作线程：

#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。只需在启动程序之前，设置如下环境变量：

export GODEBUG=gctrace=1

这样就会在屏幕上输出 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/ ）：

gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P

各部分含义：

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

以

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 1	程序启动以来的第 1 次 GC

@4.598s	程序自启动以来，已运行 4.598 秒
0%	自程序启动以来，GC 耗费了 0% 的 CPU 时间
wall-clock
0.057	标记阶段的 STW 时长（单 P）
1.0	并发标记的时长（所有 P）
0.034	标记结束阶段的 STW 时长（单 P）
CPU time
0.22	整个进程在标记阶段 STW 时长
0.77	标记准备时长
0.94	回收时长
0	空闲时长
0.13	整个进程在标记结束阶段 STW 时长

7	开始标记前使用的堆大小
7	标记结束后使用的堆大小
6	标记结束后，被标记为活跃的堆大小
8	下一次触发 GC 的堆大小
Threads
4 P	使用了 4 个 CPU 核

附1：不依赖 libc 库

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

-ldflags ‘-linkmode “external” -extldflags “-static”’

示例：

go build -o grpc_server -ldflags ‘-linkmode “external” -extldflags “-static”’ grpc_server.go hello.pb.go

附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 即 Goroutine，协程。

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

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 方式查看结果：

go tool trace -http=:80 grpc_client.trace

一见

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
Go程序CPU消耗分析

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 { fm
复制链接

扫一扫