Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-9721

Performance regression in Windows build

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Critical - P2 Critical - P2
    • 2.4.4, 2.5.1
    • Affects Version/s: 2.4.3
    • Component/s: Performance
    • Labels:
      None
    • Environment:
      Windows
    • Windows

      Performance of the Windows version in a simple getmore loop is much worse in version 2.4.3 than in version 2.2.4.

      Here are some JavaScript functions that I used for this testing:

      var makeData = function(howMany) {
    howMany = howMany || 2000;
    var arr = [];
    var i;
    for (i = 0; i < 10000; ++i) {
        arr.push(i);
    }
    for (i = 0; i < howMany; ++i) {
        db.RawTrade.insert({arr: arr});
    }
}

var time = function (f) {
    var start = new ISODate();
    f();
    var end = new ISODate();
    print("Took " + (end - start) + " milliseconds");
}

var func = function() {
    var c = db.RawTrade.find({}, {_id: 1});
    while (c.hasNext()) {
        var d = c.next();
    }
}

var func2 = function() {
    var c = db.RawTrade.find({}, {_id: 1}).hint({_id: 1});
    while (c.hasNext()) {
        var d = c.next();
    }
}

      The created collection's documents contain just an _id (ObjectID) and an array. The purpose of the array is to bulk up the documents and slow down the scanning code. These are the statistics on the test collection:

      > db.RawTrade.stats()
{
        "ns" : "Gems.RawTrade",
        "count" : 2000,
        "size" : 294879824,
        "avgObjSize" : 147439.912,
        "storageSize" : 355581952,
        "numExtents" : 10,
        "nindexes" : 1,
        "lastExtentSize" : 98213888,
        "paddingFactor" : 1,
        "systemFlags" : 1,
        "userFlags" : 0,
        "totalIndexSize" : 73584,
        "indexSizes" : {
                "_id_" : 73584
        },
        "ok" : 1
}

      The "First pass" and "Second pass" columns are from running "time(func)" twice against a single run of the server. "First hinted" and "Second hinted" are the same thing using "time(func2)". In all tests, I restarted the server between the "func" and "func2" tests and I used the current 2.5.0-pre- version of the mongo shell for all tests, leaving it running between tests, to reduce the number of variables. The data file was generated once per platform and then reused for later tests. The disk is a Samsung 840 Pro SSD, which is quite fast. The only thing that changed from one test to the next was what version of mongod was running.

      Here are the results:

      Platform Version First pass Second pass First hinted Second hinted
      Windows 2.5.0-pre- 1909 15 17 17
      Windows 2.4.3 1923 16 16 18
      Windows 2.2.4 32 15 20 16
      Windows 2.0.9 21 14 18 16
      Linux 2.5.0-pre- 17 12 13 12
      Linux 2.4.3 16 16 14 14
      Linux 2.2.4 19 15 16 11
      Linux 2.0.9 18 12 34 11

      The change in timing between version 2.2.4 and version 2.5.0-pre- is not due to a change in the number of yields, so something else is going on.

      2.5.0-pre-:

      Fri May 17 10:44:30.450 [conn1] getmore Gems.RawTrade cursorid:2185026643454168 ntoreturn:0 keyUpdates:0 numYields: 1877 locks(micros) r:48590 nreturned:1899 reslen:41798 1878ms

      2.2.4:

      Fri May 17 10:46:01 [conn1] getmore Gems.RawTrade cursorid:132721786774769 ntoreturn:0 keyUpdates:0 numYields: 1884 locks(micros) r:4287 nreturned:1899 reslen:41798 8ms

      With very similar numbers of yields (1877 vs. 1884), version 2.5.0-pre- took 1878 milliseconds while version 2.2.4 took 8 milliseconds.

        1. getmore_performance.js
          2 kB
          Tad Marshall

            Assignee:
            milkie@mongodb.com Eric Milkie
            Reporter:
            tad Tad Marshall
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: