ealsur
commented
1 year ago @neildsh could you take a look?
Closed IsaacBoy closed 7 months ago
ealsur
commented
1 year ago @neildsh could you take a look?
neildsh
commented
1 year ago Hello @IsaacBoy thanks for reporting this issue. Would you mind attaching the following information:
Thanks!
IsaacBoy
commented
1 year ago Hello @IsaacBoy thanks for reporting this issue. Would you mind attaching the following information:
- The diagnostics for these requests ?
- The SQL indexing policy used on the collection
Thanks!
sure. The diagnostics from the first call is:
{
"Summary":{
"DirectCalls":{
"(200, 0)":1
}
},
"name":"Typed FeedIterator ReadNextAsync",
"id":"9ec2ab27-2f29-4d92-8bc4-91091cb8d6eb",
"start time":"06:32:06:958",
"duration in milliseconds":328.734,
"data":{
"Synchronization Context":"Xunit.Sdk.MaxConcurrencySyncContext",
"Query Correlated ActivityId":"033f23b7-9b81-49e1-aa5b-2371372b8d8c"
},
"children":[
{
"name":"Create Query Pipeline",
"id":"f9133e77-8768-4581-bc1a-1df7c4144b4b",
"start time":"06:32:06:967",
"duration in milliseconds":82.7911,
"children":[
{
"name":"Get Container Properties",
"id":"d0570f2c-1901-4e84-b500-0793b358fb0b",
"start time":"06:32:06:968",
"duration in milliseconds":0.024,
"children":[
{
"name":"Get Collection Cache",
"id":"c71cf0a2-3fc6-4588-9858-704a42ac33d1",
"start time":"06:32:06:968",
"duration in milliseconds":0.0035
}
]
},
{
"name":"Service Interop Query Plan",
"id":"3f5c26b9-7b85-40bc-a1d4-c789bbace9d1",
"start time":"06:32:06:983",
"duration in milliseconds":30.2872
},
{
"name":"Get Partition Key Ranges",
"id":"89d18d31-a272-4260-a81d-41b87e58f24f",
"start time":"06:32:07:016",
"duration in milliseconds":6.4834,
"children":[
{
"name":"Try Get Overlapping Ranges",
"id":"118f549d-e799-45cf-b322-d1be762956f2",
"start time":"06:32:07:021",
"duration in milliseconds":1.6405
}
]
}
]
},
{
"name":"Prefetching",
"id":"fd4e44fc-c30a-441c-881d-ea814263ae83",
"start time":"06:32:07:057",
"duration in milliseconds":0.0104
},
{
"name":"[,FF) move next",
"id":"b105961a-fd32-4589-9c77-d0b718d96f00",
"start time":"06:32:07:059",
"duration in milliseconds":205.098,
"children":[
{
"name":"[,FF) move next",
"id":"00448a35-8d50-4ff8-bc52-1b3323b8514b",
"start time":"06:32:07:059",
"duration in milliseconds":204.3369,
"children":[
{
"name":"Prefetch",
"id":"551346c2-ace7-4b13-ac3b-d0754b51a825",
"start time":"06:32:07:061",
"duration in milliseconds":202.2716,
"children":[
{
"name":"[,FF) move next",
"id":"f0d54586-62af-4ddf-962c-ec5693a52019",
"start time":"06:32:07:061",
"duration in milliseconds":201.5887,
"data":{
"Query Metrics":"Retrieved Document Count : 1 \r\nRetrieved Document Size : 497 bytes \r\nOutput Document Count : 1 \r\nOutput Document Size : 648 bytes \r\nIndex Utilization : 100.00 % \r\nTotal Query Execution Time : 0.84 milliseconds\r\n Query Preparation Time : 0.34 milliseconds\r\n Index Lookup Time : 0.18 milliseconds\r\n Document Load Time : 0.03 milliseconds\r\n Runtime Execution Times : 0.00 milliseconds\r\n Document Write Time : 0.00 milliseconds\r\n\r\nIndex Utilization Information\r\n Utilized Single Indexes\r\n Potential Single Indexes\r\n Utilized Composite Indexes\r\n Potential Composite Indexes\r\n"
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
"id":"43ad015d-1d6d-44cb-94f0-e3def8299c07",
"start time":"06:32:07:063",
"duration in milliseconds":173.8425,
"children":[
{
"name":"Get Collection Cache",
"id":"79020f55-7735-4ed5-be07-2d7ddf3b72f0",
"start time":"06:32:07:063",
"duration in milliseconds":0.002
},
{
"name":"Get Partition Key Range Cache",
"id":"30a116e1-4e1c-4e32-8f60-0cef87696437",
"start time":"06:32:07:063",
"duration in milliseconds":0.0004
},
{
"name":"Try Get Overlapping Ranges",
"id":"9006d76f-cac3-491c-8550-4b606dea18c8",
"start time":"06:32:07:063",
"duration in milliseconds":0.0438
},
{
"name":"Blackbaud.Cosmos.MissingIndexHandler",
"id":"89b40f61-0df6-40f2-9699-2bfad7717674",
"start time":"06:32:07:064",
"duration in milliseconds":172.7872,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
"id":"f26a9d86-5dc5-4108-a2a6-78628d1c8131",
"start time":"06:32:07:064",
"duration in milliseconds":165.5329,
"data":{
"System Info":{
"systemHistory":[
{
"dateUtc":"2023-01-10T18:32:05.2531642Z",
"cpu":5.607,
"memory":769688.000,
"threadInfo":{
"isThreadStarving":"no info",
"availableThreads":32765,
"minThreads":12,
"maxThreads":32767
},
"numberOfOpenTcpConnection":0
}
]
}
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RetryHandler",
"id":"e7891225-75e8-4e19-9644-eb76a462b704",
"start time":"06:32:07:064",
"duration in milliseconds":165.5238,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RouterHandler",
"id":"7295b491-fa51-4fa7-a71f-34003a8fad32",
"start time":"06:32:07:064",
"duration in milliseconds":165.5069,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.TransportHandler",
"id":"7cbdef77-e37e-400c-bc07-0660dc01fe9a",
"start time":"06:32:07:064",
"duration in milliseconds":165.5035,
"children":[
{
"name":"Microsoft.Azure.Documents.ServerStoreModel Transport Request",
"id":"e95e6014-41dd-4e49-b00b-037098fdf288",
"start time":"06:32:07:064",
"duration in milliseconds":165.3583,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
{
"Count":1,
"Uri":"rntbd://cdb-ms-prod-eastus2-fd1.documents.azure.com:14110/apps/1dd544e5-a379-42fd-bbcb-28044e88d561/services/4c7019d4-567d-4632-bd28-b61700d01760/partitions/84ab3449-794c-4172-bd81-2d082e0c1d0c/replicas/133177516299464252s/"
}
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
],
"StoreResponseStatistics":[
{
"ResponseTimeUTC":"2023-01-10T18:32:07.2285357Z",
"ResourceType":"Document",
"OperationType":"Query",
"RequestSessionToken":"0:-1#1808",
"LocationEndpoint":"https://[[address]]-eastus2.documents.azure.com/",
"StoreResult":{
"ActivityId":"938b51e6-c864-4592-b198-f66f2073dc34",
"StatusCode":"Ok",
"SubStatusCode":"Unknown",
"LSN":1808,
"PartitionKeyRangeId":"0",
"GlobalCommittedLSN":1807,
"ItemLSN":-1,
"UsingLocalLSN":true,
"QuorumAckedLSN":-1,
"SessionToken":"-1#1808",
"CurrentWriteQuorum":-1,
"CurrentReplicaSetSize":-1,
"NumberOfReadRegions":0,
"IsValid":true,
"StorePhysicalAddress":"rntbd://cdb-ms-prod-eastus2-fd1.documents.azure.com:14110/apps/1dd544e5-a379-42fd-bbcb-28044e88d561/services/4c7019d4-567d-4632-bd28-b61700d01760/partitions/84ab3449-794c-4172-bd81-2d082e0c1d0c/replicas/133177516299464252s/",
"RequestCharge":2.83,
"RetryAfterInMs":null,
"BELatencyInMs":"1.333",
"transportRequestTimeline":{
"requestTimeline":[
{
"event":"Created",
"startTimeUtc":"2023-01-10T18:32:07.0670971Z",
"durationInMs":0.0438
},
{
"event":"ChannelAcquisitionStarted",
"startTimeUtc":"2023-01-10T18:32:07.0671409Z",
"durationInMs":131.5759
},
{
"event":"Pipelined",
"startTimeUtc":"2023-01-10T18:32:07.1987168Z",
"durationInMs":0.9668
},
{
"event":"Transit Time",
"startTimeUtc":"2023-01-10T18:32:07.1996836Z",
"durationInMs":27.6827
},
{
"event":"Received",
"startTimeUtc":"2023-01-10T18:32:07.2273663Z",
"durationInMs":0.3477
},
{
"event":"Completed",
"startTimeUtc":"2023-01-10T18:32:07.2277140Z",
"durationInMs":0
}
],
"serviceEndpointStats":{
"inflightRequests":1,
"openConnections":1
},
"connectionStats":{
"waitforConnectionInit":"True",
"callsPendingReceive":0,
"lastSendAttempt":"2023-01-10T18:32:07.1717526Z",
"lastSend":"2023-01-10T18:32:07.1718378Z",
"lastReceive":"2023-01-10T18:32:07.1980642Z"
},
"requestSizeInBytes":758,
"requestBodySizeInBytes":300,
"responseMetadataSizeInBytes":1319,
"responseBodySizeInBytes":648
},
"TransportException":null
}
}
]
}
}
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"name":"Get Cosmos Element Response",
"id":"83996e17-80bb-4c4e-8034-cd4c8ddcbe0a",
"start time":"06:32:07:239",
"duration in milliseconds":21.242
}
]
}
]
}
]
}
]
},
{
"name":"Query Response Serialization",
"id":"d5e51897-40b8-4e59-96ad-ae81dcbfee3c",
"start time":"06:32:07:282",
"duration in milliseconds":4.3104
}
]
}And then from one using the continuation token with the filter property set
{
"Summary":{
"DirectCalls":{
"(200, 0)":1
}
},
"name":"Typed FeedIterator ReadNextAsync",
"id":"79ebb32a-be9c-44ac-aa7b-41546ef819ae",
"start time":"06:29:15:729",
"duration in milliseconds":44.9197,
"data":{
"Synchronization Context":"Xunit.Sdk.MaxConcurrencySyncContext",
"Query Correlated ActivityId":"2585ddef-452c-4697-a613-bd236b4346f4"
},
"children":[
{
"name":"Create Query Pipeline",
"id":"6954ad43-c5fd-4c37-8d4d-08ff506ad97f",
"start time":"06:29:15:729",
"duration in milliseconds":12.6105,
"children":[
{
"name":"Get Container Properties",
"id":"acfee589-1a8b-4208-9a69-d0e1e592e9ac",
"start time":"06:29:15:730",
"duration in milliseconds":0.0509,
"children":[
{
"name":"Get Collection Cache",
"id":"601c7e1b-8c6e-4261-9d3a-de4b6ac2ecbe",
"start time":"06:29:15:730",
"duration in milliseconds":0.0024
}
]
},
{
"name":"Service Interop Query Plan",
"id":"af685b3e-4aee-48eb-b799-fabfb3fda585",
"start time":"06:29:15:730",
"duration in milliseconds":9.2169
},
{
"name":"Get Partition Key Ranges",
"id":"da73f8d0-ad0b-43a8-8302-5de1b17966d8",
"start time":"06:29:15:740",
"duration in milliseconds":0.0446,
"children":[
{
"name":"Try Get Overlapping Ranges",
"id":"57e3daba-94d5-47be-8fc4-34ec84a80752",
"start time":"06:29:15:740",
"duration in milliseconds":0.0235
}
]
}
]
},
{
"name":"Prefetching",
"id":"13721626-15e6-43ef-b3a9-a3ff49edcea1",
"start time":"06:29:15:742",
"duration in milliseconds":0.0013
},
{
"name":"[,FF) move next",
"id":"109b58ee-039f-4e6f-8206-87c19395558b",
"start time":"06:29:15:742",
"duration in milliseconds":30.4374,
"children":[
{
"name":"[,FF) move next",
"id":"da5624a8-78e4-42d2-9dfc-1989a49cf0c5",
"start time":"06:29:15:742",
"duration in milliseconds":30.4295,
"children":[
{
"name":"Prefetch",
"id":"d3dae2b9-c116-4d83-aad3-5e51167951a4",
"start time":"06:29:15:742",
"duration in milliseconds":30.4197,
"children":[
{
"name":"[,FF) move next",
"id":"2856fde2-cc10-4ca6-8860-1a4926e53353",
"start time":"06:29:15:742",
"duration in milliseconds":30.4142,
"data":{
"Query Metrics":"Retrieved Document Count : 6 \r\nRetrieved Document Size : 2,982 bytes \r\nOutput Document Count : 1 \r\nOutput Document Size : 648 bytes \r\nIndex Utilization : 100.00 % \r\nTotal Query Execution Time : 1.21 milliseconds\r\n Query Preparation Time : 0.64 milliseconds\r\n Index Lookup Time : 0.05 milliseconds\r\n Document Load Time : 0.08 milliseconds\r\n Runtime Execution Times : 0.00 milliseconds\r\n Document Write Time : 0.00 milliseconds\r\n\r\nIndex Utilization Information\r\n Utilized Single Indexes\r\n Potential Single Indexes\r\n Utilized Composite Indexes\r\n Potential Composite Indexes\r\n"
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
"id":"276ffad6-7960-40ec-96e9-8cffda418736",
"start time":"06:29:15:742",
"duration in milliseconds":30.2667,
"children":[
{
"name":"Get Collection Cache",
"id":"50f29d3a-a9b7-483d-b048-82aa2be997b6",
"start time":"06:29:15:742",
"duration in milliseconds":0.0009
},
{
"name":"Get Partition Key Range Cache",
"id":"b9ae1c90-84d2-4f0f-9762-bd7249d1b1c3",
"start time":"06:29:15:742",
"duration in milliseconds":0.0003
},
{
"name":"Try Get Overlapping Ranges",
"id":"18895f00-c3fc-40bc-a215-58f0b257f2ac",
"start time":"06:29:15:742",
"duration in milliseconds":0.0183
},
{
"name":"Blackbaud.Cosmos.MissingIndexHandler",
"id":"96d29d7e-06ed-4fb7-84d6-14943fc7991f",
"start time":"06:29:15:742",
"duration in milliseconds":30.1969,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
"id":"dc47055d-0a2f-4cfc-8650-3b58f02f4469",
"start time":"06:29:15:742",
"duration in milliseconds":30.0189,
"data":{
"System Info":{
"systemHistory":[
{
"dateUtc":"2023-01-10T18:28:58.1255038Z",
"cpu":5.606,
"memory":1051868.000,
"threadInfo":{
"isThreadStarving":"no info",
"availableThreads":32765,
"minThreads":12,
"maxThreads":32767
},
"numberOfOpenTcpConnection":0
},
{
"dateUtc":"2023-01-10T18:29:15.6994485Z",
"cpu":7.183,
"memory":1042648.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.1407,
"availableThreads":32760,
"minThreads":12,
"maxThreads":32767
},
"numberOfOpenTcpConnection":4
}
]
}
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RetryHandler",
"id":"34d173a0-5d74-4091-9bda-c422703a2bb4",
"start time":"06:29:15:742",
"duration in milliseconds":30.0093,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RouterHandler",
"id":"7250e226-3062-497e-ac3f-00310e48d1fa",
"start time":"06:29:15:742",
"duration in milliseconds":29.9942,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.TransportHandler",
"id":"c73790ff-941b-46ff-968a-e69242a7f5e4",
"start time":"06:29:15:742",
"duration in milliseconds":29.989,
"children":[
{
"name":"Microsoft.Azure.Documents.ServerStoreModel Transport Request",
"id":"7c551390-55f7-49a2-87ee-318d4bd0cd40",
"start time":"06:29:15:742",
"duration in milliseconds":29.9358,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
{
"Count":1,
"Uri":"rntbd://cdb-ms-prod-eastus2-fd1.documents.azure.com:14377/apps/1dd544e5-a379-42fd-bbcb-28044e88d561/services/4c7019d4-567d-4632-bd28-b61700d01760/partitions/84ab3449-794c-4172-bd81-2d082e0c1d0c/replicas/133177515037180419p/"
}
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
],
"StoreResponseStatistics":[
{
"ResponseTimeUTC":"2023-01-10T18:29:15.7722492Z",
"ResourceType":"Document",
"OperationType":"Query",
"RequestSessionToken":"0:-1#1805",
"LocationEndpoint":"https://[[address]]-eastus2.documents.azure.com/",
"StoreResult":{
"ActivityId":"ee852cd1-ce3c-4091-b373-e4e47bed7314",
"StatusCode":"Ok",
"SubStatusCode":"Unknown",
"LSN":1805,
"PartitionKeyRangeId":"0",
"GlobalCommittedLSN":1805,
"ItemLSN":-1,
"UsingLocalLSN":true,
"QuorumAckedLSN":1805,
"SessionToken":"-1#1805",
"CurrentWriteQuorum":3,
"CurrentReplicaSetSize":4,
"NumberOfReadRegions":0,
"IsValid":true,
"StorePhysicalAddress":"rntbd://cdb-ms-prod-eastus2-fd1.documents.azure.com:14377/apps/1dd544e5-a379-42fd-bbcb-28044e88d561/services/4c7019d4-567d-4632-bd28-b61700d01760/partitions/84ab3449-794c-4172-bd81-2d082e0c1d0c/replicas/133177515037180419p/",
"RequestCharge":2.78,
"RetryAfterInMs":null,
"BELatencyInMs":"3.264",
"transportRequestTimeline":{
"requestTimeline":[
{
"event":"Created",
"startTimeUtc":"2023-01-10T18:29:15.7426187Z",
"durationInMs":0.0032
},
{
"event":"ChannelAcquisitionStarted",
"startTimeUtc":"2023-01-10T18:29:15.7426219Z",
"durationInMs":0.0151
},
{
"event":"Pipelined",
"startTimeUtc":"2023-01-10T18:29:15.7426370Z",
"durationInMs":0.1676
},
{
"event":"Transit Time",
"startTimeUtc":"2023-01-10T18:29:15.7428046Z",
"durationInMs":28.6065
},
{
"event":"Received",
"startTimeUtc":"2023-01-10T18:29:15.7714111Z",
"durationInMs":0.829
},
{
"event":"Completed",
"startTimeUtc":"2023-01-10T18:29:15.7722401Z",
"durationInMs":0
}
],
"serviceEndpointStats":{
"inflightRequests":1,
"openConnections":1
},
"connectionStats":{
"waitforConnectionInit":"False",
"callsPendingReceive":0,
"lastSendAttempt":"2023-01-10T18:28:59.7553312Z",
"lastSend":"2023-01-10T18:28:59.7554289Z",
"lastReceive":"2023-01-10T18:28:59.7848062Z"
},
"requestSizeInBytes":1153,
"requestBodySizeInBytes":543,
"responseMetadataSizeInBytes":3073,
"responseBodySizeInBytes":648
},
"TransportException":null
}
}
]
}
}
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"name":"Get Cosmos Element Response",
"id":"ed71acdd-33ae-4f0c-a29c-6dbe08f565f4",
"start time":"06:29:15:772",
"duration in milliseconds":0.064
}
]
}
]
}
]
}
]
},
{
"name":"Query Response Serialization",
"id":"1b4bb791-ffeb-45c8-b5a8-c41e72e0b60c",
"start time":"06:29:15:774",
"duration in milliseconds":0.0616
}
]
}The index policy is:
{
"indexingMode": "consistent",
"automatic": true,
"includedPaths": [
{
"path": "/PartitionKey/?"
},
{
"path": "/AuditDate/?"
},
{
"path": "/Summary/*"
},
{
"path": "/Version/?"
},
{
"path": "/EligibilityOverride/*"
},
{
"path": "/DocumentType/?"
},
{
"path": "/LegalEntityPurpose/?"
}
],
"excludedPaths": [
{
"path": "/*"
},
{
"path": "/\"_etag\"/?"
}
],
"compositeIndexes": [
[
{
"path": "/DocumentType",
"order": "ascending"
},
{
"path": "/AuditDate",
"order": "ascending"
}
],
[
{
"path": "/DocumentType",
"order": "ascending"
},
{
"path": "/AuditDate",
"order": "descending"
}
],
[
{
"path": "/DocumentType",
"order": "ascending"
},
{
"path": "/EligibilityOverride/AuditDate",
"order": "ascending"
}
],
[
{
"path": "/DocumentType",
"order": "ascending"
},
{
"path": "/EligibilityOverride/AuditDate",
"order": "descending"
}
],
[
{
"path": "/PartitionKey",
"order": "ascending"
},
{
"path": "/Version",
"order": "ascending"
}
],
[
{
"path": "/PartitionKey",
"order": "ascending"
},
{
"path": "/AuditDate",
"order": "ascending"
}
],
[
{
"path": "/DocumentType",
"order": "ascending"
},
{
"path": "/PartitionKey",
"order": "ascending"
}
],
[
{
"path": "/DocumentType",
"order": "ascending"
},
{
"path": "/Summary/RiskScore",
"order": "ascending"
}
]
]
}neildsh Those diag logs were from a test environment that has a much smaller subset of data. Here are the logs from the actual prod environment where the issue is occurring.
First call (no continuation token):
{
"Summary":{
"DirectCalls":{
"(200, 0)":1
},
"GatewayCalls":{
"(200, 0)":3,
"(304, 0)":1
}
},
"name":"Typed FeedIterator ReadNextAsync",
"id":"9849c13f-a1ce-490e-997e-2410b00bf610",
"start time":"09:07:45:385",
"duration in milliseconds":5322.974,
"data":{
"Client Configuration":{
"Client Created Time Utc":"2023-01-10T21:05:15.0858392Z",
"MachineId":"hashedMachineName:2b130921-b646-6748-e233-2f8097cef64a",
"NumberOfClientsCreated":1,
"NumberOfActiveClients":1,
"ConnectionMode":"Direct",
"User Agent":"cosmos-netstandard-sdk/3.31.2|1|X64|Linux 5.4.0-1098-azure 104 18|.NET 6.0.10|S|",
"ConnectionConfig":{
"gw":"(cps:50, urto:10, p:False, httpf: False)",
"rntbd":"(cto: 5, icto: -1, mrpc: 30, mcpe: 65535, erd: True, pr: ReuseUnicastPort)",
"other":"(ed:False, be:False)"
},
"ConsistencyConfig":"(consistency: NotSet, prgns:[], apprgn: East US 2)",
"ProcessorCount":1
},
"Query Correlated ActivityId":"6d435690-df73-450a-a734-328ba3676649"
},
"children":[
{
"name":"Create Query Pipeline",
"id":"5371ee93-5bb4-4f54-bf94-b78ca1f7b055",
"start time":"09:07:45:400",
"duration in milliseconds":176.3414,
"children":[
{
"name":"Get Container Properties",
"id":"62b75191-b1da-46fa-a12d-39794e45994a",
"start time":"09:07:45:401",
"duration in milliseconds":0.1496,
"children":[
{
"name":"Get Collection Cache",
"id":"1f703253-ab83-4608-ac16-5dbf68bc2965",
"start time":"09:07:45:401",
"duration in milliseconds":0.0045
}
]
},
{
"name":"Gateway QueryPlan",
"id":"7869b163-ed76-4c3c-9c2a-685ecd11cf1c",
"start time":"09:07:45:407",
"duration in milliseconds":29.3192
},
{
"name":"Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
"id":"c7d9cd03-baaf-4c65-9be6-9deef514d6bb",
"start time":"09:07:45:410",
"duration in milliseconds":39.962,
"children":[
{
"name":"Blackbaud.Cosmos.RetryRequestHandler",
"id":"a36ecf20-500d-4b9b-8003-6447736e39a8",
"start time":"09:07:45:410",
"duration in milliseconds":39.3421,
"children":[
{
"name":"Blackbaud.Cosmos.RetryCounterMetricRequestHandler",
"id":"4eaf03bf-6372-4b51-ac3e-0ad8ad1da6b6",
"start time":"09:07:45:410",
"duration in milliseconds":39.3126,
"children":[
{
"name":"Blackbaud.Cosmos.TracingRequestHandler",
"id":"52ea3fe8-52cf-4224-8d4c-f6466e241c37",
"start time":"09:07:45:410",
"duration in milliseconds":39.3088,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
"id":"31dfef16-625b-40ac-b173-e68c34158147",
"start time":"09:07:45:410",
"duration in milliseconds":39.1869,
"data":{
"System Info":{
"systemHistory":[
{
"dateUtc":"2023-01-10T21:06:55.2425018Z",
"cpu":14.372,
"memory":32298292.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.064,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:05.2428461Z",
"cpu":13.829,
"memory":32255268.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0787,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:15.2431673Z",
"cpu":14.529,
"memory":32465364.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.068,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:25.2436122Z",
"cpu":13.166,
"memory":32527180.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.1011,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:35.2439415Z",
"cpu":11.616,
"memory":32540128.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0474,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:45.2442873Z",
"cpu":10.925,
"memory":32557528.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0534,
"availableThreads":32764,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
}
]
}
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RetryHandler",
"id":"3e1d279c-7f2c-4957-ae42-1a3002972bfc",
"start time":"09:07:45:410",
"duration in milliseconds":39.1757,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RouterHandler",
"id":"b0eefd6f-ac99-4662-b36f-8e0f931779bd",
"start time":"09:07:45:410",
"duration in milliseconds":39.1567,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.TransportHandler",
"id":"96560cd7-235d-4626-8dad-e91907087be8",
"start time":"09:07:45:410",
"duration in milliseconds":39.1501,
"children":[
{
"name":"Microsoft.Azure.Cosmos.GatewayStoreModel Transport Request",
"id":"ed0a27ec-b8b0-4693-8d8e-c6cefda1f197",
"start time":"09:07:45:410",
"duration in milliseconds":39.043,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
],
"StoreResponseStatistics":[
],
"HttpResponseStats":[
{
"StartTimeUTC":"2023-01-10T21:07:45.4113729Z",
"DurationInMs":38.573,
"RequestUri":"https://[[address]]-eastus2.documents.azure.com/dbs/kyc-trust/colls/records/docs",
"ResourceType":"Document",
"HttpMethod":"POST",
"ActivityId":"91d88f87-a472-4221-955b-efd1571a792f",
"StatusCode":"OK"
}
]
},
"PointOperationStatisticsTraceDatum":{
"Id":"PointOperationStatistics",
"ActivityId":null,
"ResponseTimeUtc":"2023-01-10T21:07:45.4500286Z",
"StatusCode":200,
"SubStatusCode":0,
"RequestCharge":0,
"RequestUri":"dbs/kyc-trust/colls/records",
"ErrorMessage":null,
"RequestSessionToken":null,
"ResponseSessionToken":null,
"BELatencyInMs":null
}
}
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"name":"Get Partition Key Ranges",
"id":"c13692db-1683-41ed-9c2f-4e7ca06748b8",
"start time":"09:07:45:483",
"duration in milliseconds":63.4253,
"children":[
{
"name":"Try Get Overlapping Ranges",
"id":"9b970838-2460-4f01-801e-804e7336a804",
"start time":"09:07:45:491",
"duration in milliseconds":55.5448,
"data":{
"PKRangeCache Info(#2023-01-10T21:07:45.5425441Z)":{
"Previous Continuation Token":null,
"Continuation Token":"\"1352\""
}
},
"children":[
{
"name":"Read PartitionKeyRange Change Feed",
"id":"767893b7-8e21-4d59-9e53-940a98d9aec2",
"start time":"09:07:45:499",
"duration in milliseconds":12.0836,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
],
"StoreResponseStatistics":[
],
"HttpResponseStats":[
{
"StartTimeUTC":"2023-01-10T21:07:45.5011610Z",
"DurationInMs":9.6664,
"RequestUri":"https://[[address]]-eastus2.documents.azure.com/dbs/cVEGAA==/colls/cVEGAI+erJw=/pkranges",
"ResourceType":"PartitionKeyRange",
"HttpMethod":"GET",
"ActivityId":"7a76e397-c050-4f60-9612-871e6c410e51",
"StatusCode":"OK"
}
]
}
}
},
{
"name":"Read PartitionKeyRange Change Feed",
"id":"2f14dc9d-8392-4244-8203-6e5313dd84da",
"start time":"09:07:45:513",
"duration in milliseconds":5.3642,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
],
"StoreResponseStatistics":[
],
"HttpResponseStats":[
{
"StartTimeUTC":"2023-01-10T21:07:45.5132092Z",
"DurationInMs":5.1553,
"RequestUri":"https://[[address]]-eastus2.documents.azure.com/dbs/cVEGAA==/colls/cVEGAI+erJw=/pkranges",
"ResourceType":"PartitionKeyRange",
"HttpMethod":"GET",
"ActivityId":"d794779f-0561-4473-946e-8cb55ece86fc",
"StatusCode":"NotModified",
"ReasonPhrase":"Not Modified"
}
]
}
}
}
]
}
]
}
]
},
{
"name":"Prefetching",
"id":"c4e0a371-13f5-4c51-90f0-30a07633c5b1",
"start time":"09:07:45:585",
"duration in milliseconds":0.0259
},
{
"name":"[,FF) move next",
"id":"cc2fae7e-0a6d-419b-a547-2c6ea04a8131",
"start time":"09:07:45:588",
"duration in milliseconds":5054.4205,
"children":[
{
"name":"[,FF) move next",
"id":"37861880-4b50-4a4d-9f61-5df13e2a5e22",
"start time":"09:07:45:589",
"duration in milliseconds":5053.1434,
"children":[
{
"name":"Prefetch",
"id":"a2fd5bad-e2ac-49c6-b4ba-9db8a7d56525",
"start time":"09:07:45:591",
"duration in milliseconds":5049.9131,
"children":[
{
"name":"[,FF) move next",
"id":"6b5c1ec7-8d38-4bb3-abab-87cdfd79e3e1",
"start time":"09:07:45:591",
"duration in milliseconds":5049.286,
"data":{
"Query Metrics":"Retrieved Document Count : 1,000 \nRetrieved Document Size : 942,622 bytes \nOutput Document Count : 1,000 \nOutput Document Size : 1,045,673 bytes \nIndex Utilization : 100.00 % \nTotal Query Execution Time : 4,486.56 milliseconds\n Query Preparation Time : 0.74 milliseconds\n Index Lookup Time : 3,874.38 milliseconds\n Document Load Time : 595.44 milliseconds\n Runtime Execution Times : 0.00 milliseconds\n Document Write Time : 4.53 milliseconds\n\nIndex Utilization Information\n Utilized Single Indexes\n Potential Single Indexes\n Utilized Composite Indexes\n Potential Composite Indexes\n"
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
"id":"a9527b39-fb6d-4360-a758-f57b9a93f96e",
"start time":"09:07:45:594",
"duration in milliseconds":4962.5336,
"children":[
{
"name":"Get Collection Cache",
"id":"e6038b8c-b726-406e-877a-0e49895428e6",
"start time":"09:07:45:594",
"duration in milliseconds":0.0037
},
{
"name":"Get Partition Key Range Cache",
"id":"afff52bc-523f-4326-bcaa-0c4ae8a3e30c",
"start time":"09:07:45:594",
"duration in milliseconds":0.0043
},
{
"name":"Try Get Overlapping Ranges",
"id":"36912b1b-6810-4bdb-9a3e-3e31f02a10cf",
"start time":"09:07:45:594",
"duration in milliseconds":0.248
},
{
"name":"Blackbaud.Cosmos.RetryRequestHandler",
"id":"8359814f-1e5b-4471-9a86-b95346a1890b",
"start time":"09:07:45:596",
"duration in milliseconds":4960.2113,
"children":[
{
"name":"Blackbaud.Cosmos.RetryCounterMetricRequestHandler",
"id":"e9a342ec-8122-446b-a773-6736d04036ad",
"start time":"09:07:45:596",
"duration in milliseconds":4960.1849,
"children":[
{
"name":"Blackbaud.Cosmos.TracingRequestHandler",
"id":"945702de-eab1-4450-bfaa-e405810017ee",
"start time":"09:07:45:596",
"duration in milliseconds":4960.1813,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
"id":"2708ecf4-10f0-47a1-829e-2309a2ad33d6",
"start time":"09:07:45:600",
"duration in milliseconds":4957.0424,
"data":{
"System Info":{
"systemHistory":[
{
"dateUtc":"2023-01-10T21:06:55.2425018Z",
"cpu":14.372,
"memory":32298292.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.064,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:05.2428461Z",
"cpu":13.829,
"memory":32255268.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0787,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:15.2431673Z",
"cpu":14.529,
"memory":32465364.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.068,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:25.2436122Z",
"cpu":13.166,
"memory":32527180.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.1011,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:35.2439415Z",
"cpu":11.616,
"memory":32540128.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0474,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:45.2442873Z",
"cpu":10.925,
"memory":32557528.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0534,
"availableThreads":32764,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
}
]
}
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RetryHandler",
"id":"aade1341-395f-4c68-a7f0-9b8eb0d699e0",
"start time":"09:07:45:600",
"duration in milliseconds":4957.0245,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RouterHandler",
"id":"da0fd1fd-59cf-43ad-9840-773f5ae2d31a",
"start time":"09:07:45:600",
"duration in milliseconds":4957.0028,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.TransportHandler",
"id":"1fe161f0-325a-43b9-907e-4d8bb5c9c8b4",
"start time":"09:07:45:600",
"duration in milliseconds":4956.9968,
"children":[
{
"name":"Microsoft.Azure.Documents.ServerStoreModel Transport Request",
"id":"677543f7-4221-40d2-ab2d-454c13641ba0",
"start time":"09:07:45:600",
"duration in milliseconds":4956.7528,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
{
"Count":1,
"Uri":"rntbd://cdb-ms-prod-eastus2-fd22.documents.azure.com:14001/apps/5f61d82d-225a-4749-b895-9620dfa58833/services/82583836-d178-4100-9e16-afadfb618ec3/partitions/462cad87-cc30-473e-9dd9-154df2c031c2/replicas/132876237182405904s/"
}
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
{
"StartTimeUTC":"2023-01-10T21:07:45.6363656Z",
"EndTimeUTC":"2023-01-10T21:07:45.6478642Z",
"TargetEndpoint":"https://[[address]]-eastus2.documents.azure.com//addresses/?$resolveFor=dbs%2fcVEGAA%3d%3d%2fcolls%2fcVEGAI%2berJw%3d%2fdocs&$filter=protocol eq rntbd&$partitionKeyRangeIds=0"
}
],
"StoreResponseStatistics":[
{
"ResponseTimeUTC":"2023-01-10T21:07:50.5494024Z",
"ResourceType":"Document",
"OperationType":"Query",
"LocationEndpoint":"https://[[address]]-eastus2.documents.azure.com/",
"StoreResult":{
"ActivityId":"91d88f87-a472-4221-955b-efd1571a792f",
"StatusCode":"Ok",
"SubStatusCode":"Unknown",
"LSN":71585945,
"PartitionKeyRangeId":"0",
"GlobalCommittedLSN":71585943,
"ItemLSN":-1,
"UsingLocalLSN":true,
"QuorumAckedLSN":-1,
"SessionToken":"1#71585945#3=-1",
"CurrentWriteQuorum":-1,
"CurrentReplicaSetSize":-1,
"NumberOfReadRegions":1,
"IsValid":true,
"StorePhysicalAddress":"rntbd://cdb-ms-prod-eastus2-fd22.documents.azure.com:14001/apps/5f61d82d-225a-4749-b895-9620dfa58833/services/82583836-d178-4100-9e16-afadfb618ec3/partitions/462cad87-cc30-473e-9dd9-154df2c031c2/replicas/132876237182405904s/",
"RequestCharge":119.46,
"RetryAfterInMs":null,
"BELatencyInMs":"4487.772",
"transportRequestTimeline":{
"requestTimeline":[
{
"event":"Created",
"startTimeUtc":"2023-01-10T21:07:45.6534405Z",
"durationInMs":0.0277
},
{
"event":"ChannelAcquisitionStarted",
"startTimeUtc":"2023-01-10T21:07:45.6534682Z",
"durationInMs":29.1472
},
{
"event":"Pipelined",
"startTimeUtc":"2023-01-10T21:07:45.6826154Z",
"durationInMs":0.9206
},
{
"event":"Transit Time",
"startTimeUtc":"2023-01-10T21:07:45.6835360Z",
"durationInMs":4865.0605
},
{
"event":"Received",
"startTimeUtc":"2023-01-10T21:07:50.5485965Z",
"durationInMs":0.3212
},
{
"event":"Completed",
"startTimeUtc":"2023-01-10T21:07:50.5489177Z",
"durationInMs":0
}
],
"serviceEndpointStats":{
"inflightRequests":1,
"openConnections":1
},
"connectionStats":{
"waitforConnectionInit":"True",
"callsPendingReceive":0,
"lastSendAttempt":"2023-01-10T21:07:45.6816224Z",
"lastSend":"2023-01-10T21:07:45.6816774Z",
"lastReceive":"2023-01-10T21:07:45.6821297Z"
},
"requestSizeInBytes":739,
"requestBodySizeInBytes":299,
"responseMetadataSizeInBytes":1071,
"responseBodySizeInBytes":1045673
},
"TransportException":null
}
}
],
"HttpResponseStats":[
{
"StartTimeUTC":"2023-01-10T21:07:45.6364140Z",
"DurationInMs":10.8636,
"RequestUri":"https://[[address]]-eastus2.documents.azure.com//addresses/?$resolveFor=dbs%2fcVEGAA%3d%3d%2fcolls%2fcVEGAI%2berJw%3d%2fdocs&$filter=protocol eq rntbd&$partitionKeyRangeIds=0",
"ResourceType":"Document",
"HttpMethod":"GET",
"ActivityId":"91d88f87-a472-4221-955b-efd1571a792f",
"StatusCode":"OK"
}
]
}
}
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"name":"Get Cosmos Element Response",
"id":"fecd0c6a-8b73-457a-aa14-464ca6b143df",
"start time":"09:07:50:560",
"duration in milliseconds":75.9938
}
]
}
]
}
]
}
]
},
{
"name":"Query Response Serialization",
"id":"e93544e2-6788-42cb-93c7-3648140c8808",
"start time":"09:07:50:667",
"duration in milliseconds":40.5059
}
]
}and from the second call that uses the continuation token these returning 1 record:
{
"Summary":{
"DirectCalls":{
"(200, 0)":1
},
"GatewayCalls":{
"(200, 0)":1
}
},
"name":"Typed FeedIterator ReadNextAsync",
"id":"876fac27-be63-4812-8cc7-282cec9adca5",
"start time":"09:07:55:213",
"duration in milliseconds":692.4728,
"data":{
"Client Configuration":{
"Client Created Time Utc":"2023-01-10T21:05:16.4006790Z",
"MachineId":"hashedMachineName:2edbdc36-9ea9-a55c-cdc2-29ac9f9444dd",
"NumberOfClientsCreated":1,
"NumberOfActiveClients":1,
"ConnectionMode":"Direct",
"User Agent":"cosmos-netstandard-sdk/3.31.2|1|X64|Linux 5.4.0-1094-azure 100 18|.NET 6.0.10|S|",
"ConnectionConfig":{
"gw":"(cps:50, urto:10, p:False, httpf: False)",
"rntbd":"(cto: 5, icto: -1, mrpc: 30, mcpe: 65535, erd: True, pr: ReuseUnicastPort)",
"other":"(ed:False, be:False)"
},
"ConsistencyConfig":"(consistency: NotSet, prgns:[], apprgn: East US 2)",
"ProcessorCount":1
},
"Query Correlated ActivityId":"5c453dcf-4b3f-491a-b806-3ff4c5937ebd"
},
"children":[
{
"name":"Create Query Pipeline",
"id":"fef3a0b3-b660-4c7f-a9f4-7b1b9ea0029b",
"start time":"09:07:55:213",
"duration in milliseconds":4.7841,
"children":[
{
"name":"Get Container Properties",
"id":"f1921eb5-76c9-420f-aa35-6d6a9bea1f57",
"start time":"09:07:55:213",
"duration in milliseconds":0.0722,
"children":[
{
"name":"Get Collection Cache",
"id":"58639d2e-7492-4e83-88fc-9f9858d11b56",
"start time":"09:07:55:213",
"duration in milliseconds":0.0081
}
]
},
{
"name":"Gateway QueryPlan",
"id":"0448d0b3-8d7d-4ee2-8804-20efa935a03f",
"start time":"09:07:55:213",
"duration in milliseconds":1.4528
},
{
"name":"Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
"id":"cab7caf1-6a21-405b-8591-a952167f767f",
"start time":"09:07:55:213",
"duration in milliseconds":3.2215,
"children":[
{
"name":"Blackbaud.Cosmos.RetryRequestHandler",
"id":"837368e8-8621-4d5b-8f6d-eefce3cb469c",
"start time":"09:07:55:213",
"duration in milliseconds":3.0344,
"children":[
{
"name":"Blackbaud.Cosmos.RetryCounterMetricRequestHandler",
"id":"bdacfe3c-d359-405f-bf3d-41874f83faa5",
"start time":"09:07:55:213",
"duration in milliseconds":2.9663,
"children":[
{
"name":"Blackbaud.Cosmos.TracingRequestHandler",
"id":"e6db69ea-152b-4180-9ef6-ad5622e4c1a3",
"start time":"09:07:55:213",
"duration in milliseconds":2.96,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
"id":"e1491202-54ae-4385-b5ba-f16516ef55d9",
"start time":"09:07:55:214",
"duration in milliseconds":2.7584,
"data":{
"System Info":{
"systemHistory":[
{
"dateUtc":"2023-01-10T21:06:56.5072451Z",
"cpu":12.780,
"memory":33429336.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.1731,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:06.5076572Z",
"cpu":12.340,
"memory":33440116.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":3.7599,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:16.5082397Z",
"cpu":11.132,
"memory":33510348.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0798,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:26.5086697Z",
"cpu":10.851,
"memory":33478336.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0725,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":3
},
{
"dateUtc":"2023-01-10T21:07:36.5093974Z",
"cpu":12.190,
"memory":33404312.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.1617,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":4
},
{
"dateUtc":"2023-01-10T21:07:46.5098382Z",
"cpu":10.865,
"memory":33438604.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0837,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":4
}
]
}
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RetryHandler",
"id":"6e8b1fe8-c26f-4305-8607-20a8ddd1b354",
"start time":"09:07:55:214",
"duration in milliseconds":2.7413,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RouterHandler",
"id":"ac9658f3-8af9-4c22-b023-889309779a3b",
"start time":"09:07:55:214",
"duration in milliseconds":2.6906,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.TransportHandler",
"id":"693fb732-bd4e-47b2-aec4-5eb76730c371",
"start time":"09:07:55:214",
"duration in milliseconds":2.6796,
"children":[
{
"name":"Microsoft.Azure.Cosmos.GatewayStoreModel Transport Request",
"id":"83c29229-0cb1-4a84-8740-37f64375bf58",
"start time":"09:07:55:214",
"duration in milliseconds":2.4521,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
],
"StoreResponseStatistics":[
],
"HttpResponseStats":[
{
"StartTimeUTC":"2023-01-10T21:07:55.2146097Z",
"DurationInMs":2.0371,
"RequestUri":"https://[[address]]-eastus2.documents.azure.com/dbs/kyc-trust/colls/records/docs",
"ResourceType":"Document",
"HttpMethod":"POST",
"ActivityId":"b9853609-9fc4-4b4b-a3d8-a5b95d110df0",
"StatusCode":"OK"
}
]
},
"PointOperationStatisticsTraceDatum":{
"Id":"PointOperationStatistics",
"ActivityId":null,
"ResponseTimeUtc":"2023-01-10T21:07:55.2168304Z",
"StatusCode":200,
"SubStatusCode":0,
"RequestCharge":0,
"RequestUri":"dbs/kyc-trust/colls/records",
"ErrorMessage":null,
"RequestSessionToken":null,
"ResponseSessionToken":null,
"BELatencyInMs":null
}
}
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"name":"Get Partition Key Ranges",
"id":"18e0283b-3fbd-48a8-a528-b12af7d627cd",
"start time":"09:07:55:217",
"duration in milliseconds":0.133,
"children":[
{
"name":"Try Get Overlapping Ranges",
"id":"2a82c20b-d5c8-42c9-9d87-1c655eef658f",
"start time":"09:07:55:217",
"duration in milliseconds":0.0586
}
]
}
]
},
{
"name":"Prefetching",
"id":"73ad5b6f-f989-47b6-949a-82bd5ad7f8ab",
"start time":"09:07:55:218",
"duration in milliseconds":0.0009
},
{
"name":"[,FF) move next",
"id":"54c10b87-923a-4bc7-9def-57a92b266aaf",
"start time":"09:07:55:218",
"duration in milliseconds":684.1404,
"children":[
{
"name":"[,FF) move next",
"id":"1c359b86-f4ed-442d-bf77-5368e21cc543",
"start time":"09:07:55:218",
"duration in milliseconds":684.1143,
"children":[
{
"name":"Prefetch",
"id":"be57913a-09a3-4b1d-a7af-dd89fb98a169",
"start time":"09:07:55:218",
"duration in milliseconds":684.0806,
"children":[
{
"name":"[,FF) move next",
"id":"99cedfcf-7f3d-4c70-b1b6-efb1494d2357",
"start time":"09:07:55:218",
"duration in milliseconds":684.0514,
"data":{
"Query Metrics":"Retrieved Document Count : 1 \nRetrieved Document Size : 949 bytes \nOutput Document Count : 1 \nOutput Document Size : 1,100 bytes \nIndex Utilization : 100.00 % \nTotal Query Execution Time : 644.63 milliseconds\n Query Preparation Time : 0.99 milliseconds\n Index Lookup Time : 642.45 milliseconds\n Document Load Time : 0.57 milliseconds\n Runtime Execution Times : 0.00 milliseconds\n Document Write Time : 0.00 milliseconds\n\nIndex Utilization Information\n Utilized Single Indexes\n Potential Single Indexes\n Utilized Composite Indexes\n Potential Composite Indexes\n"
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
"id":"45d4ffff-1d67-4e43-b4da-4731b19a1018",
"start time":"09:07:55:218",
"duration in milliseconds":683.7101,
"children":[
{
"name":"Get Collection Cache",
"id":"f6e5e325-f898-4662-8a57-4b6c98f2ebda",
"start time":"09:07:55:218",
"duration in milliseconds":0.0008
},
{
"name":"Get Partition Key Range Cache",
"id":"ad266322-015d-46e6-b024-ce7417f8348d",
"start time":"09:07:55:218",
"duration in milliseconds":0.0006
},
{
"name":"Try Get Overlapping Ranges",
"id":"c33d89da-e3f6-443c-aa99-df1e7b700efd",
"start time":"09:07:55:218",
"duration in milliseconds":0.0167
},
{
"name":"Blackbaud.Cosmos.RetryRequestHandler",
"id":"ff4753a9-481a-4f5f-89c0-6a8e9fb28337",
"start time":"09:07:55:218",
"duration in milliseconds":683.5971,
"children":[
{
"name":"Blackbaud.Cosmos.RetryCounterMetricRequestHandler",
"id":"1344da6a-6db1-462e-abc5-4ffa78dfc231",
"start time":"09:07:55:218",
"duration in milliseconds":683.5829,
"children":[
{
"name":"Blackbaud.Cosmos.TracingRequestHandler",
"id":"c32d3652-d27a-4a57-b012-fc5100e5da14",
"start time":"09:07:55:218",
"duration in milliseconds":683.5807,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
"id":"b9933d80-93a0-482b-aa39-5ce0c9c39ae6",
"start time":"09:07:55:218",
"duration in milliseconds":683.3141,
"data":{
"System Info":{
"systemHistory":[
{
"dateUtc":"2023-01-10T21:06:56.5072451Z",
"cpu":12.780,
"memory":33429336.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.1731,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:06.5076572Z",
"cpu":12.340,
"memory":33440116.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":3.7599,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:16.5082397Z",
"cpu":11.132,
"memory":33510348.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0798,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":2
},
{
"dateUtc":"2023-01-10T21:07:26.5086697Z",
"cpu":10.851,
"memory":33478336.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0725,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":3
},
{
"dateUtc":"2023-01-10T21:07:36.5093974Z",
"cpu":12.190,
"memory":33404312.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.1617,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":4
},
{
"dateUtc":"2023-01-10T21:07:46.5098382Z",
"cpu":10.865,
"memory":33438604.000,
"threadInfo":{
"isThreadStarving":"False",
"threadWaitIntervalInMs":0.0837,
"availableThreads":32765,
"minThreads":1,
"maxThreads":32767
},
"numberOfOpenTcpConnection":4
}
]
}
},
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RetryHandler",
"id":"251a7fd5-9e77-4c15-8083-4c30d546405e",
"start time":"09:07:55:218",
"duration in milliseconds":683.3037,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.RouterHandler",
"id":"9321f134-b4ca-4032-8a7a-951b94e33d58",
"start time":"09:07:55:218",
"duration in milliseconds":683.2932,
"children":[
{
"name":"Microsoft.Azure.Cosmos.Handlers.TransportHandler",
"id":"aab30f21-06f7-419f-bfd6-3b260c2d5239",
"start time":"09:07:55:218",
"duration in milliseconds":683.2907,
"children":[
{
"name":"Microsoft.Azure.Documents.ServerStoreModel Transport Request",
"id":"9019661d-ee29-4fe1-8bac-8f18fd3b9db3",
"start time":"09:07:55:218",
"duration in milliseconds":683.2368,
"data":{
"Client Side Request Stats":{
"Id":"AggregatedClientSideRequestStatistics",
"ContactedReplicas":[
{
"Count":1,
"Uri":"rntbd://cdb-ms-prod-eastus2-fd22.documents.azure.com:14394/apps/5f61d82d-225a-4749-b895-9620dfa58833/services/82583836-d178-4100-9e16-afadfb618ec3/partitions/462cad87-cc30-473e-9dd9-154df2c031c2/replicas/133096568671835844s/"
}
],
"RegionsContacted":[
],
"FailedReplicas":[
],
"AddressResolutionStatistics":[
],
"StoreResponseStatistics":[
{
"ResponseTimeUTC":"2023-01-10T21:07:55.9016462Z",
"ResourceType":"Document",
"OperationType":"Query",
"RequestSessionToken":"0:1#71585945#3=-1",
"LocationEndpoint":"https://[[address]]-eastus2.documents.azure.com/",
"StoreResult":{
"ActivityId":"b9853609-9fc4-4b4b-a3d8-a5b95d110df0",
"StatusCode":"Ok",
"SubStatusCode":"Unknown",
"LSN":71585945,
"PartitionKeyRangeId":"0",
"GlobalCommittedLSN":71585943,
"ItemLSN":-1,
"UsingLocalLSN":true,
"QuorumAckedLSN":-1,
"SessionToken":"1#71585945#3=-1",
"CurrentWriteQuorum":-1,
"CurrentReplicaSetSize":-1,
"NumberOfReadRegions":1,
"IsValid":true,
"StorePhysicalAddress":"rntbd://cdb-ms-prod-eastus2-fd22.documents.azure.com:14394/apps/5f61d82d-225a-4749-b895-9620dfa58833/services/82583836-d178-4100-9e16-afadfb618ec3/partitions/462cad87-cc30-473e-9dd9-154df2c031c2/replicas/133096568671835844s/",
"RequestCharge":1874.75,
"RetryAfterInMs":null,
"BELatencyInMs":"645.346",
"transportRequestTimeline":{
"requestTimeline":[
{
"event":"Created",
"startTimeUtc":"2023-01-10T21:07:55.2192899Z",
"durationInMs":0.0507
},
{
"event":"ChannelAcquisitionStarted",
"startTimeUtc":"2023-01-10T21:07:55.2193406Z",
"durationInMs":34.7737
},
{
"event":"Pipelined",
"startTimeUtc":"2023-01-10T21:07:55.2541143Z",
"durationInMs":0.5458
},
{
"event":"Transit Time",
"startTimeUtc":"2023-01-10T21:07:55.2546601Z",
"durationInMs":646.5731
},
{
"event":"Received",
"startTimeUtc":"2023-01-10T21:07:55.9012332Z",
"durationInMs":0.3629
},
{
"event":"Completed",
"startTimeUtc":"2023-01-10T21:07:55.9015961Z",
"durationInMs":0
}
],
"serviceEndpointStats":{
"inflightRequests":1,
"openConnections":1
},
"connectionStats":{
"waitforConnectionInit":"True",
"callsPendingReceive":0,
"lastSendAttempt":"2023-01-10T21:07:55.2528684Z",
"lastSend":"2023-01-10T21:07:55.2529362Z",
"lastReceive":"2023-01-10T21:07:55.2535357Z"
},
"requestSizeInBytes":1123,
"requestBodySizeInBytes":537,
"responseMetadataSizeInBytes":11868,
"responseBodySizeInBytes":1100
},
"TransportException":null
}
}
]
}
}
}
]
}
]
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"name":"Get Cosmos Element Response",
"id":"bc10fd2f-96f3-461f-b2ad-fd7d557459aa",
"start time":"09:07:55:902",
"duration in milliseconds":0.1879
}
]
}
]
}
]
}
]
},
{
"name":"Query Response Serialization",
"id":"5e4f516b-750e-41cf-8c19-ca3a848d22c5",
"start time":"09:07:55:905",
"duration in milliseconds":0.1967
}
]
}Thanks for sharing these. We will look into why the backend was not able to push the filters down to the composite index.
neildsh
commented
1 year ago Hello @IsaacBoy , thanks for reporting this issue and for sharing the diagnostics. We will change the backend and the continuation token format to accept values so that we can remove these filters from the query. This work is currently scheduled for next month.
IsaacBoy
commented
1 year ago @neildsh Was this ever completed?
balaperu
commented
1 year ago Hi @IsaacBoy, The backend side of changes is done. We'll update the SDK once the backend changes are deployed. Thanks.
IsaacBoy
commented
1 year ago Hi @IsaacBoy, The backend side of changes is done. We'll update the SDK once the backend changes are deployed. Thanks.
@neildsh @balaperu Hey its been a few months now, was this fix ever implemented into the sdk?
balaperu
commented
1 year ago Hi @IsaacBoy, I apologize for the delay. We found an issue with our backend implementation and had to make a change in our backend. The backend changes are currently rolling out and there are few more regions to go. I'm hoping to check-in the SDK changes in a week or two if everything goes as planned. Thanks.
IsaacBoy
commented
10 months ago Hi @IsaacBoy, I apologize for the delay. We found an issue with our backend implementation and had to make a change in our backend. The backend changes are currently rolling out and there are few more regions to go. I'm hoping to check-in the SDK changes in a week or two if everything goes as planned. Thanks.
@neildsh @balaperu Hey its been a about 5 months. Hows this fix going? Thank you!
balaperu
commented
10 months ago Hi @IsaacBoy, really sorry about the delay. There is one thing or the other that keeps blocking this PR.
The PR below has the fix. But I'm not able to merge it in, as our integration tests uses the public emulator which hasn't been updated with the required backend changes. Without the emulator changes, the tests are failing in the official run. I have been working with the emulator team to get them to release a new emulator. The current ETA for the emulator release is later this month and I'll be able to check it in after that.
IsaacBoy
commented
10 months ago @balaperu No problem. Thanks for the update
IsaacBoy
commented
8 months ago Hi @IsaacBoy, really sorry about the delay. There is one thing or the other that keeps blocking this PR.
The PR below has the fix. But I'm not able to merge it in, as our integration tests uses the public emulator which hasn't been updated with the required backend changes. Without the emulator changes, the tests are failing in the official run. I have been working with the emulator team to get them to release a new emulator. The current ETA for the emulator release is later this month and I'll be able to check it in after that.
3774
@balaperu Is this the version you were waiting on? https://learn.microsoft.com/en-us/azure/cosmos-db/emulator-release-notes#latest-version-21416
balaperu
commented
8 months ago The release notes doesn't seem to indicate the version that I was waiting for, so I checked with our emulator team. Looks like the release notes got prematurely merged and the emulator is getting released only later this week.
balaperu
commented
7 months ago The emulator got released yesterday. I'll resurface the PR and work on getting it checked in.
balaperu
commented
7 months ago The change has been checked in as part of this pull request - https://github.com/Azure/azure-cosmos-dotnet-v3/pull/3774
IsaacBoy
commented
5 months ago The change has been checked in as part of this pull request - #3774
@balaperu do you happen to know if this fix was included in 3.39.0? https://github.com/Azure/azure-cosmos-dotnet-v3/blob/master/changelog.md
balaperu
commented
5 months ago Yes, I think it should be part of this release. The PR was marked as internal which is why it is not listed in the changelog.
From: Isaac @.> Sent: Wednesday, April 10, 2024 6:10 PM To: Azure/azure-cosmos-dotnet-v3 @.> Cc: Bala Perumalswamy @.>; Mention @.> Subject: Re: [Azure/azure-cosmos-dotnet-v3] Broken continuation results with ordered results with recent v3.31.2 change (Issue #3639)
The change has been checked in as part of this pull request - #3774https://github.com/Azure/azure-cosmos-dotnet-v3/pull/3774
@balaperuhttps://github.com/balaperu do you happen to know if this fix was included in 3.39.0? https://github.com/Azure/azure-cosmos-dotnet-v3/blob/master/changelog.md
- Reply to this email directly, view it on GitHubhttps://github.com/Azure/azure-cosmos-dotnet-v3/issues/3639#issuecomment-2048725614, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AFH3FTJL4GPH2DQGADWUM4TY4XPFZAVCNFSM6AAAAAATW2OK7WVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDANBYG4ZDKNRRGQ. You are receiving this because you were mentioned.Message ID: @.**@.>>
I have confirmed the issue is comming from with the change in v3.31.2. It does not happen in v3.31.1.
When fetching ordered results that cause a continuation token to be returned, the first set of results are returned as normal, but with subsequent fetches, an "odd" filter query is returned with the continuation token, which then when passed into the next query execution causes only 1 record to be returned per call (and very poor performance). So for example, when you have a dataset of 1 million records, and you query with a max page size of 1000, you'd get 1000 records, and then after that 1 record per call. Again, its definitely related to the filter being a part of the continuation token because without it (as it works with the version of the sdk previous to this) the sdk behaves as expected (1000 or max page size results returned per call to cosmos)
SDK Version: v3.31.2
The situation seems to be possibly circumstantial under unknown specific conditions, and I'm not sure which are relevant. Once it happens it consistently happens. The query I'm performing is something like
where AuditDate is a number and DocumentType is a string. The query is cross-partition. The first query returns a continuation result like this:
but the subseuent ones return one with the following
filterpropertywhich only returns one result.
I do have a composite index setup that the query is utilizing, confirmed through IndexMetrics
With the continuation token without a filter:
With the continuation token with one"