一次排查服务在磁盘满时内存不断上涨问题的过程

之前mentor就提过检索服务在磁盘满时内存占用会不断上涨，想复现一下排查一下问题，但是磁盘满这个条件一直很难满足，毕竟开发机不是我一个人在用，刚好昨天发现开发机磁盘满了，就做了一下实验，排查了一下原因，记录一下过程，考虑到数据安全问题，这里去掉了具体的数据结果，只对最后的结果进行说明

背景

• 检索服务在磁盘满时内存会不断上涨，需要排查一下原因，猜测可能与日志有关

实验设计

方案设计

• 设置A、B、C三组实验：
  • A组为磁盘满，打开日志功能，100qps，压测15分钟，记录内存和cpu的变化情况
  • B组为磁盘满，关闭日志功能，100qps，压测15分钟，记录内存和cpu的变化情况
  • C组为磁盘空间足够，打开日志功能，100qps，压测15分钟，记录内存和cpu变化情况
• 其中A组主要是为了复现问题，B组和C组为对照组，其中C组为正常环境，通过对比三组之间的结果，可以得出磁盘满时是否会出现内存占用过高的问题，并且判断其是否与日志有关

实验数据

• 由于数据安全问题，具体的实验数据就不进行展示，只说大体的结论

内存变化

• 在三组中，A组的内存占用会不断上涨，并且在15分钟时占用是B组和C组的几倍，而B组和C组的内存占用基本一致，维持在一个水平，波动不明显

CPU变化

• 在三组中，A组的CPU占用一致维持着一个较低的水平，而B组和C组的CPU占用则基本一致，维持在A组CPU占用的6～7倍的水平，且波动不明显

GC信息

• 在上述实验完毕后，可以得知A组的实验结果与B组以及C组有较大的差异，且B组和C组的实验结果基本一致，为什么会出现这个问题呢，下面结合GC信息来进行分析，使用GODEBUG=gctrace=1 ./xxxxx来启动服务，就可以打印出gc信息
• 分析gc的结果，A组在15分钟的压测过程中只进行了15次gc，而B组为1300多次，C组为1400多次，基本一致，考虑到gc会额外占用cpu时间，所以B组和C组的cpu占用高于A组是正常的

分析

基本分析

• 那么为什么A组的gc次数如此之少呢？下面可以结合压测报告来进行分析，压测结果中，B组和C组的平响、P50、P75、P95、P99基本一致，但是A组的请求基本都超时了，猜测可能是由于请求均超时，也就是一条请求处理的时间过长，导致请求的生命周期没有结束，导致计算的中间结果无法被gc，所以gc次数很少，并且内存占用很高，但是为什么请求的处理时间会过长呢？为什么去掉日志就可以正常处理请求呢？

深入分析

• 通过pprof工具进行分析，首先将磁盘占满，创建大文件的方式可以使用fallocate -l 50G text.txt这种方式，开启日志，并且启动检索服务，发送一条请求，发现没有响应，首先分析seelog的源码，seelog就是检索服务使用的日志库

1. 检索服务在初始化日志对象时，实际上调用的是下面的方法，省去了部分内容，实际上当日志类型没有定义的时候，使用的就是asyncLooploggerTypeFromString类型的日志对象，

   func createLoggerFromFullConfig(config *configForParsing) (LoggerInterface, error) {
   	if config.LogType == syncloggerTypeFromString {
   		return NewSyncLogger(&config.logConfig), nil
   	} else if config.LogType == asyncLooploggerTypeFromString {
   		return NewAsyncLoopLogger(&config.logConfig), nil
   	} else if config.LogType == asyncTimerloggerTypeFromString {
           ...
   		return logger, nil
   	} else if config.LogType == adaptiveLoggerTypeFromString {
           ...
   		return logger, nil
   	}
   	return nil, errors.New("invalid config log type/data")
   }

