使用 ETW 跟踪诊断 ADO.NET
5.00/5 (3投票s)
如何使用 ETW 跟踪诊断 ADO.NET
引言
当今大多数应用程序使用 ORM（对象关系映射）作为连接数据库的方式。这些库简化了底层 ADO.NET API 的使用，以至于我们甚至可能忘记在底层我们实际上是在处理关系模型。这种面向对象的奇妙世界通常会持续到第一个 SQL 异常出现的时候。如果我们正确配置了 ORM，我们应该能够仅通过其提供的日志来诊断数据库问题。但是，如果我们没有配置，或者问题出在 ADO.NET 层深处呢？我们可能会尝试使用调试器或 SQL Server Profiler。这两种工具虽然都很棒，但通常对于生产环境来说过于笨重（或过于侵入性）。幸运的是，还有一个选择——ADO.NET ETW 跟踪。在今天的文章中，我将向您展示如何启用这种跟踪，以及如何使用它来快速诊断一些数据库问题。
为此，我们将使用一个包含两个控制器、
namespace LowLevelDesign.DiagnosingAdoNet
{
public class HomeController : Controller
{
//
// GET: /Home/
public ActionResult Index()
{
using (var conn = new SqlConnection
(WebConfigurationManager.ConnectionStrings["dbconn"].ConnectionString))
{
conn.Open();
return View(conn.Query<Product>("select * from Products"));
}
}
}
}
namespace LowLevelDesign.DiagnosingAdoNet
{
public class ProductController : Controller
{
public ActionResult Edit(String productKey) {
Product prod = null;
if (!String.IsNullOrEmpty(productKey)) {
SqlConnection conn = new SqlConnection
(WebConfigurationManager.ConnectionStrings["dbconn"].ConnectionString);
conn.Open();
prod = conn.Query<Product>("select * from Products where _
ProductKey = @productKey", new { productKey }).SingleOrDefault();
}
return View(prod ?? new Product());
}
[HttpPost]
public ActionResult Edit(Product product) {
if (!ModelState.IsValid) {
return View(product);
}
using (SqlConnection conn = new SqlConnection
(WebConfigurationManager.ConnectionStrings["dbconn"].ConnectionString)) {
conn.Open();
var t = conn.BeginTransaction();
if (conn.Execute("update Products set Price = @Price where _
ProductKey = @ProductKey", product, t) == 0) {
conn.Execute("insert into Products values (@ProductKey, @Price)", product, t);
}
}
// save or update product
return RedirectToAction("Index", "Home");
}
}
}
两个视图并使用简单数据库的带有 bug 的 MVC 应用程序。
<configuration>
...
<connectionStrings>
<add name="dbconn" connectionString="Data Source=(local)\SQLEXPRESS;
Trusted_Connection=True;Initial Catalog=TestDb;Timeout=2;Max Pool Size=4" />
</connectionStrings>
...
create database TestDb;
use TestDb;
create table Products (
ProductKey varchar(20) primary key,
Price smallmoney
);
insert into Products values ('P1', 20);
insert into Products values ('P2', 12);
您可以从 这里 下载整个应用程序。现在让我们运行它（您可以使用应用程序目录中的 runiis.bat 脚本）来看看它的行为。如果您访问了产品编辑屏幕，您应该已经注意到更改未保存——这是我们的第一个问题。几次尝试后，您应该会遇到另一个问题：SQL 超时异常，这完全破坏了应用程序。
Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool.
This may have occurred because all pooled connections were in use and max pool size was reached.
开始 ADO.NET 跟踪
现在是时候开始收集跟踪以调查失败的原因了。在您的（或服务器）计算机上设置 ADO.NET 跟踪需要两个步骤。首先，您需要告知 ADO.NET 提供跟踪（此设置存储在注册表中——只需从我的诊断工具包页面 这里 运行 setup-ado.net4_x64.reg 或 setup-ado.net4_x86.reg）。其次，您需要安装实际的事件提供程序——转到 .NET Framework 目录（c:\Windows\Microsoft.NET\Framework64\v4.0.30319\）并运行 mofcomp adonetdiag.mof。通过运行 logman query providers 检查提供程序是否成功安装。
PS reader> logman query providers '{914ABDE2-171E-C600-3348-C514171DE148}'
Provider GUID
-------------------------------------------------------------------------------
System.Data.1 {914ABDE2-171E-C600-3348-C514171DE148}
The command completed successfully.
PS reader> logman query providers '{7ACDCAC8-8947-F88A-E51A-24018F5129EF}'
Provider GUID
-------------------------------------------------------------------------------
ADONETDIAG.ETW {7ACDCAC8-8947-F88A-E51A-24018F5129EF}
The command completed successfully.
最后，是时候重启应用程序了，但这次我们将后台收集其跟踪。Logman 有一个从文本文件读取提供程序配置的选项，所以让我们准备这样一个文件（您也可以在这里 找到它）——我们将它命名为 ctrl.guid.adonet。
{7ACDCAC8-8947-F88A-E51A-24018F5129EF} 0xFFFFFFFF 5 ADONETDIAG.ETW
{914ABDE2-171E-C600-3348-C514171DE148} 0xFFFFFFFF 5 System.Data.1
0xFFFFFFFF 值选择提供程序生成的所有事件，而 5 将日志详细程度设置为最高。现在，让我们从提升的命令提示符**开始收集**。
> logman start adonettrace -pf .\ctrl.guid.adonet -o adonettrace.etl -ets
The command completed successfully.
稍微玩弄一下 Web 应用程序，直到它损坏为止，然后停止跟踪收集。
> logman stop adonettrace -ets
The command completed successfully.
分析 ADO.NET 跟踪
一个名为 adonettrace.etl 的新文件应该在您运行命令的目录中创建。由于它是一个二进制文件，我们需要将其转换为更易读的格式（例如，使用 tracerpt）。
> tracerpt -of xml .\adonettrace.etl
Input
----------------
File(s):
.\adonettrace.etl
100.00%
Output
----------------
DumpFile: dumpfile.xml
Summary: summary.txt
The command completed successfully.
如您所见，tracerpt 创建了两个文件。Summary.txt 只是 etl 文件内容的摘要，而 dumpfile.xml 是实际的事件数据转储。如果您一切设置正确，dumpfile.xml 至少应该有几百 KB。此文件中的一个示例文档记录如下：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Guid="{914abde2-171e-c600-3348-c514171de148}" />
<EventID>0</EventID>
<Version>0</Version>
<Level>0</Level>
<Task>0</Task>
<Opcode>18</Opcode>
<Keywords>0x0</Keywords>
<TimeCreated SystemTime="2012-09-06T21:46:53.915622600Z" />
<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
<Execution ProcessID="2008" ThreadID="6280" ProcessorID="1"
KernelTime="30" UserTime="60" />
<Channel />
<Computer />
</System>
<EventData>
<Data Name="ModID"> 2</Data>
<Data Name="msgStr"><prov.DbConnectionHelper.ConnectionString_Set|
API> 1#, 'Data Source=(local)\SQLEXPRESS;Trusted_Connection=True;
Initial Catalog=TestDb;Timeout=2;Max Pool Size=4'
</Data>
</EventData>
<RenderingInfo Culture="pl-PL">
<Opcode>TextW</Opcode>
<Provider>Bid2Etw_System_Data_1</Provider>
<EventName xmlns=
"http://schemas.microsoft.com/win/2004/08/events/trace">System.Data</EventName>
</RenderingInfo>
<ExtendedTracingInfo xmlns=
"http://schemas.microsoft.com/win/2004/08/events/trace">
<EventGuid>{914abde3-171e-c600-3348-c514171de148}</EventGuid>
</ExtendedTracingInfo>
</Event>
正如您所见，此类记录中提供了大量信息。在大多数诊断情况下，检查 <Execution> 和 <Data Name=”msgStr”> 标签就足够了。<Execution> 标签对我们很有趣，因为它包含一个系统进程 ID。我忘了提的是，ETW 跟踪是全局收集的，所以如果系统中有更多应用程序在“收集”时使用了 ADO.NET，它们的跟踪也将包含在 .etl 文件（因此也包含在 dumpfile.xml）中。<Data Name=”msgStr”> 标签包含实际的 ADO.NET 日志。由于此信息可能有点难读，Microsoft 创建了一个命名约定（更多信息 在此），这有助于您组织跟踪。您也可以使用 AdoNetTraceReader ，它将提取消息字符串，缩进日志块，并最终按 PID 过滤它们。您可以从 我的 .NET 诊断工具包页面 下载此工具，并针对您的 dumpfile.xml 运行它。
> .\AdoNetTraceReader.exe -i dumpfile.xml -o parsed.txt -p 2008
2008 代表我机器上的 Web 应用程序池 ID。
现在是时候看看跟踪能告诉我们关于我们遇到的数据库问题的什么了。让我们先诊断一下应用程序为什么会崩溃。异常消息告诉我们连接池正在泄漏，这意味着代码中有一些地方在使用后没有关闭数据库连接。查找 START <sc.SqlConnection.Open|API> 以找到所有连接打开的地方。每次打开都应该有一个相应的关闭阶段：START <sc.SqlConnection.Close|API>。正如您在下面的代码片段中看到的，每个打开的连接都有自己的序号。使用此编号，我们可以跟踪特定连接发生了什么。
START <sc.SqlConnection.Open|API> 3#
<sc.SqlConnection.Open|API|Correlation> ObjectID3#,
ActivityID fd1e3c4a-fd2e-48a3-aeed-4d040907b07f:4
<prov.DbConnectionPool.GetConnection|RES|CPOOL> 1#, Getting connection.
<prov.DbConnectionPool.GetFromGeneralPool|RES|CPOOL> 1#,
Connection 5#, Popped from general pool.
<prov.DbConnectionInternal.PostPop|RES|CPOOL> 5#,
Preparing to pop from pool, owning connection 0#, pooledCount=0
<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 5#, Activating
END
...
START <sc.SqlConnection.Close|API> 3#
<sc.SqlConnection.Close|API|Correlation> ObjectID3#,
ActivityID fd1e3c4a-fd2e-48a3-aeed-4d040907b07f:6
<prov.DbConnectionInternal.PrePush|RES|CPOOL> 5#,
Preparing to push into pool, owning connection 0#, pooledCount=0
<prov.DbConnectionPool.DeactivateObject|RES|CPOOL> 1#, Connection 5#, Deactivating.
<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> 5#, Deactivating
<sc.SqlInternalConnection.Deactivate|ADV> 5# deactivating
<sc.TdsParser.Deactivate|ADV> 2# deactivating
<sc.TdsParser.Deactivate|STATE> 2#,
_physicalStateObj = False
_pMarsPhysicalConObj = True
_state = OpenLoggedIn
_server = (local)\SQLEXPRESS
_fResetConnection = False
_defaultCollation = (LCID=1045, Opts=25)
_defaultCodePage = 1250
_defaultLCID = 1045
_defaultEncoding = System.Text.SBCSCodePageEncoding
_encryptionOption = OFF
_currentTransaction = (null)
_pendingTransaction = (null)
_retainedTransactionId = 0
_nonTransactedOpenResultCount = 0
_connHandler = 5
_fMARS = False
_sessionPool = (null)
_isShiloh = True
_isShilohSP1 = True
_isYukon = True
_sniSpnBuffer = 1290
_errors = (null)
_warnings = (null)
_attentionErrors = (null)
_attentionWarnings = (null)
_statistics = True
_statisticsIsInTransaction = False
_fPreserveTransaction = False _fParallel = False
<prov.DbConnectionPool.PutNewObject|RES|CPOOL> 1#, Connection 5#, Pushing to general pool.
END
掌握了这些知识，我们应该能够快速找到第一个泄漏的连接——就我而言
START <sc.SqlConnection.Open|API> 6#
<sc.SqlConnection.Open|API|Correlation> ObjectID6#,
ActivityID fd1e3c4a-fd2e-48a3-aeed-4d040907b07f:10
<prov.DbConnectionPool.GetConnection|RES|CPOOL> 1#, Getting connection.
<prov.DbConnectionPool.GetFromGeneralPool|RES|CPOOL> 1#, Connection 5#, Popped from general pool.
<prov.DbConnectionInternal.PostPop|RES|CPOOL> 5#,
Preparing to pop from pool, owning connection 0#, pooledCount=0
<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 5#, Activating
现在是时候找出应用程序的哪个部分使用了这个连接了。阅读跟踪的下一行会显示执行的 SQL 查询及其参数——@ProductKey = 'P1'（高亮显示的行）。
...
<sc.SqlCommand.set_CommandText|API> 7#, 'select * from Products where ProductKey = @productKey'
<sc.SqlCommand.ExecuteDbDataReader|API|Correlation> ObjectID7#,
ActivityID fd1e3c4a-fd2e-48a3-aeed-4d040907b07f:11
<sc.TdsParser.GetSession|ADV> 2# getting physical session 2
<sc.SqlCommand.ExecuteReader|INFO> 7#, Command executed as RPC.
<sc.TdsParser.WritePacket|INFO|ADV>
Packet sent00000000: 03 09 01 00 00 00 01 00 | 16 00 00 00 12 00 00 00 ................
00000010: 02 00 00 00 00 00 00 00 | 00 00 01 00 00 00 FF FF ................
00000020: 0A 00 02 00 00 00 E7 6A | 00 15 04 D0 00 00 6A 00 .......j......j.
00000030: 73 00 65 00 6C 00 65 00 | 63 00 74 00 20 00 2A 00 s.e.l.e.c.t. .*.
00000040: 20 00 66 00 72 00 6F 00 | 6D 00 20 00 50 00 72 00 .f.r.o.m. .P.r.
00000050: 6F 00 64 00 75 00 63 00 | 74 00 73 00 20 00 77 00 o.d.u.c.t.s. .w.
00000060: 68 00 65 00 72 00 65 00 | 20 00 50 00 72 00 6F 00 h.e.r.e. .P.r.o.
00000070: 64 00 75 00 63 00 74 00 | 4B 00 65 00 79 00 20 00 d.u.c.t.K.e.y. .
00000080: 3D 00 20 00 40 00 70 00 | 72 00 6F 00 64 00 75 00 =. .@.p.r.o.d.u.
00000090: 63 00 74 00 4B 00 65 00 | 79 00 00 00 E7 34 00 15 c.t.K.e.y....4..
000000A0: 04 D0 00 00 34 00 40 00 | 70 00 72 00 6F 00 64 00 ....4.@.p.r.o.d.
000000B0: 75 00 63 00 74 00 4B 00 | 65 00 79 00 20 00 6E 00 u.c.t.K.e.y. .n.
000000C0: 76 00 61 00 72 00 63 00 | 68 00 61 00 72 00 28 00 v.a.r.c.h.a.r.(.
000000D0: 34 00 30 00 30 00 30 00 | 29 00 0B 40 00 70 00 72 4.0.0.0.)..@.p.r
000000E0: 00 6F 00 64 00 75 00 63 | 00 74 00 4B 00 65 00 79 .o.d.u.c.t.K.e.y
000000F0: 00 00 E7 40 1F 15 04 D0 | 00 00 04 00 50 00 31 00 ...@........P.1.
...
在我们的简单应用程序中，我们很快就发现是 ProductController 的 Edit 操作泄漏了连接。
还有一个问题需要调查：价格未更新。那么，让我们找到更新语句的跟踪。
update Products set Price = @Price where ProductKey = @ProductKey:
...
<prov.DbConnectionInternal.ActivateConnection|RES|INFO|CPOOL> 7#, Activating
END
START <sc.SqlConnection.BeginTransaction|API> 3#,
iso=-1{ds.IsolationLevel}, transactionName='None'
<sc.SqlInternalTransaction.ctor|RES|CPOOL> 1#,
Created for connection 7#, outer transaction 1#, Type 2
<sc.TdsParser.WritePacket|INFO|ADV>
Packet sent 00000000: 0E 01 00 22 00 00 01 00 | 16 00 00 00 12 00 00 00 ..."............
00000010: 02 00 00 00 00 00 00 00 | 00 00 01 00 00 00 05 00 ................
00000020: 02 00 | ..
<sc.TdsParser.ReadNetworkPacket|INFO|ADV>
Packet read 00000000: 04 01 00 23 00 34 01 00 | E3 0B 00 08 08 01 00 00 ...#.4..........
00000010: 00 34 00 00 00 00 FD 00 | 00 FD 00 00 00 00 00 00 .4..............
00000020: 00 00 00 | ...
END
<prov.DbConnectionHelper.ConnectionString_Get|API> 3#
START <prov.DbConnectionHelper.CreateDbCommand|API> 3#
<sc.SqlCommand.set_Connection|API> 3#, 3#
END
<sc.SqlCommand.set_Transaction|API> 3#
<sc.SqlCommand.set_CommandText|API> 3#, '
update Products set Price = @Price where ProductKey = @ProductKey '
START <sc.SqlCommand.ExecuteNonQuery|API> 3#
<sc.SqlCommand.ExecuteNonQuery|INFO> 3#, Command executed as RPC.
<sc.TdsParser.GetSession|ADV> 2# getting physical session 2
...
通过查看命令之前的几行，我们可以看到它是在事务中运行的。
START <sc.SqlConnection.BeginTransaction|API> 3#, iso=-1{ds.IsolationLevel}, transactionName='None'
从进一步的跟踪中，我们读到执行命令时没有错误，所以让我们专注于关闭阶段。
START <sc.SqlConnection.Close|API> 3#
<prov.DbConnectionInternal.CloseConnection|RES|CPOOL> 7# Closing.
...
<sc.TdsParser.Deactivate|STATE> 2#,
_physicalStateObj = False
_pMarsPhysicalConObj = True
_state = OpenLoggedIn
_server = (local)\SQLEXPRESS
_fResetConnection = False
_defaultCollation = (LCID=1045, Opts=25)
_defaultCodePage = 1250
_defaultLCID = 1045
_defaultEncoding = System.Text.SBCSCodePageEncoding
_encryptionOption = OFF
_currentTransaction = (ObjId=1, tranId=223338299393,_
state=Active, type=LocalFromAPI, open=0, disp=False
_pendingTransaction = (null)
_retainedTransactionId = 0
_nonTransactedOpenResultCount = 0
_connHandler = 7
_fAsync = False
_fMARS = False
_fAwaitingPreLogin = False
_fPreLoginErrorOccurred = False
_sessionPool = (null)
_isShiloh = True
_isShilohSP1 = True
_isYukon = True
_sniSpnBuffer = 1290
_errors = (null)
_warnings = (null)
_attentionErrors = (null)
_attentionWarnings = (null)
_statistics = True
_statisticsIsInTransaction = True
_fPreserveTransaction = False _fParallel = False
<sc.SqlInteralTransaction.CloseFromConnection|RES|CPOOL> 1#, Closing
高亮显示的行
-
_currentTransaction = (ObjId=1, tranId=223338299393, state=Active, type=LocalFromAPI, open=0, disp=False
-
<sc.SqlInteralTransaction.CloseFromConnection|RES|CPOOL> 1#, Closing
应该引起我们的怀疑。它们告诉我们在关闭阶段，事务仍然处于活动状态（_currentTransaction 不为 null），然后只有在连接被丢弃时才关闭。这就解释了为什么我们的更改没有反映在数据库中。在 ProductController 的 [HttpPost]Edit 操作的 return 语句之前添加 t.Commit() 可以解决我们的问题。我将把它作为一项练习留给您，以检查事务提交（或回滚）时的跟踪情况。
我希望本文提供的信息能够帮助您诊断未来的任何 ADO.NET 异常。如果您想进一步试验 ADO.NET 跟踪，请随时从 这里 下载示例应用程序代码。MSDN 上也有关于数据访问跟踪的精彩文章 MSDN，其中介绍了更多的提供程序和跟踪选项 
。
归类于： CodeProject, 诊断 ADO.NET
