# II自带日志分析工具

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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2F2zk99MSKGMy2dm4fwYvM%2Fimage.png?alt=media\&token=507bc688-0ddf-4a6f-bc1d-c762c69cc5ab)

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

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

IIS日志的配置

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

在IIS管理器中，选择某个网站，双击【日志】图标，请参考下图：![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FuIgeoivJ2i4mkCze77sR%2Fimage.png?alt=media\&token=2b3c9c6d-2a1a-422d-adbd-a68072c22e13)

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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2Fe7Xp6t5hbp6eNRdXgq5q%2Fimage.png?alt=media\&token=20705298-8c07-471f-98a7-2762aae472ea)

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

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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2Fxjz1UPIqJ10CGnC7bDVi%2Fimage.png?alt=media\&token=68f1dfa8-8e80-45b9-be06-d770e648f8e1)

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

如何分析IIS日志

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

比如：我找到了我需要的日志：

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FFoFUG5G8L7lejemLX4Jn%2Fimage.png?alt=media\&token=26791901-73a2-4b71-9c02-4e175e6fa8a4)

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

有个叫 [**Log Parser**](http://www.microsoft.com/en-us/download/details.aspx?id=24659) 的工具就可以专门解析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日志了：

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2F6E6qzF56F5YmvIwzQagx%2Fimage.png?alt=media\&token=664a1ca3-caea-46cc-b4f1-eb8fc3d0a3e6)

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

推荐的IIS日志分析方法

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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FJZN8tyHBf9fIUDcXeLeA%2Fimage.png?alt=media\&token=c2098fae-b91e-4d18-a80b-25289e173de0)

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

如果如下：\


![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FW5yVJzifyQbpt5mn15fh%2Fimage.png?alt=media\&token=b20ba8d3-b68d-4d22-892a-120df7cf06b2)

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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2F23BqF7TOnRyLU3yN1IIx%2Fimage.png?alt=media\&token=2eb31208-3de0-494e-9656-336a80979bd5)

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\


![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FEXqRrMb9VeY4b8HqWGhP%2Fimage.png?alt=media\&token=fcac439c-59f2-4d93-becb-69dc54f0cf1d)

这样处理后，你就可以直接把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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FlkTOtk9X8kaETXPlumXv%2Fimage.png?alt=media\&token=aa26fc49-34cf-4d62-83e3-25ef74ea7b5f)\
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

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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FyrzI8PeARVKzoJlRYMvL%2Fimage.png?alt=media\&token=3eab1a57-6450-4cb4-9977-8ef5ba038339)

| 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";\</p> \<p> 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);\</p> \<p> 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);\
}\</p> \<p> context.Response.Write("End");\
}\
\
段代码很简单，我不想做过多的解释，只想说一句：我用Thread.Sleep与Response.Flush这二个方法来模拟一个长时间的持续发送过程。

我们可以在浏览器中看到这样的输出（显示还没有完全结束时我截图了）

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2FrOKN7mk5czRDYvjow6Uv%2Fimage.png?alt=media\&token=30bdf2d2-b597-451f-b330-c85d3256e2b4)

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

![](https://3504178614-files.gitbook.io/~/files/v0/b/gitbook-x-prod.appspot.com/o/spaces%2F9pUnnHKrKhH99NhIo8OF%2Fuploads%2F07mhMKuYAZymwJU5R8Bl%2Fimage.png?alt=media\&token=0ae62c99-cc42-4cbb-93c4-7a8c8be09b7e)

根据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,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如果过大，我们就要分析一下到底是不是因为表单包含了过多的无用数据，可否将表单拆分。\
&#x20;  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响应也是一个页面响应，而且它们也会占用网络传输时间，尤其是这类请求不能缓存，它会一直出现，浪费网络资源。
