第1部分 又一次认识C语言

程序调试的利器—日志

        假设世界上有一个人能够保证一次写出来的代码是百分之百正确的，那么毫无疑问，他一定是世界上最棒的程序猿，沒有之中的一个。为什么要求代码写好过后要进行充分的自測(包含单元測试和集成測试)？就由于是人皆会犯错，是程序就会有bug。作为一名软件开发者，必须要学会对程序进行測试，也就是要学会程序的调试。

         一般而言，对代码的调试有下面几种方法：

        第一，凭肉眼看。在开发阶段，我们编写的每一行代码都须要用我们的“火眼金睛”多审查几遍。假设要问，最好的代码调试工具是什么？我觉得是人眼。无论是代码还是文档，在用工具检查之前，都须要先过了我们眼睛这一关。

        第二，对代码进行编译，以发现语法错误。编译器能够帮助我们发现代码中存在的语法错误，但对于那些隐蔽性的错误(如逻辑错误等)无能为力。

        第三，用代码检查工具(如Pclint等)来走查代码。假设代码编译通过，并不表示它就沒有问题了。在学校的时候，我们一般觉得仅仅要程序能够执行就能够了。但在实际的软件开发项目中，程序能够跑起来，不过“万里长征走完了第一步”。用代码检查工具能够发现许多编译器无法发现的错误，如变量定义了未引用、不同数据类型之间相互赋值、函数未声明便被调用等。

        第四，对代码进行调试。对于执行正常而输出结果不对的程序，我们能够用设置断点并进行单步跟踪调试的方法来发现当中存在的问题。比如，在VC++ 6.0里面，可实现对代码的单步调试，并输出变量在某一步产生的值，可据此推断程序的逻辑的正确与否。

       第五，对程序的日志文件进行分析。对代码的单步调试仅仅在代码行数较少的时候比較适用，如学校教材上面的程序。但在实际的软件项目中，代码少则几千行，多则数万行，用单步调试的方法显然不恰当。为了跟踪某一变量值的变化，用该方法可能要花费几个小时，这对工作效率产生了严重影响。为了解决大程序文件代码调试问题，日志系统应运而生。在程序中的重要地方打印日志，之后对产生的日志进行分析，可找到相应代码的问题。因此，日志文件分析成了大型软件项目中代码调试的主要手段。

        本文对日志相关内容进行具体的说明。

1.什么是日志文件？

        在业务软件系统中大量使用日志，日志能够起到“按图索骥”的作用，它对于故障定位和系统正常执行维护具有举足轻重的作用。

        日志文件是程序中写日志函数产生的记录程序执行情况的文件。写日志函数也是用C语言编写的，同C函数一样被调用。在恰当的地方调用该函数，可对整个程序的执行状况有一个全面的了解，方便对程序的跟踪调试。

2.有关日志等级和日志配置说明

(1)日志等级

        事有轻重缓急，日志信息也有重要与不重要之分。一般依照重要程度，将日志等级分为几类。在作者參与过的软件开发项目中，共同拥有7个等级，用宏定义表示例如以下：

//日志等级定义

#define LOG_FATAL        (int)1      //严重错误

#define LOG_ERROR       (int)2      //一般错误

#define LOG_WARN        (int)3       //警告信息

#define LOG_INFO          (int)4        //一般信息

#define LOG_TRACE       (int)5      //跟踪信息

#define LOG_DEBUG      (int)6     //调试信息

#define LOG_ALL            (int)7      //全部

        开发者依据所要打印的日志的具体情况採用不同的日志等级。

(2)日志配置

        由于不同产品程序行数、部署情况、实现功能等的区别，对日志打印的要求也不尽同样，因此须要有配置来控制日志的产生数量和显示情况。

        在配置文件里，有一个专门的[LOG]配置段，当中的配置项例如以下：

[LOG]

;日志等级, 0-Fatal 1-Error 2-Warn 3-Info 4-Trace 5-Debug 6-All

LogLevel=

;每一个日志文件的最大容量

LogMaxSize=

;是否输出该条日志在代码中的行数, 1-Yes 0-No

LogPosition=

        当中，LogLevel用于控制打印日志的等级，代码中日志等级比配置值大的日志信息均不在日志文件里显示；LogMaxSize用于控制生成一个日志文件的大小的上限，超过该值后，便又一次生成文件；LogPosition用于控制是否在日志文件里显示代码行数，方便将日志与代码相应起来。

3.怎样调用写日志函数？

        日志函数的调用遵循一般函数的调用规则。有两类写日志函数，例如以下所看到的：

        (1)第一类形如：WriteLog(LogLevel, LogInfo)。当中，參数LogLevel指日志等级(见第2节中的说明)；參数LogInfo是具体要打印的日志信息，我们据此信息来检查程序的执行情况。该函数的调用示比如：WriteLog(LOG_INFO, "The value of this integer is 3.")，日志等级为LOG_INFO，日志信息为“The value of this integer is 3.”(该信息会输出到日志文件里)。

        (2)第二类形如：WriteLogEx(LogLevel, LogInfo, ParaInfo)。这是扩展的日志函数，不但能够输出日志信息，还能够在日志信息中显示变量的值。该函数的调用示比如：WriteLogEx(LOG_INFO, "The value of integer iInt is %d.", iInt)，该日志要输出整型变量iInt的值，能够将该函数的调用与printf函数的调用比較起来看(能够觉得WriteLogEx函数不过在printf函数中添加了一个日志等级參数)。

