转投go系列-谈谈profile工具

本文介绍: Go lang 自带 profile作为性能监控和分析工具，可以进行cpu、内存、死锁分析。当看到下图说明开启分析工具成功，通过 help 命令可以查看具体操作方法。例如 list xxx 方法，可以查看我们想看的可能有问题的方法。例如 top方法，可以查看占用 cpu的情况。

profile是干啥的？

Go lang 自带 profile作为性能监控和分析工具，可以进行c pu、内存、死锁分析。

数据 采集 使用方法？

引入 runtime/p prof包，手动调用 runtime.Star tCPUPro file等方法来进行指定范围采集，灵活。
引入 _ “net/http/p prof”包，进行启动服务采集，更简单。

import (
	"fmt"
	"net/http"
	_ "net/http/pprof"
	"os"
	"runtime/pprof"
	"time"
)

func shabile() {
	var c chan int
	for {
		select {
		case v := &lt;-c:
			fmt.Printf("incorrect %v", v)
		default:
		}
	}
}

//第一种方法
func DoStartCPUProfile() {
	file, err := os.Create("./cpu.prof")
	if err != nil {
		fmt.Printf("create file failed, err:%vn", err)
		return
	}
	
	_ = pprof.StartCPUProfile(file)
	defer pprof.StopCPUProfile()
	for i := 0; i < 4; i++ {
		go shabile()
	}
	time.Sleep(10 * time.Second)
}

//第二种方法
func DoListenAndServe() {
	for i := 0; i < 4; i++ {
		go shabile()
	}
	http.ListenAndServe("0.0.0.0:6061", nil)
}

go run main.go
//第一种方法，执行之后，你会发现，生成了cpu.prof
//第二种方法，执行之后，你可以通过 http://127.0.0.1:6061/debug/pprof/ 查看

下面是对应运行截图
在这里插入图片描述

类型	解释
alloc s	内存分配情况
block	阻塞操作情况
cmd line	程序启动命令参数
goroutine	协程堆栈信息
heap	堆内存分配
mutex	互斥锁数量
profile	c pu使用情况
thread create	线程创建数量
trace	运行跟踪信息

数据分析使用方法？

//方法一
go tool pprof cpu.prof
//方法二
go tool pprof http://127.0.0.1:6061/debug/pprof/profile

当看到下图说明开启分析工具成功，通过 help 命令可以查看具体操作方法
在这里插入图片描述
例如 top方法，可以查看占用 cpu的情况

flat 该方法占用CPU的耗时
flat% 该方法占用CPU的耗时的百分比
sum% 上面的方法+本方法flat%
cu m 当前方法+该方法调用之前的累计CPU耗时
cu m% 当前方法+该方法调用之前的累计CPU耗时的百分比

例如 list xx x 方法，可以查看我们想看的可能有问题的方法
在这里插入图片描述

下面举个例子(羊了个羊)：

package go_pprof

import (
	"log"
	"net/http"
	_ "net/http/pprof"
	"os"
	"runtime"
	"sync"
	"time"
)

func DoYangLeGeYang() {
	ch := make(chan int)
	AllYangs := [4]Yang{
		&amp;LieYangYang{},
		&amp;NuanYangYang{},
		&amp;LanYangYang{},
		&amp;MeiYangYang{},
	}

	log.SetFlags(log.Lshortfile | log.LstdFlags)
	log.SetOutput(os.Stdout)
	runtime.GOMAXPROCS(1)
	runtime.SetMutexProfileFraction(1)
	runtime.SetBlockProfileRate(1)

	go func() {
		if err := http.ListenAndServe(":6061", nil); err != nil {
			log.Fatal(err)
		}
		os.Exit(0)
	}()

	for {
		for _, v := range AllYangs {
			v.Go()
		}
		log.Println("----")
		time.Sleep(time.Second)
	}
}

type Yang interface {
	Name() string
	Go()
	Run()
	Jump()
	Fight()
	Idle()
}

type LieYangYang struct {
}

func (y *LieYangYang) Name() string {
	return "烈羊羊"
}

func (y *LieYangYang) Go() {
	y.Run()
	y.Jump()
	y.Fight()
	y.Idle()
}

