记一次由日志引起的停服事故

12月28号1上午10点，所在项目停服了半个小时。期间有在推一个红包活动。根据jstack查看堆栈日志，发现是Log4j纪录日志时发生线程阻塞，如下图所示。

线程堆栈信息

赶紧去扒拉代码，发现红包活动代码里有记录接口调用时长操作。但这是正常的日志记录，怎么会引起线程阻塞呢？

去网上一查，好多有类似的案例，看来是共性问题。

原来，log4j在写入日志文件时，为了保证写入顺序，会对资源加锁。在高并发的场景下，多个线程会竞争资源，从而导致线程阻塞。

那如何解决呢？

1.日志格式要规范，去除不必要的写日志操作，只在关键部位添加日志（输入、输出参数、异常捕获等）

2.生产环境日志级别要调到最高，一般是开启info级别

3.日志框架更换，可采用logback、log4j2来替换log4j1.x

另外，在排查过程中，发现 System.currentTimeMillis()这个操作也是比较消耗性能的。