在项目中，经常遇到接口响应慢的问题，严重的会造成接口超时，体验十分不好，此时就要定位原因进行优化，最简单的方式有对关键接口增加耗时日志打印，但是对于循环调用的接口，日志打印没法计算总时间，此时就要用golang 自带的性能分析工具 pprof 定位原因了。
下面以导出报告优化为例介绍pprof的使用。

优化起因

测试多次反应数据多时，导出报告容易超时，所以需要定位准确的原因，定位是哪个方法耗时最长。

pprof的使用

服务开启pprof

我们的服务是使用gin的Web服务，所有开启pprof非常简单，引入"github.com/gin-contrib/pprof"包即可。

package main

import (
	"log"
	"net/http"

	"github.com/gin-contrib/pprof"
	"github.com/gin-gonic/gin"
)

func main() {
	engine := gin.Default()
	pprof.Register(engine, "debug/pprof")
	engine.GET("/", func(context *gin.Context) {
		context.JSON(http.StatusOK, gin.H{"message": "Hello, World!"})
	})
	log.Fatal(engine.Run(":8090"))
}

重启服务后，通过 go tool pprof http://127.0.0.1/debug/pprof/profile?seconds=10 命令就可以抓取对应服务端CPU耗时情况，输入topN就可以查看耗时最长的前N个函数
image
不过这时候是用命令行看的不够直观，为了好看还需要安装数据图形可视化

安装数据图形可视化

下载安装可视化图形软件工具 graphviz ：https://graphviz.org/download/ ，安装并把bin目录加入到系统环境变量中
这时再执行 web就可以通过图像查看了

C:\Users\wshr>go tool pprof  http://127.0.0.1/debug/pprof/profile?seconds=40
Fetching profile over HTTP from http://127.0.0.1/debug/pprof/profile?seconds=40
Saved profile in C:\Users\wshr\pprof\pprof.patrol.samples.cpu.002.pb.gz
File: patrol
Type: cpu
Time: Jun 4, 2024 at 6:10pm (CST)
Duration: 40s, Total samples = 18.34s (45.85%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) web

image

优化实战

下面通过实际的优化例子介绍怎么使用pprof

优化前

  • 服务器从接受请求到响应花了27秒
    QQ20240923-101542
  • 看看CPU负载情况，基本都是单核在跑，没发挥多核的作用
    QQ101558
  • 再看看CPU使用情况取样，就是pprof，可以看到是 saveImage->(image)jpeg.Decode 方法占用CPU时间最长!
    tapd_41973538_1717502417_824

通过上面的数据分析得出两个结论：

  • jpeg.Decode 方法被调用太多
  • 没用到CPU多核优势

分析慢的原因

网上查了一下资料，golang的官方image库是慢，至今未改，https://github.com/golang/go/issues/24499 ，虽然有第三方库可以加快图片处理，但是生成word文档的库绑定了官方库，改起来不现实，所以优化jpeg.Decode的思路PASS掉。
附上性能测试

goos: linux
goarch: amd64
pkg: patrol
cpu: Hygon Dhyana Processor
BenchmarkJPEGDecode-4                141           8225588 ns/op          448584 B/op          4 allocs/op

接下来就是往并发处理的方向了，看了一下代码发现确实有地方是循环调用了


func (w *Exporter) saveImage(doc *document.Document, patrolImage *vo.Image, run document.Run, cell document.Cell) {
    for i := range patrolImage.OriImage {
       imgFile, err := common.ImageFromBytes(patrolImage.GetImageBs(i))
       if err != nil {
          logger.Warnw("saveImage ImageFromFile failed", "sourceImg", patrolImage.OriPath, "err", err.Error())
          return
       }
    }
}

common.ImageFromBytes 是第三方库的方法，里面做了代码混淆，不过_f.Decode就是 jpeg.Decode

func ImageFromBytes(data []byte) (Image, error) {
    _bba := Image{};
    _bgbd, _ddaf, _dbe := _f.Decode(_be.NewReader(data));
    if _dbe != nil {
       return _bba, _ea.Errorf("\u0075n\u0061\u0062\u006c\u0065 \u0074\u006f\u0020\u0070\u0061r\u0073e\u0020i\u006d\u0061\u0067\u0065\u003a\u0020\u0025s", _dbe);
    };
    _bba.Data = &data;
    _bba.Format = _ddaf;
    _bba.Size = _bgbd.Bounds().Size();
    return _bba, nil;
};

所以只需要把common.ImageFromBytes通过goroution的方式并发调用，应该可以解决
主要优化代码如下：

eg := &errgroup.Group{}
eg.SetLimit(runtime.GOMAXPROCS(0))
···
eg.Go(func() error {
    fromBytes, err := common.ImageFromBytes(imageObj.OriImage[index])
    if err != nil {
       logger.Warnw("saveImage ImageFromFile failed", "sourceImg", imageObj.OriImage, "err", err.Error())
       return nil
    }
    imageObj.OriImageWordImage[index] = &fromBytes
    return nil
})
···
if err = eg.Wait(); err != nil {
    return nil, err
}

优化后

  • 优化后CPU负载，多核都有调用到
    pprof101630
  • 服务器处理耗时从27s->8s，下载速度因为还是vpn，所以忽略
    QQ20240923-101645
  • CPU采样，时间也缩短的
    tapd_41973538_1717504445_831