[SERVER-9105] why cpp/c driver is much slower than java driver when mongodb server is cold? Created: 24/Mar/13  Updated: 10/Dec/14  Resolved: 03/Apr/13

Status: Closed
Project: Core Server
Component/s: Internal Client
Affects Version/s: 2.4.1
Fix Version/s: None

Type: Improvement Priority: Minor - P4
Reporter: kobevaliant Assignee: Andrew Morrow (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

windows xp x86


Participants:

 Description   

I need load all documents in a big collection(millions), but only two fields.
My application is build in java. I don't satisfied with the speed, so I tried cpp and c driver. the result is nice when server is warmed up. But I found when the server is just started, the cpp driver is far slower than java's, the c driver is worse.

btw: it's a covered query, but without hint it will be a basic cursor. What confused me is when I add a hint, it will be slower despite indexOnly is true. @.@

The benchmark(approximate):

lang cold warm
java 48s 6s
cpp 200s 2s
c 400s 3s

I wonder how this happens?
Can you explain it? How to improve it?
Thanks



 Comments   
Comment by kobevaliant [ 18/Apr/13 ]

I switch to a win7 x64 box, then the behavior is correct. So maybe it is a xp issue.
Thank you!

Comment by Andrew Morrow (Inactive) [ 07/Apr/13 ]

The Java code you have above isn't measuring the time to open a connection to the server or to start the query: only the time to iterate the cursor. Your C++ code is timing opening a new connection to the server, the time to issue the query, to construct a vector, etc. along with iterating the cursor. Please move the call to initialize 't' in the C++ code to an analogous location to where you measure in Java: immediately before the while loop.

Also, you should remove from both loops the printf in the loop being timed. Console IO can completely skew your results.

RE optimization: you shouldn't run your C++ benchmark without optimization. Java typically uses a JIT so it will optimize the hot parts of the code, so benchmarking against unoptimized C++ is not a meaningful comparison.

Finally I'd like to reiterate my earlier request that (after performing the above updates to your benchmark code) you run these benchmarks several times, ensuring a clean memory subsystem state for all 'cold' runs, re-ordering tests as necessary to ensure that you are not observing the effects of previous runs, and reporting the relevant descriptive statistics over the individual results.

Please note as well that MongoDB 2.4.1 is not supported on Windows XP.

Comment by kobevaliant [ 07/Apr/13 ]

There's no difference. I did so forbidding the compiler optimising

Comment by Tad Marshall [ 05/Apr/13 ]

Your cpp code is pushing one million 'long long's onto a vector but your Java code is doing nothing with the documents. How do the times compare if you make the cpp code do what the Java code is doing?

Comment by kobevaliant [ 05/Apr/13 ]

Hi
I got follow information when cpp client fetch data from cold mongodb:

> db.currentOp()
{
        "inprog" : [
                {
                        "opid" : 10,
                        "active" : true,
                        "secs_running" : 115,
                        "op" : "getmore",
                        "ns" : "test.test",
                        "query" : {
 
                        },
                        "client" : "127.0.0.1:17066",
                        "desc" : "conn1",
                        "connectionId" : 1,
                        "waitingForLock" : false,
                        "numYields" : 7381,
                        "lockStats" : {
                                "timeLockedMicros" : {
                                        "r" : NumberLong(1009869),
                                        "w" : NumberLong(0)
                                },
                                "timeAcquiringMicros" : {
                                        "r" : NumberLong(115256560),
                                        "w" : NumberLong(0)
                                }
                        }
                }
        ]
}
> db.stats()
{
        "db" : "test",
        "collections" : 3,
        "objects" : 1000004,
        "avgObjSize" : 143.99963200147198,
        "dataSize" : 144000208,
        "storageSize" : 185917440,
        "numExtents" : 13,
        "indexes" : 1,
        "indexSize" : 27921040,
        "fileSize" : 520093696,
        "nsSizeMB" : 16,
        "dataFileVersion" : {
                "major" : 4,
                "minor" : 5
        },
        "ok" : 1
}

something from web console
top:

{ "host" : "20110924-1019",
  "version" : "2.4.1",
  "process" : "E:\\mongodb-win32-i386-2.4.1\\bin\\mongod",
  "pid" : 2304,
  "uptime" : 156,
  "uptimeMillis" : 156187,
  "uptimeEstimate" : 100,
  "localTime" : { "$date" : "Fri Apr 05 17:07:36 2013" },
  "asserts" : { "regular" : 0,
    "warning" : 0,
    "msg" : 0,
    "user" : 0,
    "rollovers" : 0 },
  "backgroundFlushing" : { "flushes" : 2,
    "total_ms" : 374,
    "average_ms" : 187,
    "last_ms" : 78,
    "last_finished" : { "$date" : "Fri Apr 05 17:07:00 2013" } },
  "connections" : { "current" : 1,
    "available" : 19999,
    "totalCreated" : 164 },
  "cursors" : { "totalOpen" : 1,
    "clientCursors_size" : 1,
    "timedOut" : 0,
    "pinned" : 1 },
  "extra_info" : { "note" : "fields vary by platform",
    "page_faults" : 18797,
    "usagePageFileMB" : 41,
    "totalPageFileMB" : 3934,
    "availPageFileMB" : 2627,
    "ramMB" : 2042 },
  "globalLock" : { "totalTime" : 156187000,
    "lockTime" : 36845,
    "currentQueue" : { "total" : 0,
      "readers" : 0,
      "writers" : 0 },
    "activeClients" : { "total" : 0,
      "readers" : 0,
      "writers" : 0 } },
  "indexCounters" : { "note" : "not supported on this platform" },
  "locks" : { "." : { "timeLockedMicros" : { "R" : 102,
        "W" : 36845 },
      "timeAcquiringMicros" : { "R" : 59,
        "W" : 29 } },
    "admin" : { "timeLockedMicros" : {},
      "timeAcquiringMicros" : {} },
    "local" : { "timeLockedMicros" : { "r" : 2528,
        "w" : 0 },
      "timeAcquiringMicros" : { "r" : 559,
        "w" : 0 } },
    "test" : { "timeLockedMicros" : { "r" : 1401275,
        "w" : 0 },
      "timeAcquiringMicros" : { "r" : 120246410,
        "w" : 0 } } },
  "network" : { "bytesIn" : 98,
    "bytesOut" : 4196572,
    "numRequests" : 2 },
  "opcounters" : { "insert" : 1,
    "query" : 5,
    "update" : 0,
    "delete" : 0,
    "getmore" : 2,
    "command" : 1 },
  "opcountersRepl" : { "insert" : 0,
    "query" : 0,
    "update" : 0,
    "delete" : 0,
    "getmore" : 0,
    "command" : 0 },
  "recordStats" : { "accessesNotInMemory" : 12,
    "pageFaultExceptionsThrown" : 0,
    "local" : { "accessesNotInMemory" : 3,
      "pageFaultExceptionsThrown" : 0 },
    "test" : { "accessesNotInMemory" : 6,
      "pageFaultExceptionsThrown" : 0 } },
  "writeBacksQueued" : false,
  "mem" : { "bits" : 32,
    "resident" : 65,
    "virtual" : 376,
    "supported" : true,
    "mapped" : 288 },
  "metrics" : { "document" : { "deleted" : 0,
      "inserted" : 1,
      "returned" : 190750,
      "updated" : 0 },
    "getLastError" : { "wtime" : { "num" : 0,
        "totalMillis" : 0 },
      "wtimeouts" : 0 },
    "operation" : { "fastmod" : 0,
      "idhack" : 0,
      "scanAndOrder" : 0 },
    "queryExecutor" : { "scanned" : 104 },
    "record" : { "moves" : 0 },
    "repl" : { "apply" : { "batches" : { "num" : 0,
          "totalMillis" : 0 },
        "ops" : 0 },
      "buffer" : { "count" : 0,
        "maxSizeBytes" : 268435456,
        "sizeBytes" : 0 },
      "network" : { "bytes" : 0,
        "getmores" : { "num" : 0,
          "totalMillis" : 0 },
        "ops" : 0,
        "readersCreated" : 0 },
      "oplog" : { "insert" : { "num" : 0,
          "totalMillis" : 0 },
        "insertBytes" : 0 },
      "preload" : { "docs" : { "num" : 0,
          "totalMillis" : 0 },
        "indexes" : { "num" : 0,
          "totalMillis" : 0 } } },
    "ttl" : { "deletedDocuments" : 0,
      "passes" : 2 } },
  "ok" : 1 }

serverStatus:

{ "host" : "20110924-1019",
  "version" : "2.4.1",
  "process" : "E:\\mongodb-win32-i386-2.4.1\\bin\\mongod",
  "pid" : 2304,
  "uptime" : 179,
  "uptimeMillis" : 178609,
  "uptimeEstimate" : 114,
  "localTime" : { "$date" : "Fri Apr 05 17:07:59 2013" },
  "asserts" : { "regular" : 0,
    "warning" : 0,
    "msg" : 0,
    "user" : 0,
    "rollovers" : 0 },
  "backgroundFlushing" : { "flushes" : 2,
    "total_ms" : 374,
    "average_ms" : 187,
    "last_ms" : 78,
    "last_finished" : { "$date" : "Fri Apr 05 17:07:00 2013" } },
  "connections" : { "current" : 1,
    "available" : 19999,
    "totalCreated" : 165 },
  "cursors" : { "totalOpen" : 1,
    "clientCursors_size" : 1,
    "timedOut" : 0,
    "pinned" : 1 },
  "extra_info" : { "note" : "fields vary by platform",
    "page_faults" : 20435,
    "usagePageFileMB" : 41,
    "totalPageFileMB" : 3934,
    "availPageFileMB" : 2627,
    "ramMB" : 2042 },
  "globalLock" : { "totalTime" : 178609000,
    "lockTime" : 36845,
    "currentQueue" : { "total" : 0,
      "readers" : 0,
      "writers" : 0 },
    "activeClients" : { "total" : 0,
      "readers" : 0,
      "writers" : 0 } },
  "indexCounters" : { "note" : "not supported on this platform" },
  "locks" : { "." : { "timeLockedMicros" : { "R" : 102,
        "W" : 36845 },
      "timeAcquiringMicros" : { "R" : 59,
        "W" : 29 } },
    "admin" : { "timeLockedMicros" : {},
      "timeAcquiringMicros" : {} },
    "local" : { "timeLockedMicros" : { "r" : 2546,
        "w" : 0 },
      "timeAcquiringMicros" : { "r" : 564,
        "w" : 0 } },
    "test" : { "timeLockedMicros" : { "r" : 1692983,
        "w" : 0 },
      "timeAcquiringMicros" : { "r" : 142650412,
        "w" : 0 } } },
  "network" : { "bytesIn" : 98,
    "bytesOut" : 4196572,
    "numRequests" : 2 },
  "opcounters" : { "insert" : 1,
    "query" : 5,
    "update" : 0,
    "delete" : 0,
    "getmore" : 2,
    "command" : 1 },
  "opcountersRepl" : { "insert" : 0,
    "query" : 0,
    "update" : 0,
    "delete" : 0,
    "getmore" : 0,
    "command" : 0 },
  "recordStats" : { "accessesNotInMemory" : 12,
    "pageFaultExceptionsThrown" : 0,
    "local" : { "accessesNotInMemory" : 3,
      "pageFaultExceptionsThrown" : 0 },
    "test" : { "accessesNotInMemory" : 6,
      "pageFaultExceptionsThrown" : 0 } },
  "writeBacksQueued" : false,
  "mem" : { "bits" : 32,
    "resident" : 72,
    "virtual" : 376,
    "supported" : true,
    "mapped" : 288 },
  "metrics" : { "document" : { "deleted" : 0,
      "inserted" : 1,
      "returned" : 190750,
      "updated" : 0 },
    "getLastError" : { "wtime" : { "num" : 0,
        "totalMillis" : 0 },
      "wtimeouts" : 0 },
    "operation" : { "fastmod" : 0,
      "idhack" : 0,
      "scanAndOrder" : 0 },
    "queryExecutor" : { "scanned" : 104 },
    "record" : { "moves" : 0 },
    "repl" : { "apply" : { "batches" : { "num" : 0,
          "totalMillis" : 0 },
        "ops" : 0 },
      "buffer" : { "count" : 0,
        "maxSizeBytes" : 268435456,
        "sizeBytes" : 0 },
      "network" : { "bytes" : 0,
        "getmores" : { "num" : 0,
          "totalMillis" : 0 },
        "ops" : 0,
        "readersCreated" : 0 },
      "oplog" : { "insert" : { "num" : 0,
          "totalMillis" : 0 },
        "insertBytes" : 0 },
      "preload" : { "docs" : { "num" : 0,
          "totalMillis" : 0 },
        "indexes" : { "num" : 0,
          "totalMillis" : 0 } } },
    "ttl" : { "deletedDocuments" : 0,
      "passes" : 2 } },
  "ok" : 1 }

I think the cold/warm situation should be same to client, so I didn't reboot computer or clear fs cache. I just restart mongodb.

The result of test I just runned tell java 82 sec, cpp 610 sec.

-------------------------------------------
The test code:
java:

        DBCollection c = new Mongo().getDB("test").getCollection("test");
        /*init
        BasicDBObject obj = new BasicDBObject("data", new byte[100]);
        for (int i = 0; i < 1000000; i++) {
            obj.append("_id", i).append("_v", i);
            c.insert(obj);
            if (i % 10000 == 0) System.out.println(i);
        }
        */
        DBCursor cursor = c.find(null, new BasicDBObject("_v", 1));
        int i = 0;
        long t = System.currentTimeMillis();
        while (cursor.hasNext()) {
            DBObject doc = cursor.next();
            if (i++ % 10000 == 0) System.out.println(i);
        }
        System.out.println(System.currentTimeMillis() - t);

cpp:

        const char *nsname = "test.test";
 
	int t = GetTickCount();
 
	DBClientConnection c;
	c.connect("localhost");
 
	BSONObjBuilder b;
	b.append("_v", 1);
	BSONObj keys = b.obj();
	Query q;
	auto_ptr<DBClientCursor> cursor = c.query(nsname, q, 0, 0, &keys);
	int i = 0;
	vector<long long> v;
	while(cursor->more())
	{
		BSONObj doc = cursor->next();
		long long id = doc.firstElement()._numberLong();
		v.push_back(id);
		if(i++%10000==0) printf("%d\n", i);
	}
	printf("t:%d\n", GetTickCount() - t);
 
	system("pause");

Comment by Andrew Morrow (Inactive) [ 01/Apr/13 ]

Hi -

It is difficult to tell from the information you have provided what is causing the behavior you have observed. Can you please provide the mongostat/top information that was requested earlier? Also, please keep in mind the following:

  • If possible, please re-run each lang/state experiment several times and report min/max/avg.
  • If possible, please run the experiments in different orders each time.
  • If possible on XP, drop the FS cache before each 'cold' run to ensure that the data really isn't still in the buffer cache. Alternatively, reboot the machine before each cold run.

Also, please note that MongoDB 2.4 is not supported on Windows XP.

Comment by Eliot Horowitz (Inactive) [ 24/Mar/13 ]

are you sure the language is what's causing the difference?
can you send mongostat/top info?

Comment by kobevaliant [ 24/Mar/13 ]

document schema:

{_id:int64, _v:int, data...}

db.c.ensureIndex({_id:1,_v:1})
db.c.find({},{_id:1,_v:1});

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