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

$regex prefix search with escaped "|" should use tighter index bounds

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical - P2
    • Resolution: Fixed
    • Affects Version/s: 3.0.5, 3.0.6
    • Fix Version/s: 3.6.0-rc2
    • Component/s: Querying
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Steps To Reproduce:
      Hide

      Initialization

      > db.version()
      3.0.6
      > db.test_search.drop()
      true
      > for (var i=1;i<=100;i++){db.test_search.save({_id:"id"+i})}
      WriteResult({ "nMatched" : 0, "nUpserted" : 1, "nModified" : 0, "_id" : "id100" })
      > db.test_search.find().limit(3)
      { "_id" : "id1" }
      { "_id" : "id2" }
      { "_id" : "id3" }
      > db.test_search.find().count()
      100
      

      search and view mongodb log(run with verbose)

      1. search with |

      > db.test_search.find({_id:/^id\|/})
      > db.test_search.find({_id:/^id\|sssssssss/})
      > db.test_search.find({_id:{"$regex":"^id\\|"}})
      > db.test_search.find({_id:{"$regex":"^id\\|sssssssss"}})
      

      mongodb v3.0.6 log show that "nscanned:100"

      2015-09-16T15:10:21.551+0800 I QUERY    [conn2128] query test.test_search query: { _id: /^id\|/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms
       
      2015-09-16T15:10:55.456+0800 I QUERY    [conn2128] query test.test_search query: { _id: /^id\|sssssssss/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms
       
      2015-09-16T15:11:16.113+0800 I QUERY    [conn2128] query test.test_search query: { _id: { $regex: "^id\|" } } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms
       
      2015-09-16T15:11:34.034+0800 I QUERY    [conn2128] query test.test_search query: { _id: { $regex: "^id\|sssssssss" } } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms
      

      we also tested in v2.4.7, same query showed "nscanned:0"

      Wed Sep 16 15:43:40.854 [conn3077] query test.test_search query: { _id: /^id\|/ } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:3882 nreturned:0 reslen:20 3ms
       
      Wed Sep 16 15:43:57.683 [conn3077] query test.test_search query: { _id: /^id\|sssssssss/ } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:115 nreturned:0 reslen:20 0ms
       
      Wed Sep 16 15:44:06.890 [conn3077] query test.test_search query: { _id: { $regex: "^id\|" } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:168 nreturned:0 reslen:20 0ms
       
      Wed Sep 16 15:44:13.571 [conn3077] query test.test_search query: { _id: { $regex: "^id\|sssssssss" } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:121 nreturned:0 reslen:20 0ms
      

      2. search without |

      > db.test_search.find({_id:/^idA/})
      > db.test_search.find({_id:/^id\?/})
      

      mongodb v3.0.6 show that "nscanned:0", this is expected

      2015-09-16T15:16:25.091+0800 I QUERY    [conn2128] query test.test_search query: { _id: /^idA/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:0 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 1ms
       
      2015-09-16T15:16:51.971+0800 I QUERY    [conn2128] query test.test_search query: { _id: /^id\?/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:0 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms
      

      mongodb explain info

      > db.test_search.find({_id:/^id\|/}).explain()
      {
      	"queryPlanner" : {
      		"plannerVersion" : 1,
      		"namespace" : "test.test_search",
      		"indexFilterSet" : false,
      		"parsedQuery" : {
      			"_id" : /^id\|/
      		},
      		"winningPlan" : {
      			"stage" : "FETCH",
      			"inputStage" : {
      				"stage" : "IXSCAN",
      				"filter" : {
      					"_id" : /^id\|/
      				},
      				"keyPattern" : {
      					"_id" : 1
      				},
      				"indexName" : "_id_",
      				"isMultiKey" : false,
      				"direction" : "forward",
      				"indexBounds" : {
      					"_id" : [
      						"[\"\", {})",
      						"[/^id\\|/, /^id\\|/]"
      					]
      				}
      			}
      		},
      		"rejectedPlans" : [ ]
      	},
      	"serverInfo" : {
      		"host" : "test.local",
      		"port" : 27017,
      		"version" : "3.0.6",
      		"gitVersion" : "nogitversion"
      	},
      	"ok" : 1
      }
      >
       
      > db.test_search.find({_id:/^idA/}).explain()
      {
      	"queryPlanner" : {
      		"plannerVersion" : 1,
      		"namespace" : "test.test_search",
      		"indexFilterSet" : false,
      		"parsedQuery" : {
      			"_id" : /^idA/
      		},
      		"winningPlan" : {
      			"stage" : "FETCH",
      			"inputStage" : {
      				"stage" : "IXSCAN",
      				"keyPattern" : {
      					"_id" : 1
      				},
      				"indexName" : "_id_",
      				"isMultiKey" : false,
      				"direction" : "forward",
      				"indexBounds" : {
      					"_id" : [
      						"[\"idA\", \"idB\")",
      						"[/^idA/, /^idA/]"
      					]
      				}
      			}
      		},
      		"rejectedPlans" : [ ]
      	},
      	"serverInfo" : {
      		"host" : "test.local",
      		"port" : 27017,
      		"version" : "3.0.6",
      		"gitVersion" : "nogitversion"
      	},
      	"ok" : 1
      }
      >
      

      Show
      Initialization > db.version() 3.0.6 > db.test_search.drop() true > for ( var i=1;i<=100;i++){db.test_search.save({_id: "id" +i})} WriteResult({ "nMatched" : 0, "nUpserted" : 1, "nModified" : 0, "_id" : "id100" }) > db.test_search.find().limit(3) { "_id" : "id1" } { "_id" : "id2" } { "_id" : "id3" } > db.test_search.find().count() 100 search and view mongodb log(run with verbose) 1. search with | > db.test_search.find({_id:/^id\|/}) > db.test_search.find({_id:/^id\|sssssssss/}) > db.test_search.find({_id:{ "$regex" : "^id\\|" }}) > db.test_search.find({_id:{ "$regex" : "^id\\|sssssssss" }}) mongodb v3.0.6 log show that "nscanned:100" 2015-09-16T15:10:21.551+0800 I QUERY [conn2128] query test.test_search query: { _id: /^id\|/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms   2015-09-16T15:10:55.456+0800 I QUERY [conn2128] query test.test_search query: { _id: /^id\|sssssssss/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms   2015-09-16T15:11:16.113+0800 I QUERY [conn2128] query test.test_search query: { _id: { $regex: "^id\|" } } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms   2015-09-16T15:11:34.034+0800 I QUERY [conn2128] query test.test_search query: { _id: { $regex: "^id\|sssssssss" } } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:100 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms we also tested in v2.4.7, same query showed "nscanned:0" Wed Sep 16 15:43:40.854 [conn3077] query test.test_search query: { _id: /^id\|/ } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:3882 nreturned:0 reslen:20 3ms   Wed Sep 16 15:43:57.683 [conn3077] query test.test_search query: { _id: /^id\|sssssssss/ } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:115 nreturned:0 reslen:20 0ms   Wed Sep 16 15:44:06.890 [conn3077] query test.test_search query: { _id: { $regex: "^id\|" } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:168 nreturned:0 reslen:20 0ms   Wed Sep 16 15:44:13.571 [conn3077] query test.test_search query: { _id: { $regex: "^id\|sssssssss" } } ntoreturn:0 ntoskip:0 nscanned:0 keyUpdates:0 locks(micros) r:121 nreturned:0 reslen:20 0ms 2. search without | > db.test_search.find({_id:/^idA/}) > db.test_search.find({_id:/^id\?/}) mongodb v3.0.6 show that "nscanned:0", this is expected 2015-09-16T15:16:25.091+0800 I QUERY [conn2128] query test.test_search query: { _id: /^idA/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:0 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 1ms   2015-09-16T15:16:51.971+0800 I QUERY [conn2128] query test.test_search query: { _id: /^id\?/ } planSummary: IXSCAN { _id: 1 } ntoreturn:0 ntoskip:0 nscanned:0 nscannedObjects:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { R: 1 } } } 0ms mongodb explain info > db.test_search.find({_id:/^id\|/}).explain() { "queryPlanner" : { "plannerVersion" : 1, "namespace" : "test.test_search", "indexFilterSet" : false, "parsedQuery" : { "_id" : /^id\|/ }, "winningPlan" : { "stage" : "FETCH", "inputStage" : { "stage" : "IXSCAN", "filter" : { "_id" : /^id\|/ }, "keyPattern" : { "_id" : 1 }, "indexName" : "_id_", "isMultiKey" : false, "direction" : "forward", "indexBounds" : { "_id" : [ "[\"\", {})", "[/^id\\|/, /^id\\|/]" ] } } }, "rejectedPlans" : [ ] }, "serverInfo" : { "host" : "test.local", "port" : 27017, "version" : "3.0.6", "gitVersion" : "nogitversion" }, "ok" : 1 } >   > db.test_search.find({_id:/^idA/}).explain() { "queryPlanner" : { "plannerVersion" : 1, "namespace" : "test.test_search", "indexFilterSet" : false, "parsedQuery" : { "_id" : /^idA/ }, "winningPlan" : { "stage" : "FETCH", "inputStage" : { "stage" : "IXSCAN", "keyPattern" : { "_id" : 1 }, "indexName" : "_id_", "isMultiKey" : false, "direction" : "forward", "indexBounds" : { "_id" : [ "[\"idA\", \"idB\")", "[/^idA/, /^idA/]" ] } } }, "rejectedPlans" : [ ] }, "serverInfo" : { "host" : "test.local", "port" : 27017, "version" : "3.0.6", "gitVersion" : "nogitversion" }, "ok" : 1 } >
    • Sprint:
      Query 2017-10-23, Query 2017-11-13
    • Case:

      Description

      we found an slow log, it takes 271 seconds, after check, we found that the "nscanned:107090777" is vary large. we expect that the query is an prefix search, should use index, and match only several documents.

      2015-09-14T10:57:27.819+0800 I QUERY    [conn17228] query fakedb.fakecoll query: { $query: { _id: { $regex: "^fake\|other_query_string" } }, $orderby: { _id: 1 } } planSummary: IXSCAN { _id: 1 } ntoreturn:200 ntoskip:0 nscanned:107090777 nscannedObjects:0 ke
      yUpdates:0 writeConflicts:0 numYields:836649 nreturned:0 reslen:20 locks:{ Global: { acquireCount: { r: 1673300 }, acquireWaitCount: { r: 99240 }, timeAcquiringMicros: { r: 39751354
       } }, Database: { acquireCount: { r: 836650 } }, Collection: { acquireCount: { r: 836650 } } } 271897ms
      

        Attachments

          Issue Links

            Activity

              People

              • Votes:
                1 Vote for this issue
                Watchers:
                13 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: