Go服务几个副本同时OOMKilled的诡异问题排查

现象

基于go语言开发的文件上传中间件，对于下载图片支持扩展图片处理，例如格式转换、缩略图。

最近出现一个非常诡异的现象，这个服务部署4个节点，几乎每次4个节点都是同时挂的。挂掉的原因都是OOMkill。

但是看监控，内存并不是慢慢涨上去的，而是非常诡异的突然涨上去就挂了，这个时间也就短短一两分钟的事情。

排查方法

由于内存突增的时间非常短，基本不可能等突增的时候再使用pprof查看，所以必须要有个方案能够在这一两分钟内，把内存信息记录下来，所以我们写了个代码，自动每几秒输出一次快照，并自动删除当前进程一分钟之前的快照。代码如下：

package troubleshooting

import (
	"fmt"
	"log"
	"os"
	"path/filepath"
	"regexp"
	"runtime/pprof"
	"strconv"
	"strings"
	"time"
)

var PPID = time.Now().Format("20060102150405")

// 分析命令 go tool pprof xx.prof

func init() {
	rootPath := "/data/logs"
	go func() {
		for {
			select {
			case <-time.After(1 * time.Second):
				outSnapshotCpu(rootPath)
				outSnapshotMem(rootPath)
				cleanSnapshotFile(rootPath)
			}
		}
	}()
}

func cleanSnapshotFile(rootPath string) {
	deleteIfNeedFunc := func(path, timestampStr string) error {
		timestamp, err := strconv.Atoi(timestampStr)
		if err != nil {
			return nil
		}
		// 将数字转换为时间戳，这里假设%d部分代表的是秒数自纪元以来的秒数
		fileTime := time.Unix(int64(timestamp), 0)
		now := time.Now()
		// 判断文件是否在30秒之前
		if now.Sub(fileTime) > (30 * time.Second) {
			if err = os.Remove(path); err != nil {
				fmt.Printf("Error deleting file %s: %v", path, err)
			} else {
				fmt.Printf("Deleted file: %s, file time:%s cur time:%s\n",
					path, fileTime.Format("2006-01-02 15:04:05"), now.Format("2006-01-02 15:04:05"))
			}
		}
		return nil
	}
	if err := filepath.Walk(rootPath, func(path string, info os.FileInfo, err error) error {
		if err != nil {
			return err
		}
		if info.IsDir() {
			return nil
		}
		if matched, _ := regexp.MatchString(fmt.Sprintf("romefs-profile-%s(-cpu|-mem)-\\d+\\.prof", PPID), info.Name()); matched {
			fileName := info.Name()
			matches := regexp.MustCompile(fmt.Sprintf("romefs-profile-%s(-cpu|-mem)-(\\d+)\\.prof", PPID)).FindStringSubmatch(fileName)
			if len(matches) > 2 {
				timestampStr := matches[2]
				return deleteIfNeedFunc(path, timestampStr)
			}
			return nil
		}
		return nil
	}); err != nil {
		log.Fatalf("Walking dir: %s", err)
	}
}

func outSnapshotCpu(rootPath string) {
	fileName := fmt.Sprintf("%s/romefs-profile-%s-cpu-%d.prof", rootPath, PPID, time.Now().Unix())
	f, err := os.Create(fileName)
	if err != nil {
		return
	}
	defer f.Close()
	if err = pprof.StartCPUProfile(f); err != nil {
		return
	}
	time.Sleep(5 * time.Second)
	defer pprof.StopCPUProfile()
}

func outSnapshotMem(rootPath string) {
	fileName := fmt.Sprintf("%s/romefs-profile-%s-mem-%d.prof", rootPath, PPID, time.Now().Unix())
	memProfileFile, err := os.Create(fileName)
	if err != nil {
		return
	}
	defer memProfileFile.Close()
	if err = pprof.WriteHeapProfile(memProfileFile); err != nil {
		return
	}
}

复现和排查结论

当再次重现后，我们拿到了内存快照，通过go tool pprof 命令找出了内存泄漏的原因。

从图中可以定位到是下载图片处理缩略图的逻辑，在调用image.Decode消耗的内存。

通过分析请求响应日记，发现进程kill掉的时间附近，有几个请求没有响应，通过模拟复现请求，发现其中一个请求最为耗时（xxx_290x290.jpg）。原图大小为5MB，单个请求耗时超8秒。

模拟并发几个请求后，有些请求502，并发现挂了两个节点。如果并发量超过20个，所有节点就都会同一时间挂掉。

此时问题已经找到。