[SERVER-9721] Performance regression in Windows build Created: 17/May/13  Updated: 11/Jul/16  Resolved: 22/May/13

Status: Closed
Project: Core Server
Component/s: Performance
Affects Version/s: 2.4.3
Fix Version/s: 2.4.4, 2.5.1

Type: Bug Priority: Critical - P2
Reporter: Tad Marshall Assignee: Eric Milkie
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows


Attachments: File getmore_performance.js    
Issue Links:
Depends
Related
related to SERVER-17181 Correctly invalidate RocksDB cursor w... Closed
related to SERVER-17186 remove noPassthroughWithMongod/getmor... Closed
Operating System: Windows
Participants:

 Description   

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.



 Comments   
Comment by Githook User [ 05/Feb/15 ]

Author:

{u'username': u'benety', u'name': u'Benety Goh', u'email': u'benety@mongodb.com'}

Message: SERVER-17186 removed getMore performance test

This test was originally introduced in SERVER-9721 to investigate a regression
in the Windows build.
Branch: master
https://github.com/mongodb/mongo/commit/5ed91cbddad7e9f1ee45220591257dc292432df8

Comment by auto [ 23/May/13 ]

Author:

{u'username': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-9721 Add performance test
Branch: master
https://github.com/mongodb/mongo/commit/454b52fc53c44b7b5be09ce51c140b501ef98a74

Comment by auto [ 22/May/13 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-9721 do not use sleepmicros on Windows for yielding
Branch: v2.4
https://github.com/mongodb/mongo/commit/80096f6d290ea0e9f065a9fbab6914269ef8d171

Comment by auto [ 22/May/13 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-9721 do not use sleepmicros on Windows for yielding
Branch: master
https://github.com/mongodb/mongo/commit/bb8d0b4b30dd45e4f46592e98ea770497a3f4bba

Comment by Tad Marshall [ 18/May/13 ]

The regression was introduced in commit d901ee1c28cb3c13fdfe7124b44e33f23aa82357 .

I verified that reverting this change restores performance to approximately that of version 2.2.4.

Running getmore_performance.js:

// ... snip ...
First pass took 36 ms, second pass took 15 ms, setting cutoff at 150 ms (factor of 10)
Performance test PASSED!

Comment by Tad Marshall [ 17/May/13 ]

First cut at jstest to test for performance regression.

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