我编写了一个非常简单的应用程序，它接受 XML 文件中的成批遥测日志行并将它们转录到 SQL Server 上的表中。我将这些传入数据块中的每一个称为“章节”。
出于性能原因，每一章都包含在一个事务中，这样就不是一百个隐式事务，而是一个针对 100 个新行的事务。
不幸的是，存在重复，并且由于共享事务上下文，它们占用了整章。这是不常见的，但并不罕见到可以忽略。所以我添加了一个循环、一个重试标志和一个维护跳过列表的捕获（SqlException）。当插入一行时，我回滚事务，创建一个新事务，将行号添加到跳过列表，设置重试标志并让它循环。除跳过列出的行外，所有行都被重新处理。如果第二行 barfs，除了跳过列表有两个项目外，会发生同样的事情。
整个安排有效。给我咖喱的是最后的游戏。当章节被端到端处理而没有任何异常时，循环退出，然后我检查跳过列表是否为空。当它不为空时，我尝试使用 Trace.TraceWarning() 编写一个事件日志条目，详细说明失败的行和 XML 块，以供以后取证。
正是在这一点上，事情向南发展。此 Trace 语句带有一个声称“设备未准备好”的 Win32 异常。
有没有人见过这样的事情？
一夜之间，我注意到它偶尔会毫无怨言地工作。我在 Trace.TraceWarning() 之前插入了一个 Thread.Sleep()，所以看看这是否能解决它会很有趣。我可能应该补充一点，我注意到该消息已成功记录到 Visual Studio 的跟踪侦听器中，这就是让我认为它与速度或时间相关的原因。
一天后，很明显，睡眠线程没有任何区别。我已经重写了整个业务，以便 StringBuilder 累积状态，并且在循环退出后会出现单个跟踪语句。Win32Exception 不再明显，即使在拒绝多行需要两次以上通过时也是如此。究竟是什么导致了该特定异常，我仍不清楚。我希望有人可以为这个黑暗的角落投下光明，但我没有什么要补充的，因为每章只有一个日志条目是理想的；即使没有 Win32Exception，“解决方法”也将是对代码的改进。
说得太早了。邪恶的 Win32Exception 又回来了。这是它的代码：
public void Write(string xml)
{
StringBuilder sb = new StringBuilder();
//Trace.TraceInformation(xml);
SqlConnection cxn = new SqlConnection(Properties.Settings.Default.DatabaseBob);
cxn.Open();
SqlTransaction txn = null;
SqlCommand cmd = new SqlCommand("INSERT INTO LOG(MAC, snip more fields ) VALUES(@MAC, snip more params)", cxn);
var P = cmd.Parameters;
P.Add(new SqlParameter("@MAC", SqlDbType.BigInt));
/*snip define more SQL params*/
XmlDocument doc = new XmlDocument();
bool barfed = false;
List<int> skipList = new List<int>();
_stopwatch.Start();
int i = 0;
doc.LoadXml(xml);
var root = doc.FirstChild.NextSibling;
P["@MAC"].Value = ulong.Parse(root.Attributes["MAC"].Value, System.Globalization.NumberStyles.AllowHexSpecifier);
P["@D2"].Value = P["@D3"].Value = 0; //COM2
do
try
{
cmd.Transaction = txn = cxn.BeginTransaction();
i = 0;
barfed = false;
for (var n = root.FirstChild; n != null; n = n.NextSibling)
{
foreach (XmlAttribute attr in n.Attributes)
{
var p = P["@" + attr.Name];
switch (p.SqlDbType)
{
case SqlDbType.DateTime:
p.Value = DateTime.Parse(attr.Value).ToUniversalTime();
break;
case SqlDbType.Float:
p.Value = float.Parse(attr.Value);
break;
case SqlDbType.Bit:
p.Value = Convert.ToBoolean(int.Parse(attr.Value));
break;
}
}
i++;
if (!skipList.Contains(i))
if ((DateTime)P["@GPSTIME"].Value > DateTime.UtcNow.AddMinutes(1))
{
sb.AppendFormat("Node {0} is being skipped because it has a future date.\r\n", i);
skipList.Add(i);
}
else
cmd.ExecuteNonQuery();
}
txn.Commit();
sb.AppendFormat("{0} logs per {1}ms", i, _stopwatch.ElapsedMilliseconds);
}
catch (SqlException)
{
sb.AppendFormat("Node {0} is being skipped because it is a duplicate.\r\n", i);
txn.Rollback();
skipList.Add(i);
barfed = true;
}
catch (Exception ex)
{
sb.AppendLine(ex.Message);
txn.Rollback();
}
while (barfed);
_stopwatch.Reset();
if (skipList.Count == 0)
Trace.TraceInformation(sb.ToString());
else
{
sb.AppendLine();
sb.Append(xml);
Trace.TraceWarning(sb.ToString());
}
}
这是异常的堆栈跟踪：
at System.Diagnostics.EventLogInternal.InternalWriteEvent(UInt32 eventID, UInt16 category, EventLogEntryType type, String[] strings, Byte[] rawData, String currentMachineName)
at System.Diagnostics.EventLogInternal.WriteEvent(EventInstance instance, Byte[] data, Object[] values)
at System.Diagnostics.EventLog.WriteEvent(EventInstance instance, Object[] values)
at System.Diagnostics.EventLogTraceListener.TraceEvent(TraceEventCache eventCache, String source, TraceEventType severity, Int32 id, String message)
at System.Diagnostics.TraceInternal.TraceEvent(TraceEventType eventType, Int32 id, String format, Object[] args)
at System.Diagnostics.Trace.TraceWarning(String message)
at Bob.ChapterWriter.Write(String xml) in I:\Project Bob\LogWriter\ChapterWriter.cs:line 179
at SyncInvokeWrite(Object , Object[] , Object[] )
at System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)
at System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(MessageRpc& rpc)
WCF 调用 Write 方法以响应 MSMQ 消息的到达。消息的内容是 XML 字符串。删除事件日志侦听器使问题消失（到目前为止）。
对于那些检查堆栈跟踪的人来说，第 179 行位于粘贴代码的末尾。这里又是：
Trace.TraceWarning(sb.ToString());
我突然想到：我想知道是不是因为 XML 使消息对于事件日志来说太大了？我已经有一个限制章节文件大小的设置。我会尝试减少它，看看会发生什么。