Dela via

Diagnostisera och felsöka långsamma begäranden i Azure Cosmos DB .NET SDK

  • Artikel

GÄLLER FÖR: NoSQL

I Azure Cosmos DB kan du märka långsamma begäranden. Fördröjningar kan inträffa av flera orsaker, till exempel begränsning av begäranden eller hur programmet är utformat. Den här artikeln förklarar de olika rotorsakerna till det här problemet.

Begärandefrekvensen är för hög

Begränsning av begäranden är den vanligaste orsaken till långsamma begäranden. Azure Cosmos DB begränsar begäranden om de överskrider de allokerade enheter för begäran för databasen eller containern. SDK:n har inbyggd logik för att försöka utföra dessa begäranden igen. I artikeln om för stor felsökning av begäranden förklaras hur du kontrollerar om begäranden begränsas. I artikeln beskrivs också hur du skalar ditt konto för att undvika dessa problem i framtiden.

Programdesign

När du utformar ditt program följer du metodtipsen för .NET SDK för bästa prestanda. Om ditt program inte följer SDK-metodtipsen kan du få långsamma eller misslyckade begäranden.

Tänk på följande när du utvecklar ditt program:

Metadataåtgärder

Om du behöver kontrollera att det finns en databas eller container ska du inte göra det genom att anropa Create...IfNotExistsAsync eller Read...Async innan du utför en objektåtgärd. Valideringen bör endast utföras vid programstart när det är nödvändigt, om du förväntar dig att de tas bort. Dessa metadataåtgärder genererar extra svarstid, har inget serviceavtal (SLA) och har egna separata begränsningar. De skalas inte som dataåtgärder.

Långsamma begäranden i massläge

Massläge är ett dataflödesoptimerad läge som är avsett för hög datavolymåtgärder, inte ett svarstidsoptimerad läge. Det är avsett att mätta det tillgängliga dataflödet. Om du får långsamma begäranden när du använder massläge kontrollerar du att:

  • Programmet kompileras i versionskonfigurationen.
  • Du mäter inte svarstiden när du felsöker programmet (inga felsökare är anslutna).
  • Mängden åtgärder är hög, använd inte bulk för mindre än 1 000 åtgärder. Ditt etablerade dataflöde avgör hur många åtgärder per sekund du kan bearbeta. Målet med bulk är att använda så mycket av det som möjligt.
  • Övervaka containern för begränsningsscenarier. Om containern blir kraftigt begränsad innebär det att datavolymen är större än ditt etablerade dataflöde, du måste antingen skala upp containern eller minska mängden data (kanske skapa mindre mängder data i taget).
  • Du använder async/await mönstret korrekt för att bearbeta alla samtidiga uppgifter och blockerar inte någon asynkron åtgärd.

Samla in diagnostik

Alla svar i SDK, inklusive CosmosException, har en Diagnostics egenskap. Den här egenskapen registrerar all information som rör den enskilda begäran, inklusive om det fanns återförsök eller tillfälliga fel.

Diagnostiken returneras som en sträng. Strängen ändras med varje version eftersom den har förbättrats för felsökning av olika scenarier. Med varje version av SDK:t har strängen icke-bakåtkompatibla ändringar i formateringen. Parsa inte strängen för att undvika icke-bakåtkompatibla ändringar. Följande kodexempel visar hur du läser diagnostikloggar med hjälp av .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()
}

Diagnostik i version 3.19 och senare

JSON-strukturen har icke-bakåtkompatibla ändringar med varje version av SDK:t. Detta gör det osäkert att parsas. JSON representerar en trädstruktur för begäran som går igenom SDK:t. Följande avsnitt beskriver några viktiga saker att titta på.

CPU-historik

Hög CPU-användning är den vanligaste orsaken till långsamma begäranden. För att få en optimal svarstid bör processoranvändningen vara ungefär 40 procent. Använd 10 sekunder som intervall för att övervaka den maximala (inte genomsnittliga) processoranvändningen. CPU-toppar är vanligare med frågor mellan partitioner, där begäranden kan göra flera anslutningar för en enda fråga.

