多语言展示
当前在线:1231今日阅读:168今日分享:49

推荐一个IIS日志分析方法

对于一个需要长期维护的网站来说,如何让网站长久稳定运行是件很有意义的事情。 有些在开发阶段没有暴露的问题很有可能就在运维阶段出现了,这也是很正常的。 还有些时候,我们希望不断地优化网站,让网站更快速的响应用户请求, 这些事情都发生在开发之后的运维阶段。  与开发阶段不同的,运维阶段不可能让你去调试程序,发现各类问题, 我们只能通过各种系统日志来分析网站的运行状况, 对于部署在IIS上的网站来说,IIS日志提供了最有价值的信息,我们可以通过它来分析网站的响应情况,来判断网站是否有性能问题, 或者存在哪些需要改进的地方。
方法/步骤
1

虽然Log Parser支持将解析的IIS日志以表格形式供人阅读,但是有时候我们需要再做一些细致分析时,可能会按不同的方式进行【多次】查询, 对于这种需求,如果每次查询都直接运行Log Parser,你会浪费很多时间。 幸运的是,Log Parser支持将解析结果以多种格式导出(以下为帮助文档截图):

2

在此,我建议选择输出格式为 SQL 。  注意:这里的SQL并不是指SQLSERVER,而是指所有提供ODBC访问接口的数据库。  我可以使用下面的命令将IIS日志导入到SQLSERVER中(说明:为了不影响页面宽度我将命令文本换行了):'C:\Program Files\Log Parser 2.2\logparser.exe'   'SELECT  *  FROM  'D:\Temp\u_ex130615.log'  to MyMVC_WebLog' -i:IISW3C -o:SQL -oConnString:'Driver={SQL Server};server=localhost\sqlexpress;database=MyTestDb;Integrated Security=SSPI' -createtable:ON  导入完成后,我们就可以用熟悉的SQLSERVER来做各种查询和统计分析了,例如下面的查询:SELECT cip,csmethod,sport,csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken FROM dbo.MyMVC_WebLog  如果如下:

3

1. IIS日志在将结果导出到SQLSERVER时,字段名中不符合标识符规范的字符将会删除。  例如:c-ip 会变成 cip, s-port 会变成 sport 。  2. IIS日志中记录的时间是UTC时间,而且把日期和时间分开了,导出到SQLSERVER时,会生成二个字段:

4

date, time这二个字段看起来很不舒服,对吧?  我也很反感这个结果,下面来说说的二种解决方法:  1. 在SQLSERVER中增加一列,然后把UTC时间换成本地时区的时间,T-SQL脚本如下:alter table MyMVC_WebLog add RequestTime datetime goupdate MyMVC_WebLog set RequestTime=dateadd(hh,8,convert(varchar(10),date,120)            + ' ' + convert(varchar(13),time,114))  2. 直接在导出IIS日志时,把时间转换过来,此时要修改命令:'C:\Program Files\Log Parser 2.2\logparser.exe'   'SELECT TO_LOCALTIME(TO_TIMESTAMP(ADD(TO_STRING(date, 'yyyy-MM-dd '), TO_STRING(time, 'hh:mm:ss')), 'yyyy-MM-dd hh:mm:ss')) AS RequestTime, *  FROM  'D:\Temp\u_ex130615.log'  to  MyMVC_WebLog2' -i:IISW3C -o:SQL -oConnString:'Driver={SQL Server};server=localhost\sqlexpress;database=MyTestDb;Integrated Security=SSPI'-createtable:ON  再看这三列:select RequestTime, date, time from MyMVC_WebLog2

5

这样处理后,你就可以直接把date, time这二列删除了(你也可以在导出IIS日志时忽略它们,但要明确指出每个字段名)。  IIS日志中的UTC时间问题就说到这里,但愿每个人都懂了~~~~~~~~~~~  IIS日志中的异常记录  IIS日志中记录了每个请求的信息,包括正常的响应请求和有异常的请求。  这里所说的【异常】与 .net framework 中的异常没有关系。  对于一个ASP.NET程序来说,如果抛出一个未捕获异常,会记录到IIS日志中(500),但我所说的异常不仅限于此。  本文所说的异常可分为四个部分:  1. (ASP.NET)程序抛出的未捕获异常,导致服务器产生500的响应输出。  2. 404之类的请求资源不存在错误。  3. 大于500的服务器错误,例如:502,503  4. 系统错误或网络传输错误。  前三类异常可以用下面的查询获得:select scStatus, count(*) AS count, sum(timetaken * 1.0) /1000.0 AS sum_timetaken_secondfrom MyMVC_WebLog with(nolock)group by scStatusorder by 3 desc

