Diagnóstico y resolución de problemas relacionados con solicitudes lentas del SDK de .NET de Azure Cosmos DB

  • Artículo

SE APLICA A: NoSQL

En Azure Cosmos DB, es posible que observe solicitudes lentas. Azure Cosmos DB puede experimentar solicitudes lentas por varias razones, como una limitación de las solicitudes o el diseño de la aplicación. En este artículo se explican las distintas causas principales de esta incidencia.

Tasa de solicitudes demasiado grande

La limitación de las solicitudes es la razón más común de que se produzcan solicitudes lentas. Azure Cosmos DB limitará las solicitudes si superan las RU asignadas para la base de datos o el contenedor. El SDK tiene una lógica integrada para reintentar estas solicitudes. En el artículo sobre solución de problemas relacionados con una tasa de solicitudes demasiado elevada se explica cómo comprobar si se están limitando las solicitudes. En el artículo también se describe cómo escalar su cuenta para evitar estos problemas en el futuro.

Diseño de aplicación

Al diseñar la aplicación, siga los procedimientos recomendados del SDK de .NET para obtener el mejor rendimiento. Si su solicitud no sigue los procedimientos recomendados del SDK, puede obtener solicitudes lentas o fallidas.

Tenga en cuenta lo siguiente al desarrollar la aplicación:

Operaciones de metadatos

Si necesita comprobar que existe una base de datos o un contenedor, no lo haga llamando a Create...IfNotExistsAsync o Read...Async antes de realizar una operación de elemento. La validación solo debe realizarse en el inicio de la aplicación cuando sea necesario, si espera que se eliminen (de lo contrario, no es necesario). Estas operaciones de metadatos generan latencia adicional, no tienen ningún acuerdo de nivel de servicio (SLA) y tienen sus propias limitaciones independientes. No se escalan como las operaciones de datos.

Solicitudes lentas en modo masivo

El modo masivo es un modo optimizado para el rendimiento diseñado para operaciones de gran volumen de datos, no un modo optimizado para latencia. Está pensado para saturar el rendimiento disponible. Si experimenta solicitudes lentas al usar el modo masivo, asegúrese de que:

  • La aplicación se compila en configuración de versión.
  • No se mide la latencia durante la depuración de la aplicación (no hay depuradores asociados).
  • El volumen de operaciones es alto, no use el modo masivo para menos de 1000 operaciones. El rendimiento aprovisionado determina cuántas operaciones por segundo se pueden procesar, el objetivo de forma masiva sería utilizar tanto como sea posible.
  • Supervise el contenedor en escenarios de limitación. Si el contenedor está muy limitado, significa que el volumen de datos es mayor que el rendimiento aprovisionado y debe escalar verticalmente el contenedor o reducir el volumen de datos (quizás crear lotes de datos más pequeños cada vez).
  • Está usando correctamente el patrón async/await para procesar todas las tareas simultáneas y no bloquear ninguna operación asincrónica.

Captura de diagnósticos

Todas las respuestas del SDK, incluida CosmosException, tienen una propiedad Diagnostics. Esta propiedad registra toda la información relacionada con la solicitud única, incluidos los reintentos o errores transitorios.

Los diagnósticos se devuelven como una cadena. La cadena cambia con cada versión a medida que se mejora para ofrecer mejores soluciones a los problemas de los distintos escenarios. Con cada versión del SDK, la cadena tendrá cambios importantes en el formato. No analice la cadena para evitar cambios importantes. En el siguiente ejemplo de código se muestra cómo leer los registros de diagnóstico mediante el SDK de .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 en la versión 3.19 y posteriores

La estructura JSON tiene cambios importantes con cada versión del SDK. Esto hace que no sea seguro analizarlo. JSON representa una estructura de árbol de la solicitud que pasa por el SDK. Las secciones siguientes cubren algunos aspectos clave que hay que tener en cuenta.

Historial de CPU

