诊断和排查 Azure Cosmos DB .NET SDK 中请求缓慢的问题

项目
09/14/2024

适用范围： NoSQL

在 Azure Cosmos DB 中，你可能会注意到请求速度缓慢。延迟的原因有多种，例如请求限制或应用程序的设计方式。本文介绍此问题的各种根本原因。

请求速率过大

请求限制是请求缓慢的最常见原因。如果请求超过为数据库或容器分配的请求单位，Azure Cosmos DB 将限制请求。 SDK 具有重试这些请求的内置逻辑。请求速率过大故障排除一文介绍了如何检查请求是否受到限制。本文还介绍了如何缩放帐户，避免将来出现这些问题。

应用程序设计

设计应用程序时，遵循 .NET SDK 最佳做法以获得最佳性能。如果应用程序未遵循 SDK 最佳做法，则可能会遇到请求缓慢或失败问题。

开发应用程序时，请考虑以下事项：

应用程序应与 Azure Cosmos DB 帐户在同一区域。
ApplicationRegion 或 ApplicationPreferredRegions 应反映区域首选项，并指向部署应用程序的区域。
由于流量较大，网络接口可能出现了瓶颈。如果应用程序在 Azure 虚拟机上运行，则可以使用以下解决方法：
- 考虑使用启用了加速网络的虚拟机。
- 启用现有虚拟机上的加速网络。
- 考虑使用更高端的虚拟机。
首选直接连接模式。
避免 CPU 使用率过高。请务必查看“最大 CPU 使用率”而不是“平均值”，这是大多数日志系统的默认值。使用率超过 40% 的内容都可能会增加延迟。

元数据操作

如果需要验证数据库或容器是否存在，那么在执行项操作之前，请不要调用 Create...IfNotExistsAsync 或 Read...Async 来进行验证。如果希望删除这些内容，只应在必要时在应用程序启动时进行验证。这些元数据操作会产生额外的延迟，没有服务级别协议 (SLA)，并且具有自己单独的限制。它们不会像数据操作一样缩放。

批量模式下的慢速请求

批量模式是优化了吞吐量的模式，适用于高数据量操作，它不是优化延迟的模式；它旨在使可用吞吐量饱和。如果在使用批量模式时遇到请求缓慢，请确保：

应用程序在发布配置中编译。
没有在调试应用程序时测量延迟（未附加调试程序）。
操作量较高，请勿在少于 1000 个操作的情况下使用批量。预配的吞吐量决定了每秒可以处理多少操作，批量的目标是要尽可能充分地利用这个操作量。
监视容器中的限制场景。如果容器受到严格限制，则意味着数据量大于预配的吞吐量，那么就需要纵向扩展容器或减少数据量（也许每次创建较小的数据批次）。
你在正确使用 async/await 模式来处理所有并发任务，并且没有阻止任何异步操作。

捕获诊断

SDK 中的所有响应（包括 CosmosException）都具有 Diagnostics 属性。此属性记录与单一请求相关的所有信息，包括是否发生重试或任何瞬时故障。

诊断以字符串形式返回。字符串会随每个版本而不断变化并进行改进，以对不同场景进行故障排除。对于 SDK 的每个版本，字符串对格式设置都有中断性变更。为避免发生中断性变更，请勿分析字符串。以下代码示例展示了如何使用 .NET SDK 读取诊断日志：

try
{
    ItemResponse<Book> response = await this.Container.CreateItemAsync<Book>(item: testItem);
    if (response.Diagnostics.GetClientElapsedTime() > ConfigurableSlowRequestTimeSpan)
    {
        // Log the response.Diagnostics.ToString() and add any additional info necessary to correlate to other logs 
    }
}
catch (CosmosException cosmosException)
{
    // Log the full exception including the stack trace with: cosmosException.ToString()
    
    // The Diagnostics can be logged separately if required with: cosmosException.Diagnostics.ToString()
}

// When using Stream APIs
ResponseMessage response = await this.Container.CreateItemStreamAsync(partitionKey, stream);
if (response.Diagnostics.GetClientElapsedTime() > ConfigurableSlowRequestTimeSpan || !response.IsSuccessStatusCode)
{
    // Log the diagnostics and add any additional info necessary to correlate to other logs with: response.Diagnostics.ToString()
}

3.19 及更高版本的诊断

JSON 结构在每个版本的 SDK 中都有中断性变更。这使得分析不安全。 JSON 表示通过 SDK 的请求的树结构。以下各部分介绍了一些需要注意的关键事项。

CPU 历史记录

CPU 使用率过高是请求缓慢的最常见原因。为实现最佳延迟，CPU 利用率应大约为 40%。将时间间隔设为 10 秒来监视最大 CPU 利用率（而不是平均利用率）。 CPU 峰值在跨分区查询中更常见，其中请求可能为单一查询执行多个连接。

3.21 或更高版本 SDK
旧版 SDK

超时包括诊断，其中包含以下内容，例如：

"systemHistory": [
{
"dateUtc": "2021-11-17T23:38:28.3115496Z",
"cpu": 16.731,
"memory": 9024120.000,
"threadInfo": {
"isThreadStarving": "False",
....
}

},
{
"dateUtc": "2021-11-17T23:38:38.3115496Z",
"cpu": 16.731,
"memory": 9024120.000,
"threadInfo": {
"isThreadStarving": "False",
....
}

},
...
]

如果 cpu 值超过 70%，则超时可能是由于 CPU 耗尽导致的。在这种情况下，解决方法是调查 CPU 利用率较高的源并使其减少，或将计算机扩展到更大的资源大小。
如果 threadInfo/isThreadStarving 节点具有 True 值，原因为线程耗尽。在这种情况下，解决方法是调查线程不足（可能锁定的线程）的源，或将计算机扩展到更大的资源大小。
如果两次测量之间的 dateUtc 时间并非大约 10 秒，则它还指示线程池发生争用。 CPU 作为独立任务进行度量，每 10 秒在线程池中排队一次。如果度量间隔时间较长，则表示无法及时处理异步任务。最常见的情况是，应用程序代码阻止对异步代码的调用。

如果错误包含 TransportException 信息，它可能还包含 CPU history：

CPU history:
(2020-08-28T00:40:09.1769900Z 0.114),
(2020-08-28T00:40:19.1763818Z 1.732),
(2020-08-28T00:40:29.1759235Z 0.000),
(2020-08-28T00:40:39.1763208Z 0.063),
(2020-08-28T00:40:49.1767057Z 0.648),
(2020-08-28T00:40:59.1689401Z 0.137),
CPU count: 8)

如果 CPU 度量超过 70%，则超时可能是由于 CPU 耗尽导致的。在这种情况下，解决方法是调查 CPU 利用率较高的源并使其减少，或将计算机扩展到更大的资源大小。
如果 CPU 度量不是每 10 秒进行一次（例如，间隔或测量时间指示两次度量之间的时间更长），那么原因可能是“线程不足”。在这种情况下，解决方法是调查线程不足（可能锁定的线程）的源，或将计算机扩展到更大的资源大小。

解决方案

应纵向扩展或横向扩展使用 SDK 的客户端应用程序。

HttpResponseStats

HttpResponseStats 是转到网关的请求。即使在直接模式下，SDK 也会从网关获取所有元数据信息。

如果请求速度较慢，请首先验证前面的建议均未产生所需的结果。如果速度仍然缓慢，则不同模式指向不同的问题。下表提供更多详细信息。

请求数量	方案	说明
单一到全部	请求超时或 `HttpRequestExceptions`	指向 SNAT 端口耗尽或计算机上缺少资源，无法实时处理请求。
单一或一小部分（不违反 SLA）	全部	单一或一小部分请求速度缓慢可能是由几个不同的暂时性问题引起的，并且应该可预料到。
全部	全部	指向基础结构或网络的问题。
违反 SLA	没有删除对应用程序和 SLA 的更改。	指向 Azure Cosmos DB 服务的问题。