Tidsgränserna omfattar diagnostik, som innehåller följande, till exempel:

"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 Om värdena är över 70 procent orsakas tidsgränsen sannolikt av cpu-överbelastning. I det här fallet är lösningen att undersöka källan till hög processoranvändning och minska den, eller skala datorn till en större resursstorlek.
  • threadInfo/isThreadStarving Om noderna har True värden är orsaken trådsvältning. I det här fallet är lösningen att undersöka källan eller källorna till trådsvältningen (potentiellt låsta trådar) eller skala datorn eller datorerna till en större resursstorlek.
  • dateUtc Om tiden mellan måtten inte är cirka 10 sekunder indikerar det också konkurrens i trådpoolen. CPU mäts som en oberoende uppgift som placeras i trådpoolen var 10:e sekund. Om tiden mellan mätningarna är längre anger det att asynkrona uppgifter inte kan bearbetas i tid. Det vanligaste scenariot är när programkoden blockerar anrop via asynkron kod.

Lösning

Klientprogrammet som använder SDK:t ska skalas upp eller ut.

HttpResponseStats

HttpResponseStatsär begäranden som går till gatewayen. Även i direktläge hämtar SDK all metadatainformation från gatewayen.

Om begäran är långsam kontrollerar du först att inget av de tidigare förslagen ger önskat resultat. Om det fortfarande är långsamt pekar olika mönster på olika problem. Följande tabell innehåller mer information.

Antal begäranden Scenario beskrivning
Enkel till alla Tidsgräns för begäran eller HttpRequestExceptions Pekar på SNAT-portöverbelastning eller brist på resurser på datorn för att bearbeta begäran i tid.
Enstaka eller liten procentandel (serviceavtal överträds inte) Alla En enskild eller liten andel långsamma begäranden kan orsakas av flera olika tillfälliga problem och bör förväntas.
Alla Alla Pekar på ett problem med infrastrukturen eller nätverket.
SLA har brutits Inga ändringar i programmet och serviceavtalet har tagits bort. Pekar på ett problem med Azure Cosmos DB-tjänsten. 
"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 representerar en enskild begäran till Azure Cosmos DB genom att använda direktläge med TCP-protokollet.

Om det fortfarande är långsamt pekar olika mönster på olika problem. Följande tabell innehåller mer information.

Antal begäranden Scenario beskrivning
Enkel till alla StoreResult Innehåller TransportException Pekar på SNAT-portöverbelastning eller brist på resurser på datorn för att bearbeta begäran i tid.
Enstaka eller liten procentandel (serviceavtal överträds inte) Alla En enskild eller liten andel långsamma begäranden kan orsakas av flera olika tillfälliga problem och bör förväntas.
Alla Alla Ett problem med infrastrukturen eller nätverket.
SLA har brutits Begäranden innehåller flera felkoder, till exempel 410 Pekar på ett problem med Azure Cosmos DB-tjänsten eller klientdatorn.
SLA har brutits StorePhysicalAddress är desamma, utan felstatuskod. Sannolikt ett problem med Azure Cosmos DB.
SLA har brutits StorePhysicalAddress har samma partitions-ID, men olika replik-ID:n, utan felstatuskod. Sannolikt ett problem med Azure Cosmos DB.
SLA har brutits StorePhysicalAddress är slumpmässig, utan felstatuskod. Pekar på ett problem med datorn.

Tänk på följande för flera lagringsresultat för en enskild begäran:

  • Stark konsekvens och begränsad föråldringskonsekvens har alltid minst två lagringsresultat.
  • Kontrollera statuskoden för varje StoreResult. SDK:et försöker automatiskt igen vid flera olika tillfälliga fel. SDK:et förbättras ständigt för att täcka fler scenarier.

RequestTimeline

Visa tiden för de olika stegen för att skicka och ta emot en begäran i transportlagret.

  • ChannelAcquisitionStarted: Det är dags att hämta eller skapa en ny anslutning. Anslutningar kan skapas av flera orsaker, till exempel: Den tidigare anslutningen stängdes på grund av inaktivitet med CosmosClientOptions.IdleTcpConnectionTimeout, volymen samtidiga begäranden överskrider CosmosClientOptions.MaxRequestsPerTcpConnection, anslutningen stängdes på grund av ett nätverksfel eller så följer programmet inte Singleton-mönstret och nya instanser skapas ständigt. När en anslutning har upprättats återanvänds den för efterföljande begäranden, så detta bör inte påverka P99-svarstiden om inte de tidigare nämnda problemen inträffar.
  • Pipelined: Den tid som ägnas åt att skriva begäran till TCP-socketen. Begäran kan bara skrivas på en TCP-socket en i taget, ett stort värde anger en flaskhals på TCP-socketen som ofta associeras med låsta trådar av programkoden eller storleken på stora begäranden.
  • Transit time: Den tid som lagts på nätverket efter att begäran skrevs på TCP-socketen. Jämför det här talet med BELatencyInMs. Om BELatencyInMs är liten har tiden lagts på nätverket och inte på Azure Cosmos DB-tjänsten. Om begäran misslyckades med en tidsgräns anger den hur länge klienten väntade utan svar och källan är nätverksfördröjning.
  • Received: Tiden mellan svaret togs emot och bearbetades av SDK:et. Ett stort värde orsakas normalt av en trådsvält eller låsta trådar.

ServiceEndpointStatistics

Information om en viss serverdelsserver. SDK kan öppna flera anslutningar till en enskild serverdelsserver beroende på antalet väntande begäranden och MaxConcurrentRequestsPerConnection.

  • inflightRequests Antalet väntande begäranden till en serverdelsserver (kanske från olika partitioner). Ett högt antal kan leda till mer trafik och högre svarstider.
  • openConnections är det totala antalet anslutningar som är öppna för en enskild serverdelsserver. Detta kan vara användbart för att visa SNAT-portöverbelastning om det här talet är mycket högt.

ConnectionStatistics

Information om den specifika anslutningen (ny eller gammal) som begäran tilldelas till.

  • waitforConnectionInit: Den aktuella begäran väntade på att den nya anslutningsinitieringen skulle slutföras. Detta leder till högre svarstider.
  • callsPendingReceive: Antal samtal som väntar på att ta emot innan det här samtalet skickades. Ett högt antal kan visa oss att det fanns många anrop före det här anropet och det kan leda till högre svarstider. Om det här talet är högt pekar det på ett problem med blockering av huvudlinjen som kan orsakas av en annan begäran, till exempel en fråga eller flödesåtgärd som tar lång tid att bearbeta. Försök att sänka CosmosClientOptions.MaxRequestsPerTcpConnection för att öka antalet kanaler.
  • LastSentTime: Tidpunkten för den senaste begäran som skickades till den här servern. Detta tillsammans med LastReceivedTime kan användas för att se anslutningsproblem eller slutpunktsproblem. Om det till exempel finns många tidsgränser för mottagning blir sändningstiden mycket större än mottagningstiden.
  • lastReceive: Tidpunkten för den senaste begäran som togs emot från den här servern
  • lastSendAttempt: Tidpunkten för det senaste sändningsförsöket

Storlekar för begäran och svar

  • requestSizeInBytes: Den totala storleken på den begäran som skickas till Azure Cosmos DB
  • responseMetadataSizeInBytes: Storleken på rubriker som returneras från Azure Cosmos DB
  • responseBodySizeInBytes: Storleken på innehåll som returneras från 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
}

Felfrekvensen bryter mot serviceavtalet för Azure Cosmos DB

Kontakta Azure Support.

Nästa steg