DotTrace系列：5. 诊断程序的 慢File 和 慢SQL

一：背景

1. 讲故事

上一篇跟大家聊到了 UI Freeze 的问题，让大家感受到了时间轴的强大和美观，这个是 perfview 所不具备的，本篇跟大家聊一下用 dottrace 诊断Windows子系统模块（File，SQL），虽然perfivew也能做这些，毕竟都是基于ETW机制，但前者占据了可观性，后者占据了信息的完整性，大家在实践上根据需要综合使用吧。

二：子系统模块诊断

1. 如何寻找慢File

有一天你发现自己的生产程序有一段时间特别卡，一时也找不到原因，后来你通过监控发现程序在卡的时候，磁盘使用量明显变高，读取达到了 125M+/s ，截图如下：

找到了蛛丝马迹之后，接下来就可以上 dottrace 了，为了防止信息有遗漏，我们选用 External .NET Process 模式，然后输入我们监控的 ConsoleApp4.exe程序，即程序后启动模式，截图如下：

故障复现之后可立即停止收集，打开收集文件，选择 File Operations 之后观察时间轴，可以看到主线程上有大片的深蓝色，说明3~22s这个时间段有大量的文件读写，接下来选中这个时间段，截图如下：

从卦象上可以看到很多信息。

SubSystems：File I/O 占比 99.9%
Direction：只有读没有写，看样子读很猛。
FileName：原来是对 1GB_LogFile.log 文件的读取。
Hotspots：TestInefficientReading 方法占比 99.9%，问题方法无疑了。

找到问题方法之后，在方法上右键选择 Show Code 即可观察到源代码，参考如下：

staticvoidTestInefficientReading(string filePath)        {            Stopwatch sw = Stopwatch.StartNew();long totalBytesRead = 0;// 最差的实现方式：逐字节读取using (FileStream fs = new FileStream(filePath, FileMode.Open, FileAccess.Read))            {int b;while ((b = fs.ReadByte()) != -1) // 逐字节读取                {                    totalBytesRead++;                }            }            sw.Stop();            Console.WriteLine($"n低效方式读取完成，总字节数: {totalBytesRead}");            Console.WriteLine($"总耗时: {sw.Elapsed.TotalSeconds:F2}秒");            Console.WriteLine($"读取速度: {(totalBytesRead / (1024 * 1024) / sw.Elapsed.TotalSeconds):F2} MB/s");        }

从卦中代码看，这是对文件按逐字节读取的方式，有些朋友可能有疑问，现在的 SSD 读取不都是几G几G 的读取吗？怎么才1G的文件要读取 5.8s，说不通哈，其实这里还有一些干扰因素，第一个是SSD都有理论值，第二个是dottrace在开启ETW时会有额外开销，不然你的诊断数据从哪里得来的？

接下来关掉 ETW，直接运行程序，你会发现程序有 近3倍 的提升，截图如下：

2. 如何诊断慢 SQL

很多时候做程序的性能优化，有一个不容忽视的点就是观察下程序没有没出现一些慢SQL，慢SQL的危害很多，如果是同步访问容易引发线程饥饿，如果是异步访问容易导致托管堆产生过多的 Overlapped 引发托管堆碎片，进而导致内存占用过高，内存过高又会引发程序频繁的GC，最终导致程序的性能低下，有一句话叫 蝴蝶效应，就是这样的真实再现。。。

接下来就是如何诊断慢SQL，如果在 SERVER 端直接开启那这个影响面就比较大，谨慎起见还是在 Client 端临时开启来点对点的针对优化，当然这东西的本质也是借助 ETW 的，而这个 ETW 只针对微软自家的 SQL SERVER，这个是有些遗憾。。。

使用 dottrace 的 timeline 模式，打开追踪文件，选择 SQL Queries 事件，观察多个线程之间的时序，看样子 SQL 都是异步哈，截图如下：

为了寻找慢SQL，观察 SQL Queries: Command 筛选器中的SQL列表，很快就找到了一个 2s 的SQL，同时也看到了它是由 FullTableScanAsync 方法产生的，截图如下：

可以点击右键 Show Code 观察方法的源代码，参考如下：

staticasync Task FullTableScanAsync(SqlConnection connection)        {var cmd = new SqlCommand(@"-- 添加2秒延迟                WAITFOR DELAY '00:00:02';                SELECT *                 FROM Orders                WHERE OrderStatus = 'Processing'                 ORDER BY OrderDate DESC", connection);using (var reader = await cmd.ExecuteReaderAsync())            {int count = 0;while (await reader.ReadAsync())                {                    count++;if (count % 100 == 0) Console.Write(".");                }                Console.WriteLine($"n找到 {count} 条处理中的订单");            }        }