12月28号1上午10点,所在项目停服了半个小时。期间有在推一个红包活动。根据jstack查看堆栈日志,发现是Log4j纪录日志时发生线程阻塞,如下图所示。
赶紧去扒拉代码,发现红包活动代码里有记录接口调用时长操作。但这是正常的日志记录,怎么会引起线程阻塞呢?
去网上一查,好多有类似的案例,看来是共性问题。
原来,log4j在写入日志文件时,为了保证写入顺序,会对资源加锁。在高并发的场景下,多个线程会竞争资源,从而导致线程阻塞。
那如何解决呢?
1.日志格式要规范,去除不必要的写日志操作,只在关键部位添加日志(输入、输出参数、异常捕获等)
2.生产环境日志级别要调到最高,一般是开启info级别
3.日志框架更换,可采用logback、log4j2来替换log4j1.x
另外,在排查过程中,发现 System.currentTimeMillis()这个操作也是比较消耗性能的。