Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-46536

Make query planner log level 5 output readable again

    • 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.

            Assignee:
            backlog-query-optimization [DO NOT USE] Backlog - Query Optimization
            Reporter:
            ian.boros@mongodb.com Ian Boros
            Votes:
            0 Vote for this issue
            Watchers:
            9 Start watching this issue

              Created:
              Updated: