如何优雅的打日志 – optimal-logging

发件人:                           Ma,Guannan
发送时间:                       2014年3月9日星期日 21:40
收件人:                           Ma,Guannan
主题:                               优雅的打日志
作者:Anthony Vallone 翻译: 马冠南
在你的系统故障后,一般需要多久才能找到根本原因? 5分钟? 5天? 如果你的回答是[接近五分钟]。可能你的系统有非常棒的Log输出(机制)。太多时候,这些看起来不是特别重要的处理逻辑如Log输出、Exception处理、测试点等内容都是人们事后才加入的。永远不要低估logging的作用。一个好的日志logging机制可以使调试者需要更少的相关信息来做debug工作。
以下是数年来对我很有帮助的一些方法:
梳理你那不温不火的日志吧:
不要打印太多(无用信息)。
大量的、(打印速度)能让硬盘着火的打印方式说明你没怎么在日志打印上花精力。如果你大量打印, 需要考虑怎么去减少硬盘存取、维护历史日志文件、将他们归档、并且对它们做查询和信息收集。 更重要的是,事后你会发现这些大量打印的无聊东东会让你很难收集到有价值的信息。信息量太大且无用了。
同样,也不要吝啬你的打印语句。
一般情况下,打印日志是为了找到系统的bug或者复现某个问题、或者对某件事情做确认。如果你的日志不能帮你找到bug的原因或者不能帮你确认某件事情确实发生了, 你就需要多打印一些,兄弟,不要太吝啬你的硬盘。
一些适合打印的东西:
·         [启动阶段] 关键的配置参数
·         [运行阶段] Error级别信息
·         [运行阶段] Warning级别信息
·         [运行阶段] 对持久化的信息做了新增或者改动
·         [运行阶段] 重要的状态变更
·         [逻辑处理] 对系统非常重要的分支被触发, 可能是逻辑上或者某个等待事件方面比较重要的分支.
·         [逻辑处理] 长时间运行的逻辑中周期性处理的部分被触发和完成时
·         [逻辑处理] 在上层函数中做言简意赅的日志打印,反应目前的处理逻辑进行到哪一步了.
·         [资源竞争] 某个可能比较耗时的条件的wait操作将被触发
·         [用户交互] 用户操作
·         [已知风险] 监测到已知风险被触及
一些不适合打印的东西如下:
·         [内部逻辑] 不要打印函数的入口 = = 除非她十分的重要, 或者在DEBUG level去打印她。
·         [数据记录] 不要打印for while循环内的数据记录 = = 尽量避免打印一个数据比较多的循环内的数据。 可以在上层的大循环中打印。非常重要且数据量小的可以尝试打印。
·         [异常处理] 巨大的信息、或者文件类。 可以用某种方法把她们做归类、聚合,总结性的打印日志
·         [异常处理] 良性、可被正确处理的错误。该类错误可能对日志阅读者产生困惑。可以用DEBUG level的方式打印她。
·         [异常处理] 重复性的错误日志。不要重复的打印相同、相近的日志。 这样打印会很快的充满你的日志、掩盖真正的错误原因。通过打印一条然后标定他的出现次数是个不错的选择。选择有特殊需要和目的的地方进行细致的打印。
使用多种日志打印级别
不要把所有东西没有区分的打印在同一个层次里面. 最好划分几个层次. 一般的log库都提供数个日志Level.你可以在启动阶段使用其中的几个level. 这能很好的控制日志的详细程度。
经典的几个日志Level有:
·         Debug – 非常详细的打印level、一般只在开发或者调试阶段才会打开这个level.
·         Info – 最受欢迎的level, 一般生产环境都设置成Info Level.
·         Warning – 奇怪或者异常的情况发生时的打印level, 这类日志表明出现了一定问题, 但一般不影响系统的使用。
·         Error – 发生了错误, 但是系统、进程可以恢复。
·         Critical – 发生了重大问题。一般系统、进程等受到影响会死掉、重启或者被关闭。
从实践的经验来看,一般两个日志配置项是需要的。
·         生产环境  – 除了Debug level之外,其他的层次都是需要的。 这种情况下, 一旦发生了错误,一般日志能很好的找到错误原因。
·         开发、调试环境- 在开发新的feature或者模块或者需要复现比较难的生产环境问题时候, 会激活所有的日志level.
测试程序的日志是同等重要的
    打印日志的质量在生产环境和测试环境是同等重要的。如果在测试环境中,某个测试用例失败了。测试code中打印的日志应该能清晰的反映出这次失败  – – 是用例错误导致的失败、还是被测的程序确实产生了问题。如果反映不出,则这个日志打印规则与生产环境是不统一的,需要调整。
测试日志应该包含:
·         测试执行时的环境信息
·         初始状态
·         程序setup内容
·         测试中的关键步骤的checkpoint点
·         与被测系统的交互
·         测试用例的期望结果 – 若出错,一并打印实际的结果
·         环境清除内容和执行结果
提供动态的日志Level的激活和关闭 (比如设定条件触发)
    当生产环境发生问题时候,很明显, 大家一般会去聚焦在查找问题、解决问题。但与此同时,请应该把log也考虑进来。如果你发现,诶,这次很难发现这个问题的原因,你就赚到了。这是一个改善你的日志打印的机会。在fix你的bug或者问题之前,先优化下你的日志,让她下一次在问题发生后能很好、很简单的展示错误发生的原因。
如果你不能复现这个问题或者这是个不稳定的问题,优化这个log直到当再次发现问题时能很好的帮助debugger追踪到问题。
在整个开发过程中,用终止进程(abort程序)的方式来改善日志打印方式。当撰写新的代码的时候,应该牢记尽量避免后面来进行人工调试,应该尽量使用log来查找问题。也要常记着思考,这些log能有效的记录现在系统发生了什么?如果不能,说明日志打印不够充分。
性能数据相关log也应该打印
打印性能数据能很好的帮助debug性能相关的问题。举个例子,在一个大型系统中,一般很难发现某个动作、命令timeout的原因,除非你在每一个很重要的时间点上做了日志log追踪和打印。这种日志优化可以通过打印耗时的处理逻辑的入口和出口来实现,比如:
·         重要的系统调用
·         网络请求处理
·         CPU密集型的处理逻辑
·         已链接的设备、模块的互动操作
·         事务等
多进程、多线程执行中记录事务的踪迹
    我们应该为可能被多个进程、线程处理的事务创建唯一的标识码。可以在事务的初始阶段创建,并传递给每一个事务的处理逻辑。这个唯一的标识码应该被每个处理逻辑在打印日志的时候包含, 这样在系统并行的处理多个事务的时候可以很方便快捷的找到你需要找的那一个。
打印日志并监控你的系统模块
    一个生产环境需要既有日志模块又有监控模块。监控能够提供实时的系统状态汇总。她能在系统出现错误、不寻常的网络请求、持续下降的性能等问题时候提醒你。在某些案例当中,这些信息能够帮助你找到问题的真正原因。不过有意思的是,可能一般情况下监控模块的提醒是你开始介入调查的开始。监控告诉你系统里发生了某些异常,日志打印模块告诉你哪些事务、事件等发生了,从而帮助你了解究竟发生了什么,哪些才是发生这些事情的真正原因。

Leave a Reply

Your email address will not be published. Required fields are marked *