日志打印
ü 日志重要性
ü 日志规则
ü 日志格式
1、日志重要性
日志无论是在开发过程还是定位问题以及了解应用的运行轨迹都有非常重要的意义。日志打印也是一项技术活,好的日志对日后的维护工作带来意想不到的帮助。
通过日志的打印来定位问题
通过日志的打印了解应用的运行轨迹
通过日志完成性能调优
通过日志了解应用状态
2、日志规则
l 打印日志是用来分析的不是用来看的
日志有很大一部分作用是用来分析的。打印出便于分析的日志,就是好的日志。便于分析可以从生产环境来考虑,大部分的生产环境都是Linux操作系统,Linux操作系统文本分析工具很强大很方便。所以要从这个角度去考虑日志的打印,打印日志能够使用简单的grep命令或是awk命令就能将有用的信息提取出来。
如下是BossAgent模块打印的日志。该日志记录了从Boss测请求报文,以及请求报文转换为MM2请求对象,以及发送给PSS的MM2对象结构体,以及从PSS测返回的MM2响应结构体。以及根据PSS测返回的MM2响应结构体组装成xml报文返回给Boss测。该日志看似打印的很详细,但是该日志缺乏总结性日志。也就是打印的都是流水账,过于详细,对于后期的日志分析带来了很大的困难。
例如想统计所有13722223310号码的注册结果,使用Linux命令无法完成这个看似简单的任务。因为缺乏总结性的日志,虽然从后台返回的MM2结构体中我们可以看到该次业务请求的结果,但是当日志文件很大、打印速度飞快的情况下,使用VI或是cat命令是非常不现实的。而使用grep命令又无法得知结果,这样的日志给后期的日志分析带来很大困难。
总结性日志提高可分析性
应该在最后加入该次请求的状态,如129 17:23:09.782 13722223310 register success
你可能想这样不就可以使用简单的grep 13722223310 register 日志文件名,来查询结果了吗。
使用状态码定义提高可分析性
这样的日志从分析角度来讲还是不便于分析。例如success这样的词语在日志中应该是大量分布的。想通过该关键字来分析日志,会引入很多不必要的信息,给日志分析带来麻烦。建议使用状态码例如使用200来代替success,这样通过这个状态码可以过滤掉很多无用的信息。但是单纯是使用grep 200 日志文件名,这样手机号码中包含200也会被搜索到。
使用分隔符提高可分析性
如上日志中可使用13722223310|register|200,这样就可以使用简单的命令grep提取关键信息,过滤掉无用杂乱的信息。
相关日志尽量不要断行
Linux上强大简单易用的文本分析工具,但是大多数分析工具都是以行为单位的,如awk grep sed wc,将相关日志打印到一行,可以免用多行处理,在行之间找对应关系。
l 日志打印应该分层、分角度
一个好的日志不应该只打印与业务有关的日志。
日志打印应该从以下几个方面去打印:
模块运行日志:模块运行日志包括消息队列的监控、线程的运行状态。该日志应该以INFO级别打印,并且采用间隔打印,或叫做定时打印。以减少日志打印总量。从该角度可以反应出该模块是否有消息队列积压,是否所有线程都运行正常。消息队列的打印可以采用日下格式:
使用统一的关键字Monitor来标示模块运行日志。队列监控日志使用|队列名|消息放入速度|消息取出速度|消息放入个数|消息取出个数|当前队列消息个数|。线程监控日志使用|线程名|线程状态码|,线程状态码可以自己扩展。0表示正常1表示运行结束2表示线程阻塞。
09:16:59.347 INFO |Monitor|ReceiveTimerQueue|0/s|0/s|0|0|0| 09:16:59.347 INFO |Monitor|SendRegistQueue|0/s|0/s|0|0|0| 09:16:59.347 INFO |Monitor|boss->omc|0/s|0/s|0|0|0| 09:16:59.347 INFO |Monitor|SendQueue|0/s|0/s|0|0|0| 09:16:59.347 INFO |Monitor|boss->pss|0/s|0/s|7037|7037|0| 09:16:59.347 INFO |Monitor|ReceiveAuthQueue|0/s|0/s|0|0|0| 09:16:59.347 INFO |Monitor|ReceiveQueue|0/s|0/s|0|0|0| 09:16:59.348 INFO |Monitor|receiveHandler5|0|SendHandler1|0|receiveAuthMsgHandleThread1|0| receiveTimerMsgHandler1|0|SendRegHandler|0|SendHandler3|0|SendHandler2|0|receiveHandler4|0|receiveHandler8|0|receiveHandler7|0|receiveHandler2|0|receiveHandler3|0|receiveHandler6|0|receiveHandler1|0| |
业务日志:业务日志打印用户请求流程,能够清楚的使用某几个关键字可以提取一个用户的业务流程就可以。业务日志要分详细日志,如上BossAgent打印的日志,非常详细,应该都打印DEBUG级别的日志,而另外就需要打印总结性日志,总结性日志以INFO级别打印,包括|请求开始时间|请求结束时间|请求主体|请求类型|请求结果|请求外部资源返回结果|。其中请求主体可以继续扩展,如BossAgent的请求主体可以扩展为|手机号码|省份编码|MM2消息SEQUENCE|,DSS的请求主体可能属性更多一些,|手机号码|手机密码|手机UA|手机MOD|手机MAN|计费类型|套餐类型|白名单|。
模块性能日志:模块的性能日志应该能够通过该日志清晰的反应该模块目前性能,包括外部请求的压力,内部请求处理速度。
模块外部资源日志:模块的外部资源日志需要详细记录,现今单独的模块很少见了,很多大型复杂的系统往往是由多个模块构成,模块间采用或标准或私有协议进行通信。这种场景下爆发的问题往往比较复杂,并且与多个模块都有关系或是责任。所以在模块级别上将该模块所依赖的外部资源都打印出来非常重要,通过这些日志应该能够完成快速定位问题与哪些模块相关联或是哪些模块需要负根本责任。通常模块的外部资源包括数据库,系统间内部模块、第三方系统。如BossAgent的外部资源包括数据库,系统间内部模块为PSS、第三方系统应该是一级Boss。数据库资源的打印应该包括所有的SQL语句,这个非常重要,无论是问题的定位还是后续的SQL优化,还是数据库架构的调整,都需要这些信息能够快读的整理出该模块所有的SQL语句,提供给专业的DBA进行分析。SQL语句的打印还应该包括参数的打印。
第三方系统的打印主要包括,请求压力的统计、截流告警、请求处理的延迟、以及超时。
l 对异常的打印
异常日志的打印对于问题的分析和定义有极大的帮助,异常日志的打印应该注意以下几点,杂异常分支必须打印日志。如switch case语句块中的default,if else中的 else分支。Try catch语句块中catch分支。对于catch分支的打印,应该尽量使用标准的异常打印,不应该打印的控制台上,对于异常的处理不在本开发指南的讨论范围,所以简单说明。异常应该打印堆栈信息,并且打印日志发生的场景。
l 日志级别
日志级别对于定位问题的重要性,在现网运营的过程中,往往都会打印低级别的日志,一些过于详细得日志记录程DEBUG,而一些总结性的日志记录为INFO级别,对于外部资源日志,如果日志过于庞大,请将日志打印为DEBUG日志,在此基础上在抽取总结性日志,打印为INFO日志。
l 考虑日志对性能的影响
日志的频繁打印会对模块的性能产生极大的影响。如BPP的在每次接受到消息后都会打印消息结构体,将该日志注掉,性能在原有的基础上上升了600条/秒。
l 日志打印内容
l 不打印无用的日志
如现网的BossAgent将与PSS之间通信的心跳消息结构体打印出来,该日志不仅打印频繁,而且没有任何意义。
l 不打印不完全的日志
不打印不完全的日志,如BossAgent的消息队列积压的告警日志,只打印了消息队列满,但是没有打印是谁满了,也就是缺少主语,对于后续的定位产生了极大的阻碍。
l 不打印重复的日志
如上BossAgent日志,将MM2消息结构体打印了多次,没有任何意义。
l 不在循环里打印日志
如果代码的逻辑是一个无限循环或是循环的次数较多,这里的日志不应当打印太过频繁,使用尽量缩减日志量,并且将有用的信息打印出来。在循环打印日志或占用大量CPU时间,这里需要进行特殊的打印。就是采取间隔打印或是定时打印。
3、日志格式
日志格式统一使用主语+谓语+宾语+状语的格式,日志打印应该遵从人类的自然语言,任何没有开发经验或是外行人都能从你的日志中捕获到有用的信息,相信你的日志就打印的很成功了。
加入分隔符,使用分隔符使每个域都能够清晰识别,分隔符可以提高日志可分析性,也可以过滤空格。
如下日志:13722223310 register 200,没有采用域分隔符,这样都手机号码中出现异常数据如13722223310+空格,无法快速定位。加入域分隔符以后13722223310 |register|200|,可以清晰的看清楚手机号码后有多余的空格。