日志乱了,问题就藏得更深
前两天同事老李值班,半夜三点被报警叫醒。服务挂了,查日志的时候发现一堆乱码似的输出,时间戳错乱,不同请求的日志混在一起,像极了一锅炖乱的方便面。最后定位下来,不是业务逻辑的问题,而是多个线程同时写日志,没做同步处理。
这种场景在高并发服务里太常见了。用户下单、支付回调、库存扣减,每个动作都在独立线程跑,都往同一个日志文件里写。要是不加控制,轻则日志看不懂,重则文件损坏,排查问题全靠猜。
为什么普通日志打印会出事
假设你用的是最简单的 printf 或 System.out.println,在单线程下没问题。但一旦多个线程同时调用,操作系统对文件写入的调度是不可预测的。线程 A 写到一半被切出去,线程 B 接着写,结果两段日志粘在一起,谁也看不明白。
更麻烦的是,有些日志库内部用了缓冲区,多个线程共用一个 buffer,没加锁的话,可能还会出现内存访问冲突,直接导致程序崩溃。
怎么做才是线程安全的
核心思路就一个:保证同一时刻只有一个线程能写日志。最直接的办法是加锁。比如用互斥锁(mutex)把写文件的操作包起来。
pthread_mutex_t log_mutex = PTHREAD_MUTEX_INITIALIZER;;
void safe_log(const char* msg) {
pthread_mutex_lock(&log_mutex);
fprintf(log_file, "%s\n", msg);
pthread_mutex_unlock(&log_mutex);
}每次写日志前先抢锁,写完释放。虽然会有一点性能损耗,但在大多数场景下可以接受。毕竟看不清日志带来的排查成本,远比这点锁开销高得多。
用现成的日志库更省心
自己实现容易出错,推荐直接上成熟的日志框架。比如 C++ 里的 spdlog,Java 里的 Logback 或 Log4j2,这些库默认就是线程安全的。它们底层用了队列 + 单独写线程的模式,应用线程只负责把日志消息丢进队列,真正写文件的工作由一个专用线程完成。
# Python 示例:使用 logging 模块自带锁
import logging
from threading import Thread
logging.basicConfig(level=logging.INFO)
def worker():
for i in range(5):
logging.info(f"Worker running: {i}")
for _ in range(3):
Thread(target=worker).start()上面这段代码即使启动多个线程,日志也不会交错。因为 Python 的 logging 模块在 handler 上默认加了锁。
别忘了异步日志这个选项
如果对性能要求特别高,比如每秒几万条日志,同步写磁盘会成为瓶颈。这时候可以考虑异步日志。原理是把日志消息扔进无锁队列,后台有一个专门的线程负责消费并写入文件。
像 C++ 的 spdlog 提供了 async logger:
auto async_logger = spdlog::basic_logger_mt<spdlog::async_factory>("async", "logs/async.txt");
async_logger->info("This is an async log message");这种方式既保证了线程安全,又避免了频繁 IO 阻塞业务线程。
线上服务稳不稳定,很多时候就看细节做得到不到位。日志看着不起眼,真出问题时它就是你的第一双眼睛。别让本该帮你的人,变成了添乱的。”}