线上日志写磁盘延时问题

前言

线上环境,在高并发场景遇到日志写本地磁盘延迟的情况。例如当前时间17:00,日志最近一条记录是14:00,延迟多个小时,但是日志数量不会发生丢失。且发现内存占用达到10几G,比其他正常机器高出很多倍。

过程

应用程序在内存中维护一个队列,当用户请求到达,产生用户日志的时候,会将用户日志入队列。同时应用会启一个异步线程,不断的轮询队列,将队列的队头元素出队列,调用IO函数写入磁盘。

改造前
1
2
3
4
5
6
7
8
9
public class AsyncThread{
public void doWork(){
while(queue.Count>0){
String log = queue.dequeue();
IOUtil.WriteLine(log);
IOUtil.flush();
}
}
}

分析

通过JMeter在本地环境模拟高并发情况,复现了该问题。仔细分析原因,发现问题出在异步线程轮训的过程中,会不断调用IO函数,而该IO函数会调用flush刷新缓冲区数据,且每次都只有队头元素这一个日志写入磁盘,这就导致了频繁的上下文切换,设置的缓冲区无效,每次只有一行日志写入缓冲区,并flush刷入磁盘。使得日志入队列的速度远远大于日志写入磁盘的速度。日志不断的在队列中积压,这就导致了机器内存的不断上升。

解决

异步线程在轮训的过程中,每次都将队列所有元素取出,然后再调用IO函数进行日志写入。该线上问题,也说明CPU的上下文切换是非常耗时的,IO缓冲区的存在也是非常有必要的。

改造后
1
2
3
4
5
6
7
8
9
public class AsyncThread{
public void doWork(){
while(queue.Count>0){
String log = queue.dequeue();
IOUtil.WriteLine(log);
}
IOUtil.flush();
}
}