[SERVER-7545] TTL collection very slow to access Created: 02/Nov/12  Updated: 11/Jul/16  Resolved: 03/Sep/13

Status: Closed
Project: Core Server
Component/s: Performance
Affects Version/s: 2.2.0
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: John Woakes Assignee: David Hows
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows 7 64-bit


Operating System: Windows
Participants:

 Description   

We have a time to live collection that is storing log data. We are inputting lots of data all the time. We have indexes on all the columns. In general all querying and inserting is very slow.

I created a test database to look into this in more detail. It has 4 columns including a date field with a TTL index set to 10 minutes. I set profiling on and added MMS

https://mms.10gen.com/host/detail/6bf3ac009f2f321516e6e03349fdca19

Account = iQmetrix
Host = User-PC:27017

I then created a program to insert data as fast as it could, setting safemode=false. This program averages inserting about 600 records per second and queries on indexed fields often take over 30 seconds.

Without TTL and only the _id index I can insert at about 33,000 per second.



 Comments   
Comment by David Hows [ 26/Aug/13 ]

Hi John and Vasyl,

Just following up. Are these issues still continuing for you?

If so, can we re-group and try to resolve?

Thanks,
David

Comment by Vasyl [ 08/Feb/13 ]

Same issue here (mongo 2.2.0, CentOS 6, 2 rs-ed shards, 30 GB ram on each node)

Comment by John Woakes [ 05/Nov/12 ]

No, not in this case. This was originally running on VMs on machines here but this test code was running on my home machine [database and code]. Machine is Windows 7 ultimate, 8GB.

Comment by Tad Marshall [ 05/Nov/12 ]

Hi John,

Just to confirm; this is running on Windows Azure and so may be affected by SERVER-7378; is this correct?

Tad

Comment by John Woakes [ 05/Nov/12 ]

And the EventData_1 index is a TTL of 10 minutes.

Comment by John Woakes [ 05/Nov/12 ]

running the stats() gives:

> db.Events.stats()
{
        "ns" : "Stress.Events",
        "count" : 2787728,
        "size" : 312225536,
        "avgObjSize" : 112,
        "storageSize" : 460881920,
        "numExtents" : 15,
        "nindexes" : 3,
        "lastExtentSize" : 124985344,
        "paddingFactor" : 1,
        "systemFlags" : 1,
        "userFlags" : 1,
        "totalIndexSize" : 408783648,
        "indexSizes" : {
                "_id_" : 99093120,
                "EventData_1" : 98561680,
                "Payload_1" : 211128848
        },
        "ok" : 1
}
>

Comment by John Woakes [ 05/Nov/12 ]

using System;
using System.Diagnostics;
using MongoDB.Bson;
using MongoDB.Driver;
 
namespace MongoStress
{
    internal class Program
    {
        private static void Main(string[] args)
        {
            PumpInData(new Random());
            Console.ReadLine();
        }
 
        private static void PumpInData(Random random)
        {
            var events = GetLogDataCollection();
 
            var sw = Stopwatch.StartNew();
 
            for (var i = 0; i < 10000000; i++)
                events.Save(CreateNewEvent(random));
 
            sw.Stop();
            Console.WriteLine("Took {0} seconds", sw.Elapsed.TotalSeconds);
        }
 
        private static LogData CreateNewEvent(Random r)
        {
            var seconds = r.Next(0, 10*60);
            return new LogData
                       {
                           EventData = DateTime.UtcNow.Add(TimeSpan.FromSeconds(seconds)),
                           Payload = string.Format("This is a bunch of stuff for {0}", seconds),
                           ActualDate = DateTime.UtcNow
                       };
        }
 
        private static MongoCollection<LogData> GetLogDataCollection()
        {
            var settings = new MongoServerSettings
                               {
                                   ConnectionMode = ConnectionMode.Direct,
                                   ReadPreference = ReadPreference.Nearest,
                                   SafeMode = SafeMode.False,
                                   Server = new MongoServerAddress("localhost")
                               };
            var svr = MongoServer.Create(settings);
            var database = svr.GetDatabase("Stress");
            return database.GetCollection<LogData>("Events");
        }
    }
 
    public class LogData
    {
        public BsonObjectId Id { get; set; }
        public DateTime EventData { get; set; }
        public DateTime ActualDate { get; set; }
        public string Payload { get; set; }
    }
}

Comment by Daniel Pasette (Inactive) [ 05/Nov/12 ]

Could you attach your test program and the output of db.Events.stats() so that we can try to repro?

Comment by John Woakes [ 05/Nov/12 ]

I ran this command 5 times in Mongo.exe, always get the same result. Twice it came back instantly, and 3 times it took 30 seconds +/- 4 seconds. The millis is always 0. This is while I am running the insert program.

I then stopped the insert program and ran it again a bunch of times. It was very fast except once when it took 60 seconds to return but still millis was 0.

I have 8GB ram. Check MMS for anything else you need to know - database is Stress.

I am not currently running the insert program but I will leave it running Monday 7:00am PST - 7:00pm PST

> db.Events.find({ }).limit(50).sort({ "EventData" : -1 }).explain()
{
        "cursor" : "BtreeCursor EventData_1 reverse",
        "isMultiKey" : false,
        "n" : 50,
        "nscannedObjects" : 50,
        "nscanned" : 50,
        "nscannedObjectsAllPlans" : 50,
        "nscannedAllPlans" : 50,
        "scanAndOrder" : false,
        "indexOnly" : false,
        "nYields" : 0,
        "nChunkSkips" : 0,
        "millis" : 0,
        "indexBounds" : {
                "EventData" : [
                        [
                                {
                                        "$maxElement" : 1
                                },
                                {
                                        "$minElement" : 1
                                }
                        ]
                ]
        },
        "server" : "User-PC:27017"
}

Comment by Eliot Horowitz (Inactive) [ 04/Nov/12 ]

Can you send the explain for the query that takes 30 seconds?
How big is the data set compared to ram?
Obviously, more indexes will increase write times, but shouldn't be as drastic as it sounds.

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