4.编写日志的基本原则、基本要求和位置要求

       日志编写的整体原则是简单清晰、便于排查问题。

(1)日志编写的基本原则

        1)显式输出，关键信息必须输出；

        2)在编码时使用正确的日志级别，error错误和warning错误必须反应出实在的含义，不是特别严重的问题不能将日志等级定义为LOG_FATAL；

        3)在写日志描写叙述时，要使用正常简单易懂的语言，不能使用晦涩难懂的语言或某些专业术语；

        4)在极少数特殊情况不希望用户知道时，可使用特殊日志标记；

        5)为了写出优美的代码，在自己改动或加入代码的地方，都要正确的打上标记(包含作者、日期信息等)，方便追踪版本号的演进情况。

(2)日志编写的基本要求

       1)分多条信息分别输出，不要企图一次将全部打印信息出来；

       2)分时输出；

       3)必须分日志级别，这样可依据等级迅速对日志进行分析；

       4)控制日志信息的条数，不重要的信息尽量不要打印日志。

(3)输出日志的位置要求

       1)全部的输入输出，包含收消息和发消息都要求输出日志；

       2)关键控制点必须输出日志；

       3)调用底层或第三方软件，必须输出日志，并且对不可靠底层，必须加上begin/end两行日志；

       4)对方系统处理时间必须输出日志，以利以后维护时高速定位性能问题。

       此外，作者觉得，在编写日志时还须要注意下面几点：

       1) 在编写日志时须要注重日志细节，目标是为了方便以后维护，在遇到问题时，能够高速定位问题。

       2) 不要在同一行中写意思反复的日志。

       3) 日志须要足够的精简，不要任意换行。

       4) 日志中字段之间能够用空格或其他符号分断，不能将日志一直连续而不将其分断，尽量使日志本身具备进行“识文断句”的能力。

       5) 对于日志中的特殊信息(如会话号、IP地址等)，用特殊的符号进行标识，其主要目的是为了便于搜索。

5.总结

        日志系统在软件程序中占有很重要的地位，日志文件是排查程序问题的主要工具，是程序调试的利器。作为一名合格的软件开发工程师，一定要学会日志函数的灵活调用及准确通过日志文件来定位程序问题。

      “实践出真知”，唯独通过不断的积累和总结，才会对日志有更全面的认识。

附：

一起数据库表唯一索引问题的排查过程

【文章摘要】

        某模块在系统中占有很重要的地位，该模块能够对符合条件的动态信箱进行清理。本模块直接清理的信箱包含：过期动态信箱、冷冻信箱和空动态信箱；删除非动态信箱由本模块发送消息到还有一模块完成。

        近期，某局点出现了信箱删除缓慢而导致过期动态信箱积压的问题，经过仔细的分析和追踪，最后定位的原由于用户数据表和暂时表在相应字段上的索引不一致。本文对该问题的分析过程进行具体介绍，为相关模块现场问题的分析提供了故意的參考。

【关键词】

       模块 数据库  索引 过期动态信箱

一、现场问题描写叙述

        现场外籍返回了本模块的几个问题，包含：

        (1)某些满足删除条件的过期信箱还存在于数据库中，而沒有被清除掉。

        (2)现场有N个数据库，某个数据库中的信箱个数是其他数据库的两倍。

        现场返回了该模块的日志，发现模块执行正常，有删除过期动态信箱的记录。

二、本接口删除的信箱类型

        本接口删除的信箱类型如图1所看到的：

图1本模块删除的信箱类型

        从图1能够看出，本模块要删除三类信箱：过期动态信箱、冷冻信箱和空动态信箱。

三、本接口程序执行整体流程

       本模块的程序整体流程如图2所看到的：

图2程序执行整体流程

       从图2能够看出，全部满足删除条件的信箱是先被扫描出来放到内存链表中，最后再执行存储过程将其清理掉。

四、问题原因初步分析

        与现场外籍沟通，让他返回了本模块的日志、该模块要用到的一些系统參数的值，并让他完整地导回了现场的数据库。

        经过对參数及数据库中数据的分析，我们发现：

        (1)依据系统參数的值，确实应该有大量的信箱号码被删除掉。

        (2)某一个数据库中的数据是其他数据库的两倍。

       鉴于本模块执行是正常的，我们觉得问题的解决的方法可能是：

       (1)本模块所调用的存储过程沒有将全部满足条件的信箱扫描出来。

       (2)全部信箱尽管被扫描出来了，但沒有全然插入本模块的内存链表中。

       (3)全部信箱尽管被插入到本模块的内存链表中，但删除信箱的存储过程沒有将这些信箱全部删除掉。

五、问题定位

        我们在測试部环境上恢复了现场导回来的数据库，并在本模块代码中加入了部分调试日志，用以推断每一步扫描出的信箱和插入到内存表中的信箱的个数。

       准备工作完成之后，我们启动了本模块程序。在经过长时间的执行之后，我们查看了本模块的日志，部分关键的日志例如以下：

2014.02.25 17:18:57.647 [INFO ] F[xxx.c ] L[004001] ScanTask0: zzx test(Step 1). Scantable=0, total Scaned num=141, insert into list num=141 //第一步流程处理过期动态信箱

2014.02.25 17:18:57.022 [INFO ] F[xxx.c ] L[004285] ScanTask0: zzx test(Step 2). Scantable=0, total Scaned num=141, insert into list num=141 //第二步流程处理冷冻信箱，数目没添加说明沒有冷冻信箱

2014.02.25 17:46:20.596 [INFO ] F[xxx.c ] L[004671] ScanTask0: zzx test(Step 3). Scantable=0, total Scaned num=147013, insert into list num=147013  // 第三步流程处理无留言动态信箱，147013-141为无留言动态信箱数目

2014.02.25 17:48:08.123 [INFO ] F[xxx.c ] L[004847] ScanTask0: Finished processing, total mailbox num:147013, processed mailbox num:141 //总的扫描出来的信箱数和删除掉的信箱数

        从日志能够看出，仅仅要是扫描出来的信箱，都是全然被插入到内存链表中的，也是全然被删除掉的(无留言动态信箱沒有被删除，是由于删除无留言动态信箱的标志沒有被打开)。

        我们发现了一个问题，在第一步处理过期动态信箱流程中，仅仅扫描出来了141个信箱，但实际上在数据库中存在的过期动态信箱远不止这个数目。那么问题一定出在第一步，这样就缩小了搜寻范围。

六、真相大白

        依据上一步的分析，是在处理过期动态信箱的流程中出了问题，我们就须要对该流程进行重点的分析。

        查询过期信箱的流程如图3所看到的：

图3查询过期信箱流程

        图3所看到的，该流程涉及到两个存储过程：存储过程1和存储过程2。当中，存储过程1用以推断是否存在过期信箱(该存储过程的返回值为过期信箱的个数)，存储过程2用以将过期信箱扫描出来。

        通过对第一步的日志进行更加仔细的分析，发现存储过程1扫描出的信箱数有十几万，但存储过程2返回的信箱数唯独141个。那么一定是存储过程2有问题。下面该存储过程进行分析。

        (1)该存储过程将用户信息从用户信息表中取出之后，插入到暂时表中，然后从暂时表中选择相关字段并返回。

        (2)我们将该存储过程中的insert语句拷贝出来单独执行，发现要报错，报错信息为用户信息表和暂时表在某字段上的索引不一致，不能插入该字段同样的数据。

       (3)我们马上查看数据库中这两类表的定义，发现用户信息表在boxnumber字段上建立了普通索引，而暂时表在boxnumber字段上建立了唯一索引。假设用户信息表的boxnumber字段值有反复，那么就不能插入到暂时表中。难道信箱号码真的有反复？

       (4)对现场返回的数据进行分析，发现确有信箱号码反复的数据。

       难道就是索引不一致造成的吗？依据分析结果，我们将暂时表在boxnumber字段上的唯一索引改动为普通索引，然后又一次导入数据并启动本模块，发现一段时间之后，满足删除条件的动态信箱都被删除掉了。

       看来，的确是索引不一致惹的祸！

七、总结

        在本次现场问题的排查中，依靠数据库中的记录发现问题，而利用日志来定位了问题。双管齐下，终于找到了症结所在。

        通过本次问题排查，我们总结出的经验有下面几个：

        (1)详尽的日志有助于问题的定位。为了更清晰地了解问题出当今哪段代码，我们能够在程序的关键节点加入上一些測试日志，供分析所用。

        (2)对于数据表来说，假设字段内容类似，且要进行从一个表到还有一个表的插入等操作，那么在相应字段上的索引性质一定要同样(即不能一个为唯一索引，一个为普通索引)，避免由于索引不一致而导致的数据操作失败问题。

        (3)存储过程中，在insert、update等语句之后，一定要考虑异常处理，即在这些语句执行失败之后要抛出异常信息，方便定位问题。

        (4)现场数据库表一定要有人定期查看和维护，并定期阅读数据库执行日志，以发现可能存在的问题。

       本文对实际软件开发项目中某模块的现场问题的排查过程进行了具体的介绍，为相关模块程序和数据库设计及维护提供了參考。

(欢迎訪问南邮BBS：http://bbs.njupt.edu.cn/)
(欢迎訪问重邮BBS：http://bbs.cqupt.edu.cn/nForum/index)

(本系列文章每周更新两篇，敬请期待！本人新浪微博：http://weibo.com/zhouzxi?topnav=1&wvr=5，微信号：245924426，欢迎关注！)