IIS日志-网站运维的好帮手

对于一个须要长期维护的网站来讲，如何让网站长久稳定运行是件颇有意义的事情。 有些在开发阶段没有暴露的问题颇有可能就在运维阶段出现了，这也是很正常的。 还有些时候，咱们但愿不断地优化网站，让网站更快速的响应用户请求， 这些事情都发生在开发以后的运维阶段。

与开发阶段不一样的，运维阶段不可能让你去调试程序，发现各种问题， 咱们只能经过各类系统日志来分析网站的运行情况， 对于部署在IIS上的网站来讲，IIS日志提供了最有价值的信息，咱们能够经过它来分析网站的响应状况，来判断网站是否有性能问题， 或者存在哪些须要改进的地方。

IIS日志包含了哪些信息

我前面说到【IIS日志提供了最有价值的信息】，这些信息有哪些呢？看看这个截图吧：

这里面记录了：
1. 请求发生在什么时刻，
2. 哪一个客户端IP访问了服务端IP的哪一个端口，
3. 客户端工具是什么类型，什么版本，
4. 请求的URL以及查询字符串参数是什么，
5. 请求的方式是GET仍是POST，
6. 请求的处理结果是什么样的：HTTP状态码，以及操做系统底层的状态码，
7. 请求过程当中，客户端上传了多少数据，服务端发送了多少数据，
8. 请求总共占用服务器多长时间、等等。

这些信息在分析时有什么用途，我后面再说。先对它有个印象就能够了。

IIS日志的配置

默认状况下，IIS会产生日志文件，不过，仍是有些参数值得咱们关注。 IIS的设置界面以下（本文以 IIS 8 的界面为例）。

在IIS管理器中，选择某个网站，双击【日志】图标，请参考下图：

此时（主要部分）界面以下：

在截图中，日志的建立方式是天天产生一个新文件，按日期来生成文件名（这是默认值）。
说明：IIS使用UTC时间，因此我勾选了最下面的复选框，告诉IIS用本地时间来生成文件名。

点击【选择字段】按钮，将出现如下对话框：

注意：【发送的字段数】和【接收的字节数】默认是没有选择的。建议勾选它们。
至于其它字段，你能够根据须要来决定是否要勾选它们。

如何分析IIS日志

若是你按照我前面介绍的方法设置了IIS日志参数，那么IIS在处理请求后（的一段时间以后），会生成IIS日志。
咱们能够在【日志界面】的右边区域【操做】中点击【查看日志文件】快速定位到IIS日志的根目录， 而后到目录中寻找相应的日志文件（默认会根据应用程序池序号来区分目录）。

好比：我找到了我须要的日志：

这个文件一大堆密密麻麻的字符，如今我该如何分析它呢？

有个叫 Log Parser 的工具就能够专门解析IIS日志，咱们能够用它来查看日志中的信息。
好比我能够运行下面的命令行（说明：为了避免影响页面宽度我将命令文本换行了）：

"C:\Program Files\Log Parser 2.2\LogParser.exe" -i:IISW3C -o:DATAGRID 
"SELECT c-ip,cs-method,s-port,cs-uri-stem,sc-status,sc-win32-status,
sc-bytes,cs-bytes,time-taken FROM u_ex130615.log"

如今就能够以表格形式来阅读IIS日志了：

说明：我不推荐用这种方法来分析IIS日志，缘由有二点：
1. 慢：当日志文件稍大一点的时候，用它来分析就比较浪费时间了（尤为是须要屡次统计时）。
2. 不方便：它支持的查询语法不够丰富，没有像SQL Server针对数据表查询那样全面。

推荐的IIS日志分析方法

虽然Log Parser支持将解析的IIS日志以表格形式供人阅读，可是有时候咱们须要再作一些细致分析时，可能会按不一样的方式进行【屡次】查询， 对于这种需求，若是每次查询都直接运行Log Parser，你会浪费不少时间。 幸运的是，Log Parser支持将解析结果以多种格式导出（如下为帮助文档截图）：

在此，我建议选择输出格式为 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

若是以下：

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

date, time这二个字段看起来很不舒服，对吧？
我也很反感这个结果，下面来讲说的二种解决方法：

1. 在SQLSERVER中增长一列，而后把UTC时间换成本地时区的时间，T-SQL脚本以下：

alter table MyMVC_WebLog add RequestTime datetime
go
update 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

这样处理后，你就能够直接把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_second
from MyMVC_WebLog with(nolock)
group by scStatus
order by 3 desc

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 > 0
group by scWin32Status
order by 2 desc

下表列出了比较常见的与网络相关的错误及解释：

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次，只有2次是所有显示完成了，其他6次我提早关闭了浏览器窗口。
而后，咱们再来看IIS日志的内容：

根据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,timetaken
from dbo.MyMVC_WebLog with(nolock)
where csUriStem like '/Pages/%'
order by timeTaken desc

再或者我想再看看最慢的20个AJAX状况的响应状况，能够这样查询：

select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken
from 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_timeTaken
from MyMVC_WebLog with(nolock)
where csUriStem like '/Pages/%'
group by csUriStem
order 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就不要再使用了。

若是，您认为阅读这篇博客让您有些收获，不妨点击一下右下角的【推荐】按钮。
若是，您但愿更容易地发现个人新博客，不妨点击一下右下角的【关注 Fish Li】。
由于，个人写做热情也离不开您的确定支持。

感谢您的阅读，若是您对个人博客所讲述的内容有兴趣，请继续关注个人后续博客，我是Fish Li 。