[SERVER-19849] Query don't use index Created: 10/Aug/15  Updated: 03/Oct/15  Resolved: 03/Oct/15

Status: Closed
Project: Core Server
Component/s: Index Maintenance, Performance
Affects Version/s: 3.0.5
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: SHUK LING Assignee: Ramon Fernandez Marina
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

Randomly with high load on slave or master.
DB: 33G, replset (1master - 2slaves).
3x servers: EC2 m4.large (8Gb RAM)

Participants:

 Description   

Randomly the query (slave or master) stop to use an index and start to scan the collection.

Here is an extract of the db.currentOp:

		{
			"desc" : "conn206",
			"threadId" : "0x65818e0",
			"connectionId" : 206,
			"opid" : 38888384,
			"active" : true,
			"secs_running" : 131,
			"microsecs_running" : NumberLong(131062659),
			"op" : "query",
			"ns" : "prod.cart",
			"query" : {
				"orderby" : {
					"_id" : 1
				},
				"$query" : {
					"offer" : "OFFER1",
					"code" : "CODE2",
					"customerId" : ObjectId("55c82exxxxxxxxxxx")
				}
			},
			"planSummary" : "IXSCAN { code: 1 }, IXSCAN { code: 1 }",
			"client" : "172.x.x.x:52977",
			"numYields" : 6191,
			"locks" : {
				"Global" : "r",
				"MMAPV1Journal" : "r",
				"Database" : "r",
				"Collection" : "R"
			},
			"waitingForLock" : false,
			"lockStats" : {
				"Global" : {
					"acquireCount" : {
						"r" : NumberLong(12384)
					},
					"acquireWaitCount" : {
						"r" : NumberLong(831)
					},
					"timeAcquiringMicros" : {
						"r" : NumberLong(7836539)
					}
				},
				"MMAPV1Journal" : {
					"acquireCount" : {
						"r" : NumberLong(6192)
					},
					"acquireWaitCount" : {
						"r" : NumberLong(27)
					},
					"timeAcquiringMicros" : {
						"r" : NumberLong(204897)
					}
				},
				"Database" : {
					"acquireCount" : {
						"r" : NumberLong(6192)
					}
				},
				"Collection" : {
					"acquireCount" : {
						"R" : NumberLong(6192)
					}
				}
			}
		}

Index:

[
	{
		"v" : 1,
		"key" : {
			"_id" : 1
		},
		"name" : "_id_",
		"ns" : "prod.Cart"
	},
	{
		"v" : 1,
		"key" : {
			"customerId" : 1
		},
		"name" : "customerId_1",
		"ns" : "prod.Cart"
	},
	{
		"v" : 1,
		"key" : {
			"code" : 1
		},
		"name" : "code_1",
		"ns" : "prod.Cart"
	},
	{
		"v" : 1,
		"key" : {
			"offer" : 1
		},
		"name" : "offer_1",
		"ns" : "prod.Cart",
		"background" : true
	}
]



 Comments   
Comment by Ramon Fernandez Marina [ 03/Oct/15 ]

support@sesam.hk, we haven't heard back from you for a while so I'm closing this ticket. If the issue persists please provide the information requested in my previous comment so we can investigate further.

Regards,
Ramón.

Comment by Ramon Fernandez Marina [ 10/Sep/15 ]

support@sesam.hk, unless I missed something the information you sent does not capture the problem described in the ticket. From the initial description my best guess is that this is an issue with index selection: the {code:1} index is being used and it's not selective enough to complete the query quickly.

If your query is on {offerCode:1, dropCode:1, customerId:1} then one option is to build such an index. Another alternative is to hint() on the {customerId:1} index, which is bound to be more selective.

Unfortunately the output of the explain(true) command doesn't provide the information I was looking for. Can you please run the following commands on your primary:

db.cart.find({ offerCode: "OP1", dropCode: "LK_R2BISOP1_FR", customerId: ObjectId('55c149e595c9af3600087aa5') }).explain(true);
db.cart.find({ offerCode: "OP1", dropCode: "LK_R2BISOP1_FR", customerId: ObjectId('55c149e595c9af3600087aa5') }).sort({_id : 1}).explain(true);

And also the following command on a secondary:

db.cart.getIndexes()

Thanks,
Ramón

Comment by SHUK LING [ 17/Aug/15 ]

Hi,

Do you need more informations ?

Best regards

Comment by Ramon Fernandez Marina [ 11/Aug/15 ]

Thanks for opening a new ticket support@sesam.hk,

we'll need more information to diagnose this problem. The output of db.currentOp indicates an index scan, not a collection scan, but it could be that a suboptimal index is being used for your query. First off, can you please confirm that the offending query is as follows:

db.cart.find({ "offer" : "OFFER1", "code" : "CODE2", "customerId" : ObjectId("55c82exxxxxxxxxxx")}).sort({_id : 1})

Next I'd like you ask you to follow the steps below and upload the resulting information:

  • Increase the log level by running:

    db.adminCommand( { setParameter: 1, logLevel: 2 } )

  • Display query shapes from the plan cache:

    use prod
    db.cart.getPlanCache().listQueryShapes()

  • Run getPlansByQuery on the offending query:

    db.cart.getPlanCache().getPlansByQuery(<your query here>)
    

  • Run the query with explain(true):

    db.cart.find(<your query yere>).sort(<your sort here>).explain(true)

  • Re-set the log level to the previous value (probably 0 if you didn't change this before) to prevent logs from taking too much space:

    db.adminCommand( { setParameter: 1, logLevel: 0 } )
    

You can put each piece of information in a file, zip all files along with the part of the mongod.log log file created while running the above commands, and post it to this ticket. If the resulting file is too large (hundreds of megabytes) please let me know before and I'll send you different upload instructions.

Thanks,
Ramón.

Generated at Thu Feb 08 03:52:16 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.