程序日志_如何调试程序.pdf

《程序日志_如何调试程序.pdf》由会员分享，可在线阅读，更多相关《程序日志_如何调试程序.pdf（29页珍藏版）》请在得力文库 - 分享文档赚钱的网站上搜索。

1、程序日志0.认识一下日志是什么？非官方定义：服务程序在运行过程中打印出的反映服务当前运行状态的一些信息记录为什么打日志呢？通过查看日志，可以：?1确定程序的运行状态是否正常2发现和跟踪错误，辅助定位Bug3支持统计工作，比如流量统计、访问特征统计等程序必须打印日志，否则没有人能够知道程序在干些什么（服务性程序），也没有人知道程序当前的状态是否良好 打日志是不是很简单？实例1：?问题何在？简单吗？实例2：?NOTICE:02-26 13:20:54:datacenter.*196633 logid:2798785731proctime:total:0(ms)rev:0+proc:0+write:

2、0reqip:127.0.0.1reqsvr:cmdno:svrname:queryerrno:?问题何在？真的简单吗？实例3：?WARNING:01-21 00:39:11:pspui.*57352 logid:12345reqip:0.0.0.0pspui.cpp:213receive apache request failedunsupport apache command number WARNING:01-21 00:42:16:clogin.*40966 illegal vcode!WARNING:01-21 00:44:44:checkPass.*8194 logid:11011

3、66481reqip:10.65.15.245checkPass_imp.cpp:1130parse_dbshell_read_response:pusrinfo_res_t:cant find current user from dbshell?FATAL:08-12 23:31:04:uscore.*81931 hd_tscore_res:the memory offset beyond the limit!Line 123?问题何在？真的很简单？实例4：?NOTICE:11-29 22:43:51:confilter.*204826 request;576565637:trans_log

4、id=0,cmd_no=100009 qid=40391458 aid=0 uip=3238627806(222.137.9.193)uid=2853478 username=qeao130 opuid=0 op_username=create_time=0(Thu Jan 1 08:00:00 1970)title=cid=88 anonymous=0 score=0 uscore=300 icon_sys=0 status=0 detail_len=846 NOTICE:11-29 22:43:51:confilter.*204826 chk_url_counter;renew sdb s

5、uccessed NOTICE:11-29 22:43:51:confilter.*204826 fc_eval;denied index 266886 NOTICE:11-29 22:43:51:confilter.*204826 fc_eval;denied index 160474 NOTICE:11-29 22:43:51:confilter.*204826 fc_eval;denied index 782237 NOTICE:11-29 22:43:51:confilter.*204826 chk_url_counter;denied url NOTICE:11-29 22:43:5

6、1:confilter.*204826 op_filter;find a denied url NOTICE:11-29 22:43:51:confilter.*204826 op_filter;find AUrl,denied NOTICE:11-29 22:43:51:confilter.*204826 response;576565637:version=1 err_no=12002 reason=-22 hilight=theccn fword_num=1 fb_flag=0 adv_flag=1 url_flag=1 hisens_flag=0 flood_flag=0 ellaps

7、e_ms=5 cmd_no=100009 ip=3238627806(222.137.9.193)uid=2853478?问题何在？还是简单？实例5：FATAL:05-05 22:02:47:ssnif.*1189128544 logid:0reqip:10.65.21.233ssnif_clt_dc.cpp:803interacter with dc error.?WARNING:05-05 22:02:47:ssnif.*1189128544 logid:0reqip:10.65.21.233ssnif_work.cpp:464fail to get data from SSNSM WAR

8、NING:05-05 22:02:47:ssnif.*1189128544 logid:0reqip:10.65.21.233ssnif_imp_ifoldc.cpp:99fail to process the request WARNING:05-05 22:02:47:ssnif.*1598232928 logid:1003191001reqip:10.65.11.72ssnif_clt_dc.cpp:379dc_res:pl_err_no:3?FATAL:05-05 22:02:47:ssnif.*1262557536 logid:0reqip:10.65.22.43ssnif_clt_

9、dc.cpp:803interacter with dc error.?WARNING:05-05 22:02:47:ssnif.*1262557536 logid:0reqip:10.65.22.43ssnif_work.cpp:464fail to get data from SSNSM WARNING:05-05 22:02:47:ssnif.*1262557536 logid:0reqip:10.65.22.43ssnif_imp_ifoldc.cpp:99fail to process the request?问题何在？还是简单？实例6：?TRACE:05-05 22:37:23:d

10、bshell.*352300 logid:931714056check pack valid ok.TRACE:05-05 22:37:23:dbshell.*352300 logid:931714056data from module checkPass(10.65.6.228)is received finish by thread 41.TRACE:05-05 22:37:23:dbshell.*352300 logid:931714056rcv incoming request success.TRACE:05-05 22:37:23:dbshell.*352300 logid:931

11、714056fieldcount:5 TRACE:05-05 22:37:23:dbshell.*352300 logid:931714056user id is 0,translate username into userid TRACE:05-05 22:37:23:dbshell.*352300 logid:931714056check cache for user:yu6250575.TRACE:05-05 22:37:23:dbshell.*352300 logid:931714056user:yu not found in cache.TRACE:05-05 22:37:23:db

12、shell.*352300 logid:931714056not exist in cache of user:yu6250575.TRACE:05-05 22:37:23:dbshell.*352300 logid:931714056hashcode culculate ok.result:605.?问题何在？还是简单？实例7：?NOTICE:01-21 00:47:07:pspui.*8194 logid:1244128892proctime:7ms reqip:117.92.61.63reqsvr:psp-apachecmdno:1(LOGIN)svrname:errno:0(ok)ta

13、lk(-clogin:cmd:1 username:dujin vcode:client_ip:117.92.61.63 etimes:2 safeflg:0 bduid:C64E8991F17799CEF5EA3A2E04B35D5A:FG=1-fm:cmd:1 username:dujin bduid:C64E8991F17799CEF5EA3A2E04B35D5A:FG=1 ip:117.92.61.63 log_flag:0 -fm:err_no=0,d_err_no=0 fm:cmd:1 username:dujin bduid:C64E8991F17799CEF5EA3A2E04B

14、35D5A:FG=1 ip:117.92.61.63 log_flag:1 )param(tpl:sp u:./username:dujin psp_tt:0 bduid:C64E8991F17799CEF5EA3A2E04B35D5A:FG=1)time(receive/process/buildpage/send/TOTAL:0/6/0/0/7ms)?问题何在？打日志最容易犯的错误1.不打日志（实例1）装酷2.缺少必要信息（实例2、实例3）打也白打3.犹抱琵琶半遮面（实例3）卖个关子先4.冗余严重（实例4）叫你让我打日志5.动辄FATAL（实例5）狼来啦6.不区分日志级别（实例6、实例4）

15、胡子眉毛一把抓7.信息不明确（实例7）别玩躲猫猫打日志的一些规则和技巧区分FATAL和WARNING?一次请求处理失败打WARNING，整个服务要挂掉了，才打FATAL?2个原则：?不要动辄FATAL，切忌把FATAL当WARNING来用，否则就是狼来了。错误日志输出的信息要完备但是不冗长。完备信息：为什么出错 出错时操作对象 出错 误时的参数。技巧1：区分清楚日志级别之一（不要胡子眉毛一把抓）打日志的一些规则和技巧区分TRACE和DEBUG?TRACE日志用于打印各个分支的处理情况，给出提示性信息，可以了解各个分支的工作情况，只是重要性没有NOTICE日志高。DEBUG日志的格式和内容完全由

16、实现者自己确定，DEBUG需要给出最详细的日志信息，争取避免使用GDB来确定一些需要的信息。技巧2：区分清楚日志级别之二。（不要胡子眉毛一把抓）TRACE:08-13 11:43:52:qcm.*32773 read 56 bytes(want 56 bytes)from UI:22 OK?DEBUG:11-29 18:03:36:qcm.*8192 Write iknow bn948654 fno101 length0打日志的一些规则和技巧不要只是报错，而要说明出错时的关键信息。技巧3：错误日志打印的几个要素。（打印关键信息）ui1asbsui2logid1 logid2Logid1/log

17、id2打出出错时的函数名（学gdb，呵呵）。?出错日志打印出logid。打日志的一些规则和技巧Notice日志一般不用于跟踪和调试，而更多地用于日志统计和分析。技巧4：打NOTICE要矜持，不要滥打。（区分清楚日志级别）?几个原则不要动不动就打NOTICE。由于线上服务一般日志级别开的是4，TRACE、DEBUG都打不出来，因此不少同学把很多 TRACE的信息都打成NOTICE，结果将原本很有价值的NOTICE日志淹没。完成一次交互，无论成败，都应该打出一条，而且只有一条NOTICE日志。输出的信息要完备但是不冗长。把本次交互的关键信息打印出来。特别说明：重要的正常信息也可以通过NOTICE日

18、志打出，一般用于日常监控，比如周期性数据 dump或者数据merge等，注意和第一类notice日志格式进行区分。打日志的一些规则和技巧技巧5：打NOTICE日志的一些必要信息NOTICE日志最通常的用法，就是在每次和其它模块交互结束后打印一条完整的日志，一般这种日志应该有如下几个要素：用于和上下关联模块联查。请求来源模块的名字，表明请求来源。用于表示本次交互是否成功。用于打印错误码，表明错误原因。耗时情况，一般包括各部分耗时和总耗时。这个视情况而定，打出关键信息用于统计、分析和问题排查。打日志的一些规则和技巧打NOTICE日志的一个示例NOTICE:11-29 16:35:04:fm.*49

19、159 UI_REQ:logid=511364708 pvder=UI-server iid=576 cmd=100011 ip=313455066 uid=27230079 un=lq3158 cid=88 qid=28625301 d_len=19 uscore=35|STATUS=0(0 is ok)IPF:c=1 s=0 t=0msFANS:c=0 s=0 t=0msCNF:c=1 s=0 t=0ms UCHK:c=0 s=0 t=0ms|RES:errno=0|TIME:GET_REQ/GET_RES/SEND_RES/TOTAL_TIME:0/1/0/1ms?打日志的一些规则和技巧

20、技巧6：白首太玄经要打 要打到位 要打得精简日志艺术就体现在你对日志打印级别和每一个级别日志内容和格式的控制上，这是一门艺术。使用ul_log打日志的一些注意事项1.关于logsize的设置ul_openlog时指定?注意，logsize并非是指一条日志的长度，而是指文件大小的限制。其默认单位是M，配置有效范围是（0,2048.使用ul_log打日志的一些注意事项2.关于一条日志的最大长度我们没有办法修改每条日志的最大长度，最老的版本是支持640bytes，现在的ul log库，支持2048bytes。单条日志多于2048会被截断，会因此影响统计、评估等。?使用ul_log打日志的一些注意事项

21、3.日志级别配置，不支持16进制数#整型 日志输出等级，需要配置成十进制整数，不支持16进制数?#建议一般配置为4，取值范围：0=&=255?#对用C代码的LOG_LEVEL 宏定义描述?#define UL_LOG_NONE 0?#define UL_LOG_FATAL 0 x01 /*fatal errors*/?#define UL_LOG_WARNING 0 x02 /*exceptional events*/?#define UL_LOG_NOTICE 0 x04 /*informational notices*/?#define UL_LOG_TRACE 0 x08 /*progr

22、am tracing*/?#define UL_LOG_DEBUG 0 x10 /*full debugging*/?#define UL_LOG_ALL 0 xff /*everything */使用ul_log打日志的一些注意事项4.不要使用fprintf打日志ul_log一旦初始化成功，就不要再使用fprintf打日志了，不安全也不规范。?ul_log是百度使用最广泛的打印日志的库，还有一些库都是在ul_log基础上封装起来的，比如ub_log。还是受ul_log系统限制的。使用ul_log打日志的一些注意事项5.日志打太多会影响性能？分两种情况说：打日志也是写文件，日志打太多肯定会影响

23、程序性能。?级别控制得好，则关系不大。比如程序打了很多debug日志，而程序启动时设置的打印级别高于debug，那此时的开销就很小了，除非是耗cpu型的服务，不需要太担心。使用ul_log打日志的一些注意事项6.避免白天是天使，晚上是魔鬼有些程序需要晚上定时做一些工作，比如数据的check、merge等等，如果写程序打日志不注意这种情况，会造成白天日志很清爽，但是晚上日志一团糟的情况，更有可能影响数据处理的性能。所以对于这种情况要多加关注。分析日志时的一些注意事项线上服务的正常工作对我们来说是第一位的，任何时候不能影响线上服务，追查问题和统计日志也不例外，常见的需要注意的地方如下：?不要用vi打开日志文件进行查看。一般来说日志文件会比较大，用vi打开会造成很大的系统负担。?不要在线上机器做比较耗资源的日志分析操作，比如sort、uniq等。如果做复杂的统计，可以将日志备份到线下机器再进行分析。?不要直接从线上scp大的日志文件，最好使用限速的方法下载。理想威廉曾经说，他最喜欢的事情，就是写完程序之后，捧着杯咖啡看程序日志的滚动，只看日志就知道程序运行的情况如何。境界回顾和总结要重视打日志意识 要会打日志，日志要打得得体、打得漂亮区分清楚日志级别 打错误日志时，注意打印必要的错误信息 打notice日志时，要考虑统计需求 日志在精不在于多常见问题：7个推荐资料地址http:/