Collect and log CosmosDB query metrics when extra logging is enabled #4275

chetanmeh · 2019-02-13T08:43:25Z

Collect and logs CosmosDB query metrics when extra logging is enabled

Description

if a request is performed with X-OW-EXTRA-LOGGING header set to on like below

curl -k --user "23bc46b1-71f6-4ed5-8c54-816aa4f8c502:123zO3xZCLrMN6v2BKK1dXYFpXlPkccOFqm12CdAsMgRU4VrNZ9lyGVCGuMDGIwP" \
     -H "X-OW-EXTRA-LOGGING: on" \
     "https://172.17.0.1:10001/api/v1/namespaces/_/activations?limit=30&skip=0"

Then in the logs following entries would logged which provide detailed insight into how query is executed by CosmosDB

[2019-02-13T14:11:48.689Z] [INFO] [#tid_FUn23vWbEbEQBFi5rIcioaZJkB4a2Wfw] [CosmosDBArtifactStore] [QueryMetricsEnabled] Collection [subjects] - Query [SELECT r AS view FROM root r JOIN n in r.namespaces WHERE (NOT(IS_DEFINED(r.blocked)) OR r.blocked = false) AND ((r.uuid = @uuid AND r.key = @key) OR (n.uuid = @uuid AND n.key = @key))].
QueryMetrics
[Retrieved Document Count                 :               1              
Retrieved Document Size                  :             428 bytes        
Output Document Count                    :               1              
Output Document Size                     :             682 bytes        
Index Utilization                        :          100.00 %            
Total Query Execution Time               :            0.00 milliseconds 
Query Preparation Times 
    Query Compilation Time               :        1.250000 milliseconds 
    Logical Plan Build Time              :        0.440000 milliseconds 
    Physical Plan Build Time             :        0.510000 milliseconds 
    Query Optimization Time              :        0.070000 milliseconds 
  Index Lookup Time                      :        0.640000 milliseconds 
  Document Load Time                     :        0.020000 milliseconds 
Runtime Execution Times 
    Query Engine Times                   :        0.090000 milliseconds 
    System Function Execution Time       :        0.000000 milliseconds 
    User-defined Function Execution Time :        0.000000 milliseconds 
  Document Write Time                    :        0.000000 milliseconds 
Client Side Metrics 
  Retry Count                            :              10              
  Request Charge                         :           15.25 RUs          
 
Partition Execution Timeline 
?------------?------------------------------------?----------------?----------------?-------------?-------------------?-----------? 
?Partition Id?                         Activity Id?Start Time (UTC)?  End Time (UTC)?Duration (ms)?Number of Documents?Retry Count? 
?------------?------------------------------------?----------------?----------------?-------------?-------------------?-----------? 
?           0?6d930ac9-39e8-49f9-a0c6-348ddc0a753b?   08:41:47:6920?   08:41:47:9370?        245.0?                  0?          4? 
?           0?4a823e13-f723-48e8-a6e9-aaa8c975b3b3?   08:41:47:4540?   08:41:47:6910?        237.0?                  0?          3? 
?           0?bc36fe9d-b75c-4a4f-a6d8-27c7aca7c209?   08:41:47:2170?   08:41:47:4540?        237.0?                  1?          2? 
?           0?22fd7bb1-1c99-4df1-b934-f8f6ae584f01?   08:41:46:9830?   08:41:47:2160?        233.0?                  0?          1? 
?           0?d0ddda24-5954-408e-9e16-038d36805301?   08:41:46:7380?   08:41:46:9720?        234.0?                  0?          0? 
?------------?------------------------------------?----------------?----------------?-------------?-------------------?-----------? 
 
Scheduling Metrics 
?------------?------------------?-------------?--------------?--------------------?---------------------? 
?Partition Id?Response Time (ms)?Run Time (ms)?Wait Time (ms)?Turnaround Time (ms)?Number of Preemptions? 
?------------?------------------?-------------?--------------?--------------------?---------------------? 
?           0?                 1?          233?             2?                 235?                    1? 
?           0?                 1?          232?           248?                 479?                    2? 
?           0?                 1?          236?           481?                 717?                    3? 
?           0?                 1?          236?           718?                 954?                    4? 
?           0?                 1?          244?           956?                1200?                    5? 
?------------?------------------?-------------?--------------?--------------------?---------------------? 
]
[2019-02-13T14:11:48.690Z] [INFO] [#tid_FUn23vWbEbEQBFi5rIcioaZJkB4a2Wfw] [CosmosDBArtifactStore]  [marker:database_queryView_finish:2342:2241]

Related issue and scope

I opened an issue to propose and discuss this change (Dump CosmosDB query metrics with debug mode #4268)

My changes affect the following components

Types of changes

Bug fix (generally a non-breaking change which closes an issue).
Enhancement or new feature (adds new functionality).
Breaking change (a bug fix or enhancement which changes existing behavior).

Checklist:

I signed an Apache CLA.
I reviewed the style guides and followed the recommendations (Travis CI will check :).
I added tests to cover my changes.
My changes require further changes to the documentation.
I updated the documentation where necessary.

codecov-io · 2019-02-13T09:19:07Z

Codecov Report

Merging #4275 into master will decrease coverage by 4.78%.
The diff coverage is 0%.

@@            Coverage Diff             @@
##           master    #4275      +/-   ##
==========================================
- Coverage   85.66%   80.88%   -4.79%     
==========================================
  Files         168      168              
  Lines        7839     7861      +22     
  Branches      519      523       +4     
==========================================
- Hits         6715     6358     -357     
- Misses       1124     1503     +379

Impacted Files	Coverage Δ
...core/database/cosmosdb/CosmosDBArtifactStore.scala	`0% <0%> (-95.18%)`	⬇️
...core/database/cosmosdb/RxObservableImplicits.scala	`0% <0%> (-100%)`	⬇️
...sk/core/database/cosmosdb/CosmosDBViewMapper.scala	`0% <0%> (-92.6%)`	⬇️
...whisk/core/database/cosmosdb/CosmosDBSupport.scala	`0% <0%> (-84.62%)`	⬇️
...abase/cosmosdb/CosmosDBArtifactStoreProvider.scala	`4% <0%> (-52%)`	⬇️
...in/scala/org/apache/openwhisk/common/Counter.scala	`40% <0%> (-20%)`	⬇️
.../scala/org/apache/openwhisk/utils/Exceptions.scala	`20% <0%> (-20%)`	⬇️
...whisk/connector/kafka/KafkaProducerConnector.scala	`72.5% <0%> (-15%)`	⬇️
...nwhisk/core/database/cosmosdb/CosmosDBConfig.scala	`94.11% <0%> (-5.89%)`	⬇️
... and 4 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update bb9f408...7667123. Read the comment docs.

tysonnorris · 2019-02-25T16:18:02Z

...scala/src/main/scala/org/apache/openwhisk/core/database/cosmosdb/CosmosDBArtifactStore.scala

+    } else None
+
+    def collectQueryMetrics(r: FeedResponse[Document]): Unit = {
+      collectMetrics(queryToken, r.getRequestCharge)


should collectMetrics() be skipped if queryMetrics.isEmpty?
nevermind - I see collectMetrics is just MetricEmitter

tysonnorris · 2019-02-25T16:30:07Z

...scala/src/main/scala/org/apache/openwhisk/core/database/cosmosdb/CosmosDBArtifactStore.scala

+    val options = newFeedOptions()
+    val queryMetrics = if (transid.meta.extraLogging) {
+      options.setPopulateQueryMetrics(true)
+      Some(scala.collection.mutable.Buffer[QueryMetrics]())


Any reason not to use a var for queryMetrics, init to List.empty (or whatever empty collection), and just assign to queryMetrics = r.getQueryMetrics.values() below, in case extra logging enabled?

There can be multiple FeedResponse with each having a set of QueryMetrics attached and they would need to be accumulated. Hence need to use Buffer so as to append them and cannot use List.empty.

Sorry, replace List.empty with Buffer[QueryMetrics](). I just thought the use of Option here was confusing - if you don't set options.setPopulateQueryMetrics(true), does r.getQueryMetrics.values() have any values?
If not, you can just always run buffer.appendAll...).
I guess not creating the buffer at all is slightly better, just harder to read.

I guess not creating the buffer at all is slightly better, just harder to read.

Yes the objective was to avoid that part for a debug logic. However I see the readability point. Refactored the code to use suggested approach

tysonnorris · 2019-02-25T16:34:01Z

...scala/src/main/scala/org/apache/openwhisk/core/database/cosmosdb/CosmosDBArtifactStore.scala

+          val combinedMetrics = QueryMetrics.ZERO.add(m: _*)
+          logging.debug(
+            this,
+            s"[QueryMetricsEnabled] Collection [$collName] - Query [${querySpec.getQueryText}].\nQueryMetrics\n[$combinedMetrics]")


what shows up in $combinedMetrics - do you have some sample output? I don't see it in the test

The sample output is there in PR description. The testcase currently only looks for a marker QueryMetricsEnabled to assert that log statement is executed

Fixes apache#4268

tysonnorris

LGTM

tysonnorris · 2019-02-28T16:50:43Z

LGTM Thanks!

…pache#4275) * Collect and log CosmosDB query metrics when extra logging is enabled Fixes apache#4268

chetanmeh mentioned this pull request Feb 13, 2019

Any plans to support query metrics Azure/azure-cosmosdb-java#66

Closed

rabbah assigned tysonnorris Feb 13, 2019

tysonnorris reviewed Feb 25, 2019

View reviewed changes

Collect and log CosmosDB query metrics when extra logging is enabled

49024e0

Fixes apache#4268

chetanmeh force-pushed the cosmosdb-query-metrics branch from a651847 to 49024e0 Compare February 27, 2019 06:00

tysonnorris approved these changes Feb 28, 2019

View reviewed changes

Review - Use buffer instead of option for better readability

7667123

tysonnorris merged commit 2ddd3c9 into apache:master Feb 28, 2019

chetanmeh mentioned this pull request Sep 30, 2019

Capture document size, RU usage, retry stats for get and put in CosmosDB #4652

Merged

21 tasks

BillZong pushed a commit to BillZong/openwhisk that referenced this pull request Nov 18, 2019

Collect and log CosmosDB query metrics when extra logging is enabled (a…

30e1ac5

…pache#4275) * Collect and log CosmosDB query metrics when extra logging is enabled Fixes apache#4268

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Collect and log CosmosDB query metrics when extra logging is enabled #4275

Collect and log CosmosDB query metrics when extra logging is enabled #4275

chetanmeh commented Feb 13, 2019

codecov-io commented Feb 13, 2019 •

edited

Loading

tysonnorris Feb 25, 2019 •

edited

Loading

tysonnorris Feb 25, 2019

chetanmeh Feb 27, 2019

tysonnorris Feb 28, 2019

chetanmeh Feb 28, 2019

tysonnorris Feb 25, 2019

chetanmeh Feb 27, 2019

tysonnorris left a comment

tysonnorris commented Feb 28, 2019

Collect and log CosmosDB query metrics when extra logging is enabled #4275

Collect and log CosmosDB query metrics when extra logging is enabled #4275

Conversation

chetanmeh commented Feb 13, 2019

Description

Related issue and scope

My changes affect the following components

Types of changes

Checklist:

codecov-io commented Feb 13, 2019 • edited Loading

Codecov Report

tysonnorris Feb 25, 2019 • edited Loading

Choose a reason for hiding this comment

tysonnorris Feb 25, 2019

Choose a reason for hiding this comment

chetanmeh Feb 27, 2019

Choose a reason for hiding this comment

tysonnorris Feb 28, 2019

Choose a reason for hiding this comment

chetanmeh Feb 28, 2019

Choose a reason for hiding this comment

tysonnorris Feb 25, 2019

Choose a reason for hiding this comment

chetanmeh Feb 27, 2019

Choose a reason for hiding this comment

tysonnorris left a comment

Choose a reason for hiding this comment

tysonnorris commented Feb 28, 2019

codecov-io commented Feb 13, 2019 •

edited

Loading

tysonnorris Feb 25, 2019 •

edited

Loading