Diagnosticar e solucionar problemas de solicitações lentas no Azure Cosmos DB com o SDK do .NET

  • Artigo

APLICA-SE A: NoSQL

No Azure Cosmos DB, você pode observar solicitações lentas. Atrasos podem acontecer por vários motivos, como limitação de solicitações ou a maneira como seu aplicativo foi projetado. Este artigo explica as diferentes causas raiz desse problema.

Taxa de solicitação grande demais

A limitação de solicitações é o motivo mais comum para solicitações lentas. O Azure Cosmos DB limita as solicitações se elas excederem as unidades de solicitação alocadas para o banco de dados ou o contêiner. O SDK possui lógica interna para repetir essas solicitações. O artigo de solução de problemas taxa de solicitação grande demais explica como verificar se as solicitações estão sendo limitadas. O artigo também aborda como dimensionar sua conta para evitar esses problemas no futuro.

Design do aplicativo

Ao projetar seu aplicativo, siga as melhores práticas do SDK do .NET para ter o melhor desempenho. Se o seu aplicativo não seguir as melhores práticas do SDK, poderão ocorrer solicitações lentas ou com falha.

Considere o seguinte ao desenvolver seu aplicativo:

Operações de metadados

Se você precisar verificar se um banco de dados ou um contêiner existe, não faça isso chamando Create...IfNotExistsAsync ou Read...Async antes de fazer uma operação de item. A validação só deverá ser feita na inicialização do aplicativo quando for necessário, se você esperar que eles sejam excluídos. Essas operações de metadados geram latência extra, não têm nenhum SLA (Contrato de Nível de Serviço) e têm limitações separadas. Elas não são dimensionadas como operações de dados.

Solicitações lentas no modo em massa

O modo em massa é um modo otimizado para taxa de transferência destinado a operações de alto volume de dados, e não um modo otimizado para latência; ele deve saturar a taxa de transferência disponível. Se você estiver enfrentando solicitações lentas ao usar o modo em massa, certifique-se de que:

  • Seu aplicativo está compilado na configuração de versão.
  • Você não está medindo a latência durante a depuração do aplicativo (sem depurador anexado).
  • O volume de operações é alto. Não use o modo em massa para menos de 1000 operações. Sua taxa de transferência provisionada determina quantas operações por segundo você pode processar. Seu objetivo com o modo em massa seria utilizar o máximo possível dela.
  • Monitore o contêiner para cenários de limitação. Se o contêiner estiver sendo muito limitado, isso significa que o volume de dados é maior do que a taxa de transferência provisionada. Você precisará escalar verticalmente o contêiner ou reduzir o volume de dados (talvez criando lotes menores de dados de cada vez).
  • Você está usando corretamente o padrão async/await para processar todas as tarefas simultâneas e não está bloqueando nenhuma operação assíncrona.

Capturar diagnósticos

Todas as respostas no SDK, incluindo CosmosException, têm uma propriedade Diagnostics. Ela registra todas as informações relacionadas à solicitação única, incluindo se houve novas tentativas ou quaisquer falhas temporárias.

Os diagnósticos são retornados como uma cadeia de caracteres. A cadeia de caracteres muda a cada versão, à medida que é aprimorada para solucionar melhor os diferentes cenários. Com cada versão do SDK, a cadeia de caracteres terá alterações interruptivas na formatação. Não analise a cadeia de caracteres para evitar alterações interruptivas. O exemplo de código a seguir mostra como ler os logs de diagnóstico usando o SDK do .NET:

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()
}

Diagnósticos na versão 3.19 e mais recentes

A estrutura JSON tem alterações interruptivas a cada versão do SDK. Devido a isso, a análise dele não é segura. O JSON representa uma estrutura em árvore da solicitação que passa pelo SDK. As seções a seguir abrangem alguns aspectos importantes a serem examinados.

Histórico da CPU

A alta utilização da CPU é a causa mais comum de solicitações lentas. Para ter uma latência ideal, o uso da CPU deve ser de aproximadamente 40%. Use 10 segundos como o intervalo para monitorar a utilização máxima (não média) da CPU. Picos de uso de CPU são mais comuns com consultas de partição cruzada, em que as solicitações podem fazer várias conexões para uma única consulta.

Os tempos limites incluem diagnósticos, que contêm o seguinte, por exemplo:

"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",
....
}

},
...
]
  • Se os valores cpu estão acima de 70%, é provável que o tempo limite seja causado pelo esgotamento da CPU. Nesse caso, a solução é investigar a origem da alta utilização da CPU e reduzi-la, ou dimensionar a máquina para um tamanho de recurso maior.
  • Se os nós threadInfo/isThreadStarving têm valores True, a causa é a privação de threads. Nesse caso, a solução é investigar as origens da privação de thread (threads potencialmente bloqueados) ou dimensionar as máquinas para um tamanho de recurso maior.
  • Se o tempo dateUtc entre as medições não for de cerca de 10 segundos, isso também indicará contenção no pool de threads. A CPU é medida como uma tarefa independente que é enfileirada no pool de threads a cada 10 segundos. Se o tempo entre as medidas for maior, isso indicará que as tarefas assíncronas não poderão ser processadas em tempo hábil. O cenário mais comum é quando o código do seu aplicativo está bloqueando chamadas por código assíncrono.

Solução

O aplicativo cliente que usa o SDK deve ser expandido ou escalado verticalmente.

HttpResponseStats

HttpResponseStats são solicitações que vão para o gateway. Mesmo no modo direto, o SDK obtém todas as informações de metadados do gateway.

Se a solicitação estiver lenta, primeiro verifique se nenhuma das sugestões anteriores produz os resultados desejados. Se o problema persistir, observe que padrões diferentes apontam para problemas diferentes. A tabela a seguir fornece mais detalhes.

Número de solicitações Cenário Descrição
Único para todos Tempo limite da solicitação ou HttpRequestExceptions Aponta para Esgotamento de porta SNAT ou falta de recursos no computador para processar a solicitação a tempo.
Porcentagem única ou pequena (o SLA não é violado) Tudo Uma porcentagem única ou pequena de solicitações lentas pode ser causada por vários problemas temporários diferentes, sendo, portanto, algo esperado.
Tudo Tudo Aponta para um problema de infraestrutura ou de rede.
SLA violado Nenhuma alteração no aplicativo e SLA descartado. Aponta para um problema com o serviço do 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

O StoreResult representa apenas uma solicitação ao Azure Cosmos DB usando o modo direto com o protocolo TCP.

Se o problema persistir, observe que padrões diferentes apontam para problemas diferentes. A tabela a seguir fornece mais detalhes.

Número de solicitações Cenário Descrição
Único para todos StoreResult contém TransportException Aponta para Esgotamento de porta SNAT ou falta de recursos no computador para processar a solicitação a tempo.
Porcentagem única ou pequena (o SLA não é violado) Tudo Uma porcentagem única ou pequena de solicitações lentas pode ser causada por vários problemas temporários diferentes, sendo, portanto, algo esperado.
Tudo Tudo Um problema com a infraestrutura ou a rede.
SLA violado As solicitações contêm vários códigos de erro de falha, como 410 Aponta para um problema com o serviço do Azure Cosmos DB ou com o computador cliente.
SLA violado StorePhysicalAddress são os mesmos, sem código de status de falha. Provavelmente um problema com Azure Cosmos DB.
SLA violado StorePhysicalAddress tem a mesma ID de partição, mas diferentes IDs de replicação, sem código de status de falha. Provavelmente um problema com Azure Cosmos DB.
SLA violado StorePhysicalAddress é aleatório, sem código de status de falha. Aponta para um problema com o computador.

Para vários resultados de armazenamento para apenas uma solicitação, esteja ciente do seguinte:

  • A consistência forte e a consistência de desatualização limitada sempre têm pelo menos dois resultados de armazenamento.
  • Confira o código de status de cada StoreResult. O SDK tenta lidar novamente com várias falhas temporárias diferentes de maneira automática. O SDK é constantemente aprimorado para abranger mais cenários.

RequestTimeline

Mostra o tempo das diferentes etapas de envio e recebimento de uma solicitação na camada de transporte.

  • ChannelAcquisitionStarted: o tempo para obter ou criar uma conexão. As conexões podem ser criadas por vários motivos, como: a conexão anterior foi fechada devido à inatividade usando CosmosClientOptions.IdleTcpConnectionTimeout, o volume de solicitações simultâneas excede o CosmosClientOptions.MaxRequestsPerTcpConnection, a conexão foi fechada devido a um erro de rede ou o aplicativo não está seguindo o padrão Singleton, e novas instâncias são criadas constantemente. Depois que uma conexão é estabelecida, ela é reusada nas solicitações subsequentes, portanto, isso não deve afetar a latência P99, a menos que os problemas mencionados anteriormente estejam acontecendo.
  • tempo de Pipelined é grande e pode ser causado por uma solicitação grande.
  • Transit time é grande, o que leva a um problema de rede. Compare esse número com BELatencyInMs. Se BELatencyInMs for pequeno, o tempo foi gasto na rede e não no serviço do Azure Cosmos DB.
  • tempo de Received e pode ser causado por um problema de privação de threads. Este é o tempo entre o recebimento da resposta e o retorno do resultado.

ServiceEndpointStatistics

Informações sobre um servidor de back-end específico. O SDK pode abrir várias conexões com um servidor de back-end dependendo do número de solicitações pendentes e de MaxConcurrentRequestsPerConnection.

  • inflightRequests O número de solicitações pendentes para um servidor de back-end (talvez de partições diferentes). Um número alto pode levar a mais tráfego e latências mais altas.
  • openConnections é o número total de conexões abertas para um servidor de back-end. Isso pode ser útil para mostrar a exaustão da porta SNAT quando esse número é muito alto.

ConnectionStatistics

Informações sobre a conexão específica (nova ou antiga) à qual a solicitação foi atribuída.

  • waitforConnectionInit: a solicitação atual estava aguardando a conclusão da inicialização da nova conexão. Isso levará a latências mais altas.
  • callsPendingReceive: número de chamadas com recebimento pendente antes dessa chamada ter sido enviada. Um número alto pode mostrar que havia muitas chamadas antes dessa, o que pode levar a latências mais altas. Se o número for alto, isso apontará para um problema de bloqueio de linha, possivelmente causado por outra solicitação, como uma operação de consulta ou de feed que está demorando muito para ser processada. Tente reduzir CosmosClientOptions.MaxRequestsPerTcpConnection para aumentar o número de canais.
  • LastSentTime: hora da última solicitação enviada para este servidor. Em conjunto com LastReceivedTime, pode ser usado para ver problemas de conectividade ou ponto de extremidade. Por exemplo, se houver muitos tempos limite de recebimento, a hora de envio será muito posterior à hora de recebimento.
  • lastReceive: hora da última solicitação que foi recebida desse servidor
  • lastSendAttempt: hora da última tentativa de envio

Tamanhos de solicitação e resposta

  • requestSizeInBytes: o tamanho total da solicitação enviada ao Azure Cosmos DB
  • responseMetadataSizeInBytes: o tamanho dos cabeçalhos retornados do Azure Cosmos DB
  • responseBodySizeInBytes: o tamanho do conteúdo retornado do 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
}

A taxa de falha viola o SLA do Azure Cosmos DB

Entre em contato com o Suporte do Azure.

Próximas etapas