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

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Done
    • Priority: Critical - P2
    • 3.6.0-rc2
    • Affects Version/s: 3.0.5, 3.0.6
    • Component/s: Querying
    • None
    • Fully Compatible
    • ALL
    • 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 } >
    • Query 2017-10-23, Query 2017-11-13
    • None
    • 0
    • None
    • None
    • None
    • None
    • None
    • None

      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

            Assignee:
            Kyle Suarez (Inactive)
            Reporter:
            ma6174
            Votes:
            1 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:
              Resolved: