Partilhar via

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

  • Artigo

APLICA-SE A: NoSQL

No Azure Cosmos DB, você pode notar solicitações lentas. Os atrasos podem acontecer por vários motivos, como a limitação de solicitações ou a maneira como seu aplicativo é projetado. Este artigo explica as diferentes causas para este problema.

A taxa de pedidos é demasiado grande

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 contêiner. O SDK tem lógica interna para repetir essas solicitações. O artigo de solução de problemas de taxa de solicitação muito grande explica como verificar se as solicitações estão sendo limitadas. O artigo também discute como dimensionar sua conta para evitar esses problemas no futuro.

Design da aplicação

Ao projetar seu aplicativo, siga as práticas recomendadas do SDK do .NET para obter o melhor desempenho. Se seu aplicativo não seguir as práticas recomendadas do SDK, você poderá receber solicitações lentas ou com falha.

Considere o seguinte ao desenvolver seu aplicativo:

  • O aplicativo deve estar na mesma região que sua conta do Azure Cosmos DB.
  • Seu ApplicationRegion ou ApplicationPreferredRegions deve refletir sua preferência regional e apontar para a região em que seu aplicativo está implantado.
  • Pode haver um gargalo na interface de rede devido ao alto tráfego. Se o aplicativo estiver sendo executado em Máquinas Virtuais do Azure, há soluções possíveis:
  • Prefira o modo de conectividade direta.
  • Evite CPU alta. Certifique-se de examinar a CPU máxima e não a média, que é o padrão para a maioria dos sistemas de registro. Qualquer coisa acima de cerca de 40% pode aumentar a latência.

Operações de metadados

Se você precisar verificar se um banco de dados ou 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ó deve ser feita na inicialização do aplicativo quando for necessário, se você espera que eles sejam excluídos. Essas operações de metadados geram latência extra, não têm contrato de nível de serviço (SLA) e têm suas próprias limitações separadas. Eles não são dimensionados como operações de dados.

Solicitações lentas no modo em massa

O modo em massa é um modo otimizado de taxa de transferência destinado a operações de alto volume de dados, não um modo otimizado de latência, destina-se a 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 é compilado na configuração de versão.
  • Você não está medindo a latência durante a depuração do aplicativo (nenhum depurador anexado).
  • O volume de operações é alto, não use bulk para menos de 1000 operações. Sua taxa de transferência provisionada dita quantas operações por segundo você pode processar, seu objetivo com o bulk seria utilizar o máximo possível.
  • Monitore o contêiner para cenários de limitação. Se o contêiner estiver sendo fortemente limitado, isso significa que o volume de dados é maior do que a taxa de transferência provisionada, você precisará aumentar a escala do contêiner ou reduzir o volume de dados (talvez crie lotes menores de dados de cada vez).
  • Você está usando corretamente o padrão para processar todas as tarefas simultâneas e não bloquear nenhuma operação assíncrona.async/await

Capturar diagnósticos

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

Os diagnósticos são retornados como uma cadeia de caracteres. A cadeia de caracteres muda a cada versão, pois é aprimorada para solucionar problemas de diferentes cenários. Com cada versão do SDK, a cadeia de caracteres terá alterações de quebra na formatação. Não analise a cadeia de caracteres para evitar a quebra de alterações. O exemplo de código a seguir mostra como ler 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óstico na versão 3.19 e posterior

A estrutura JSON tem alterações significativas com cada versão do SDK. Isso faz com que não seja seguro ser analisado. O JSON representa uma estrutura de árvore da solicitação que passa pelo SDK. As seções a seguir cobrem alguns aspetos importantes a serem observados.

Histórico da CPU

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

Os tempos limite 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 forem superiores a cpu 70%, é provável que o tempo limite seja causado pela exaustão da CPU. Neste caso, a solução consiste em investigar a origem da utilização elevada da CPU e reduzi-la ou dimensionar o computador para um tamanho de recurso maior.
  • Se os threadInfo/isThreadStarving nós tiverem True valores, a causa é a fome de thread. Nesse caso, a solução é investigar a origem ou fontes da inanição de thread (threads potencialmente bloqueados), ou dimensionar a máquina ou máquinas para um tamanho de recurso maior.
  • Se o dateUtc tempo entre as medições não for de aproximadamente 10 segundos, isso também indica 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 medições for maior, isso indica que as tarefas assíncronas não podem ser processadas em tempo hábil. O cenário mais comum é quando o código do aplicativo está bloqueando chamadas por meio de código assíncrono.

Solução

A aplicação cliente que utiliza o SDK deve ser aumentada vertical ou horizontalmente.

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 for lenta, primeiro verifique se nenhuma das sugestões anteriores produz os resultados desejados. Se ainda for lento, padrões diferentes apontam para problemas diferentes. A tabela a seguir fornece mais detalhes.