El uso elevado de la CPU es la causa más común de que se produzcan solicitudes lentas. Para lograr una latencia óptima, el uso de la CPU debe ser de aproximadamente el 40 por ciento. Use 10 segundos como intervalo para supervisar el uso máximo de la CPU (no el promedio). Los picos de CPU son más habituales con consultas entre particiones en las que se pueden realizar varias conexiones para una sola consulta.

Los tiempos de espera incluyen diagnósticos, que contienen lo siguiente, por ejemplo:

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

},
...
]
  • Si los valores cpu superan el 70 %, es probable que el tiempo de estera se deba al agotamiento de la CPU. En este caso, la solución es investigar el origen del uso intensivo de la CPU y reducirlo, o bien escalar el equipo a un tamaño de recurso mayor.
  • Si los nodos threadInfo/isThreadStarving tienen valores True, la causa es el colapso de subprocesos. En este caso, la solución es investigar el origen u orígenes del colapso de subprocesos (subprocesos potencialmente bloqueados) o escalar los equipos a un tamaño de recurso mayor.
  • Si el tiempo dateUtc entre mediciones no es de aproximadamente 10 segundos, también indicaría contención en el grupo de subprocesos. La CPU se mide como una tarea independiente que se coloca en cola en el grupo de subprocesos cada 10 segundos. Si el tiempo entre mediciones es mayor, indica que las tareas asincrónicas no se pueden procesar de forma oportuna. El escenario más común es cuando el código de la aplicación está bloqueando las llamadas a través de código asincrónico.

Solución

La aplicación cliente que usa el SDK se debe escalar vertical u horizontalmente.

HttpResponseStats

HttpResponseStats son solicitudes que van a la puerta de enlace. Incluso en el modo Directo, el SDK obtiene toda la información de metadatos de la puerta de enlace.

Si la solicitud es lenta, compruebe primero que ninguna de las sugerencias anteriores produce los resultados deseados. Si sigue siendo lenta, la incidencia puede variar en función del patrón. En la tabla siguiente se proporciona los detalles.

Número de solicitudes Escenario Descripción
Desde una hasta todas Tiempo de espera de solicitud o HttpRequestExceptions Indica un agotamiento del puerto SNAT o una falta de recursos en la máquina para procesar la solicitud a tiempo.
Una o un porcentaje reducido (no se infringe el contrato de nivel de servicio) Todo Una sola solicitud lenta o un porcentaje reducido de solicitudes lentas pueden deberse a varias incidencias transitorias diferentes y entran dentro de lo previsto.
All All Indica una incidencia con la infraestructura o las redes.
Incumplimiento del contrato de nivel de servicio No se ha eliminado ningún cambio en la aplicación ni en el contrato de nivel de servicio. Indica una incidencia con el servicio 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

StoreResultrepresenta una única solicitud a Azure Cosmos DB mediante el modo Directo con el protocolo TCP.

Si sigue siendo lenta, la incidencia puede variar en función del patrón. En la tabla siguiente se proporciona los detalles.

Número de solicitudes Escenario Descripción
Desde una hasta todas StoreResult contiene TransportException Indica un agotamiento del puerto SNAT o una falta de recursos en la máquina para procesar la solicitud a tiempo.
Una o un porcentaje reducido (no se infringe el contrato de nivel de servicio) Todo Una sola solicitud lenta o un porcentaje reducido de solicitudes lentas pueden deberse a varias incidencias transitorias diferentes y entran dentro de lo previsto.
All All Indica una incidencia con la infraestructura o las redes.
Incumplimiento del contrato de nivel de servicio Las solicitudes contienen varios códigos de error, como 410 Indica un problema con el servicio Azure Cosmos DB o la máquina cliente.
Incumplimiento del contrato de nivel de servicio StorePhysicalAddressson los mismos sin código de estado de error. Es probable que haya un problema con Azure Cosmos DB.
Incumplimiento del contrato de nivel de servicio StorePhysicalAddress tiene el mismo Id. de partición, pero diferentes id. de réplica sin código de estado de error. Es probable que haya un problema con Azure Cosmos DB.
Incumplimiento del contrato de nivel de servicio StorePhysicalAddresses aleatorio sin código de estado de error. Apunta a un problema con la máquina.

En el caso de los resultados de varios almacenes para una única solicitud, tenga en cuenta lo siguiente:

  • La coherencia fuerte y de obsolescencia limitada siempre tendrá al menos dos resultados de almacén.
  • Compruebe el código de estado de cada StoreResult. El SDK vuelve a intentarlo automáticamente con varios errores transitorios diferentes. El SDK se está mejorando constantemente para abarcar más escenarios.

RequestTimeline

Muestra la hora de las distintas fases de envío y recepción de una solicitud en la capa de transporte.

  • ChannelAcquisitionStarted: La hora para obtener o crear una conexión. Las conexiones se pueden crear por numerosas razones, como: La conexión anterior se cerró debido a la inactividad mediante CosmosClientOptions.IdleTcpConnectionTimeout, el volumen de solicitudes simultáneas supera cosmosClientOptions.MaxRequestsPerTcpConnection, la conexión se cerró debido a un error de red o la aplicación no sigue el patrón Singleton y se crean constantemente nuevas instancias. Una vez establecida una conexión, se reutiliza en las solicitudes posteriores, por lo que esto no debería afectar a la latencia P99 a menos que se produzca alguno de los problemas mencionados anteriormente.
  • El tiempo elevado de Pipelined puede deberse a una solicitud grande.
  • Transit time es grande, lo que provoca un problema de red. Compare este número con BELatencyInMs. Si BELatencyInMs es bajo, el tiempo se ha dedicado a la red y no al servicio Azure Cosmos DB.
  • El tiempo elevado de Received puede deberse a un problema de inanición de subprocesos. Este es el tiempo comprendido entre que se tiene la respuesta y se devuelve el resultado.

ServiceEndpointStatistics

Información sobre un servidor backend determinado. El SDK puede abrir varias conexiones a un único servidor backend según el número de solicitudes pendientes y MaxConcurrentRequestsPerConnection.

  • inflightRequests Número de solicitudes pendientes a un servidor backend (quizás de diferentes particiones). Un número elevado puede dar lugar a más tráfico y latencias mayores.
  • openConnections es el número total de conexiones abiertas a un único servidor backend. Esto puede servir para mostrar el agotamiento del puerto SNAT si este número es muy alto.

ConnectionStatistics

Información sobre la conexión concreta (nueva o antigua) a la que se asigna la solicitud.

  • waitforConnectionInit: la solicitud actual estaba esperando a que se complete la nueva inicialización de conexión. Esto provocará latencias más altas.
  • callsPendingReceive: número de llamadas pendientes de recepción antes de enviar esta llamada. Un número elevado puede mostrarnos que hubo muchas llamadas antes de esta llamada y puede llevar a una mayor latencia. Si este número es alto, apunta a un problema de bloqueo de línea posiblemente causado por otra solicitud como la operación de consulta o fuente que tarda mucho tiempo en procesarse. Intente reducir el CosmosClientOptions.MaxRequestsPerTcpConnection para aumentar el número de canales.
  • LastSentTime: hora de la última solicitud que se envió a este servidor. Esto junto con LastReceivedTime se puede usar para ver problemas de conectividad o punto de conexión. Por ejemplo, si hay muchos tiempos de espera de recepción, el tiempo enviado será mucho mayor que el tiempo de recepción.
  • lastReceive: hora de la última solicitud recibida de este servidor
  • lastSendAttempt: hora del último intento de envío

Tamaños de solicitud y respuesta

  • requestSizeInBytes: tamaño total de la solicitud enviada a Azure Cosmos DB
  • responseMetadataSizeInBytes: tamaño de los encabezados devueltos de Azure Cosmos DB
  • responseBodySizeInBytes: tamaño del contenido devuelto de 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
}

La tasa de errores infringe el Acuerdo de Nivel de Servicio de Azure Cosmos DB

Póngase en contacto con el equipo de soporte técnico de Azure.

Pasos siguientes