"HttpResponseStats": [
    {
        "StartTimeUTC": "2021-06-15T13:53:09.7961124Z",
        "EndTimeUTC": "2021-06-15T13:53:09.7961127Z",
        "RequestUri": "https://127.0.0.1:8081/dbs/347a8e44-a550-493e-88ee-29a19c070ecc/colls/4f72e752-fa91-455a-82c1-bf253a5a3c4e",
        "ResourceType": "Collection",
        "HttpMethod": "GET",
        "ActivityId": "e16e98ec-f2e3-430c-b9e9-7d99e58a4f72",
        "StatusCode": "OK"
    }
]

StoreResult

StoreResult 表示使用 TCP 协议的直接模式对 Azure Cosmos DB 的单一请求。

如果速度仍然缓慢，则不同模式指向不同的问题。下表提供更多详细信息。

请求数量	方案	说明
单一到全部	`StoreResult` 包含 `TransportException`	指向 SNAT 端口耗尽或计算机上缺少资源，无法实时处理请求。
单一或一小部分（不违反 SLA）	全部	单一或一小部分请求速度缓慢可能是由几个不同的暂时性问题引起的，并且应该可预料到。
全部	全部	基础结构或网络的问题。
违反 SLA	请求包含多个失败错误代码，如 `410`	指向 Azure Cosmos DB 服务或客户端计算机的问题。
违反 SLA	`StorePhysicalAddress` 相同，没有失败状态代码。	Azure Cosmos DB 可能有问题。
违反 SLA	`StorePhysicalAddress` 具有相同的分区 ID，但副本 ID 不同，没有失败状态代码。	Azure Cosmos DB 可能有问题。
违反 SLA	`StorePhysicalAddress` 是随机的，没有失败状态代码。	指向计算机的问题。

对于单个请求的多个存储结果，请注意以下几点：

强一致性和有限过期一致性始终具有至少两个存储结果。
请检查每个 StoreResult 的状态代码。 SDK 会自动重试多个不同的瞬时故障。 SDK 会不断改进，以应对更多场景。

RequestTimeline

显示传输层中发送和接收请求在不同阶段消耗的时间。

ChannelAcquisitionStarted：获取或创建新连接的时间。创建连接的原因有很多，例如：上一个连接由于使用 CosmosClientOptions.IdleTcpConnectionTimeout 处于非活动状态而关闭、并发请求量超过了 CosmosClientOptions.MaxRequestsPerTcpConnection、连接由于网络错误而关闭、或者应用程序不遵循单一实例模式并且不断创建新实例。一旦建立连接，该连接就会被重新用于后续请求，因此不应影响 P99 延迟，除非发生前面提到的问题。
Pipelined：将请求写入 TCP 套接字所用的时间。一次只能在一个 TCP 套接字上写入请求，较大的值表示 TCP 套接字上存在瓶颈，这通常与应用程序代码锁定线程或请求大小较大有关。
Transit time：将请求写入 TCP 套接字后在网络上花费的时间。将此数字与 BELatencyInMs 进行比较。如果 BELatencyInMs 较小，则时间消耗在网络上，而不是在 Azure Cosmos DB 服务上。如果请求失败并显示超时，则表示客户端在没有响应的情况下等待了多长时间，并且问题的根源是网络延迟。
Received：SDK 接收和处理响应之间的时间。较大的值通常是由线程不足或线程被锁定引起的。

ServiceEndpointStatistics

有关特定后端服务器的信息。 SDK 可以根据待处理请求的数量和 MaxConcurrentRequestsPerConnection 向单个后端服务器打开多个连接。

inflightRequests 对后端服务器的待处理请求数（可能来自不同的分区）。较高的数字可能导致更多的流量和更高的延迟。
openConnections 是对单个后端服务器打开的连接总数。如果此数字非常高，则显示 SNAT 端口耗尽可能会很有用。

ConnectionStatistics

关于被分配了请求的特定连接（新或旧）的信息。

waitforConnectionInit：当前请求正在等待新的连接初始化完成。这将导致更高的延迟。
callsPendingReceive：在发送此调用之前等待接收的调用数。高数字表明，在此调用之前有很多调用，这可能会导致更高的延迟。如果这个数字很高，就表明发生了行首阻塞问题，可能是由另一个请求引起的（如查询或馈送操作），需要很长的时间来处理。尝试降低 CosmosClientOptions.MaxRequestsPerTcpConnection 以增加通道数。
LastSentTime：发送到此服务器的最后一个请求的时间。这与 LastReceivedTime 一起可用于查看连接或终结点问题。例如，如果发生许多次接收超时，则发送时间将远大于接收时间。
lastReceive：从此服务器接收的最后一个请求的时间
lastSendAttempt：上次发送尝试的时间

请求和响应大小

requestSizeInBytes：发送到 Azure Cosmos DB 的请求的总大小
responseMetadataSizeInBytes：从 Azure Cosmos DB 返回的标头的大小
responseBodySizeInBytes：从 Azure Cosmos DB 返回的内容的大小

"StoreResult": {
    "ActivityId": "bab6ade1-b8de-407f-b89d-fa2138a91284",
    "StatusCode": "Ok",
    "SubStatusCode": "Unknown",
    "LSN": 453362,
    "PartitionKeyRangeId": "1",
    "GlobalCommittedLSN": 0,
    "ItemLSN": 453358,
    "UsingLocalLSN": true,
    "QuorumAckedLSN": -1,
    "SessionToken": "-1#453362",
    "CurrentWriteQuorum": -1,
    "CurrentReplicaSetSize": -1,
    "NumberOfReadRegions": 0,
    "IsValid": true,
    "StorePhysicalAddress": "rntbd://127.0.0.1:10253/apps/DocDbApp/services/DocDbServer92/partitions/a4cb49a8-38c8-11e6-8106-8cdcd42c33be/replicas/1s/",
    "RequestCharge": 1,
    "RetryAfterInMs": null,
    "BELatencyInMs": "0.304",
    "transportRequestTimeline": {
        "requestTimeline": [
            {
                "event": "Created",
                "startTimeUtc": "2022-05-25T12:03:36.3081190Z",
                "durationInMs": 0.0024
            },
            {
                "event": "ChannelAcquisitionStarted",
                "startTimeUtc": "2022-05-25T12:03:36.3081214Z",
                "durationInMs": 0.0132
            },
            {
                "event": "Pipelined",
                "startTimeUtc": "2022-05-25T12:03:36.3081346Z",
                "durationInMs": 0.0865
            },
            {
                "event": "Transit Time",
                "startTimeUtc": "2022-05-25T12:03:36.3082211Z",
                "durationInMs": 1.3324
            },
            {
                "event": "Received",
                "startTimeUtc": "2022-05-25T12:03:36.3095535Z",
                "durationInMs": 12.6128
            },
            {
                "event": "Completed",
                "startTimeUtc": "2022-05-25T12:03:36.8621663Z",
                "durationInMs": 0
            }
        ],
        "serviceEndpointStats": {
            "inflightRequests": 1,
            "openConnections": 1
        },
        "connectionStats": {
            "waitforConnectionInit": "False",
            "callsPendingReceive": 0,
            "lastSendAttempt": "2022-05-25T12:03:34.0222760Z",
            "lastSend": "2022-05-25T12:03:34.0223280Z",
            "lastReceive": "2022-05-25T12:03:34.0257728Z"
        },
        "requestSizeInBytes": 447,
        "responseMetadataSizeInBytes": 438,
        "responseBodySizeInBytes": 604
    },
    "TransportException": null
}

失败率与 Azure Cosmos DB SLA 不符

联络 Azure 支持部门。

后续步骤

诊断和排查在使用 Azure Cosmos DB .NET SDK 时遇到的问题。
了解 .NET SDK 的性能准则。
了解 .NET SDK 的最佳做法

通过