Número de pedidos Cenário Description
Único para todos Tempo limite de solicitação ou HttpRequestExceptions Aponta para o esgotamento da porta SNAT ou falta de recursos na máquina para processar a solicitação a tempo.
Porcentagem única ou pequena (SLA não violado) Todos Uma única ou pequena porcentagem de solicitações lentas pode ser causada por vários problemas transitórios diferentes e deve ser esperada.
Todos Todos Aponta para um problema com a infraestrutura ou rede.
SLA violado Nenhuma alteração no aplicativo e o SLA foi descartado. Aponta para um problema com o serviço 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 representa uma única solicitação para o Azure Cosmos DB, usando o modo direto com o protocolo TCP.

Se ainda for lento, padrões diferentes apontam para problemas diferentes. A tabela a seguir fornece mais detalhes.

Número de pedidos Cenário Description
Único para todos StoreResult contém: TransportException Aponta para o esgotamento da porta SNAT ou falta de recursos na máquina para processar a solicitação a tempo.
Porcentagem única ou pequena (SLA não violado) Todos Uma única ou pequena porcentagem de solicitações lentas pode ser causada por vários problemas transitórios diferentes e deve ser esperada.
Todos Todos Um problema com a infraestrutura ou 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 Azure Cosmos DB ou a máquina cliente.
SLA violado StorePhysicalAddress são os mesmos, sem código de status de falha. Provavelmente um problema com o Azure Cosmos DB.
SLA violado StorePhysicalAddress têm o mesmo ID de partição, mas IDs de réplica diferentes, sem código de status de falha. Provavelmente um problema com o Azure Cosmos DB.
SLA violado StorePhysicalAddress é aleatório, sem código de status de falha. Aponta para um problema com a máquina.

Para resultados de várias lojas para uma única solicitação, esteja ciente do seguinte:

  • Consistência forte e consistência de estagnação limitada sempre têm pelo menos dois resultados de loja.
  • Verifique o código de status de cada StoreResult. O SDK tenta novamente automaticamente em várias falhas transitórias diferentes. O SDK é constantemente melhorado para cobrir mais cenários.

RequestTimeline

Mostre o tempo para as diferentes etapas de envio e recebimento de uma solicitação na camada de transporte.

  • ChannelAcquisitionStarted: O tempo para obter ou criar uma nova conexão. As conexões podem ser criadas por vários motivos, tais 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 constantemente criadas. Uma vez que uma conexão é estabelecida, ela é reutilizada para solicitações subsequentes, portanto, isso não deve afetar a latência do P99, a menos que os problemas mencionados anteriormente estejam acontecendo.
  • Pipelined: O tempo gasto gravando a solicitação no soquete TCP. A solicitação só pode ser gravada em um soquete TCP um de cada vez, um valor grande indica um afunilamento no soquete TCP que é comumente associado a threads bloqueados pelo código do aplicativo ou tamanho de solicitações grandes.
  • Transit time: O tempo gasto na rede depois que a solicitação foi gravada no soquete TCP. Compare este número com o BELatencyInMs. Se BELatencyInMs for pequeno, o tempo foi gasto na rede e não no serviço Azure Cosmos DB. Se a solicitação falhou com um tempo limite, ele indica quanto tempo o cliente esperou sem resposta e a origem é a latência da rede.
  • Received: O tempo entre a resposta foi recebido e processado pelo SDK. Um valor grande é normalmente causado por uma inanição de thread ou threads bloqueados.

ServiceEndpointStatistics

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

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

ConnectionStatistics

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

  • waitforConnectionInit: A solicitação atual estava aguardando a conclusão da nova inicialização da conexão. Isso levará a latências mais altas.
  • callsPendingReceive: Número de chamadas pendentes recebidas antes do envio desta chamada. Um número elevado pode mostrar-nos que havia muitas chamadas antes desta chamada e pode levar a latências mais elevadas. Se esse número for alto, ele aponta para um problema de bloqueio de linha possivelmente causado por outra solicitação, como consulta ou operação de feed, que está demorando muito tempo para ser processada. Tente reduzir o CosmosClientOptions.MaxRequestsPerTcpConnection para aumentar o número de canais.
  • LastSentTime: Hora da última solicitação que foi enviada a este servidor. Isso junto com LastReceivedTime pode ser usado para ver problemas de conectividade ou ponto final. Por exemplo, se houver muitos tempos limite de recebimento, o tempo de envio será muito maior do que o tempo de recebimento.
  • lastReceive: Hora da última solicitação recebida deste 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óximos passos

  • Diagnostique e solucione problemas ao usar o SDK .NET do Azure Cosmos DB.
  • Saiba mais sobre as diretrizes de desempenho para o SDK do .NET.
  • Saiba mais sobre as práticas recomendadas para o SDK do .NET