[SERVER-11649] Log results and explain results differences Created: 09/Nov/13  Updated: 10/Dec/14  Resolved: 02/Jan/14

Status: Closed
Project: Core Server
Component/s: Index Maintenance
Affects Version/s: 2.2.2
Fix Version/s: None

Type: Question Priority: Blocker - P1
Reporter: Huseyin Yurtseven Assignee: Thomas Rueckstiess
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive 1.json.zip     Zip Archive cnn.zip     PNG File slow_by_pattern.png    
Participants:

 Description   

Hello,

I have an interesting problem for indexing and i need additional help.

I use mongodb for our multisite CMS system and we put all kind of contents to the same contents collection.

Our document is like:

{
   "_id": ObjectId("507eb67f564e66097c7378f7"),
   "_t": ["Base","Content","Article"],
   "Application": "com.cnnturk",
   "Status": 0,
   "ContentType": "Article",
   "Path": "/dunya/",
   "Title" : "...",
   "Description": "...",
   "Text" : "...",
   "StartDate": ISODate("2013-09-20T08:15:10.901Z"),
   ...
}

_t = C# driver put this field to hold inheritance
Application = We separate different web sites with this field
Status = Active = 0, Passive = 1 etc.
ContentType = content type, Article, Video, Episode etc.
Path = Our folder, for example we put all worlds articles to the /dunya/ path and in any path we have approximately 200000 contents /turkiye/, /ekonomi/ etc.
StartDate= contents appear on the web sites after this date

We have following indexes

{_t:1,Application:1,Status:1,Path:1}
{StartDate:-1,_t:1,Application:1,Status:1,Path:1}
 
{Application:1,Status:1,Path:1,ContentType:1}
{StartDate:-1,Application:1,Status:1,Path:1,ContentType:1}

and we have mostly following queries

