[SERVER-60848] Log which engine was used for processing a query Created: 20/Oct/21  Updated: 29/Oct/23  Resolved: 24/Jan/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 5.3.0, 5.2.1

Type: Task Priority: Major - P3
Reporter: Pawel Terlecki Assignee: Jennifer Peshansky (Inactive)
Resolution: Fixed Votes: 0
Labels: neweng
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Documented
is documented by DOCS-15061 Investigate changes in SERVER-60848: ... Closed
Related
is related to SERVER-62760 Add information to query log line ind... Closed
is related to SERVER-71172 Expose hybrid plans in profiler, slow... Closed
Backwards Compatibility: Minor Change
Backport Requested:
v5.2, v5.1
Sprint: QE 2021-11-01, QE 2021-11-15, QE 2021-11-29, QE 2021-12-13, QE 2021-12-27, QE 2022-01-10, QE 2022-02-07, QE 2022-01-24
Participants:

 Description   

Add a field that indicates whether we used classic or SBE for a query. We should backport it to 5.1. At the least we want to see how many queries are exposed to SBE.

Worth considering:

  • just logging a field if the less common case happens (e.g. "sbe")
  • should we use the same field in the future for the optimizer (e.g. "sbe" (executed with sbe) / "cqf" (optimized and executed with cqf)


 Comments   
Comment by Githook User [ 25/Jan/22 ]

Author:

{'name': 'Jennifer Peshansky', 'email': 'jennifer.peshansky@mongodb.com', 'username': 'jenniferpeshansky'}

Message: SERVER-60848 Add SBE to the slow query log line and to curop metrics

(cherry picked from commit 52de3c52493f35e4ac4714178bf9d554835bdff7)
Branch: v5.2
https://github.com/mongodb/mongo/commit/c66a46ea750e3aaf2d8f652e6dc3d3c44ea3baef

Comment by Jennifer Peshansky (Inactive) [ 24/Jan/22 ]

Detailed before and after, for downstream changes

Change Before After
Slow query log "msg":"Slow query","attr":{ ..., "planCacheKey":"84A11A7D","reslen":166,", ... "msg":"Slow query","attr":{ ..., "planCacheKey":"84A11A7D","queryExecutionEngine":"sbe","reslen":166,", ...
OR
"msg":"Slow query","attr":{ ..., "planCacheKey":"84A11A7D","queryExecutionEngine":"classic","reslen":166,", ...
Server Status counters db.serverStatus().metrics.query { "planCacheTotalSizeEstimateBytes" : NumberLong(0), "updateOneOpStyleBroadcastWithExactIDCount" : NumberLong(0) } db.serverStatus().metrics.query
{
     "planCacheTotalSizeEstimateBytes" : NumberLong(0),
     "queryExecutionEngine" : {
            "find": {
                   sbe: 3
                   classic: 2
            }
            "aggregate": {
                   sbeOnly: 7
                   classicOnly: 7
                   sbeHybrid: 4
                   classicHybrid: 4
            }
     },
     "updateOneOpStyleBroadcastWithExactIDCount" : NumberLong(0)
}
Comment by Githook User [ 24/Jan/22 ]

Author:

{'name': 'Jennifer Peshansky', 'email': 'jennifer.peshansky@mongodb.com', 'username': 'jenniferpeshansky'}

Message: SERVER-60848 Add SBE to the slow query log line and to curop metrics
Branch: master
https://github.com/mongodb/mongo/commit/ba25336add6ed39d8a5dc3d0371e3e34730aa83d

Comment by David Storch [ 20/Oct/21 ]

I think there are actually four cases which we may want to distinguish:

  • SBE
  • Classic plan stages
  • SBE / DocumentSource hybrid plan
  • Classic / DocumentSource hybrid plan
Comment by Kyle Suarez [ 20/Oct/21 ]

christopher.harris, mihai.andrei suggested also adding a serverStatus counter to track the number of SBE queries run. Would you consider that in scope for this ticket?

Generated at Thu Feb 08 05:50:53 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.