Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Broken continuation results with ordered results with recent v3.31.2 change #3639

Closed
IsaacBoy opened this issue Jan 10, 2023 · 19 comments
Closed
Assignees
Labels

Comments

@IsaacBoy
Copy link

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

SELECT VALUE c FROM c WHERE c.DocumentType = @documentType ORDER BY c.DocumentType ASC, c.AuditDate DESC

where AuditDate is a number and DocumentType is a string. The query is cross-partition. The first query returns a continuation result like this:

[{"compositeToken":{"token":"+RID:~MjYdAJoN+QFnBgAAAAAAAA==#RT:1#TRC:1#RTD:NuyR9A/x6vbOO5/KeBRJrwVkdnN9cHNoAPs+J4e/4+f/////4A==#ISV:2#IEO:65567#QCF:8","range":{"min":"","max":"FF"}},"orderByItems":[{"item":"cur|org"},{"item":1673790342}],"rid":"MjYdAJoN+QFnBgAAAAAAAA==","skipCount":0,"filter":"true"}]

but the subseuent ones return one with the following filter property

[{"compositeToken":{"token":"+RID:~MjYdAJoN+QFwBgAAAAAAAA==#RT:2#TRC:2#RTD:NuyR9A/x6vbOO5/KeBRJrwVkdnN9cHNoAPs+J4f/gSv/////4A==#ISV:2#IEO:65567#QCF:8#FPC:AWwGAAAAAAAAcQYAAAAAAAA=","range":{"min":"","max":"FF"}},"orderByItems":[{"item":"cur|org"},{"item":1673531381}],"rid":"MjYdAJoN+QFwBgAAAAAAAA==","skipCount":0,"filter":"((c.DocumentType > \"cur|org\"  OR IS_ARRAY(c.DocumentType)  OR IS_OBJECT(c.DocumentType) )) OR ((c.DocumentType = \"cur|org\" ) AND (c.AuditDate <= 1673617781  OR NOT IS_DEFINED(c.AuditDate)  OR IS_NULL(c.AuditDate)  OR IS_BOOLEAN(c.AuditDate) ))"}]

which 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:

Index Utilization Information
  Utilized Single Indexes
  Potential Single Indexes
  Utilized Composite Indexes
    Index Spec: /DocumentType ASC, /AuditDate DESC
    Index Impact Score: High
    ---
  Potential Composite Indexes

With the continuation token with one"


Index Utilization Information
  Utilized Single Indexes
    Index Spec: /DocumentType/?
    Index Impact Score: High
    ---
    Index Spec: /AuditDate/?
    Index Impact Score: High
    ---
    Index Spec: /DocumentType/?
    Index Impact Score: High
    ---
    Index Spec: /AuditDate/?
    Index Impact Score: Low
    ---
    Index Spec: /DocumentType/?
    Index Impact Score: High
    ---
    Index Spec: /AuditDate/?
    Index Impact Score: High
    ---
    Index Spec: /DocumentType/?
    Index Impact Score: High
    ---
    Index Spec: /AuditDate/?
    Index Impact Score: High
    ---
    Index Spec: /DocumentType/?
    Index Impact Score: High
    ---
    Index Spec: /AuditDate/?
    Index Impact Score: High
    ---
  Potential Single Indexes
  Utilized Composite Indexes
    Index Spec: /DocumentType ASC, /AuditDate ASC
    Index Impact Score: High
    ---
    Index Spec: /DocumentType ASC, /AuditDate DESC
    Index Impact Score: High
    ---
  Potential Composite Indexes
@ealsur
Copy link
Member

ealsur commented Jan 10, 2023

@neildsh could you take a look?

@neildsh
Copy link
Contributor

neildsh commented Jan 10, 2023

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!

@IsaacBoy
Copy link
Author

IsaacBoy commented Jan 10, 2023

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"
            }
        ]
    ]
}

@IsaacBoy
Copy link
Author

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
      }
   ]
}

@neildsh
Copy link
Contributor

neildsh commented Jan 11, 2023

Thanks for sharing these. We will look into why the backend was not able to push the filters down to the composite index.

@neildsh
Copy link
Contributor

neildsh commented Jan 30, 2023

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
Copy link
Author

@neildsh Was this ever completed?

@balaperu
Copy link
Contributor

Hi @IsaacBoy, The backend side of changes is done. We'll update the SDK once the backend changes are deployed. Thanks.

@IsaacBoy
Copy link
Author

IsaacBoy commented Jun 20, 2023

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
Copy link
Contributor

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
Copy link
Author

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
Copy link
Contributor

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

@IsaacBoy
Copy link
Author

@balaperu No problem. Thanks for the update

@IsaacBoy
Copy link
Author

IsaacBoy commented Jan 8, 2024

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
Copy link
Contributor

balaperu commented Jan 9, 2024

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
Copy link
Contributor

The emulator got released yesterday. I'll resurface the PR and work on getting it checked in.

@balaperu
Copy link
Contributor

The change has been checked in as part of this pull request - #3774

@IsaacBoy
Copy link
Author

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
Copy link
Contributor

balaperu commented Apr 11, 2024 via email

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

5 participants