[SERVER-46536] Make query planner log level 5 output readable again Created: 02/Mar/20  Updated: 15/May/23

Status: Backlog
Project: Core Server
Component/s: Querying
Affects Version/s: None
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: Ian Boros Assignee: Backlog - Query Optimization
Resolution: Unresolved Votes: 0
Labels: neweng, qopt-team, storch
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Assigned Teams:
Query Optimization
Backport Requested:
v5.0, v4.4
Sprint: Query 2020-06-15, QE 2021-08-09
Participants:

 Description   

With the removal of "text format" logging, the log level 5 messages from the query planner are no longer of much use. Instead of printing nicely formatted trees, like:

[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| 2020-02-28T18:50:18.665-0500 D5 QUERY    [conn1] Enumerator: memo just before moving:
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| [Node #1]: AND enumstate counter 0
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| 	choice 0:
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| 		subnodes:
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| 		idx[0]
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| 			pos 0 pred TEXT : query=indigo Oklahoma, language=english, caseSensitive=0, diacriticSensitive=0, tag=NULL
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020|
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| 2020-02-28T18:50:18.666-0500 D5 QUERY    [conn1] About to build solntree from tagged tree:
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| TEXT : query=indigo Oklahoma, language=english, caseSensitive=0, diacriticSensitive=0, tag= || Selected Index #0 pos 0 combine 1
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| 2020-02-28T18:50:18.666-0500 D5 QUERY    [conn1] PROJECTION: Current plan is:
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| SKIP
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| ---skip= 9
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.666-0500 d30020| ---fetched = 1
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---sortedByDiskLoc = 0
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---getSort = []
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---Child:
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ------SORT
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------type = SIMPLE
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------pattern = { obj.obj.obj.obj.num: -1.0 }
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------limit = 27
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------fetched = 1
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------sortedByDiskLoc = 0
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------getSort = []
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------Child:
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ------------TEXT
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------------name = $**_text
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.667-0500 d30020| ---------------keyPattern = { _fts: "text", _ftsx: 1 }
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------query = indigo Oklahoma
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------language = english
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------caseSensitive= 0
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------diacriticSensitive= 0
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------indexPrefix = {}
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------fetched = 1
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------sortedByDiskLoc = 0
[js_test:query_fuzzer-113d-1580435579441-1] 2020-02-28T18:50:18.668-0500 d30020| ---------------getSort = []

We now get this:

[js_test:query_fuzzer-113d-1580435579441-1] 2020-03-02T13:09:36.851-0500 d30020| {"t":{"$date":"2020-03-02T13:09:36.851-0500"},"s":"D5","c":"QUERY",   "id":20949,"ctx":"conn1","msg":"PROJECTION: Current plan is:\n{solnRoot}","attr":{"solnRoot":"SKIP\n---skip= 9\n---fetched = 1\n---sortedByDiskLoc = 0\n---getSort = []\n---Child:\n------SORT\n---------type = SIMPLE\n---------pattern = { obj.obj.obj.obj.num: -1.0 }\n---------limit = 27\n---------fetched = 1\n---------sortedByDiskLoc = 0\n---------getSort = []\n---------Child:\n------------TEXT\n---------------name = $**_text\n---------------keyPattern = { _fts: \"text\", _ftsx: 1 }\n---------------query = indigo Oklahoma\n---------------language = english\n---------------caseSensitive= 0\n---------------diacriticSensitive= 0\n---------------indexPrefix = {}\n---------------fetched = 1\n---------------sortedByDiskLoc = 0\n---------------getSort = []\n"}}

As someone who likes to use log level 5 query output to get a summary of the plans considered with a quick glance, this is a pretty unfortunate change. Now that we have JSON logs we may as well log objects (similar to explain) instead of strings.



 Comments   
Comment by Rui Liu [ 29/Jul/21 ]

ian.boros I learned a trick today that you can copy the json text and do `echo -e <json>` to view the plan with \n interpreted. Maybe that's something interesting to you.  

Comment by Rushan Chen [ 22/Jul/21 ]

For Rui. 

Backport for 5.0

Comment by David Storch [ 20/Aug/20 ]

mindaugas.malinauskas I'm going to return this to the triage queue to give you more time to focus on the doc validation project.

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