2. 那么会走到下面的方法，创建asyncLoopLogger对象，这个对象内部其实包含了一个asyncLogger对象，可以看到asyncLogger对象内部持有一个双向链表，并且有一个锁。

   func NewAsyncLoopLogger(config *logConfig) *asyncLoopLogger {
   	asnLoopLogger := new(asyncLoopLogger)
   	asnLoopLogger.asyncLogger = *newAsyncLogger(config)
   	go asnLoopLogger.processQueue()
   	return asnLoopLogger
   }
   
   type asyncLoopLogger struct {
   	asyncLogger
   }
   
   type asyncLogger struct {
   	commonLogger
   	msgQueue         *list.List
   	queueHasElements *sync.Cond
   }

3. 上述在实例化asyncLoopLogger对象时，可以看到是启动了一个协程，不断执行下面的任务，实际上就是当日志打印未关闭时会不断进行processItem()操作，在这个方法里首先会去抢asnLoopLogger.queueHasElements.L的锁，注意这把锁其实就是内部持有的asyncLogger的queueHasElements.L锁

   func (asnLoopLogger *asyncLoopLogger) processQueue() {
   	for !asnLoopLogger.Closed() {
   		closed := asnLoopLogger.processItem()
   		if closed {
   			break
   		}
   	}
   }
   
   func (asnLoopLogger *asyncLoopLogger) processItem() (closed bool) {
   	asnLoopLogger.queueHasElements.L.Lock()
   	defer asnLoopLogger.queueHasElements.L.Unlock()
   	for asnLoopLogger.msgQueue.Len() == 0 && !asnLoopLogger.Closed() {
   		asnLoopLogger.queueHasElements.Wait()
   	}
   	if asnLoopLogger.Closed() {
   		return true
   	}
   	asnLoopLogger.processQueueElement()
   	return false
   }

4. 在打印日志时，实际上不论什么类型的日志，最终都会走到下面的log方法中，在log方法中，首先会去抢cLogger.m锁，这个锁是互斥锁，那么如果多个协程并行请求这个方法，最终会是串行执行的

   func (cLogger *commonLogger) log(level LogLevel, message fmt.Stringer, stackCallDepth int) {
   	if cLogger.unusedLevels[level] {
   		return
   	}
   	cLogger.m.Lock()
   	defer cLogger.m.Unlock()
   	if cLogger.Closed() {
   		return
   	}
   	context, _ := specifyContext(stackCallDepth+cLogger.addStackDepth, cLogger.customContext)
   	cLogger.innerLogger.innerLog(level, context, message)
   }

5. 如果成功抢到锁，会进入到下面方法中，向链表中添加日志，在第6行可以看到，首先会进行抢asnLogger.queueHasElements.L的操作，注意这把锁和上面写日志的协程需要抢的锁其实是同一把，所以这个链表的读写是完全互斥的

   func (asnLogger *asyncLogger) addMsgToQueue(
   	level LogLevel,
   	context LogContextInterface,
   	message fmt.Stringer) {
   	if !asnLogger.Closed() {
   		asnLogger.queueHasElements.L.Lock()
   		defer asnLogger.queueHasElements.L.Unlock()
   		if asnLogger.msgQueue.Len() >= MaxQueueSize {
   			fmt.Printf("Seelog queue overflow: more than %v messages in the queue. Flushing.\n", MaxQueueSize)
   			asnLogger.flushQueue(false)
   		}
   		queueItem := msgQueueItem{level, context, message}
   		asnLogger.msgQueue.PushBack(queueItem)
   		asnLogger.queueHasElements.Broadcast()
   	} else {
   		err := fmt.Errorf("queue closed! Cannot process element: %d %#v", level, message)
   		reportInternalError(err)
   	}
   }

• 根据上述分析，理论上
  • 应该有一个协程A，来不断读取链表中的日志，并执行write系统调用
  • 应该有一个协程B，抢到了log方法中的cLogger.m锁，并与上述协程，两个协程中有一个阻塞在抢asnLogger.queueHasElements.L锁处，有一个可以往下执行
  • 应该有大于等于一个协程C，阻塞在log方法中的cLogger.m锁处
• 接下来使用pprof工具查看协程信息，go tool pprof http://[ip]:[port]/debug/pprof/goroutines，这里具体的截图就不进行展示，结论是验证了上述的推论，其中，协程A在执行write系统调用，协程B阻塞在抢asnLogger.queueHasElements.L锁处，有多个协程C阻塞在log方法中的抢cLogger.m锁处
• 通过上述的分析以及实验，可以得知seelog日志库的性能是比较差的，全库使用的都是互斥锁，对比来看，项目中使用的另一个集团的日志库使用的就是cas操作，大部分情况下省去了上下文切换的开销，以及在链表方面，可以参考多维数组的方式，采用多维链表的形式，让锁的粒度更小，让同时能进入写链表的协程更多，这是一些可能的优化方案，seelog库在github上最后一次版本更新已经是2015年，年代太过久远
• 理论上日志库性能较低，那么当请求大量到来时，可能会产生大量协程阻塞，接下来还是使用pprof工具进行分析：
  • 在A组，压测10分钟时，使用pprof查看协程信息，可以看到确实有68000多个协程阻塞，查看其细节信息，有64000多个协程都是阻塞在调用seelog的log方法中，抢cLogger.m锁的过程产生了阻塞，这些协程实际上都是请求产生的，请求被阻塞，自然无法正常响应。这里还有4000多个协程被阻塞，实际上是调用了集团的另一个日志库，用cron启动了后台任务，会定期新开协程去执行一些统计的任务，这些协程和请求无关，所以不会阻塞请求，但是它们也和seelog库一样被阻塞了
  • 对比C组对照组，压测10分钟时使用pprof查看协程信息，可以发现协程的数量是非常少的，只有几百个，其中处于阻塞中的只有300多个
• 那么为什么内存会不断上涨呢？一方面是协程的不断增加，另一方面是协程阻塞在打印日志处，导致请求的中间计算结果无法被gc回收，随着请求的增多，内存也会不断上涨
• 通过上述分析得知，是由于seelog库的性能下降，导致请求被阻塞，大量请求堆积，导致中间计算结果无法被释放，导致内存不断上涨，并且随着请求到来协程的数量也不断增多，锁竞争加剧，也加剧了这一现象。那么最后一个问题是：为什么磁盘满会导致seelog库的性能下降呢？
  • 事实上，磁盘满不仅仅对于seelog库的性能有较大影响，对于检索服务中使用的集团的另一个日志库也有着较大的影响，在B组中，关掉seelog库的日志服务，虽然服务的平响以及内存和cpu不会产生什么明显的变化，但是实际上检索服务中的cron任务会定时启动新的协程，去执行一些任务，而这些任务和请求无关，所以不会阻塞请求，不会导致明显的内存上涨，不会影响平响，但是阻塞的协程数仍然是会不断上涨的，只不过这个周期是比较长的
  • 所以根本原因在于：在正常情况下，执行write系统调用是非常快的，write系统调用正常只会将待写入的内容写入page cache，但是当执行write系统调用时发现page cache内容过多，就会阻塞write调用，将page cache的内容进行刷盘，但是此时磁盘是满的，没有多余空间可供写入，再回到write调用，返回错误信息，由于刷盘不成功，每次write调用都会进行此过程，大大加长了调用的时间。使用strace对比一下磁盘满时和不满时执行系统调用所花费的时间，可以发现磁盘满时，执行futex和write调用，10000多次的耗时达到了8秒和6秒，而正常情况下，同样的执行次数，耗时是毫秒级。

结论

• 磁盘满时，由于write系统调用耗时增长，随着请求的协程增多，打印日志的请求会不断增多，锁竞争会加剧，导致请求执行缓慢，导致中间计算结果无法被gc回收，最终导致内存不断上涨
• 可能的解决方案：
  • 磁盘容量报警，不允许磁盘满
  • 服务使用请求级的超时控制，一旦超时立即快速降级，并且释放资源
• 更换日志库应该解决不了问题，因为这是系统级的问题，可能会像另一个日志库一样，内存和cpu没变化，但是协程会不断增多，问题暴露出来的时间会加长