提高使用 CreateDocumentQuery 和 ExecuteNextAsync 时的性能

Posted 2023-02-19

【中文标题】提高使用 CreateDocumentQuery 和 ExecuteNextAsync 时的性能

【英文标题】：Improving performance when using CreateDocumentQuery and ExecuteNextAsync

【发布时间】：2020-11-13 12:43:43

【问题描述】：

当我直接在 Azure 门户的数据资源管理器中运行以下查询时，大约需要 2 秒才能完成。使用 DocumentDB SDK 运行相同的查询大约需要 1 分钟才能完成。为什么两种方法的性能差距如此之大？如何使用 SDK 实现相同的性能？

从 c 中选择不同的 c.docId，其中 c.documentType = 'Article' 和 LOWER(c.userId) = 'someone' 和 c.docId in (812,838,901,1557,1558,1372,1367,1592,1081,1590,1364,第1441章）

我们使用的代码：

公共异步任务> GetItemsAsync（字符串表达式，int pageSize = -1，字符串 continueToken = null） 使用 (var bench = new Benchmark(expr)) var queryable = _Client.CreateDocumentQuery(UriFactory.CreateDocumentCollectionUri(DatabaseId, CollectionId) , 表达式 , 新 FeedOptions MaxItemCount = pageSize, RequestContinuation = continueToken, EnableCrossPartitionQuery = true ) .AsDocumentQuery(); 列表结果 = new List(); 而（可查询。HasMoreResults） var queryResult = await queryable.ExecuteNextAsync(); 结果.AddRange(queryResult); 返回结果；

我们使用包 Microsoft.Azure.DocumentDB.2.11.2。 _Client 使用 ConnectionMode.Direct 和 Protocol.Tcp 打开

RequestDiagnosticsString：

QueryMetrics：分区 0 检索到的文档数：1,847 检索到的文档大小：1,166,051 字节 输出文档数：0 输出文件大小：49 字节 指数利用率：0.00 % 使用的索引 潜在指标 总查询执行时间：21.20 毫秒 查询准备时间 查询编译时间：0.22 毫秒 逻辑计划构建时间：0.22 毫秒 物理计划构建时间：0.12 毫秒 查询优化时间：0.01 毫秒 索引查找时间：0.87 毫秒 文件加载时间：13.38 毫秒 运行时执行时间 查询引擎时间：5.68 毫秒 系统功能执行时间：1.35毫秒 用户自定义函数执行时间：0.00毫秒 文档写入时间：0.00 毫秒 客户端指标 重试次数：0 请求费用：74.85 RU 分区执行时间线 ┌────────────┬──────────────────────────────────── ┬────────────────┬──────────────┬───────────────── ─┬───────────────────┬────────────┐ │Partition Id│Activity Id │开始时间（UTC）│结束时间（UTC）│持续时间（ms）│文档数│重试次数│ ├────────────┼──────────────────────────────────── ┼────────────────┼──────────────┼──────────────── ─┼─────────────────────┼────────────┤ │ 0│54693cfe-843d-404b-82da-446347d5a71f│ 02:11:28.1185Z│02:11:28.3639Z│ 245.38│ 0│ 0│ └────────────┴──────────────────────────────────── ┴────────────────┴──────────────┴───────────────── ─┴───────────────────┴────────────┘ 调度指标 ┌────────────┬──────────────────────┬─────────────── ──────┬────────────────────┬────────────────────┬── ────────────────────┐ │Partition Id│响应时间（ms）│运行时间（ms）│等待时间（ms）│周转时间（ms）│抢占次数│ ├────────────┼────────────────────┼────────────── ──────┼────────────────────┼────────────────────┼── ────────────────────┤ │ 0│ 84.02│ 245.38│ 106.94│ 352.32│ 1│ └────────────┴──────────────────────┴─────────────── ──────┴────────────────────┴────────────────────┴── ────────────────────┘ 客户端请求统计： 0：[ RequestStartTime：2020-07-25T02：11：28.3895792Z，RequestEndTime：2020-07-25T02：11：28.3895792Z，尝试的区域数：1 ] == QueryMetrics：分区 21 检索到的文档数：21,747 检索到的文档大小：14,783,785 字节 输出文件数：7 输出文件大小：171 字节 指数利用率：0.00 % 使用的索引 潜在指标 总查询执行时间：187.95 毫秒 查询准备时间 查询编译时间：1.10 毫秒 逻辑计划构建时间：1.83 毫秒 物理计划构建时间：0.17 毫秒 查询优化时间：0.01 毫秒 索引查找时间：1.99 毫秒 文档加载时间：123.47 毫秒 运行时执行时间 查询引擎时间：52.73 毫秒 系统功能执行时间：11.06毫秒 用户自定义函数执行时间：0.00毫秒 文档写入时间：0.01 毫秒 客户端指标 重试次数：0 请求费用：849.38 RU 分区执行时间线 ┌────────────┬──────────────────────────────────── ┬────────────────┬──────────────┬───────────────── ─┬───────────────────┬────────────┐ │Partition Id│Activity Id │开始时间（UTC）│结束时间（UTC）│持续时间（ms）│文档数│重试次数│ ├────────────┼──────────────────────────────────── ┼────────────────┼──────────────┼──────────────── ─┼─────────────────────┼────────────┤ │ 21│e0745d8f-ec34-4a40-9dac-556ffc8e8603│ 02:16:14.5334Z│02:16:14.8970Z│ 363.53│ 7│ 0│ └────────────┴──────────────────────────────────── ┴────────────────┴──────────────┴───────────────── ─┴───────────────────┴────────────┘ 调度指标 ┌────────────┬──────────────────────┬─────────────── ──────┬────────────────────┬────────────────────┬── ────────────────────┐ │Partition Id│响应时间（ms）│运行时间（ms）│等待时间（ms）│周转时间（ms）│抢占次数│ ├────────────┼────────────────────┼────────────── ──────┼────────────────────┼────────────────────┼── ────────────────────┤ │ 21│ 54314.14│ 363.53│ 54314.22│ 54677.76│ 1│ └────────────┴──────────────────────┴─────────────── ──────┴────────────────────┴────────────────────┴── ────────────────────┘ 客户端请求统计： 21：[ RequestStartTime：2020-07-25T02：16：14.8967387Z，RequestEndTime：2020-07-25T02：16：14.8967387Z，尝试的区域数：1 ] == QueryMetrics：分区 20 检索到的文档数：44,693 检索到的文档大小：30,777,951 字节 输出文件数：9 输出文件大小：256 字节 指数利用率：0.00 % 使用的索引 潜在指标 总查询执行时间：434.05 毫秒 查询准备时间 查询编译时间：2.37 毫秒 逻辑计划构建时间：4.01 毫秒 物理计划构建时间：0.46 毫秒 查询优化时间：0.04 毫秒 索引查找时间：2.61 毫秒 文档加载时间：283.05 毫秒 运行时执行时间 查询引擎时间：126.52 毫秒 系统功能执行时间：23.76毫秒 用户自定义函数执行时间：0.00毫秒 文档写入时间：0.02 毫秒 客户端指标 重试次数：0 请求费用：1,740.93 RU 分区执行时间线 ┌────────────┬──────────────────────────────────── ┬────────────────┬──────────────┬───────────────── ─┬───────────────────┬────────────┐ │Partition Id│Activity Id │开始时间（UTC）│结束时间（UTC）│持续时间（ms）│文档数│重试次数│ ├────────────┼──────────────────────────────────── ┼────────────────┼──────────────┼──────────────── ─┼─────────────────────┼────────────┤ │ 20│5b5045a4-613d-408e-9d94-d44fd7a8e5d3│ 02:16:13.8872Z│02:16:14.3596Z│ 472.41│ 5│ 0│ │ 20│45c14bfb-f9bf-48f8-ab0d-7680f7aeac99│ 02:16:14.3602Z│02:16:14.5278Z│ 167.61│ 4│ 0│ └────────────┴──────────────────────────────────── ┴────────────────┴──────────────┴───────────────── ─┴───────────────────┴────────────┘ 调度指标 ┌────────────┬──────────────────────┬─────────────── ──────┬────────────────────┬────────────────────┬── ────────────────────┐ │Partition Id│响应时间（ms）│运行时间（ms）│等待时间（ms）│周转时间（ms）│抢占次数│ ├────────────┼────────────────────┼────────────── ──────┼────────────────────┼────────────────────┼── ────────────────────┤ │ 20│ 53667.87│ 640.03│ 53668.52│ 54308.55│ 2│ └────────────┴──────────────────────┴─────────────── ──────┴────────────────────┴────────────────────┴── ────────────────────┘ 客户端请求统计： 20：[ RequestStartTime：2020-07-25T02：16：14.3599211Z，RequestEndTime：2020-07-25T02：16：14.3599211Z，尝试的区域数：1 , RequestStartTime：2020-07-25T02：16：14.5274725Z，RequestEndTime：2020-07-25T02：16：14.5274725Z，尝试的区域数：1 ]

【问题讨论】：

这是您在客户端上执行的第一个操作，还是您正在使用前一个操作（或调用 OpenAsync）预热连接？

在初始化期间使用 _Client.OpenAsync() 打开连接。我多次重复运行，它一直很慢。

尝试在 FeedOptions 中使用 PopulateQueryMetrics = true 捕获网络诊断信息，并从响应的 RequestDiagnosticsString 中读取它们。那和docs.microsoft.com/en-us/azure/cosmos-db/…

我使用 RequestDiagnosticsString 的输出编辑了我的帖子。你能评论一下我应该在输出中寻找什么吗？

您帖子中的数据仅显示了非常小的查询持续时间。你确定时间花在 SDK 上吗？我建议使用调试器单步执行代码并找出持续时间的罪魁祸首。

【参考方案1】：

附加的诊断信息似乎表明您正在执行跨分区查询（似乎要访问 3 个分区来获取查询结果），您可以在每个分区统计信息中看到“运行时间”（245 毫秒、363 毫秒） , 640 毫秒）。

似乎这个数字很高是由于结果数量也很大（其中一个查询为 44K）。

我们不知道您正在执行哪种类型的查询，但它看起来确实像扫描 (reference)。这似乎与您对LOWER 的使用一致（另请参阅您的诊断中的Index Utilization: 0.00 % ）。

另一个有用的链接是guide to tune query performance，它有一些很好的提示（请参阅链接以获得解释：

将MaxItemCount 设置为-1 将MaxDegreeOfParallelism 设置为-1

但总体而言，问题似乎在于由于使用了LOWER，您没有使用任何索引。

【讨论】：

我想报告从查询中删除 LOWER 并应用上述其他建议将执行时间从一分钟缩短到不到 5 秒。谢谢！