问题出现
近期,我们对项目中的一个子功能进行了重构,该功能涉及多个子流程的串行执行。
在测试阶段,我们注意到当此子功能运行时,其他API调用出现了无响应的情况。进一步分析日志文件后,发现其中一个子流程输出了大量的日志,导致整体系统性能下降。
日志库使用的是:zap。
那么产生以下几个疑问?
- 为什么日志量大会导致程序性能下降?
- zap在写日志文件时,如何执行的?
- 针对这种问题,我们该如何处理?
zap源码分析
程序中通常会使用lumberjack+zap库结合使用。lumberjack用于对日志进行轮转归档, 防止日志文件过大,造成排查时无法打开的情况。
画板
从代码逻辑我们可以看出:
日志输出过程中,由于是并发写操作,不同的输出Core会调用不同的内部所机制;如:
- IoCore调用mutex.Lock(),输出到/dec/stdout中。
- lumberjack调用标准库中File.Write,获取到文件写锁,进一步用过系统调用将内容写入到磁盘中。
到这里,为什么日志的阻塞点已经排查清楚。
那么为什么是性能下降, 而不是程序整体阻塞呢?
在golang中,API请求进入后,golang会创建不同的go协程进行处理,如果有些API接口中如果不涉及到日志的编写,那么就不会被阻塞住。
测试代码参考:github.com/toheart/gol…
解决方案
面对上面这个问题,直接将日志中输出的内容删除即可。
思考如何优化
在一般情况下,日志输出所带来的性能消耗还是能够接受的。那,硬要提高程序性能,该如何处理呢?
当前的问题,主要的冲突点在于 并发多写,针对这种问题,往往有以下解决办法:
- 异步写入:通过异步线程进行写入;
- 减少锁冲突:将不同的处理,写入到不同的日志中,降低锁冲突。
- 批量处理: 日志毕竟要保存到磁盘文件中,往往需要通过系统调用,所以将多条日志保存到内存中,批量写入到日志文件中。
异步并发写入测试
这里直接引入 vearne.cc/archives/39… 文章中的测试代码,从结果来有效果。
在文章中给出的为lumberjack文件写入的异步批量写入操作,而在云原生的场景下,日志往往需要标准输出,所以
总结
日志记录是软件开发和维护过程中极其重要的一个环节,它对于问题的排查、系统的监控以及性能分析等方面都有着不可替代的作用。良好的日志打印输出规范不仅能够帮助开发者更高效地定位问题所在,还能为后续的系统优化提供宝贵的数据支持。因此,在项目正式启动之前,团队应该花时间讨论并确立一套适用于整个项目的日志记录标准。这套标准应当涵盖但不限于以下几个方面:
- 日志级别定义:明确不同情况下应使用何种级别的日志(如DEBUG, INFO, WARN, ERROR等),以确保信息量适中而不至于造成日志文件过于庞大或遗漏关键信息。
- 格式统一:所有日志条目都应该遵循相同的格式,包括时间戳、TraceId、类名及方法名等基本信息,这样可以方便地通过工具进行解析与过滤。
- 敏感信息处理:严禁将密码、用户私密数据等敏感信息直接写入日志;若不可避免需要记录,则必须采取加密或其他保护措施。
- 异常捕获与记录:当程序发生异常时,除了记录错误消息外,还应该尽可能多地收集堆栈跟踪信息,以便于快速定位故障原因。
- 定期审查机制:在代码审查阶段,不仅要检查功能实现是否正确,同时也要验证其日志记录部分是否符合既定规范,并满足安全性要求。
此外,随着项目的发展,原有的日志规范可能不再完全适用,此时就需要根据实际情况作出相应的调整。