web测试环(UNIX)Log日志整理

LOG日志的介绍

1、 在看log之前，首先需要了解每个log文件要记录什么信息：比如，performance.log是一个查看性能的log日志，而search-velocity.log则是一个查看页面信息的日志；由于每个project的log文件都有其特定性，所以在看log之前需要先清楚每个log文件代表什么信息；

 51Testing软件测试网@pw4q O6Zc

2、 Log信息问几种级别：OFF、FATAL、ERROR、WARN、INFO、DEBUG、ALL；但是平时一般只用四种：DEBUG、INFO、WARN、ERROR；前三个级别的信息一般是在程序员用来调试的信息，而第四种（error）级别是日志信息里级别最高的，ERROR级别信息的产生分两种；一种是程序出错，一种只是程序员用来调试输出；一般在日志文件中，ERROR级别的信息是需要特别关注的；而在性能监控的日志文件里，则不需要特别去关注ERROR级别的信息，而是去关注操作带来的时间瓶颈；51Testing软件测试网"do:_k2t_1Ei5t

3、 下面以一个应用工程为例讲讲；

4、 如某个应用常用的日志文件分为两块：系统级（sys）和用户级(user),这一步是分成两个目录保存，/sys和/user；我们主要关注系统级的日志信息，用户级的日志信息只是关注用户在系统中的行为，一般不需要去关注；而sys级的常用日志一般也分为两块：功能性的日志和关注性能方面的日志：

功能性的日志一般为：51Testing软件测试网!nU}waGTH

                        i.             dal.log:     用来记录数据层程序执行sql的信息，可以看到sql语句以及执行的情况，该日志不会产生error级别的信息；

                      ii.             velocity.log: 用来记录页面的信息；51Testing软件测试网z.|v5v7xL

                     iii.             webx.log:   该日志记录系统运行期间发生的信息，该日志记录的都是java类运行发生的信息，当程序出错后，首要查看的是该日志；51Testing软件测试网WfR!O'BI]+YP&C

性能方面的日志：51Testing软件测试网 A.M9|*hQ#vW4EM6C7C

                    iv.             performance.log：记录ao、dao类运行时间，由什么请求发起，属于性能监控；51Testing软件测试网0B+}C3f8Ku-ZLc

                      v.             webx-filter.log： 用来记录每个ie请求的信息，以及该请求从开始到结束所经过的各个请求以及每个请求所开销的时间,属于性能监控；

                    vi.             hacking.log:     是记录用户修改登陆信息的日志；51Testing软件测试网\ i9g(EX\*Xs
H*I~P

 51Testing软件测试网d%`_s9R9]4t%Auu-k

 功能性的日志一般需要关注的是ERROR级别的日志信息，除dal.log外，因为dal.log是没有信息级别表识的，它只是打印sql执行的语句；但如果在webx.log和velocity.log日志中发现ERROR级别的信息，那肯定就是程序出错，需要返馈给程序员，由程序员去修改程序；下面对以上的日志举例进行讲解。51Testing软件测试网r-Ka~,i.Y~ Vuo+P

 51Testing软件测试网'G1F,w3ecd

4、一般每条日志信息包含了几大要素：51Testing软件测试网,O"~8pf(B^m

a)        发生的时间；

b)       信息级别；51Testing软件测试网Sq!R8dm G4roy

c)       执行什么操作，如果出错，则有出错的异常类型；51Testing软件测试网3tTrB9Obf
^

d)       调试的输出信息，如出错，则有出错的提示；51Testing软件测试网5pd)dB+]"b9Z3g

e)        如出错，相关出错的地方，在做什么动作的时候发生，具体出错在哪一行；

   操作步骤：

确定要查看什么功能，打开相应的日志文件，先查看是否有ERROR级别的信息；51Testing软件测试网Lm9yE g{

然后确认该error信息的时间是否是要查询的操作时间，看是否是在该操作时间段内发生的；51Testing软件测试网GI5yah3UKP

以上两点都符合的话，则进行下一步，举例分析ERROR发生的原因；

 51Testing软件测试网,~T']XGs%o

5、举例说明：

      功能性的日志：51Testing软件测试网T6u1W(r#VhQ

velocity.log：该日志是用来记录页面信息的；当页面运行时，页面的信息会被记录在该日志中，页面出错首先看这份文件，然后再看webx.log确定是页面出错还是环境或配置或程序出错；

      如：2007-08-06 15:02:20,335 ERROR VelocityService.aso - ResourceManager : unable to find resource 'macros.vm' in any resource loader.

      分析：51Testing软件测试网"n)H!ai U:qJ \"p#}

发生的时间，2007-08-06 15:02:20；

信息级别，ERROR，表明是出错信息；51Testing软件测试网W.P:lj*L8Z

出错的提示：unable to find resource 'macros.vm' in any resource loader；

         根据出错提示可得出系统找不到macros.vm，该摸板没有被载入，据此就可以把这信息反馈给功能负责者或程序员，让他去改正这一bug；51Testing软件测试网f0A:Lef9|

但是页面的出错有时候并不能完全确定是页面或摸板出的错，也有可能是业务层或数据层出的错，比如页面出现505错误，这个时候就需要看Webx.log；51Testing软件测试网7ML+h LZ3n ohKK s

 51Testing软件测试网q o2a(ipxyx

Webx.log:一般环境、程序、配置出错，都看这份文件；

2007-08-06 15:03:59,567 [] ERROR service.ServiceManager - Service BeanFactoryService failed to initialize51Testing软件测试网/[f
`p IJ H`

com.alibaba.service.ServiceInitializationException: Failed to initialize BeanFactory51Testing软件测试网,F9h"]d1JW*kT

at com.alibaba.service.spring.DefaultBeanFactoryService.init(DefaultBeanFactoryService.java:84)

      at com.alibaba.service.GenericService.init(GenericService.java:26)51Testing软件测试网4HQ vhC"y
AS

      at com.alibaba.service.DefaultServiceManager.initService(DefaultServiceManager.java:458)51Testing软件测试网#Ue8?+Mh{Q

      at com.alibaba.service.DefaultServiceManager.getService(DefaultServiceManager.java:829)

      at com.alibaba.service.DefaultServiceManager.getService(DefaultServiceManager.java:801)

      at com.alibaba.service.DefaultServiceManager.initAll(DefaultServiceManager.java:186)

      at com.alibaba.service.context.SingletonServiceManagerLoader.getInstance(SingletonServiceManagerLoader.java:72)

             ……………………

  分析：

发生的时间，2007-08-06 15:03:59；

信息级别，ERROR，表明是出错信息；51Testing软件测试网9v0g&zA;n3L
}!Ar

出错的异常类型：ServiceInitializationException；51Testing软件测试网3{-T8N)} Ii

出错的提示：Failed to initialize BeanFactory，初始化BeanFactory失败；51Testing软件测试网)`.tv+}tq%I"['J

相关类的出错的地方，在做什么动作的时候发生，具体出错在哪一行；51Testing软件测试网8|0zb4l#TEJ!V4ubw#C

如：at com.alibaba.service.GenericService.init(GenericService.java:26)，表明是在执行GenericService.java的方法init时出错，在GenericService.java类的第26行；

 dal.log:从该日志信息，主要能打印出整个sql语句；该日志信息是没有显示信息级别的，目的只是为了打印出整个执行的sql语句；

      如：2007-08-02 17:40:40,573 DEBUG sql.Connection - {conn-100003} Preparing Statement:             select       sum(case when STATUS='published' and GMT_EXPIRE>sysdate then 1 else 0 end) total_count,    sum(case when STATUS='member expired' or (STATUS = 'published' AND GMT_EXPIRE < SYSDATE) then 1 else 0 end) expired_count   from offer    where member_id=?       51Testing软件测试网;O(]9o8X8Z j

从这条信息中能看到，发生的时间，执行的完整的sql；51Testing软件测试网7VIvG-t

性能监控的日志：51Testing软件测试网R0?8w2{-N i

performance.log：从该日志信息能看到AO，DAO层java类在发生请求时，执行的时间；

如：2007-08-02 17:40:40,581 INFO - Call interface com.alibaba.exodus2.biz.dal.daointerface.OfferDAO.getOfferTotalAndExpiredCountByMemberId() take 8 ms. - [/ims/my_alitalk_info.htm?member_id=alipff]51Testing软件测试网EG\ T,[yJ#jY

分析：51Testing软件测试网 M"@7Ee@;qn2A

      发生的时间：2007-08-02 17:40:40；51Testing软件测试网cXv+oV+U5y

   信息级别： INFO；

     类：com.alibaba.exodus2.biz.dal.daointerface.OfferDAO

      该类执行的方法：getOfferTotalAndExpiredCountByMemberId()

      执行该方法花费的时间：8 ms；

      执行该方法的请求：/ims/my_alitalk_info.htm?member_id=alipff；51Testing软件测试网ap h\Fg

根据以上的这些信息，就能够确定出这个请求在执行java类的方法时花了多少时间？在监控java类性能上可以查看该信息；51Testing软件测试网Au{(wUH DE ?

 51Testing软件测试网M4g6N?E

webx-filter.log：该信息用来查看发起一次请求，所经过那些请求，以及每个请求所花费的时间，用来性能监控；51Testing软件测试网RHpY zN(WO b

 51Testing软件测试网`.f;T&G1mI'`

如：2007-08-02 18:05:18,906 INFO timer.TimerFilter - Started processing request: GET /offer/select_page.htm?needsignin=151Testing软件测试网1]1{x.Tk;h

2007-08-02 18:05:19,575 INFO timer.TimerFilter - Response of GET /offer/select_page.htm?needsignin=1 returned in 657ms51Testing软件测试网Y9jZ&qH d"^+q)J$N

Detail: 0 [657ms, 100%] - process HTTP request

       +---0 [0ms] - Preparing request context: BufferedRequestContextImpl(14723050)51Testing软件测试网/v F3I,\ {?([#E7m~
k:_

       +---0 [0ms] - Preparing request context: LazyCommitRequestContextImpl(19925149)51Testing软件测试网:lx
M ^TP.x

       +---0 [0ms] - Preparing request context: ParserRequestContextImpl(8754866)51Testing软件测试网 KARD,iUfJf

       +---0 [1ms, 0%, 0%] - Preparing request context: SessionRequestContextImpl(6861740)

       +---1 [6ms, 1%, 1%] - Preparing request context: SetLocaleRequestContextImpl(32252426)51Testing软件测试网)HP(m E3N!lQ,w&^$ip

       |  `---1 [6ms (5ms), 100%, 1%] - Decoding cookie for session object51Testing软件测试网NoW2v5F _*rrv
@

       |      `---1 [1ms, 17%, 0%] - Decrypting cookie for session object

       +---7 [1ms, 0%, 0%] - Preparing request context: RewriteRequestContextImpl(5203636)

       +---8 [0ms] - Preparing request context: RemoteAddrRequestContextImpl(14670479)

       +---8 [0ms] - Preparing request context: ChinaRunData(8789037)

       +---8 [16ms, 2%, 2%] - before request51Testing软件测试网2g `
|2n
Cs@.XI

       +---24 [625ms (84ms), 95%, 95%] - handle request

       |  +---94 [289ms (52ms), 46%, 44%] - load and execute screen module: SelectPage (template: screen/selectPage.vm)51Testing软件测试网WX`;?3_#x
{

       |  |  +---145 [94ms, 33%, 14%] - Dispatch and process command: offerBaseAO51Testing软件测试网}'CGB![f9K.w Q

       |  |  `---240 [143ms (119ms), 49%, 22%] - render velocity template: /screen/selectPage.vm51Testing软件测试网#l|o1Gr@#Q%U

       |  |      +---327 [11ms (4ms), 8%, 2%] - load and execute control module: TemplateControl (template: control/post/style.vm)

       |  |      |  `---331 [7ms, 64%, 1%] - render velocity template: /control/post/style.vm

       |  |      `---363 [13ms, 9%, 2%] - load and execute control module: TemplateControl (template: control/excelpost/uploadExcelModule.vm)51Testing软件测试网u'J5K'q R@7B

       |  |          `---363 [13ms, 100%, 2%] - render velocity template: /control/excelpost/uploadExcelModule.vm

       |  `---397 [252ms, 40%, 38%] - load and execute layout module: TemplateLayout51Testing软件测试网2n*j(e#^%cqr

       |      `---397 [252ms (128ms), 100%, 38%] - render velocity template: /layout/myalibaba.vm51Testing软件测试网gP+X2n,m&Y

       |          +---453 [21ms (9ms), 8%, 3%] - load and execute control module: home:TemplateControl (template: control/share/meta.vm)51Testing软件测试网F![(mj%u)uPM{

       |          |  `---462 [12ms, 57%, 2%] - render velocity template: /control/share/meta.vm51Testing软件测试网#hA(siR pS/i!jy

       |          +---494 [5ms, 2%, 1%] - load and execute control module: home:TemplateControl (template: control/common/style/myalibaba.vm)

       |          |  `---494 [5ms, 100%, 1%] - render velocity template: /control/common/style/myalibaba.vm

       |          +---508 [2ms, 1%, 0%] - load and execute control module: TemplateControl (template: control/excelpost/uploadExcelDiv.vm)51Testing软件测试网P.a*x:k.y9Ar.dv:o

       |          |  `---508 [2ms, 100%, 0%] - render velocity template: /control/excelpost/uploadExcelDiv.vm

       |          +---524 [3ms, 1%, 0%] - load and execute control module: home:TemplateControl (template: control/common/top/top.vm)51Testing软件测试网,K,d2DEJ mg

       |          |  `---524 [3ms, 100%, 0%] - render velocity template: /control/common/top/top.vm

       |          +---542 [83ms, 33%, 13%] - load and execute control module: home:TemplateControl (template: control/common/menu/myalibabaLeftMenu.vm)

       |          |  `---542 [83ms (30ms), 100%, 13%] - render velocity template: /control/common/menu/myalibabaLeftMenu.vm

       |          |      `---572 [53ms, 64%, 8%] - load and execute control module: home:TemplateControl (template: control/common/style/menuArray.vm)51Testing软件测试网5bv0@&Z?*Q/p

       |          |          `---572 [53ms, 100%, 8%] - render velocity template: /control/common/style/menuArray.vm51Testing软件测试网 G}&M7VQ3m

       |          `---639 [10ms (1ms), 4%, 2%] - load and execute control module: home:TemplateControl (template: control/common/bottom/bottom.vm)51Testing软件测试网1\(^"d3YN I$T }K

       |              `---640 [9ms, 90%, 1%] - render velocity template: /control/common/bottom/bottom.vm51Testing软件测试网1Qdu _iv_ x

       +---649 [2ms, 0%, 0%] - after request

       +---651 [0ms] - Committing request context: ChinaRunData(8789037)51Testing软件测试网-]tP!Mk$w#H!hH

       +---651 [0ms] - Committing request context: RemoteAddrRequestContextImpl(14670479)

       +---651 [0ms] - Committing request context: RewriteRequestContextImpl(5203636)

       +---651 [0ms] - Committing request context: SetLocaleRequestContextImpl(32252426)

       +---651 [5ms (2ms), 1%, 1%] - Committing request context: SessionRequestContextImpl(6861740)51Testing软件测试网9I FW,v&m$D Z ^)T

       |  `---652 [3ms, 60%, 0%] - Encoding cookie for session object

       |      `---655 [0ms] - Encrypting cookie for session object