学习

GO的调优之实战pprof性能调优（二）

排查协程泄露 由于 golang 自带内存回收，所以一般不会发生内存泄露。但凡事都有例外，在 golang 中，协程本身是可能泄露的，或者叫协程失控，进而导致内存泄露。 我们在浏览器里可以看到，此时程序的协程数已经多达 106 条： 虽然 106 条并不算多，但对于这样一个小程序来说，似乎还是不正常

排查协程泄露

由于 golang 自带内存回收，所以一般不会发生内存泄露。但凡事都有例外，在 golang 中，协程本身是可能泄露的，或者叫协程失控，进而导致内存泄露。

我们在浏览器里可以看到，此时程序的协程数已经多达 106 条：

虽然 106 条并不算多，但对于这样一个小程序来说，似乎还是不正常的。为求安心，我们再次是用 pprof 来排查一下：

go tool pprof http://localhost:6060/debug/pprof/goroutine

Untitled.png

可以看到有93次gopark，似乎都是Drink方法调用出来的

Untitled.png

可能这次问题藏得比较隐晦，但仔细观察还是不难发现，问题在于 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink 在不停地创建没有实际作用的协程：

func (w *Wolf)Drink() {
	log.Println(w.Name(), "drink")
for i := 0; i < 10; i++ {
gofunc() {
			time.Sleep(30 * time.Second)
		}()
	}
}

删除后变正常：

Untitled.png

排查锁的争用

到目前为止，我们已经解决这个炸弹程序的所有资源占用问题，但是事情还没有完，我们需要进一步排查那些会导致程序运行慢的性能问题，这些问题可能并不会导致资源占用，但会让程序效率低下，这同样是高性能程序所忌讳的。

我们首先想到的就是程序中是否有不合理的锁的争用，我们倒一倒，回头看看上一张图，虽然协程数已经降到 4 条，但还显示有一个 mutex 存在争用问题。

相信到这里，你已经触类旁通了，无需多言，开整。

go tool pprof http://localhost:6060/debug/pprof/mutex

同样是 top、list、web 大法：

Untitled.png

Untitled.png

可以看出来这问题出在 github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl。但要知道，在代码中使用锁是无可非议的，并不是所有的锁都会被标记有问题，我们看看这个有问题的锁那儿触雷了。

func (w *Wolf)Howl() {
	log.Println(w.Name(), "howl")

	m := &sync.Mutex{}
	m.Lock()
gofunc() {
		time.Sleep(time.Second)
		m.Unlock()
	}()
	m.Lock()
}

可以看到，这个锁由主协程 Lock，并启动子协程去 Unlock，主协程会阻塞在第二次 Lock 这儿等待子协程完成任务，但由于子协程足足睡眠了一秒，导致主协程等待这个锁释放足足等了一秒钟。虽然这可能是实际的业务需要，逻辑上说得通，并不一定真的是性能瓶颈，但既然它出现在我写的“炸弹”里，就肯定不是什么“业务需要”啦。

所以，我们注释掉这段问题代码，重新编译执行，继续。

只是删除掉了time.Sleep ，可以看到锁的竞争总时间变到微妙级别

Untitled.png

排查阻塞操作

好了，我们开始排查最后一个问题。

在程序中，除了锁的争用会导致阻塞之外，很多逻辑都会导致阻塞。

d830dc8a7323e7106d05857e97ceed34541212f47cb30071fe4a67ff8ab15aeb.jpg

可以看到，这里仍有 2 个阻塞操作，虽然不一定是有问题的，但我们保证程序性能，我们还是要老老实实排查确认一下才对。

go tool pprof http://localhost:6060/debug/pprof/block

Untitled.png

可以看到，阻塞操作位于 github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee：

func (c *Cat)Pee() {
	log.Println(c.Name(), "pee")

	<-time.After(time.Second)
}

你应该可以看懂，不同于睡眠一秒，这里是从一个 channel 里读数据时，发生了阻塞，直到这个 channel 在一秒后才有数据读出，这就导致程序阻塞了一秒而非睡眠了一秒。

这里有个疑点，就是上文中是可以看到有两个阻塞操作的，但这里只排查出了一个，我没有找到其准确原因，但怀疑另一个阻塞操作是程序监听端口提供 porof 查询时，涉及到 IO 操作发生了阻塞，即阻塞在对 HTTP 端口的监听上，但我没有进一步考证。

Comment