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.

Sign up for GitHub

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

Jump to bottom

Cosmos Diagnostics: Client Side Request Statistics are Appearing Empty for Certain Connection Timeouts #3885

Closed
kundadebdatta opened this issue Jun 1, 2023 · 2 comments
Closed

Cosmos Diagnostics: Client Side Request Statistics are Appearing Empty for Certain Connection Timeouts #3885

kundadebdatta opened this issue Jun 1, 2023 · 2 comments
Assignees
@kundadebdatta
Labels
needs-investigation

Comments

@kundadebdatta
Copy link
Member

kundadebdatta commented Jun 1, 2023 •
edited
Loading

Description:

The commerce team has started experiencing intermittent connection timeouts, with the following error message:

Response status code does not indicate success: RequestTimeout (408); Substatus: 0; ActivityId: 125a1716-3321-42e7-895a-acd14f3f9a83; Reason: (GatewayStoreClient Request Timeout. Start Time UTC:05/30/2023 16:51:33; Total Duration:71505.4693 Ms; Request Timeout 65000 Ms; Http Client Timeout:65000 Ms; Activity id: e35dfee6-c5c9-4ed1-9219-ec5f8aa915ec;)

They have captured a series of diagnostics, and interestingly none of the diagnostics contain the client side request statistics, in other words they appear in the diagnostics as empty json arrays. Please take a look at the below sample diagnostics for more detail.

Cosmos Client Configurations:

  • Connection Mode: Direct
  • VM Region: West US 2
  • User Agent: cosmos-netstandard-sdk/3.31.1|10|X64|Linux 5.15.0-1038-azure 45-Ub|.NET 6.0.16|L|F 00000010|

Sample Diagnostics:

Example 1 From 05/30/2023 
  
    {
        "Summary": {},
        "name": "Typed FeedIterator ReadNextAsync",
        "id": "890225c6-8c27-4600-b0e4-9d4881a5c6e7",
        "start time": "04:52:34:106",
        "duration in milliseconds": 11137.7,
        "data": {
            "Client Configuration": {
                "Client Created Time Utc": "2023-05-26T01:24:23.0468274Z",
                "MachineId": "hashedVmId:8f2f092f-88a5-8089-d327-79d3639b5a97",
                "VM Region": "westus2",
                "NumberOfClientsCreated": 48,
                "NumberOfActiveClients": 48,
                "ConnectionMode": "Direct",
                "User Agent": "cosmos-netstandard-sdk/3.31.1|10|X64|Linux 5.15.0-1038-azure 45-Ub|.NET 6.0.16|L|F 00000010|",
                "ConnectionConfig": {
                    "gw": "(cps:50, urto:7, p:False, httpf: True)",
                    "rntbd": "(cto: 5, icto: -1, mrpc: 30, mcpe: 65535, erd: True, pr: ReuseUnicastPort)",
                    "other": "(ed:False, be:False)"
                },
                "ConsistencyConfig": "(consistency: NotSet, prgns:[East US, East US 2], apprgn: )",
                "ProcessorCount": 14
            },
            "Query Correlated ActivityId": "5c9dced0-ecb5-446c-ba43-a1bff5528fe7"
        },
        "children": [
            {
                "name": "Create Query Pipeline",
                "id": "4dbb8c54-1bbc-4617-85ef-d892d0de5d0b",
                "start time": "04:52:34:106",
                "duration in milliseconds": 0.2402,
                "children": [
                    {
                        "name": "Get Container Properties",
                        "id": "ca07269c-821d-4177-a389-115741bcc7f8",
                        "start time": "04:52:34:106",
                        "duration in milliseconds": 0.0096,
                        "children": [
                            {
                                "name": "Get Collection Cache",
                                "id": "8e72b336-4cbd-49e4-ab37-ceccda87f680",
                                "start time": "04:52:34:106",
                                "duration in milliseconds": 0.001
                            }
                        ]
                    },
                    {
                        "name": "Parse Query",
                        "id": "2cc6c4e9-3967-408f-ae1f-5d224fcb342d",
                        "start time": "04:52:34:106",
                        "duration in milliseconds": 0.1798
                    },
                    {
                        "name": "Get Partition Key Ranges",
                        "id": "c1dfe094-ca89-4e0c-af5d-72828febdfb8",
                        "start time": "04:52:34:106",
                        "duration in milliseconds": 0.0216,
                        "children": [
                            {
                                "name": "Try Get Overlapping Ranges",
                                "id": "d687cf81-fc85-48cb-b37a-d34f0ee06c4b",
                                "start time": "04:52:34:106",
                                "duration in milliseconds": 0.0123
                            }
                        ]
                    }
                ]
            },
            {
                "name": "MoveNextAsync",
                "id": "cfe3e523-dd49-4509-977f-1b236c9447a4",
                "start time": "04:52:34:106",
                "duration in milliseconds": 11137.4902,
                "children": [
                    {
                        "name": "Prefetching",
                        "id": "672256f2-24a3-4028-abdc-0522fdecfc2e",
                        "start time": "04:52:34:106",
                        "duration in milliseconds": 0.0004
                    },
                    {
                        "name": "[05C1E7FFFFFFFE,FF) move next",
                        "id": "f6f28fd0-0872-46ce-8bed-f48fa782b7ea",
                        "start time": "04:52:34:106",
                        "duration in milliseconds": 11137.483,
                        "children": [
                            {
                                "name": "Prefetch",
                                "id": "c35c2a21-e7f3-4589-8372-4796e064ddf7",
                                "start time": "04:52:34:106",
                                "duration in milliseconds": 11137.4833,
                                "children": [
                                    {
                                        "name": "[05C1E7FFFFFFFE,FF) move next",
                                        "id": "6649b53b-ea46-41a6-8913-14e6d06a33bc",
                                        "start time": "04:52:34:106",
                                        "duration in milliseconds": 11137.4845,
                                        "children": [
                                            {
                                                "name": "Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
                                                "id": "256cdca7-4543-4ce4-a0a3-790116c1198b",
                                                "start time": "04:52:34:106",
                                                "duration in milliseconds": 11137.4708,
                                                "children": [
                                                    {
                                                        "name": "Commerce.Shared.CosmosExtensions.Diagnostics.DiagnosticSourceHandler",
                                                        "id": "85c3eb58-1c3e-4109-8e9a-a45c1b6cb44f",
                                                        "start time": "04:52:34:106",
                                                        "duration in milliseconds": 11137.4604,
                                                        "children": [
                                                            {
                                                                "name": "Commerce.Shared.CosmosExtensions.Timeout.TimeoutHandler",
                                                                "id": "128bd314-f14d-4627-8d53-fa8dcb30bc06",
                                                                "start time": "04:52:34:106",
                                                                "duration in milliseconds": 11137.2491,
                                                                "children": [
                                                                    {
                                                                        "name": "Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
                                                                        "id": "163d0f22-c08e-401f-bff3-7232d2e2be06",
                                                                        "start time": "04:52:34:106",
                                                                        "duration in milliseconds": 11137.2438,
                                                                        "data": {
                                                                            "System Info": {
                                                                                "systemHistory": [
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T16:51:53.3506594Z",
                                                                                        "cpu": 8.074,
                                                                                        "memory": 55882240,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0233,
                                                                                            "availableThreads": 32762,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T16:52:03.3508845Z",
                                                                                        "cpu": 13.119,
                                                                                        "memory": 55889640,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0154,
                                                                                            "availableThreads": 32763,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T16:52:13.3511043Z",
                                                                                        "cpu": 11.89,
                                                                                        "memory": 55889708,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0303,
                                                                                            "availableThreads": 32764,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T16:52:23.3513364Z",
                                                                                        "cpu": 9.016,
                                                                                        "memory": 55913348,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0185,
                                                                                            "availableThreads": 32766,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T16:52:33.3515385Z",
                                                                                        "cpu": 11.504,
                                                                                        "memory": 55865456,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0187,
                                                                                            "availableThreads": 32766,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T16:52:43.3517362Z",
                                                                                        "cpu": 11.314,
                                                                                        "memory": 55971076,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0266,
                                                                                            "availableThreads": 32766,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    }
                                                                                ]
                                                                            }
                                                                        },
                                                                        "children": [
                                                                            {
                                                                                "name": "Microsoft.Azure.Cosmos.Handlers.RetryHandler",
                                                                                "id": "0c7ad05c-5050-4d50-b44a-7a0910ad4299",
                                                                                "start time": "04:52:34:106",
                                                                                "duration in milliseconds": 11137.2357,
                                                                                "children": [
                                                                                    {
                                                                                        "name": "Microsoft.Azure.Cosmos.Handlers.RouterHandler",
                                                                                        "id": "eab6fcb8-33a0-4e49-8d86-013417ea8c64",
                                                                                        "start time": "04:52:34:106",
                                                                                        "duration in milliseconds": 11137.2142,
                                                                                        "children": [
                                                                                            {
                                                                                                "name": "Microsoft.Azure.Cosmos.Handlers.TransportHandler",
                                                                                                "id": "971fb922-63f0-4d73-97d0-3fff34e364ce",
                                                                                                "start time": "04:52:34:106",
                                                                                                "duration in milliseconds": 11137.2114,
                                                                                                "children": [
                                                                                                    {
                                                                                                        "name": "Microsoft.Azure.Documents.ServerStoreModel Transport Request",
                                                                                                        "id": "3297c799-326f-478e-92fd-87b5c7d4fced",
                                                                                                        "start time": "04:52:34:106",
                                                                                                        "duration in milliseconds": 11137.0069,
                                                                                                        "data": {
                                                                                                            "Client Side Request Stats": {
                                                                                                                "Id": "AggregatedClientSideRequestStatistics",
                                                                                                                "ContactedReplicas": [],
                                                                                                                "RegionsContacted": [],
                                                                                                                "FailedReplicas": [],
                                                                                                                "AddressResolutionStatistics": [],
                                                                                                                "StoreResponseStatistics": []
                                                                                                            }
                                                                                                        }
                                                                                                    }
                                                                                                ]
                                                                                            }
                                                                                        ]
                                                                                    }
                                                                                ]
                                                                            }
                                                                        ]
                                                                    }
                                                                ]
                                                            }
                                                        ]
                                                    }
                                                ]
                                            }
                                        ]
                                    }
                                ]
                            }
                        ]
                    }
                ]
            }
        ]
    }
Example 2 From 05/30/2023 
  
    {
        "Summary": {},
        "name": "Typed FeedIterator ReadNextAsync",
        "id": "05a139ea-c61e-483e-9bb6-0a3feae51b85",
        "start time": "05:05:09:244",
        "duration in milliseconds": 8524.6795,
        "data": {
            "Client Configuration": {
                "Client Created Time Utc": "2023-05-26T01:24:23.0468274Z",
                "MachineId": "hashedVmId:8f2f092f-88a5-8089-d327-79d3639b5a97",
                "VM Region": "westus2",
                "NumberOfClientsCreated": 48,
                "NumberOfActiveClients": 48,
                "ConnectionMode": "Direct",
                "User Agent": "cosmos-netstandard-sdk/3.31.1|10|X64|Linux 5.15.0-1038-azure 45-Ub|.NET 6.0.16|L|F 00000010|",
                "ConnectionConfig": {
                    "gw": "(cps:50, urto:7, p:False, httpf: True)",
                    "rntbd": "(cto: 5, icto: -1, mrpc: 30, mcpe: 65535, erd: True, pr: ReuseUnicastPort)",
                    "other": "(ed:False, be:False)"
                },
                "ConsistencyConfig": "(consistency: NotSet, prgns:[East US, East US 2], apprgn: )",
                "ProcessorCount": 14
            },
            "Query Correlated ActivityId": "9cda1ce7-2c70-43ba-b9c3-b0002838fb66"
        },
        "children": [
            {
                "name": "Create Query Pipeline",
                "id": "a5c5a06c-f122-42aa-ab4b-367356beabf0",
                "start time": "05:05:09:244",
                "duration in milliseconds": 0.2642,
                "children": [
                    {
                        "name": "Get Container Properties",
                        "id": "02fd9c65-ed46-44b8-9bc1-2a57143a3092",
                        "start time": "05:05:09:244",
                        "duration in milliseconds": 0.0124,
                        "children": [
                            {
                                "name": "Get Collection Cache",
                                "id": "51c9bfdd-1d57-458e-9910-ffe3bf902a21",
                                "start time": "05:05:09:244",
                                "duration in milliseconds": 0.0009
                            }
                        ]
                    },
                    {
                        "name": "Parse Query",
                        "id": "8e830799-a3b7-418a-a868-3c6c25940ce5",
                        "start time": "05:05:09:244",
                        "duration in milliseconds": 0.1909
                    },
                    {
                        "name": "Get Partition Key Ranges",
                        "id": "d13103f8-0414-4099-b7cb-511b43a98ab4",
                        "start time": "05:05:09:244",
                        "duration in milliseconds": 0.0255,
                        "children": [
                            {
                                "name": "Try Get Overlapping Ranges",
                                "id": "c0631534-8564-4020-ba9f-f3a261fc296e",
                                "start time": "05:05:09:244",
                                "duration in milliseconds": 0.0144
                            }
                        ]
                    }
                ]
            },
            {
                "name": "MoveNextAsync",
                "id": "410459e1-7f12-4e69-8b12-badbefc8af25",
                "start time": "05:05:09:244",
                "duration in milliseconds": 8524.4241,
                "children": [
                    {
                        "name": "Prefetching",
                        "id": "20e5e16c-251b-4805-9f7e-33f100486758",
                        "start time": "05:05:09:244",
                        "duration in milliseconds": 0.0004
                    },
                    {
                        "name": "[05C1E7FFFFFFFE,FF) move next",
                        "id": "3835ba63-5241-4295-b0ea-f9ec25164e9e",
                        "start time": "05:05:09:244",
                        "duration in milliseconds": 8524.4149,
                        "children": [
                            {
                                "name": "Prefetch",
                                "id": "3f33c6d2-60dd-4393-968b-53d6d5748dcc",
                                "start time": "05:05:09:244",
                                "duration in milliseconds": 8524.4143,
                                "children": [
                                    {
                                        "name": "[05C1E7FFFFFFFE,FF) move next",
                                        "id": "892496c3-2f8d-4547-946b-6ea59806f68e",
                                        "start time": "05:05:09:244",
                                        "duration in milliseconds": 8524.4155,
                                        "children": [
                                            {
                                                "name": "Microsoft.Azure.Cosmos.Handlers.RequestInvokerHandler",
                                                "id": "4a9e15a4-c925-4089-a4cf-7ac2954b0b66",
                                                "start time": "05:05:09:244",
                                                "duration in milliseconds": 8524.4009,
                                                "children": [
                                                    {
                                                        "name": "Commerce.Shared.CosmosExtensions.Diagnostics.DiagnosticSourceHandler",
                                                        "id": "fa7bb3a5-a30d-498a-9cf9-606c29036adf",
                                                        "start time": "05:05:09:244",
                                                        "duration in milliseconds": 8524.3889,
                                                        "children": [
                                                            {
                                                                "name": "Commerce.Shared.CosmosExtensions.Timeout.TimeoutHandler",
                                                                "id": "c7678d1f-1eef-4880-a967-37fd917c0896",
                                                                "start time": "05:05:09:244",
                                                                "duration in milliseconds": 8524.2516,
                                                                "children": [
                                                                    {
                                                                        "name": "Microsoft.Azure.Cosmos.Handlers.DiagnosticsHandler",
                                                                        "id": "429db6a0-98f2-46fc-8577-550449546280",
                                                                        "start time": "05:05:09:244",
                                                                        "duration in milliseconds": 8524.2473,
                                                                        "data": {
                                                                            "System Info": {
                                                                                "systemHistory": [
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T17:04:23.3680263Z",
                                                                                        "cpu": 7.921,
                                                                                        "memory": 55901872,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0217,
                                                                                            "availableThreads": 32763,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T17:04:33.3682845Z",
                                                                                        "cpu": 13.378,
                                                                                        "memory": 55866916,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0046,
                                                                                            "availableThreads": 32766,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T17:04:43.3684966Z",
                                                                                        "cpu": 17.621,
                                                                                        "memory": 55983688,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0249,
                                                                                            "availableThreads": 32762,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T17:04:53.3687548Z",
                                                                                        "cpu": 10.456,
                                                                                        "memory": 56017112,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0374,
                                                                                            "availableThreads": 32764,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T17:05:03.3691551Z",
                                                                                        "cpu": 11.675,
                                                                                        "memory": 56004764,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.2381,
                                                                                            "availableThreads": 32766,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    },
                                                                                    {
                                                                                        "dateUtc": "2023-05-30T17:05:13.3693779Z",
                                                                                        "cpu": 10.635,
                                                                                        "memory": 55997308,
                                                                                        "threadInfo": {
                                                                                            "isThreadStarving": "False",
                                                                                            "threadWaitIntervalInMs": 0.0269,
                                                                                            "availableThreads": 32766,
                                                                                            "minThreads": 1000,
                                                                                            "maxThreads": 32767
                                                                                        },
                                                                                        "numberOfOpenTcpConnection": 709
                                                                                    }
                                                                                ]
                                                                            }
                                                                        },
                                                                        "children": [
                                                                            {
                                                                                "name": "Microsoft.Azure.Cosmos.Handlers.RetryHandler",
                                                                                "id": "ddd57fa9-92ff-432e-a7c4-f949196e52ba",
                                                                                "start time": "05:05:09:244",
                                                                                "duration in milliseconds": 8524.2407,
                                                                                "children": [
                                                                                    {
                                                                                        "name": "Microsoft.Azure.Cosmos.Handlers.RouterHandler",
                                                                                        "id": "e8615585-9903-4308-a9dc-1b55f6c07995",
                                                                                        "start time": "05:05:09:244",
                                                                                        "duration in milliseconds": 8524.2223,
                                                                                        "children": [
                                                                                            {
                                                                                                "name": "Microsoft.Azure.Cosmos.Handlers.TransportHandler",
                                                                                                "id": "6cfb45f4-3951-46ab-89c9-ee7971dc084e",
                                                                                                "start time": "05:05:09:244",
                                                                                                "duration in milliseconds": 8524.2197,
                                                                                                "children": [
                                                                                                    {
                                                                                                        "name": "Microsoft.Azure.Documents.ServerStoreModel Transport Request",
                                                                                                        "id": "d41ff940-6e65-4b9f-83ca-29aea1139f9a",
                                                                                                        "start time": "05:05:09:244",
                                                                                                        "duration in milliseconds": 8524.0938,
                                                                                                        "data": {
                                                                                                            "Client Side Request Stats": {
                                                                                                                "Id": "AggregatedClientSideRequestStatistics",
                                                                                                                "ContactedReplicas": [],
                                                                                                                "RegionsContacted": [],
                                                                                                                "FailedReplicas": [],
                                                                                                                "AddressResolutionStatistics": [],
                                                                                                                "StoreResponseStatistics": []
                                                                                                            }
                                                                                                        }
                                                                                                    }
                                                                                                ]
                                                                                            }
                                                                                        ]
                                                                                    }
                                                                                ]
                                                                            }
                                                                        ]
                                                                    }
                                                                ]
                                                            }
                                                        ]
                                                    }
                                                ]
                                            }
                                        ]
                                    }
                                ]
                            }
                        ]
                    }
                ]
            }
        ]
    }

Attachments:
@ghost ghost added the needs-investigation label Jun 1, 2023
@kundadebdatta kundadebdatta self-assigned this Jun 2, 2023
@ealsur
Copy link
Member

ealsur commented Jul 31, 2023

Probably related to #3831

@sourabh1007
Copy link
Contributor

Closing on the basis of above comment. We can reopen it, if this issue occurs again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@kundadebdatta kundadebdatta

Labels
needs-investigation
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ealsur @sourabh1007 @kundadebdatta