[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: |
|
| 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:
_t = C# driver put this field to hold inheritance We have following indexes
and we have mostly following queries
(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
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 ) the queries slow down and millis goes to 2000 and higher Another problem is on count queries: for example the following query
looks very slow in log file
By the way i'm sending the db stats, collection stats and index stats:
--------- I have 3 machine replica set 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
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:
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, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| 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:
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:
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
This should speed up these types of queries noticably. Regards, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| 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
and
(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:
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, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| 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
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
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
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, | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Huseyin Yurtseven [ 11/Dec/13 ] | |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I have the following indexes on the "contents" collection
| |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| 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? |