find({_t:"Article",Application:"com.cnnturk",Status:0,Path:/^\/spor\//}).sort({StartDate:-1}).limit(5)
or
find({Application:"com.cnnturk",Status:0,Path:/^\/spor\//,ContentType:'Media'}).sort({StartDate:-1}).limit(5)

(by the way i tried to use sort field on the end of index but i couldn't get good performance)

When i try to explain those queries i see the following results

"cursor" : "BtreeCursor _t_1_Application_1_Status_1_Path_1 multi",
	"isMultiKey" : true,
	"n" : 5,
	"nscannedObjects" : 305,
	"nscanned" : 305,
	"nscannedObjectsAllPlans" : 1853,
	"nscannedAllPlans" : 2453,
	"scanAndOrder" : true,
	"indexOnly" : false,
	"nYields" : 0,
	"nChunkSkips" : 0,
	"millis" : 20,
-------------
"cursor" : "BtreeCursor Application_1_Status_1_Path_1_ContentType_1 multi",
	"isMultiKey" : false,
	"n" : 0,
	"nscannedObjects" : 0,
	"nscanned" : 15,
	"nscannedObjectsAllPlans" : 60,
	"nscannedAllPlans" : 117,
	"scanAndOrder" : true,
	"indexOnly" : false,
	"nYields" : 0,
	"nChunkSkips" : 0,
	"millis" : 0,

But in the log file millis and nscanned's are very different and very high for those queries.

Another situation is: despite of those queries don't use indexes that starts with
start date, when i drop those indexes (

{StartDate:-1, ...}

) the queries slow down and millis goes to 2000 and higher

Another problem is on count queries: for example the following query

db.Contents.find({ Application: "com.cnnturk", Status: 0, Path: /^\/spor\//, ContentType: { $in: [ "Article", "PhotoGallery", "NewsVideo" ] } } ).count()

looks very slow in log file

Sat Nov  9 11:36:43 [conn40477318] command quark_test_cnn.$cmd command: { count: "Contents", query: { Application: "com.cnnturk", Status: 0, Path: /^/spor//s, ContentType: { $in: [ "Article", "PhotoGallery", "NewsVideo" ] } } } ntoreturn:1 keyUpdates:0 numYields: 4 locks(micros) r:3824466 reslen:48 2432ms

By the way i'm sending the db stats, collection stats and index stats:

> db.stats(1024*1024)
{
	"db" : "quark_test_cnn",
	"collections" : 36,
	"objects" : 4503374,
	"avgObjSize" : 7789.841278117252,
	"dataSize" : 33455,
	"storageSize" : 35775,
	"numExtents" : 166,
	"indexes" : 50,
	"indexSize" : 485,
	"fileSize" : 40877,
	"nsSizeMB" : 16,
	"ok" : 1
}
> 
 
> db.Contents.stats(1024*1024)
{
	"ns" : "quark_test_cnn.Contents",
	"count" : 394327,
	"size" : 1052,
	"avgObjSize" : 0.0026678365924727447,
	"storageSize" : 1248,
	"numExtents" : 16,
	"nindexes" : 10,
	"lastExtentSize" : 329,
	"paddingFactor" : 1.2190000000000272,
	"systemFlags" : 0,
	"userFlags" : 0,
	"totalIndexSize" : 327,
	"indexSizes" : {
		"_id_" : 10,
		"Application_1_Status_1_Url_1" : 45,
		"Application_1_Status_1_IxName_1" : 28,
		"Application_1_Status_1_Tags_1" : 30,
		"Template.Regions.Controls.ContentViews.Content._id_1" : 0,
		"Template.Regions.Controls.Controls.ContentViews.Content._id_1" : 0,
		"Application_1_Status_1_Path_1_ContentType_1" : 23,
		"_t_1_Application_1_Status_1_Path_1" : 74,
		"StartDate_-1_Application_1_Status_1_Path_1_ContentType_1" : 27,
		"StartDate_-1__t_1_Application_1_Status_1_Path_1" : 85
	},
	"ok" : 1
}
 
> db.Contents.totalIndexSize()
343334768
 

---------

I have 3 machine replica set
64 GB Ram (Mongo uses 60 GB)
RAID 10 Spindle disk
Redhat Enterprise Linux
I set all ulimits as on your documents.
Intel(R) Xeon(R) CPU E5-2640 0 @ 2.50GHz

Thanks for your helps in advance



 Comments   
Comment by Huseyin Yurtseven [ 02/Jan/14 ]

Hello,

Thanks for your helps.

Best regards.

Comment by Thomas Rueckstiess [ 02/Jan/14 ]

Hi Huseyin,

Thanks for the log file. I've attached a graphical representation of all the queries in it, grouped by the query pattern (different colors), see slow_by_pattern.png. As you can see, the green ones are the slowest so you need to look at improving those as well. The black queries around the 400-700ms mark are the ones we have discussed here. The key to improving them is to remove the regexes, which may require some schema modifications.

Thank that i have sport articles with /sport/ path and i have football articles with /sport/football/ path and i want to show both of them in my sport page www.cnnturk.com/spor.

You may need an additional field that contains the main category "sport" for these two groups of articles. One way to do this is with tagging. For example:

// articles from the main sport category have
{ ... tags: [ "sport" ], ... }
 
// articles from sport/football have
{ ... tags: ["sport", "football"], ... }

If you query with {tags: "sport"}, you will get articles from both groups, but you can also query for "football" specifically. An index on {tags:1} will make these queries fast.

If you have further questions about optimizing these queries, you can ask them in our google group or on stack overflow with the "MongoDB" tag. This SERVER project is for bug reports, and I haven't seen any signs that the issue here is a bug in MongoDB. Sorry that I can't be of more help.

Regards,
Thomas

Comment by Huseyin Yurtseven [ 27/Dec/13 ]

Hi,

I uploaded a 5 minutes log file from secondary (by the way we use readPreference secondary for site and for cms we use primary)

Thank you.

Comment by Huseyin Yurtseven [ 27/Dec/13 ]

Meanwhile i use the _t field because i need all kinds of content in a path like ({_t:'Content',Application:'com.cnnturk',Status:0,Path:'/spor/'}).sort(

{StartDate:-1}

) to get articles, videos and photo galleries at the same time.

Comment by Huseyin Yurtseven [ 27/Dec/13 ]

Hi Thomas,

I will send the log file. Sorry i misunderstood.

I know that mongodb can't use two different indexes but somehow without sort index the query was very slow but after add

{StartDate:-1}

index the query speeded up. I don't know why.

For left anchored regex queries I know the range problem but i couldn't find another way without regex.Thank that i have sport articles with /sport/ path and i have football articles with /sport/football/ path and i want to show both of them in my sport page www.cnnturk.com/spor. That's why i use that regex queries. Actually i also have Ancestors node in the content document to hold all paths maybe i can use the ancestors array to query the path with

{Application:1,Status:1,'Ancestors.SelfPath':1,ContentType:1,StartDate:-1}

index. But in that case i cannot create an index for find({_t:'Content',Application:'com.cnnturk',Status:0,'Ancestors.SelfPath':'/spor/'}).sort(

{StartDate:-1}

) query because mongodb gives "cannot index parallel arrays [Ancestors] [_t]" error.

Ancestors Sample:

"Ancestors" : [
		{
			"_id" : "50ead2edd681c00d38109c04",
			"Title" : "Spor",
			"Path" : "/",
                        "SelfPath": '/spor/'
			"IxName" : "spor",
			"Url" : "/spor",
			"IsContainer" : true
		},
		{
			"_id" : "5273f701050668306cfbb1c6",
			"Title" : "Futbol",
			"Path" : "/spor/",
                        "SelfPath": '/spor/futbol/'
			"IxName" : "futbol",
			"Url" : "/spor/futbol",
			"IsContainer" : true
		}
	],

Thanks for your helps, i will write again after log uploaded.

Comment by Thomas Rueckstiess [ 26/Dec/13 ]

Hi Huseyin,

Thanks for the new profile output. I can see the slow queries, but to also understand what was going on during these queries I really need the log file from the mongod as well. Are you able to upload that to the same server?

As for the indexes: MongoDB currently can't use two different indexes for search and sort. Only one index can be used for a query (including sorting). Having the two separate indexes you pasted above does not help for the sort and data has to be sorted in memory.

The other problem is that the left-anchored regular expression (like /^spor/) constitutes a range (it will match every string between spor and spos). Since you have a range of matches on the Path field here, MongoDB can't make use of the sort order in an index for another range, StartDate, even if you had it in the index.

It looks like you're querying the first item/folder of a path with this index, and if you are always only interested in the top level item, it could be worth placing that first item in a separate field and running an equality query against it, for example:

{
   "_id": ObjectId("507eb67f564e66097c7378f7"),
   "_t": ["Base","Content","Article"],
   "Application": "com.cnnturk",
   "Status": 0,
   "ContentType": "Article",
   "Path": "/abc/def/ghi",
   "FirstPathItem: "abc",
   "Title" : "...",
   "Description": "...",
   "Text" : "...",
   "StartDate": ISODate("2013-09-20T08:15:10.901Z"),
   ...
}

In this schema I've added FirstPathItem and store abc separately in it. Now you can do equality matches and the sort with a single index on

{Application: 1, Status: 1, FirstPathItem: 1, ContentType: 1, StartDate: -1}

This should speed up these types of queries noticably.

Regards,
Thomas

Comment by Huseyin Yurtseven [ 26/Dec/13 ]

Hi,

There are still problems on queries. I took queries just excess 300 millis and i copied with scp as profile.json.zip. You can look into. As you can see there are some queries that excess 3000 ms and i have an index for that queries

I have the following indexes for that query

{Application:1,Status:1,Path:1,ContentType:1}

and

{StartDate:-1}

(If i wouldn't create start date index the queries are getting slower)

By the way i'have forgotten to say that i upgraded mongodb version from 2.2.2 to 2.4.8

Thank you.

Comment by Thomas Rueckstiess [ 26/Dec/13 ]

Hi Huseyin,

It's really hard to say what a good response time is for queries, because it really depends on the query patterns, indexes, how much read and write load there is at any time and your hardware. Therefore I can't tell you what the expected times should be, although 500ms for normal finds (without regexes and with proper indexes) for a dataset that size still seems long.

If you have fixed the queries that I pointed out above and still have other queries that are taking around 500ms or longer, then please upload your log file of the most recent day or so to this secure server and I will have a look at it and see if I can see anything else that can be improved:

You can do this using the following command:

scp -P 722 -r <filename> SERVER-11649@www.mongodb.com:

Substitute <filename> with the name of the compressed file(s) you want to upload. Note the colon ':' at the end of the command. When you are prompted for a password, please just press ENTER.

Let me know once you have uploaded the log file (you can of course redact sensitive information).

Regards,
Thomas

Comment by Huseyin Yurtseven [ 26/Dec/13 ]

Hi Thomas,

Thanks for your helps. I saw that queries and i fixed them. Now there is no that kind of queries. But as you know i removed /s suffix from the C# driver, after that query millis decreased, now i can't use C# driver's official release, i have to use nightly build.

You know i have approximately 400.000 documents in "Contents" collection, so that execution times are okay? so approximately max 500 ms for that size of collection? or can i decrease more? or should i think sharding for that size of collection?

What is the optimal response time for that size?

Thank you very much.

Comment by Thomas Rueckstiess [ 24/Dec/13 ]

Hi Huseyin,

Are the slow queries still an issue for you?

From the profiling output you attached, I can see a number of inefficient queries that can't make use of an index, for example:

1. Queries / Counts using $ne and empty case-insensitive regex queries

	"command" : {
		"count" : "Contents",
		"query" : {
			"Application" : "com.cnnturk",
			"_id" : {
				"$ne" : ObjectId("50d0b03e8f67be0544683dcf")
			},
			"Url" : /^/$/i,
			"Status" : 0
		}
	},

I suggest you eliminate the $ne operator and the empty regex and run the count normally. You can run a second query on just the ObjectId you're trying to exclude to see if you need to subtract 1 from the count result. Even though those are two queries, they should be much faster than the one you are executing now.

2. Queries that don't have a supporting index

	"query" : {
		"$query" : {
			"_t" : "NewsVideo",
			"Application" : "com.cnnturk",
			"Status" : 0,
			"StartDate" : {
				"$gt" : ISODate("1901-01-01T00:00:00Z")
			}
		},
		"$orderby" : {
			"StartDate" : 1
		}
	},

This query would probably benefit from an index on {_t:1, Application:1, Status:1, StartDate:1}. While you have some indexes that are similar, none of them match that exact pattern.

3. Queries using case-insensitive regexes (/.../i)

Another query that doesn't seem to be able to use indexes efficiently is

	"command" : {
		"count" : "Contents",
		"query" : {
			"Application" : "com.cnnturk",
			"Status" : 0,
			"$or" : [
				{
					"Title" : /barzani/im
				},
				{
					"Tags" : /barzani/im
				}
			],
			"ContentType" : {
				"$in" : [
					"Article"
				]
			}
		}
	},

Since you are using case-insensitive regex matches in the $or clauses, I think the best index here is actually just {Application:1, Status:1, ContentType:1 } and scan the remaining documents. How efficient that is depends on the data distribution.

All operations in your profiling output taking longer than 1000ms are of either of these three cases. Are you concerned with any others that are not covered by these? If so, if you can provide a log file that would help. You can redact any sensitive information, or I can provide a secure way of uploading the file to our server.

Regards,
Thomas

Comment by Huseyin Yurtseven [ 11/Dec/13 ]

I have the following indexes on the "contents" collection

[
	{
		"v" : 1,
		"key" : {
			"_id" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "_id_"
	},
	{
		"v" : 1,
		"key" : {
			"Template.Regions.Controls.ContentViews.Content._id" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Template.Regions.Controls.ContentViews.Content._id_1",
		"background" : true,
		"sparse" : true
	},
	{
		"v" : 1,
		"key" : {
			"Template.Regions.Controls.Controls.ContentViews.Content._id" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Template.Regions.Controls.Controls.ContentViews.Content._id_1",
		"background" : true,
		"sparse" : true
	},
	{
		"v" : 1,
		"key" : {
			"StartDate" : -1,
			"Application" : 1,
			"Status" : 1,
			"Path" : 1,
			"ContentType" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "StartDate_-1_Application_1_Status_1_Path_1_ContentType_1"
	},
	{
		"v" : 1,
		"key" : {
			"Url" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Url_1"
	},
	{
		"v" : 1,
		"key" : {
			"IxName" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "IxName_1"
	},
	{
		"v" : 1,
		"key" : {
			"Tags" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Tags_1"
	},
	{
		"v" : 1,
		"key" : {
			"Template.Regions.Controls.Controls.Controls.ContentViews.Content._id" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Template.Regions.Controls.Controls.Controls.ContentViews.Content._id_1",
		"background" : true,
		"sparse" : true
	},
	{
		"v" : 1,
		"key" : {
			"CreatedDate" : -1,
			"_t" : 1,
			"Application" : 1,
			"Status" : 1,
			"Path" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "CreatedDate_-1__t_1_Application_1_Status_1_Path_1"
	},
	{
		"v" : 1,
		"key" : {
			"Hit" : -1,
			"_t" : 1,
			"Application" : 1,
			"Status" : 1,
			"Path" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Hit_-1__t_1_Application_1_Status_1_Path_1"
	},
	{
		"v" : 1,
		"key" : {
			"Hit" : -1,
			"Application" : 1,
			"Status" : 1,
			"Path" : 1,
			"ContentType" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Hit_-1_Application_1_Status_1_Path_1_ContentType_1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"ReferenceId" : 1,
			"ContentType" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "ReferenceId_1_ContentType_1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"MediaFiles.Path" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "MediaFiles.Path_1",
		"background" : true,
		"sparse" : true
	},
	{
		"v" : 1,
		"key" : {
			"FormPages.Questions._id" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "FormPages.Questions._id_1",
		"background" : true,
		"sparse" : true
	},
	{
		"v" : 1,
		"key" : {
			"IId" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "IId_1",
		"background" : 1
	},
	{
		"v" : 1,
		"key" : {
			"StartDate" : -1,
			"_t" : 1,
			"Application" : 1,
			"Status" : 1,
			"Path" : 1,
			"ContentType" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "StartDate_-1__t_1_Application_1_Status_1_Path_1_ContentType_1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"Status" : 1,
			"StartDate" : -1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Status_1_StartDate_-1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"Status" : 1,
			"EndDate" : -1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Status_1_EndDate_-1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"Application" : 1,
			"Status" : 1,
			"Path" : 1,
			"ContentType" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Application_1_Status_1_Path_1_ContentType_1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"_t" : 1,
			"Application" : 1,
			"Status" : 1,
			"Path" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "_t_1_Application_1_Status_1_Path_1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"Application" : 1,
			"Status" : 1,
			"Title" : 1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Application_1_Status_1_Title_1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"Application" : 1,
			"Status" : 1,
			"Path" : 1,
			"ContentType" : 1,
			"StartDate" : -1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "Application_1_Status_1_Path_1_ContentType_1_StartDate_-1",
		"background" : true
	},
	{
		"v" : 1,
		"key" : {
			"_t" : 1,
			"Application" : 1,
			"Status" : 1,
			"Path" : 1,
			"StartDate" : -1
		},
		"ns" : "quark_cnnturk.Contents",
		"name" : "_t_1_Application_1_Status_1_Path_1_StartDate_-1",
		"background" : true
	}
]  

Comment by Huseyin Yurtseven [ 27/Nov/13 ]

By the way i removed /s suffix from regex queries from C# driver source code because of the performance problems.

So if you look into the log you won't see the /s suffixes and thats why you will see the millis as approx 500, with /s suffix those millis would be approx 2000.

Comment by Huseyin Yurtseven [ 27/Nov/13 ]

Hi,

I'm attaching a new profile export, I put only query that excess 100 millis. Because otherwise it it would be very large.

Thanks

Comment by Eliot Horowitz (Inactive) [ 27/Nov/13 ]

Sorry for the delay, but the zip file seems empty.

Comment by Huseyin Yurtseven [ 15/Nov/13 ]

Hello,

Is there any progress about this issue, i need to ask because we cannot launch CNN Turkey web site because of this issue.

if we upgrade mongodb from 2.2.2 to 2.4.x, will it work?

Thank you.

Comment by Huseyin Yurtseven [ 10/Nov/13 ]

Meanwhile there is another problem which you will see on the profile collection. The regex queries that come from c# driver seem weird. There is an "s" suffix on the regex clauses and i think that's why i cannot look to the profile with mongo shell. It gives an error message.

Comment by Huseyin Yurtseven [ 10/Nov/13 ]

Hi Eliot,

Thanks for your quick response and helps. I'm sending the dump file as zip.

Comment by Eliot Horowitz (Inactive) [ 10/Nov/13 ]

Can you turn on query profiling for a little while and send the mongodump of that collection?

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