-
Type:
Task
-
Resolution: Unresolved
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: Querying
-
Query Optimization
-
v5.0, v4.4
-
Query 2020-06-15, QE 2021-08-09
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.