6

IIS日志中有一列:sc-win32-status ,它记录了在处理请求过程中,发生的系统级别错误,例如网络传输错误。  正常情况下,0 表示正常,出现非零值意味着出现了错误。我们可以这样统计这类错误:declare @recCount bigint;select @recCount = count(*) from MyMVC_WebLog with(nolock)select scWin32Status, count(*) AS count, (count(*) * 100.0 / @recCount) AS [percent] from MyMVC_WebLog with(nolock)where scWin32Status > 0group by scWin32Statusorder by 2 desc

7

下表列出了比较常见的与网络相关的错误及解释:scWin32Status含义64客户端连接已关闭(或者断开)121传输超时1236本地网络中断  所有状态码都可以通过下面的命令来获取对应的解释:D:\Temp>net helpmsg 64指定的网络名不再可用。  关于scwin32status与scStatus,我还想补充说明一下:它们没有关联。  比如请求这个地址:http://www.abc.com/test.aspx  有可能scStatus=200,但scwin32status=64,此时表示ASP.NET已成功处理请求,但是IIS在发送响应结果时,客户端的连接断开了。  另一种情况是:scStatus=500,但scwin32status=0,此时表示,在处理请求过程中发生了未捕获异常,但异常结果成功发送给客户端。  再谈 scwin32status=64  记得以前看到 scStatus=200,scwin32status=64 这种情况时很不理解,于是搜索了互联网,各种答案都有,有的甚至说与网络爬虫有关。 为了验证各种答案,我做了一个试验。我写一个ashx文件,用它来模拟长时间的网络传输,代码如下:public class Test_IIS_time_taken : IHttpHandler {    public void ProcessRequest (HttpContext context) {        context.Response.ContentType = 'text/plain';        System.Threading.Thread.Sleep(1000 * 2);        context.Response.Write(string.Format('{0}, {1}\r\n', 'Start', DateTime.Now));        context.Response.Flush();        System.Threading.Thread.Sleep(1000 * 2);        for( int i = 0; i < 20; i++ ) {            context.Response.Write(string.Format('{0}, {1}\r\n', i, DateTime.Now));            context.Response.Flush();            System.Threading.Thread.Sleep(1000 * 1);        }        context.Response.Write('End');    }  这段代码很简单,我不想做过多的解释,只想说一句:我用Thread.Sleep与Response.Flush这二个方法来模拟一个长时间的持续发送过程。  我们可以在浏览器中看到这样的输出(显示还没有完全结束时我截图了)

8

我把这个测试做了8次,只有2次是全部显示完成了,其余6次我提前关闭了浏览器窗口。  然后,我们再来看IIS日志的内容:

9

根据IIS日志并结合我自己的操作可以发现:  1. 当我提前关闭浏览器窗口时,就会看到scStatus=200,scwin32status=64  2. 如果请求内容全部显示完成,我就会看到scStatus=200,scwin32status=0  从这个试验我们还可以发现:timeTaken 包含了网络传输时间。  根据这个试验的结果,你是否想过一个问题:  如果你的网站的IIS日志中出现了大量的scStatus=200,scwin32status=64, 而且请求是由用户的浏览器发起的。  这是什么原因造成的呢?  我的【猜想】是:用户在访问这个网站时已经不愿意再等待了,他们把浏览器窗口关掉了。  换句话说:可以从scwin32status=64的统计结果看出网站的响应速度是否能让用户满意。  寻找性能问题  IIS日志中有一列叫:timeTaken,在IIS的界面中显示了它的含义:所有时间。  这个所用时间的定义是:从服务端收到请求的第一个字节开始起,直到把所有响应内容发送出去为止的时间。  微软的网站有对这个字段做过说明:http://support.microsoft.com/kb/944884  知道了timeTaken的定义后,我们就可以利用它来分析一些请求的处理时间,即性能分析。  例如,我想查看最慢的20个页面的加载情况,可以这样查询:select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetakenfrom dbo.MyMVC_WebLog with(nolock)where csUriStem like '/Pages/%'order by timeTaken desc  再或者我想再看看最慢的20个AJAX情况的响应情况,可以这样查询:select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetakenfrom dbo.MyMVC_WebLog with(nolock)where csUriStem like '/ajax/%'order by timeTaken desc  总之,寻找性能问题的方法就是:在查询选择timeTaken字段,并且用它做降序排序。  注意:scbytes,csbytes 这二个字段也是值得我们关注的:  1. csbytes如果过大,我们就要分析一下到底是不是因为表单包含了过多的无用数据,可否将表单拆分。  csbytes变大还有一种可能:Cookie太大,但它会表现为很多请求的csbytes都偏大,因此容易区分。  2. scbytes如果过大,我们就要检查页面是否没有分页,或者可以考虑用按需加载的方式来实现。  典型的情况是:当大量使用ViewState时,这二个值都会变大。因此我们能通过IIS日志发现ViewState的滥用问题。  还有一种特殊情况是:上传下载文件也会导致这二个数值变大,原因我就不解释了。  scbytes,csbytes,不管是哪个数值很大,都会占用网络传输时间,对于用户来说,就需要更长的等待时间。  一下子说了三个字段,在寻找性能问题时,到底该参考哪个呢?  我认为:应该优先关注timeTaken,因为它的数值直接反映了用户的等待时间(不包括前端渲染时间)。  如果timeTaken过大时,有必要检查scbytes,csbytes是否也过大,  如果后二者也过大,那么优化的方向就是减少数据传输量,否则表示是程序处理占用了大量的时间,应该考虑优化程序代码。  寻找可改进的目标  除了可以从IIS日志中发现性能问题,还可以用它来寻找可改进的目标。  例如:  1. 有没有404错误?  2. 是否存在大量的304请求?  3. 是否存在大量重复请求?  当发现有404响应时,我们应该分析产生404的原因:  1. 是用户输入错误的URL地址吗?  2. 还是开发人员引用不存在的资源文件?  如果是后者,就应该尽快移除无效的引用,因为404响应也是一个页面响应,而且它们也会占用网络传输时间, 尤其是这类请求不能缓存,它会一直出现,浪费网络资源。  如果你希望在开发阶段就能轻易的发现404错误,可以参考我的博客:程序在发布前就应该发现的一些错误  如果发现有大量的304请求也应该仔细分析:  1. 是由于ASP.NET缓存响应而产生的304请求吗?  2. 还是请求静态资源文件时产生的304请求?  如果是后者,则有可能与浏览器的设置有关,也有可能与IIS设置有关。  IIS有个【启用内容过期】功能,可用来在输出响应时设置缓存头,减少请求数量。  此功能对静态文件有用,ASP.NET处理的结果则不受影响。  具体设置方法可参考:不修改代码就能优化ASP.NET网站性能的一些方法  我们可以用这样的查询来分析页面的加载频率:select top 20 csUriStem, count(*) AS [count],    avg(timeTaken) AS avg_timeTaken, max(timeTaken) AS max_timeTakenfrom MyMVC_WebLog with(nolock)where csUriStem like '/Pages/%'group by csUriStemorder by 2 desc  如果发现有大量的重复请求,也需要再仔细分析:  1. 请求的响应内容是否随着不同的参数而各不相同?  2. 请求的URL是固定的,响应内容也是极少变化的。  如果是后者,则可以考虑使用页面缓存功能。例如:ASP.NET的OutputCache  我的博客不修改代码就能优化ASP.NET网站性能的一些方法 介绍了一种不用修改代码就能缓存请求的功能,如果需要,可以试试。  程序架构对IIS日志分析过程的影响  前面我介绍了一些分析IIS日志的方法,这些方法的使用都离不开查询。 绝大多数时候,我们需要在查询中输出URL信息(cs-uri-stem)并依据它们分组来统计, 因此,合理的设计URL会给后期的统计带来方便, 也能得到更准确的统计结果。 一个极端的反例是:采用WebForms默认的开发方式,页面加载以及每个按钮的提交都是同一个URL,你会发现很难统计用户的每个操作花了多少时间。  怎样的URL设计才能满足统计需要呢?  我认为:每个用户操作(页面显示或者提交)都应该有一个URL与之对应,且不同的URL能反映不同的操作。  另外还建议:不同的用户操作能在URL中清楚的区分开,这样能方便做更多的统计(例如:页面加载,AJAX请求,报表显示)。  虽然我们可以用timeTaken来做性能统计,然而,当你在程序中大量使用frameset或者iframe时, 你将难以统计某个页面(包含iframe的页面)加载到底花了多长时间。 因为整个页面被分成了多个请求,它们在IIS日志中并不是连续的,你无法准确地按用户请求来统计。 例如:a1.aspx用iframe的方式嵌入了b1.aspx, b2.aspx, b3.aspx,当你统计a1.aspx的加载时间时, 你得到的结果永远和用户感受的情况不一样,因为a1.aspx的timeTaken并不包含b1.aspx, b2.aspx, b3.aspx这三个请求的timeTaken!  因此,如果你希望利用IIS日志来分析程序性能,那么iframe就不要再使用了。

推荐信息