一个成功的软件,全力开发的时间可能占其整个生命周期的1/4还不到,软件发布后要运维(Operation),运维的视角和开发的视角是很不一样的,但是有一点,运维的数据能反哺开发,同时,开发的时候也得考虑可运维性,其中非常重要的一点是日志,没有日志,运维就瞎了大半。怎么写日志,就得从运维的需求来看了,通常会有以下一些常见的场景(已典型互联网应用为例):

1. 访问来源,包括访问量,访问者数据,如用户名、IP等等。

2. 基于上一点细化,访问的接口,读、写、删……

3. 软件系统内部的核心链路,比如我这有个系统要在中美直接同步文件,那同步的情况运维的时候就要掌握。

4. 软件系统对其他所依赖系统的访问情况,比如我这个系统依赖一个分布式缓存,那访问缓存的量、是否超时等情况需要了解。

5. 系统异常,比如磁盘满了。

记录这些信息的目的大抵有:帮助分析系统容量方便扩容;在系统某些部分工作不正常的时候及早发现;发生严重故障后方面定位问题原因。认识到这些需求后,下一步就是怎么实现的问题了。

前面提到的5点,有些可以通过抛异常实现,例如访问分布式缓存超时,有些则显然不是异常,例如就是正常的缓存访问。我觉得可以用一种统一、规范的方式记录,这种方法就是打码。我记得以前用Windows 98/2000的时候,经常会遇到蓝屏,蓝屏上会有一堆我看不懂的英文,并且总是伴随着一个错误码。

wKiom1NXNhnx3_ZtAAEhc2Zcxtc720.gif

虽然我看这玩意儿没一点好心情,但我相信微软的工程师肯定能从那个奇怪的状态码上判断出是哪里出了问题,硬盘坏道?光驱卡死?诸如此类……其实类似的做法数据库也用,比如MySQL。

用统一的代码表示错误(也可以表示正常但核心的业务点)最大的好处就是便于搜索、统计和分析,在动辄数以万行记的日志文件中寻找感兴趣的信息,一页一页翻看是不现实的,稍微做过点运维的必然会用上 grep,awk,wc 等工具,这个时候如果信息都有代码标识,那真是再方便不过了!例如,我用代码 FS_DOWN_200 表示对系统的正常下载访问,日志是写在 monitor.log 文件中的,我就可以使用一行shell统计4月22号5点到6点之间的正常访问量:

 
  
  1. $ grep FS_DOWN_200 monitor.log | grep "2014-04-22 05:" | wc -l

具体每条日志记录什么,那就是更详细的了,基本就是时间、日志编码、额外的有用信息,如:

 
  
  1. 2014-04-22 05:06:18,561 - FS_DOWN_200 216 UT8TFSDXc8XXXagOFbXj.jpg

除了时间和日志编码外,还有响应时间(216ms)和具体访问的文件名。

当然如果你有日志监控和分析系统就更棒了!你就可以在系统中录入关键字监控,比如每分钟统计次数,然后看一天、一周的访问量趋势图。进一步的,如果这个量发生异常,让系统发出报警。如果没有关键字,从海量日志中分析纷繁复杂形态各异的信息,再监控,是非常难的一件事情。

为什么要把日志代码设计成 FS_DOWN_200 这样子的,下面稍微解释下,这个代码分成三段:
1. FS: 表示我们的系统,这是最高的级别,公司中有很多系统,那各自定义自己的标识。
2. DOWN: 表示我们系统中的一个核心业务点或者对其他依赖系统的访问,还可以是UP(上传),SYNC(同步),或者TAIR(对缓存系统访问)。
3. 200: 具体健康码,参考HTTP规范,200表示OK,其他包括404(不存在),504(超时)等等。

有了这些代码,再结合公司的监控系统,我们做统计分析就非常方便了,每天多少下载、多少上传、多少成功、多少失败、对其他依赖系统访问多少量、多少失败率,一目了然。进一步的加上监控,当某些值突然发生变化,比如下载量/上传量暴跌、访问其他系统依赖超时大量增多,就能及时响应。

日志对于运维实在太重要了,而如果不接触运维,又怎能理解其真正的需求,因此我说,不做运维,不懂日志。