Core Server
  1. Core Server
  2. SERVER-1745

Query performance very poor when using $all

    Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Major - P3 Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 1.6.2
    • Fix Version/s: None
    • Component/s: Performance
    • Labels:
      None
    • Environment:
      Ubuntu lucid server with mongodb-stable package from 10gen's apt repository
    • Backport:
      No
    • Operating System:
      ALL
    • # Replies:
      7
    • Last comment by Customer:
      false

      Description

      At random (seemingly) the performance of all of our queries using $all (and potentially others) have dropped significantly. Queries that were taking 4 to 20 milliseconds are now taking anywhere from 4 to 10 seconds (sometimes even longer). mongostat only shows a blip on the radar for the queries however (ie: it happens in under a second according to mongostat). Here's an example query:

      ----- code ---------
      db.products.count({ "variations.attributeIds" :

      { "$all" : [ 3873 , 3898]}

      , "enabled" : true});
      ----- / code ---------

      another convenient query for timing is:
      ----- code -----
      function timeThis() {
      var ret = new Date()+"\n";
      ret = db.products.count({ "variations.attributeIds" : { "$all" : [ 3873 , 3898]}})"\n";
      ret += new Date();
      return ret;
      }
      timeThis();
      ----- /code -----

      That query takes anywhere from 4 to 8 seconds to execute. CPU usage by the mongod process raises significantly (I'm not sure if this is a bad thing). I've copied the dataset to a machine with 70GB of RAM (yes, 70 gigabytes) and 8 processor cores just to eliminate any potential hardware issues and the problems sill persist.

      the following indexes exist:
      ----- code ---------
      db.products.ensureIndex(

      {"uid":1}

      ,

      {unique:true, dropDups : true}

      );
      db.products.ensureIndex(

      {weight:-1}

      );

      db.products.ensureIndex(

      {"dateCreated": 1, "weight": -1}

      );
      db.products.ensureIndex(

      {"dateCreated": -1, "weight": -1}

      );

      db.products.ensureIndex(

      {"variations.price": 1, "weight": -1}

      );
      db.products.ensureIndex(

      {"variations.price": -1, "weight": -1}

      );

      db.products.ensureIndex(

      {"variations.salePercent": 1, "weight": -1}

      );
      db.products.ensureIndex(

      {"variations.salePercent": -1, "weight": -1}

      );

      db.products.ensureIndex(

      {"keywords": 1, "weight": -1}

      );
      db.products.ensureIndex(

      {"variations.attributeIds":1}

      );
      db.products.ensureIndex(

      {"variations.attributeIds":1, "enabled":1}

      );
      ----- / code ---------

      The dataset attached is half of the collection that is in production that is causing issues, i did the following to reduce it to half:

      ----- code ---------
      function reduceByHalf(colName) {
      var i = 0;
      var c = 0;
      db[colName].find().forEach(function(doc) {
      if ((i%2)==0) {
      db[colName].remove({_id:doc._id});
      c++;
      }
      i++;
      });
      return "Deleted "c" documents";
      }
      reduceByHalf("products");
      ----- / code ---------

      The dataset has roughly 16k documents in it and is attached to this issue in tar/gz format

      1. dump.tar.gz
        66.15 MB
        Brian C. Dilley

        Issue Links

          Activity

          Hide
          Brian C. Dilley
          added a comment -

          So i continued to play with this and found that sometimes variations.attributeIds contained over 3K entries (many times actually) and that's what was slowing things down. Code elsewhere was doing this and causing that to happen. So if you want to close this bug on those grounds that's fine - unless you think it should still perform.

          Show
          Brian C. Dilley
          added a comment - So i continued to play with this and found that sometimes variations.attributeIds contained over 3K entries (many times actually) and that's what was slowing things down. Code elsewhere was doing this and causing that to happen. So if you want to close this bug on those grounds that's fine - unless you think it should still perform.
          Hide
          Aaron Staple (Inactive)
          added a comment -

          Thanks for reporting this - you're right, it's slow. I filed SERVER-1748 to represent a fix for the slow component.

          Show
          Aaron Staple (Inactive)
          added a comment - Thanks for reporting this - you're right, it's slow. I filed SERVER-1748 to represent a fix for the slow component.
          Hide
          Brian C. Dilley
          added a comment -

          The other thing that is worth mentioning is that mongostat showed the queries completing in (or under) a second when they obviously did not.

          Show
          Brian C. Dilley
          added a comment - The other thing that is worth mentioning is that mongostat showed the queries completing in (or under) a second when they obviously did not.
          Hide
          Aaron Staple (Inactive)
          added a comment -

          It looks like mongostat just shows the number of new operations per second, rather than the duration of any particular operation. If you're interested in the time taken by a particular operation, you can use the http interface <http://www.mongodb.org/display/DOCS/Http+Interface> or look at the mongod log.

          Show
          Aaron Staple (Inactive)
          added a comment - It looks like mongostat just shows the number of new operations per second, rather than the duration of any particular operation. If you're interested in the time taken by a particular operation, you can use the http interface < http://www.mongodb.org/display/DOCS/Http+Interface > or look at the mongod log.
          Hide
          Aaron Staple (Inactive)
          added a comment -

          Already filed a jira for the slow $all queries

          Show
          Aaron Staple (Inactive)
          added a comment - Already filed a jira for the slow $all queries
          Hide
          Brian C. Dilley
          added a comment -

          Where is the jira for the slow $all queries?

          Show
          Brian C. Dilley
          added a comment - Where is the jira for the slow $all queries?
          Hide
          Ian Whalen
          added a comment -

          @brian that is ticket SERVER-1748

          Show
          Ian Whalen
          added a comment - @brian that is ticket SERVER-1748

            People

            • Votes:
              3 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                Days since reply:
                2 years, 3 days ago
                Date of 1st Reply: