坑暗花明：又遇 .NET Core 中 System.Data.SqlClient 查询缓慢的问题

栏目: ASP.NET · 发布时间: 5年前

内容简介：之前发布过一篇博文这两天我们又在另外一个 ASP.NET Core 2.2 项目中也遇到了查询 100 数据库记录速度慢（需要4~6秒）的问题，而且所查询的数据库表数据量并不是很大。通过 EF Core 的日志记录发现耗时发生在 Executed DbCommand 时，耗时发生点与之前的情况不一样，之前是发生在 Executed DbCommand 之后 SqlDataReader 从数据库读取数据时。而通过 SQL Server Management Studio 执行同样的 SQL 语句只需要 20

之前发布过一篇博文下单快发货慢：一个 JOIN SQL 引起 SqlClient 读取数据慢的奇特问题，当时遇到的问题是从 SQL Server 2008 R2 中查询获取 100 条记录竟然耗时 10 多秒，排查中发现问题与 SQL 查询中包含 INNER JOIN 有关，去掉 INNER JOIN 立马查询飞快。当时天真地以为原因是 JOIN 的那张表数据记录太多以及主表聚集索引不合理，于是采用将 INNER JOIN 部分拆分出来单独查询临时解决了问题。

这两天我们又在另外一个 ASP.NET Core 2.2 项目中也遇到了查询 100 数据库记录速度慢（需要4~6秒）的问题，而且所查询的数据库表数据量并不是很大。通过 EF Core 的日志记录发现耗时发生在 Executed DbCommand 时，耗时发生点与之前的情况不一样，之前是发生在 Executed DbCommand 之后 SqlDataReader 从数据库读取数据时。

2019-05-11T14:21:38.1015229+08:00 [INFORMATION] Executed DbCommand ("5,850"ms)

而通过 SQL Server Management Studio 执行同样的 SQL 语句只需要 20 毫秒左右，相差200多倍。

Executed DbCommand 日志记录的是 dbCommand.ExecuteReaderAsync 执行的时间（详见 EF Core 的源码）

result = new RelationalDataReader(
    connection,
    dbCommand,
    await dbCommand.ExecuteReaderAsync(cancellationToken),
    commandId,
    Logger);

dbCommand.ExecuteReaderAsync 的实现代码在 corefx 的 System.Data.SqlClient 中，如果是 .net core 的问题，那问题就出在 System.Data.SqlClient 。

在上次排查 SqlDataReader 读取数据速度慢问题，就曾怀疑 System.Data.SqlClient ，花了很多时间在 System.Data.SqlClient 的源码中打点排查，最终没有找到线索，这次不敢轻易怀疑它。

虽然这次的耗时发生点与上次不一样，但这次的 SQL 查询语句中有个地方和上次是一样的，也包含 INNER JOIN 查询，于是试着去掉 INNER JOIN ，Executed DbCommand 只需2毫秒。

[INFORMATION] Executed DbCommand ("2"ms)

啊，怎么也与 INNER JOIN 有关，没道理啊，这次 JOIN 的表数据量不大，完全不可能造成 200 多倍的性能之差。看来上次归罪于 INNER JOIN ，可能是冤枉它了，得重新思考与排查这个问题。

由于问题是在某个时间点之后出现，于是采取笨方法，回退 git 提交历史直至问题消失。。。

最终发现，竟然是在一次 git commit 中给这个查询在 SELECT 时增加了1个字段引起的，去掉这个字段，问题立马消失。进一步测试发现，只要任意去掉 SELECT 中的1个字段，就不会出现问题，太奇怪了。数了数 SELECT 中有20个字段，难道与 SELECT 字段的数量有关？之前的项目会不会也与 SELECT 字段的数量有关？

于是回到之前的项目，恢复 INNER JOIN 查询，这时惊讶地发现 SqlDataReader 读取数据速度慢的问题竟然消失了。回想当时处理问题后到现在所做的变更，唯一的变更就是从 .NET Core 3.0 Preivew 4 升级到 .NET Core 3.0 Preivew 5 ，难道 3.0 Preivew 5 把这个问题给修复了？难道真的是 System.Data.SqlClient 的 bug ?

答案很容易验证，将当前遇到 Executed DbCommand 执行慢的项目升级到 .NET Core 3.0 Preivew 5 ，昨天晚上完成升级后