• 发现问题
• 初步评估
• 再次分析
• 深入分析
• 解决问题

发现问题

业务压测过程中发现，服务空闲时cpu使用率保持在10%左右，没有按预期的降为约0%。下面记录笔者使用伽利略和Go提供的监控工具，对这个问题进行debug排查的过程。

初步评估

空闲时cpu使用率不为0的常见原因是没有退出的for循环，导致cpu被一直占用。容器规格是8核，10%的cpu使用率刚好约等于1个cpu核被占满。为了定位是哪部分代码逻辑使用了没有退出的for循环，可以使用火焰图分析cpu执行堆栈。结果表明，没有业务代码占用cpu，占用cpu的只有两块，一是消息队列的event循环，二是go runtime的调度。这两块似乎都是正常的逻辑，那么会导致为何cpu占用率居高不下呢？

再次分析

经查go火焰图说明，存在未退出的for循环的猜测是错误的。但是也有新的发现，go runtime的schedule占用了大部分的cpu时间，这可能说明当前Go程序存在大量goroutine。查看go协程数，果然如此。

其中，11:40时协程数陡增到10k并基本保持不变，与11:40之后cpu使用率保持在10以上对应上了。那么，基本可以确定，是因为因为协程过多且一直没有被释放，go runtime调度时占用了一部分cpu。

深入分析

为了确定大量协程是如何产生出来的，则需要使用到Go提供的pprof工具。结果出乎意料，与github.com/apache/pulsar-client-go包相关的goroutine占了绝大部分。进一步分析相关堆栈后发现，大部分协程都是生产者的协程，阻塞在生产者的event loop中。这也与前面的火焰图形成了印证。笔者分析包中的调用关系发现，调用CreateProducer方法是构造生产者并执行event loop的唯一方法，而该方法的唯一调用方是笔者使用的该sdk的封装库，该库执行获取生产者的逻辑可以简化如下。 1.尝试从缓存获取； 2.调用pulsar-client-go提供的CreateProducer方法获取生产者； 3.将生产者保存在缓存。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20

// ClientTransport 客户端传输结构
type ClientTransport struct {
    producers sync.Map
}

// GetProducer 获取生产者
func (ct *ClientTransport) GetProducer(address string) (*Producer, error) {
    // 1.尝试从缓存获取producer
    value, ok := ct.producers.Load(address)
    if ok {
        return value.(*Producer), nil
    }
    
    // 2.调用pulsar-client-go提供的CreateProducer方法获取生产者
    producer := pulsar-client-go.CreateProducer()
    
    // 3.将生产者保存在缓存
    ct.producers.Store(address, producer)
    return producer, nil
} 

解决问题

定位到这部分代码后，问题则很明显了。生产者没有缓存时，并发地获取生产者，将导致并发地请求CreateProducer方法，获取到很多的生产者，这些生产者都将阻塞在event loop循环中，导致goroutine无法被释放。 这个问题与缓存击穿类似，都是在缓存不存在时，大量请求穿透到下层。不同的是，缓存击穿往往导致下游crash，而这里则导致本地过多goroutine无法被释放。解决方案既然明确了问题，那么解决方案则很明显了。只需要在调用CreateProducer方法时，保证同时只允许调用一次即可。使用singleflight包保证CreateProducer方法只调用一次，类似问题不再出现。