|
| 1 | +--- |
| 2 | +title: Get SQL query performance & execution metrics |
| 3 | +description: Learn how to retrieve SQL query execution metrics and profile SQL query performance of Azure Cosmos DB requests. |
| 4 | +author: ginamr |
| 5 | +ms.service: cosmos-db |
| 6 | +ms.subservice: cosmosdb-sql |
| 7 | +ms.topic: conceptual |
| 8 | +ms.date: 05/17/2019 |
| 9 | +ms.author: girobins |
| 10 | + |
| 11 | +--- |
| 12 | +# Get SQL query execution metrics and analyze query performance using .NET SDK |
| 13 | + |
| 14 | +This article presents how to profile SQL query performance on Azure Cosmos DB. This profiling can be done using `QueryMetrics` retrieved from the .NET SDK and is detailed here. [QueryMetrics](https://msdn.microsoft.com/library/microsoft.azure.documents.querymetrics.aspx) is a strongly typed object with information about the backend query execution. These metrics are documented in more detail in the [Tune Query Performance](https://docs.microsoft.com/azure/cosmos-db/documentdb-sql-query-metrics) article. |
| 15 | + |
| 16 | +## Set the FeedOptions parameter |
| 17 | + |
| 18 | +All the overloads for [DocumentClient.CreateDocumentQuery](https://msdn.microsoft.com/library/microsoft.azure.documents.client.documentclient.createdocumentquery.aspx) take in an optional [FeedOptions](https://msdn.microsoft.com/library/microsoft.azure.documents.client.feedoptions.aspx) parameter. This option is what allows query execution to be tuned and parameterized. |
| 19 | + |
| 20 | +To collect the Sql query execution metrics, you must set the parameter [PopulateQueryMetrics](https://msdn.microsoft.com/library/microsoft.azure.documents.client.feedoptions.populatequerymetrics.aspx#P:Microsoft.Azure.Documents.Client.FeedOptions.PopulateQueryMetrics) in the [FeedOptions](https://msdn.microsoft.com/library/microsoft.azure.documents.client.feedoptions.aspx) to `true`. Setting `PopulateQueryMetrics` to true will make it so that the `FeedResponse` will contain the relevant `QueryMetrics`. |
| 21 | + |
| 22 | +## Get query metrics with AsDocumentQuery() |
| 23 | +The following code sample shows how to do retrieve metrics when using [AsDocumentQuery()](https://msdn.microsoft.com/library/microsoft.azure.documents.linq.documentqueryable.asdocumentquery.aspx) method: |
| 24 | + |
| 25 | +```csharp |
| 26 | +// Initialize this DocumentClient and Collection |
| 27 | +DocumentClient documentClient = null; |
| 28 | +DocumentCollection collection = null; |
| 29 | + |
| 30 | +// Setting PopulateQueryMetrics to true in the FeedOptions |
| 31 | +FeedOptions feedOptions = new FeedOptions |
| 32 | +{ |
| 33 | + PopulateQueryMetrics = true |
| 34 | +}; |
| 35 | + |
| 36 | +string query = "SELECT TOP 5 * FROM c"; |
| 37 | +IDocumentQuery<dynamic> documentQuery = documentClient.CreateDocumentQuery(Collection.SelfLink, query, feedOptions).AsDocumentQuery(); |
| 38 | + |
| 39 | +while (documentQuery.HasMoreResults) |
| 40 | +{ |
| 41 | + // Execute one continuation of the query |
| 42 | + FeedResponse<dynamic> feedResponse = await documentQuery.ExecuteNextAsync(); |
| 43 | + |
| 44 | + // This dictionary maps the partitionId to the QueryMetrics of that query |
| 45 | + IReadOnlyDictionary<string, QueryMetrics> partitionIdToQueryMetrics = feedResponse.QueryMetrics; |
| 46 | + |
| 47 | + // At this point you have QueryMetrics which you can serialize using .ToString() |
| 48 | + foreach (KeyValuePair<string, QueryMetrics> kvp in partitionIdToQueryMetrics) |
| 49 | + { |
| 50 | + string partitionId = kvp.Key; |
| 51 | + QueryMetrics queryMetrics = kvp.Value; |
| 52 | + |
| 53 | + // Do whatever logging you need |
| 54 | + DoSomeLoggingOfQueryMetrics(query, partitionId, queryMetrics); |
| 55 | + } |
| 56 | +} |
| 57 | +``` |
| 58 | +## Aggregating QueryMetrics |
| 59 | + |
| 60 | +In the previous section, notice that there were multiple calls to [ExecuteNextAsync](https://msdn.microsoft.com/library/azure/dn850294.aspx) method. Each call returned a `FeedResponse` object that has a dictionary of `QueryMetrics`; one for every continuation of the query. The following example shows how to aggregate these `QueryMetrics` using LINQ: |
| 61 | + |
| 62 | +```csharp |
| 63 | +List<QueryMetrics> queryMetricsList = new List<QueryMetrics>(); |
| 64 | + |
| 65 | +while (documentQuery.HasMoreResults) |
| 66 | +{ |
| 67 | + // Execute one continuation of the query |
| 68 | + FeedResponse<dynamic> feedResponse = await documentQuery.ExecuteNextAsync(); |
| 69 | + |
| 70 | + // This dictionary maps the partitionId to the QueryMetrics of that query |
| 71 | + IReadOnlyDictionary<string, QueryMetrics> partitionIdToQueryMetrics = feedResponse.QueryMetrics; |
| 72 | + queryMetricsList.AddRange(partitionIdToQueryMetrics.Values); |
| 73 | +} |
| 74 | + |
| 75 | +// Aggregate the QueryMetrics using the + operator overload of the QueryMetrics class. |
| 76 | +QueryMetrics aggregatedQueryMetrics = queryMetricsList.Aggregate((curr, acc) => curr + acc); |
| 77 | +Console.WriteLine(aggregatedQueryMetrics); |
| 78 | +``` |
| 79 | + |
| 80 | +## Grouping query metrics by Partition ID |
| 81 | + |
| 82 | +You can group the `QueryMetrics` by the Partition ID. Grouping by Partition ID allows you to see if a specific Partition is causing performance issues when compared to others. The following example shows how to group `QueryMetrics` with LINQ: |
| 83 | + |
| 84 | +```csharp |
| 85 | +List<KeyValuePair<string, QueryMetrics>> partitionedQueryMetrics = new List<KeyValuePair<string, QueryMetrics>>(); |
| 86 | +while (documentQuery.HasMoreResults) |
| 87 | +{ |
| 88 | + // Execute one continuation of the query |
| 89 | + FeedResponse<dynamic> feedResponse = await documentQuery.ExecuteNextAsync(); |
| 90 | + |
| 91 | + // This dictionary is maps the partitionId to the QueryMetrics of that query |
| 92 | + IReadOnlyDictionary<string, QueryMetrics> partitionIdToQueryMetrics = feedResponse.QueryMetrics; |
| 93 | + partitionedQueryMetrics.AddRange(partitionIdToQueryMetrics.ToList()); |
| 94 | +} |
| 95 | + |
| 96 | +// Now we are able to group the query metrics by partitionId |
| 97 | +IEnumerable<IGrouping<string, KeyValuePair<string, QueryMetrics>>> groupedByQueryMetrics = partitionedQueryMetrics |
| 98 | + .GroupBy(kvp => kvp.Key); |
| 99 | + |
| 100 | +// If we wanted to we could even aggregate the groupedby QueryMetrics |
| 101 | +foreach(IGrouping<string, KeyValuePair<string, QueryMetrics>> grouping in groupedByQueryMetrics) |
| 102 | +{ |
| 103 | + string partitionId = grouping.Key; |
| 104 | + QueryMetrics aggregatedQueryMetricsForPartition = grouping |
| 105 | + .Select(kvp => kvp.Value) |
| 106 | + .Aggregate((curr, acc) => curr + acc); |
| 107 | + DoSomeLoggingOfQueryMetrics(query, partitionId, aggregatedQueryMetricsForPartition); |
| 108 | +} |
| 109 | +``` |
| 110 | + |
| 111 | +## LINQ on DocumentQuery |
| 112 | + |
| 113 | +You can also get the `FeedResponse` from a LINQ Query using the `AsDocumentQuery()` method: |
| 114 | + |
| 115 | +```csharp |
| 116 | +IDocumentQuery<Document> linqQuery = client.CreateDocumentQuery(collection.SelfLink, feedOptions) |
| 117 | + .Take(1) |
| 118 | + .Where(document => document.Id == "42") |
| 119 | + .OrderBy(document => document.Timestamp) |
| 120 | + .AsDocumentQuery(); |
| 121 | +FeedResponse<Document> feedResponse = await linqQuery.ExecuteNextAsync<Document>(); |
| 122 | +IReadOnlyDictionary<string, QueryMetrics> queryMetrics = feedResponse.QueryMetrics; |
| 123 | +``` |
| 124 | + |
| 125 | +## Expensive Queries |
| 126 | + |
| 127 | +You can capture the request units consumed by each query to investigate expensive queries or queries that consume high throughput. You can get the request charge by using the [RequestCharge](https://msdn.microsoft.com/library/azure/dn948712.aspx) property in `FeedResponse`. To learn more about how to get the request charge using the Azure portal and different SDKs, see [find the request unit charge](find-request-unit-charge.md) article. |
| 128 | + |
| 129 | +```csharp |
| 130 | +string query = "SELECT * FROM c"; |
| 131 | +IDocumentQuery<dynamic> documentQuery = documentClient.CreateDocumentQuery(Collection.SelfLink, query, feedOptions).AsDocumentQuery(); |
| 132 | + |
| 133 | +while (documentQuery.HasMoreResults) |
| 134 | +{ |
| 135 | + // Execute one continuation of the query |
| 136 | + FeedResponse<dynamic> feedResponse = await documentQuery.ExecuteNextAsync(); |
| 137 | + double requestCharge = feedResponse.RequestCharge |
| 138 | + |
| 139 | + // Log the RequestCharge how ever you want. |
| 140 | + DoSomeLogging(requestCharge); |
| 141 | +} |
| 142 | +``` |
| 143 | + |
| 144 | +## Get the query execution time |
| 145 | + |
| 146 | +When calculating the time required to execute a client-side query, make sure that you only include the time to call the `ExecuteNextAsync` method and not other parts of your code base. Just these calls help you in calculating how long the query execution took as shown in the following example: |
| 147 | + |
| 148 | +```csharp |
| 149 | +string query = "SELECT * FROM c"; |
| 150 | +IDocumentQuery<dynamic> documentQuery = documentClient.CreateDocumentQuery(Collection.SelfLink, query, feedOptions).AsDocumentQuery(); |
| 151 | +Stopwatch queryExecutionTimeEndToEndTotal = new Stopwatch(); |
| 152 | +while (documentQuery.HasMoreResults) |
| 153 | +{ |
| 154 | + // Execute one continuation of the query |
| 155 | + queryExecutionTimeEndToEndTotal.Start(); |
| 156 | + FeedResponse<dynamic> feedResponse = await documentQuery.ExecuteNextAsync(); |
| 157 | + queryExecutionTimeEndToEndTotal.Stop(); |
| 158 | +} |
| 159 | + |
| 160 | +// Log the elapsed time |
| 161 | +DoSomeLogging(queryExecutionTimeEndToEndTotal.Elapsed); |
| 162 | +``` |
| 163 | + |
| 164 | +## Scan queries (commonly slow and expensive) |
| 165 | + |
| 166 | +A scan query refers to a query that wasn't served by the index, due to which, many documents are loaded before returning the result set. |
| 167 | + |
| 168 | +Below is an example of a scan query: |
| 169 | + |
| 170 | +```sql |
| 171 | +SELECT VALUE c.description |
| 172 | +FROM c |
| 173 | +WHERE UPPER(c.description) = "BABYFOOD, DESSERT, FRUIT DESSERT, WITHOUT ASCORBIC ACID, JUNIOR" |
| 174 | +``` |
| 175 | + |
| 176 | +This query's filter uses the system function UPPER, which isn't served from the index. Executing this query against a large collection produced the following query metrics for the first continuation: |
| 177 | + |
| 178 | +``` |
| 179 | +QueryMetrics |
| 180 | +
|
| 181 | +Retrieved Document Count : 60,951 |
| 182 | +Retrieved Document Size : 399,998,938 bytes |
| 183 | +Output Document Count : 7 |
| 184 | +Output Document Size : 510 bytes |
| 185 | +Index Utilization : 0.00 % |
| 186 | +Total Query Execution Time : 4,500.34 milliseconds |
| 187 | + Query Preparation Times |
| 188 | + Query Compilation Time : 0.09 milliseconds |
| 189 | + Logical Plan Build Time : 0.05 milliseconds |
| 190 | + Physical Plan Build Time : 0.04 milliseconds |
| 191 | + Query Optimization Time : 0.01 milliseconds |
| 192 | + Index Lookup Time : 0.01 milliseconds |
| 193 | + Document Load Time : 4,177.66 milliseconds |
| 194 | + Runtime Execution Times |
| 195 | + Query Engine Times : 322.16 milliseconds |
| 196 | + System Function Execution Time : 85.74 milliseconds |
| 197 | + User-defined Function Execution Time : 0.00 milliseconds |
| 198 | + Document Write Time : 0.01 milliseconds |
| 199 | +Client Side Metrics |
| 200 | + Retry Count : 0 |
| 201 | + Request Charge : 4,059.95 RUs |
| 202 | +``` |
| 203 | + |
| 204 | +Note the following values from the query metrics output: |
| 205 | + |
| 206 | +``` |
| 207 | +Retrieved Document Count : 60,951 |
| 208 | +Retrieved Document Size : 399,998,938 bytes |
| 209 | +``` |
| 210 | + |
| 211 | +This query loaded 60,951 documents, which totaled 399,998,938 bytes. Loading this many bytes results in high cost or request unit charge. It also takes a long time to execute the query, which is clear with the total time spent property: |
| 212 | + |
| 213 | +``` |
| 214 | +Total Query Execution Time : 4,500.34 milliseconds |
| 215 | +``` |
| 216 | + |
| 217 | +Meaning that the query took 4.5 seconds to execute (and this was only one continuation). |
| 218 | + |
| 219 | +To optimize this example query, avoid the use of UPPER in the filter. Instead, when documents are created or updated, the `c.description` values must be inserted in all uppercase characters. The query then becomes: |
| 220 | + |
| 221 | +```sql |
| 222 | +SELECT VALUE c.description |
| 223 | +FROM c |
| 224 | +WHERE c.description = "BABYFOOD, DESSERT, FRUIT DESSERT, WITHOUT ASCORBIC ACID, JUNIOR" |
| 225 | +``` |
| 226 | + |
| 227 | +This query is now able to be served from the index. |
| 228 | + |
| 229 | +To learn more about tuning query performance, see the [Tune Query Performance](https://docs.microsoft.com/azure/cosmos-db/documentdb-sql-query-metrics) article. |
| 230 | + |
| 231 | +## <a id="References"></a>References |
| 232 | + |
| 233 | +- [Azure Cosmos DB SQL specification](https://go.microsoft.com/fwlink/p/?LinkID=510612) |
| 234 | +- [ANSI SQL 2011](https://www.iso.org/iso/iso_catalogue/catalogue_tc/catalogue_detail.htm?csnumber=53681) |
| 235 | +- [JSON](https://json.org/) |
| 236 | +- [LINQ](/previous-versions/dotnet/articles/bb308959(v=msdn.10)) |
| 237 | + |
| 238 | +## Next steps |
| 239 | + |
| 240 | +- [Tune query performance](sql-api-query-metrics.md) |
| 241 | +- [Indexing overview](index-overview.md) |
| 242 | +- [Azure Cosmos DB .NET samples](https://github.com/Azure/azure-cosmosdb-dotnet) |
0 commit comments