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 即可观察到源代码，参考如下：

        static void TestInefficientReading(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 观察方法的源代码，参考如下：

        static async 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} 条处理中的订单");
            }
        }

到这里可能有人会提一个问题， Command 面板中的 SQL 是截断的，我想观察 SQL 的全貌怎么办？毕竟这是真实项目的切实需求，可以点击 View -> SQL Queries 打开，找到目标SQL之后可以copy出来，截图如下：

三：总结

用 dottrace 对程序做性能优化，效率其实还是蛮高的，而且对容易引发性能瓶颈的IO和SQL这两大模块也处理的非常好，点赞！

作为JetBrains社区内容合作者，如有购买jetbrains的产品，可以用我的折扣码 HUANGXINCHENG，有25%的内部优惠哦。