第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，欢迎关注！)
