Loading...

XML

Word

Printable

JSON

Type: Bug
Resolution: Done
Priority: Critical - P2
Fix Version/s: 3.6.0-rc2
Affects Version/s: 3.0.5, 3.0.6
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:

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

is duplicated by

SERVER-29883 "|" in query string occur into a full index scan, slow query

Closed

is related to

SERVER-15235 Regex query returns incorrect results when index is present

Closed

related to

SERVER-26536 Regex containing an escaped | pipe symbol are not handled correctly

Closed

SERVER-16622 RegEx query predicates using the | (vertical bar) character cannot use tight index bounds

Backlog

Assignee:: Kyle Suarez

Reporter:: ma6174

Participants:: David Storch, Githook User, Ian Whalen, Kyle Suarez, ma6174, Oleg Rekutin, Stennie Steneker

Votes:: 1 Vote for this issue

Watchers:: 12 Start watching this issue

Created:: Sep 16 2015 07:53:49 AM UTC

Updated:: May 16 2018 02:27:12 PM UTC

Resolved:: Oct 26 2017 10:27:47 PM UTC

Details

Initialization

search and view mongodb log(run with verbose)

mongodb explain info

Description

Attachments

Issue Links

Activity

People

Dates