func (y *LieYangYang) Run() {
	log.Println(y.Name(), "Run")
}

func (y *LieYangYang) Jump() {
	log.Println(y.Name(), "Jump")
}

func (y *LieYangYang) Fight() {
	log.Println(y.Name(), "Fight")
	//打架太厉害了
	_ = make([]byte, 10*1024*1024)
}

func (y *LieYangYang) Idle() {
	log.Println(y.Name(), "Idle")
}

type NuanYangYang struct {
}

func (y *NuanYangYang) Name() string {
	return "暖羊羊"
}

func (y *NuanYangYang) Go() {
	y.Run()
	y.Jump()
	y.Fight()
	y.Idle()
}

func (y *NuanYangYang) Run() {
	log.Println(y.Name(), "Run")
}

func (y *NuanYangYang) Jump() {
	log.Println(y.Name(), "Jump")
}

func (y *NuanYangYang) Fight() {
	log.Println(y.Name(), "Fight")
	//不想打架
	m := &amp;sync.Mutex{}
	m.Lock()
	go func() {
		time.Sleep(time.Second)
		m.Unlock()
	}()
	m.Lock()
}

func (y *NuanYangYang) Idle() {
	log.Println(y.Name(), "Idle")
	//平静一下
	for i := 0; i < 10; i++ {
		go func() {
			time.Sleep(30 * time.Second)
		}()
	}
}

type LanYangYang struct {
}

func (y *LanYangYang) Name() string {
	return "懒羊羊"
}

func (y *LanYangYang) Go() {
	y.Run()
	y.Jump()
	y.Fight()
	y.Idle()
}

func (y *LanYangYang) Run() {
	log.Println(y.Name(), "Run")
}

func (y *LanYangYang) Jump() {
	log.Println(y.Name(), "Jump")
	// 不想跳
	times := 10000000000
	for i := 0; i < times; i++ {
		// nothing
	}
}

func (y *LanYangYang) Fight() {
	log.Println(y.Name(), "Fight")
}

func (y *LanYangYang) Idle() {
	log.Println(y.Name(), "Idle")
	// 躺一会
	<-time.After(time.Second)
}

type MeiYangYang struct {
	buffer []byte
}

func (y *MeiYangYang) Name() string {
	return "美羊羊"
}

func (y *MeiYangYang) Go() {
	y.Run()
	y.Jump()
	y.Fight()
	y.Idle()
}

func (y *MeiYangYang) Run() {
	log.Println(y.Name(), "Run")
	var max int64 = 10 * 1024 * 1024
	for int64(len(y.buffer)) < max {
		y.buffer = append(y.buffer, 'a')
	}
}

func (y *MeiYangYang) Jump() {
	log.Println(y.Name(), "Jump")
}

func (y *MeiYangYang) Fight() {
	log.Println(y.Name(), "Fight")
}

func (y *MeiYangYang) Idle() {
	log.Println(y.Name(), "Idle")
}

运行后的日志就是这样：

2022/09/20 14:38:21 yanglegeyang.go:122: 暖羊羊 Idle
2022/09/20 14:38:21 yanglegeyang.go:146: 懒羊羊 Run
2022/09/20 14:38:21 yanglegeyang.go:150: 懒羊羊 Jump
2022/09/20 14:38:24 yanglegeyang.go:159: 懒羊羊 Fight
2022/09/20 14:38:24 yanglegeyang.go:163: 懒羊羊 Idle
2022/09/20 14:38:25 yanglegeyang.go:184: 美羊羊 Run
2022/09/20 14:38:25 yanglegeyang.go:192: 美羊羊 Jump
2022/09/20 14:38:25 yanglegeyang.go:196: 美羊羊 Fight
2022/09/20 14:38:25 yanglegeyang.go:200: 美羊羊 Idle
2022/09/20 14:38:25 yanglegeyang.go:39: ----
2022/09/20 14:38:26 yanglegeyang.go:70: 烈羊羊 Run
2022/09/20 14:38:26 yanglegeyang.go:74: 烈羊羊 Jump
2022/09/20 14:38:26 yanglegeyang.go:78: 烈羊羊 Fight
2022/09/20 14:38:26 yanglegeyang.go:84: 烈羊羊 Idle
2022/09/20 14:38:26 yanglegeyang.go:102: 暖羊羊 Run
2022/09/20 14:38:26 yanglegeyang.go:106: 暖羊羊 Jump
2022/09/20 14:38:26 yanglegeyang.go:110: 暖羊羊 Fight
2022/09/20 14:38:27 yanglegeyang.go:122: 暖羊羊 Idle
2022/09/20 14:38:27 yanglegeyang.go:146: 懒羊羊 Run
2022/09/20 14:38:27 yanglegeyang.go:150: 懒羊羊 Jump

正式开始：

go tool pprof localhost:6061/debug/pprof/{分析类型}

获取 profile 文件，看看cpu有没有什么异常。

go tool pprof http://localhost:6061/debug/pprof/profile
Fetching profile over HTTP from http://localhost:6061/debug/pprof/profile
Saved profile in pprof.samples.cpu.005.pb.gz
Type: cpu
Time: Sep 20, 2022 at 2:27pm (CST)
Duration: 30s, Total samples = 13.10s (43.66%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 13060ms, 99.69% of 13100ms total
Dropped 27 nodes (cum <= 65.50ms)
      flat  flat%   sum%        cum   cum%
   12620ms 96.34% 96.34%    13060ms 99.69%  go_pprof.(*LanYangYang).Jump
     440ms  3.36% 99.69%      440ms  3.36%  runtime.asyncPreempt
         0     0% 99.69%    13090ms 99.92%  core.DoPP (inline)
         0     0% 99.69%    13060ms 99.69%  go_pprof.(*LanYangYang).Go
         0     0% 99.69%    13090ms 99.92%  go_pprof.DoYangLeGeYang
         0     0% 99.69%    13090ms 99.92%  main.main
         0     0% 99.69%    13090ms 99.92%  runtime.main

top 命令后发现，懒羊羊Jump的时候出现了问题，于是 “list Jump”

(pprof) list Jump
Total: 13.10s
ROUTINE ======================== /go_pprof.(*LanYangYang).Jump in go_pprof/yanglegeyang.go
    12.62s     13.06s (flat, cum) 99.69% of Total
         .          .    148:
         .          .    149:func (y *LanYangYang) Jump() {
         .          .    150:   log.Println(y.Name(), "Jump")
         .          .    151:   // 不想跳
         .          .    152:   times := 10000000000
    12.62s     13.06s    153:   for i := 0; i < times; i++ {
         .          .    154:           // nothing
         .          .    155:   }
         .          .    156:}
         .          .    157:
         .          .    158:func (y *LanYangYang) Fight() {

原来懒羊羊不想跳，所以进行了n次的空循环，所以CPU那么高，赶快注释掉。

接下来看看内存有没有异常

 go tool pprof http://localhost:6061/debug/pprof/heap   
Fetching profile over HTTP from http://localhost:6061/debug/pprof/heap
Saved profile in /pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb.gz
Type: inuse_space
Time: Sep 20, 2022 at 2:50pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 12128.77kB, 100% of 12128.77kB total
Showing top 10 nodes out of 19
      flat  flat%   sum%        cum   cum%
   11104kB 91.55% 91.55%    11104kB 91.55%  /go_pprof.(*MeiYangYang).Run
  512.56kB  4.23% 95.78%   512.56kB  4.23%  runtime.allocm
  512.20kB  4.22%   100%   512.20kB  4.22%  runtime.malg
         0     0%   100%    11104kB 91.55%  /core.DoPP (inline)
         0     0%   100%    11104kB 91.55%  /go_pprof.(*MeiYangYang).Go
         0     0%   100%    11104kB 91.55%  /go_pprof.DoYangLeGeYang
         0     0%   100%    11104kB 91.55%  main.main
         0     0%   100%    11104kB 91.55%  runtime.main
         0     0%   100%   512.56kB  4.23%  runtime.mstart
         0     0%   100%   512.56kB  4.23%  runtime.mstart0

发现美羊羊在跑的时候占很多？于是继续list

(pprof) list Run
Total: 11.84MB
ROUTINE ======================== go_pprof.(*MeiYangYang).Run in go_pprof/yanglegeyang.go
   10.84MB    10.84MB (flat, cum) 91.55% of Total
         .          .    179:
         .          .    180:func (y *MeiYangYang) Run() {
         .          .    181:   log.Println(y.Name(), "Run")
         .          .    182:   var max int64 = 10 * 1024 * 1024
         .          .    183:   for int64(len(y.buffer)) < max {
   10.84MB    10.84MB    184:           y.buffer = append(y.buffer, 'a')
         .          .    185:   }
         .          .    186:}
         .          .    187:
         .          .    188:func (y *MeiYangYang) Jump() {
         .          .    189:   log.Println(y.Name(), "Jump")

原来美羊羊带了一大堆首饰跑路，所以内存那么高，赶快注释掉。

之前讲过GC的频繁处理会导致STW，这个频率是需要控制的。
接下来观察一下GC

GODEBUG=gctrace=1 ./main 2>&amp;1|grep gc

在这里插入图片描述
可以看到3s触发一次GC，每次都会从10M->0，说明内存被不断的申请和释放。看看谁在搞鬼？

go tool pprof http://localhost:6061/debug/pprof/allocs
Fetching profile over HTTP from http://localhost:6061/debug/pprof/allocs
Saved profile in pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz
Type: alloc_space
Time: Sep 20, 2022 at 3:01pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 32257.69kB, 100% of 32257.69kB total
Showing top 10 nodes out of 21
      flat  flat%   sum%        cum   cum%
   30720kB 95.23% 95.23%    30720kB 95.23%  go_pprof.(*LieYangYang).Fight (inline)
 1537.69kB  4.77%   100%  1537.69kB  4.77%  runtime.allocm
         0     0%   100%    30720kB 95.23%  core.DoPP (inline)
         0     0%   100%    30720kB 95.23%  go_pprof.(*LieYangYang).Go
         0     0%   100%    30720kB 95.23%  go_pprof.DoYangLeGeYang
         0     0%   100%    30720kB 95.23%  main.main
         0     0%   100%   512.56kB  1.59%  runtime.gopreempt_m
         0     0%   100%   512.56kB  1.59%  runtime.goschedImpl
         0     0%   100%   512.56kB  1.59%  runtime.handoffp
         0     0%   100%    30720kB 95.23%  runtime.main

接下来进行list

(pprof) list Fight
Total: 31.50MB
ROUTINE ======================== /go_pprof.(*LieYangYang).Fight in /go_pprof/yanglegeyang.go
      30MB       30MB (flat, cum) 95.23% of Total
         .          .     72:}
         .          .     73:
         .          .     74:func (y *LieYangYang) Fight() {
         .          .     75:   log.Println(y.Name(), "Fight")
         .          .     76:   //打架太厉害了
      30MB       30MB     77:   _ = make([]byte, 10*1024*1024)
         .          .     78:}
         .          .     79:
         .          .     80:func (y *LieYangYang) Idle() {
         .          .     81:   log.Println(y.Name(), "Idle")
         .          .     82:}

原来烈羊羊性格火爆，频繁打架，赶快注释掉。

接下来看看协程有没有啥问题？

 go tool pprof http://localhost:6061/debug/pprof/goroutine
Fetching profile over HTTP from http://localhost:6061/debug/pprof/goroutine
Saved profile in pprof.goroutine.002.pb.gz
Type: goroutine
Time: Sep 20, 2022 at 3:05pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 105, 100% of 105 total
Showing top 10 nodes out of 38
      flat  flat%   sum%        cum   cum%
       103 98.10% 98.10%        103 98.10%  runtime.gopark
         1  0.95% 99.05%          1  0.95%  net/http.(*connReader).backgroundRead
         1  0.95%   100%          1  0.95%  runtime/pprof.runtime_goroutineProfileWithLabels
         0     0%   100%          1  0.95%  /core.DoPP
         0     0%   100%          1  0.95%  /go_pprof.(*NuanYangYang).Fight
         0     0%   100%          1  0.95%  /go_pprof.(*NuanYangYang).Fight.func1
         0     0%   100%          1  0.95%  /go_pprof.(*NuanYangYang).Go
         0     0%   100%        100 95.24%  /go_pprof.(*NuanYangYang).Idle.func1
         0     0%   100%          1  0.95%  /go_pprof.DoYangLeGeYang
         0     0%   100%          1  0.95%  /go_pprof.DoYangLeGeYang.func1

我们发现gop ark有点问题，但是好像我们代码里面没有，这个时候就需要通过 web 命令来看了。（直接命令行里面敲 web 回车）
在这里插入图片描述
通过图片我们发现暖羊羊Idle出现问题了。

(pprof) list Idle
Total: 105
ROUTINE ======================== /go_pprof.(*NuanYangYang).Idle.func1 in go_pprof/yanglegeyang.go
         0        100 (flat, cum) 95.24% of Total
         .          .    118:func (y *NuanYangYang) Idle() {
         .          .    119:   log.Println(y.Name(), "Idle")
         .          .    120:   //平静一下
         .          .    121:   for i := 0; i < 10; i++ {
         .          .    122:           go func() {
         .        100    123:                   time.Sleep(30 * time.Second)
         .          .    124:           }()
         .          .    125:   }
         .          .    126:}
         .          .    127:
         .          .    128:type LanYangYang struct {

原来暖羊羊在频繁的做白日梦，赶快注释掉。

接下来看看有没有锁的问题？

go tool pprof localhost:6061/debug/pprof/mutex
Fetching profile over HTTP from http://localhost:6061/debug/pprof/mutex
Saved profile in pprof.contentions.delay.005.pb.gz
Type: delay
Time: Sep 20, 2022 at 3:19pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 2s, 100% of 2s total
      flat  flat%   sum%        cum   cum%
        2s   100%   100%         2s   100%  sync.(*Mutex).Unlock (inline)
         0     0%   100%         2s   100%  /go_pprof.(*NuanYangYang).Fight.func1

继续list

(pprof) list Fight
Total: 2s
ROUTINE ======================== /go_pprof.(*NuanYangYang).Fight.func1 in /go_pprof/yanglegeyang.go
         0         2s (flat, cum)   100% of Total
         .          .    108:   //不想打架
         .          .    109:   m := &amp;sync.Mutex{}
         .          .    110:   m.Lock()
         .          .    111:   go func() {
         .          .    112:           time.Sleep(time.Second)
         .         2s    113:           m.Unlock()
         .          .    114:   }()
         .          .    115:   m.Lock()
         .          .    116:}
         .          .    117:
         .          .    118:func (y *NuanYangYang) Idle() {

可以看到暖羊羊不想打架，进行lock加锁后又再次加锁，解锁由另一个协程进行的，另一个协程在休眠导致阻塞。

接下来再看看是否有block？

go tool pprof localhost:6061/debug/pprof/block
Fetching profile over HTTP from http://localhost:6061/debug/pprof/block
Saved profile in pprof.contentions.delay.006.pb.gz
Type: delay
Time: Sep 20, 2022 at 3:24pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 5s, 100% of 5s total
      flat  flat%   sum%        cum   cum%
        5s   100%   100%         5s   100%  runtime.chanrecv1
         0     0%   100%         5s   100%  core.DoPP (inline)
         0     0%   100%         5s   100%  go_pprof.(*LanYangYang).Go
         0     0%   100%         5s   100%  go_pprof.(*LanYangYang).Idle
         0     0%   100%         5s   100%  go_pprof.DoYangLeGeYang
         0     0%   100%         5s   100%  main.main
         0     0%   100%         5s   100%  runtime.main

继续list

(pprof) list Idle
Total: 5s
ROUTINE ======================== go_pprof.(*LanYangYang).Idle in /go_pprof/yanglegeyang.go
         0         5s (flat, cum)   100% of Total
         .          .    156:}
         .          .    157:
         .          .    158:func (y *LanYangYang) Idle() {
         .          .    159:   log.Println(y.Name(), "Idle")
         .          .    160:   // 躺一会
         .         5s    161:   <-time.After(time.Second)
         .          .    162:}
         .          .    163:
         .          .    164:type MeiYangYang struct {
         .          .    165:   buffer []byte
         .          .    166:}