#意识
ASAP (As Soon As Possible)原则
当线上出现诡异问题,
当你意识到靠现有的日志无法定位问题时,
当现象难以在你的开发环境重现时,
请不要执著于枯坐肉眼看代码,
因为:
一)不一定是你代码逻辑问题,可能是脏数据造成的,是老业务数据造成的,是分布式环境造成的,是其他子系统造成的;
二)线上业务处于不稳定中,条件不允许问题定位无限期。
此时,请立即在问题相关的调用链条上,一次性:
在函数的入口和出口打印日志,同时打印输入、输出参数catch(){……}里打印stacktrace,同时打印try块中关键变量的值(避免你发现某个异常是问题第一原因,却不知道是什么变量传入导致的)
与其他模块交互的接口入口处打印输入参数,即,解决线上问题归根结底要靠log、a lot of log output!
在logging的力度上切勿犹犹豫豫,我们的工程师习惯于吝啬地找两个函数打印日志、打包部署一把、没看出来、再找几个函数打印、再部署、等着现象重现再观察、……,一来二去时间流逝,闲庭信步,从客服知道的小事故变成了全国皆知的大事故。
所以,再强调一遍:在你的调用链条上,逐层调用的函数入口和出口都打印详细日志,不怕多只怕少,然后部署,等待现象重现,毕其功于一役!
#工具
推荐的Java Logging框架
1)log4j:我们的配置是,
log4j.appender.CONSOLE.layout.ConversionPattern=[%-d{yyyy-MM-dd HH:mm:ss.SSS}] [%p] [%c] [%m]%n;
%p是日志优先级,%c是类目名,%m是输出信息,%n是回车换行符。
2)logback:log4j创建人Ceki Gülcü后续推出了SLF4J+logback。SLF4J(Simple Logging Facade for Java)作为commons-logging的替代,为各种logging APIs提供了一个简单的统一接口,使得最终用户能够在部署的时候配置所希望的logging APIs的实现。logback胜在性能,据称“某些关键操作,比如判定是否记录一条日志语句的操作,其性能得到了显著的提高。这个操作在logback中需要3纳秒,而在 log4j 中则需要30纳 秒。 logback 创建记录器(logger)的速度也更快:13毫秒,而在 log4j 中需要23毫秒。更重要的是,它获取已存在的记录器只需94纳秒, 而 log4j 需要2234纳秒,时间减少到了1/23。跟java.util.logging(JUL)相比性能提高也是显著的”。
#配置
不要随便从网上找一个log4j的配置文件,请确认你理解每一个配置项
我们既然输出日志,自然期望在面对“这个问题是否从过去几天开始出现?”这样的疑问时,不至于发现你的rollingPolicy错误设置导致只能看到最近几小时的日志,或者日志发生时间没有精确到毫秒。
当访问和调用极其频繁,有时候你会发现把你的工程里什么信息都打印到一个日志文件里,会让你看得头昏脑胀。
最简单的示范就是Apache的访问日志和错误日志是分开的。
同样,你也可以把更加安静的事件(偶尔出现)与更加喧闹的事件分开存储。
如,对外的开放平台可以打印三种日志文件:connection log(建立链接和关闭链接,附带接入参数),message log(内部调用链),stacktrace log(异常的堆栈打印)。
#具体实现
日志必须包含时间戳,精确到至少毫秒级。
如果只是记录到秒级,我们曾明知代码因缺乏并发控制而产生BUG,却只能郁闷地看着精确到秒级的日志。
对Java来说,最好配置为:yyyy-MM-dd/HH:mm:ss.SSS。
日志条目里打印一个会话标识(A certain session identifier),当有许多并发请求打过来时,你就能基于此字段过滤 client 了。比如,我们日志会补充打印一个浏览器 cookies 里种下的 UUID 。
如果打印信息是常量字符串或简单字符串拼接,那么不需要if ( log.isDebugEnabled() )。
如果你拼装的动作比较耗资源,请用if ( log.isDebugEnabled() )。
这样更方便grep或hadoop做性能数据抽取和挖掘,从而能很轻松地转换为图形监控。
比如,订单中心的性能数据格式为:树枝标志 当前节点起始时间 [当前节点持续时间, 当前节点自身消耗时间, 在父节点中所占的时间比例]
(1)访问数据库的dao层;
(2)访问外部资源的ext层;
(3)访问mq的方法;
(4)等等,一切不在你自己负责的工程掌握的部分(外部),或一切你认为自己工程的性能危险点,都需要加入性能监控日志。
#Sample
一个好的启动日志
[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-GFZqKEOC-1664280573192)(http://images.cnblogs.com/cnblogs_com/zhengyun_ustc/255879/o_clipboard%20-013%20%E5%89%AF%E6%9C%AC.png)]
打印了应用的版本号,客户端的会话标识,关键步骤的执行时长。
一个好的堆栈跟踪日志
[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-xDHVnPjU-1664280573193)(http://images.cnblogs.com/cnblogs_com/zhengyun_ustc/255879/o_clipboard%20-%20014%E5%89%AF%E6%9C%AC.png)]
本文首发于旁观者-郑昀的55最佳实践系列,链接:http://www.cnblogs.com/zhengyun_ustc/archive/2012/12/15/logging_bp.html
参考资源:
1,红薯,Logging 日志记录最佳实践,英文原文
2,Julius Davies:Log4j Best Practices,译文在此
3,十个转移到logback的理由[PPT]
1)55最佳实践系列:MongoDB最佳实践 (2012-12-15 15:48)
2)55最佳实践系列:Logging最佳实践 (2012-12-15 16:43)