-
Type:
Bug
-
Resolution: Done
-
Priority:
Minor - P4
-
Affects Version/s: None
-
Component/s: Performance
-
Labels:None
-
ALL
Running a 4 second benchRun with a single update operation can take much more than 4 seconds. This does not appear to be the case for inserts or queries. It also seems to take longer if you keep doing benchRun updates in a row.
> db.test.drop() true > testTime function (benchDoc) { print(new Date()) res = benchRun(benchDoc) print(new Date()) printjson(res) } > insertDoc { "parallel" : 2, "seconds" : 4, "ops" : [ { "ns" : "test.test", "op" : "insert", "doc" : { "a" : { "#RAND_INT" : [ 0, 100 ] } } } ] } > testTime(insertDoc) Tue Nov 05 2013 11:35:35 GMT-0800 (PST) Tue Nov 05 2013 11:35:39 GMT-0800 (PST) { "note" : "values per second", "errCount" : NumberLong(0), "trapped" : "error: not implemented", "insertLatencyAverageMicros" : 12.742954533536105, "insert" : 23836.25, "query" : 0, "update" : 0, "delete" : 0, "getmore" : 0, "command" : 238.75 } > queryDoc { "parallel" : 2, "seconds" : 4, "ops" : [ { "ns" : "test.test", "op" : "find", "query" : { "a" : 1 } } ] } > testTime(queryDoc) Tue Nov 05 2013 11:35:49 GMT-0800 (PST) Tue Nov 05 2013 11:35:53 GMT-0800 (PST) { "note" : "values per second", "errCount" : NumberLong(0), "trapped" : "error: not implemented", "queryLatencyAverageMicros" : 41554.18134715026, "insert" : 0, "query" : 48.25, "update" : 0, "delete" : 0, "getmore" : 48.25, "command" : 0.75 } > updateDoc { "parallel" : 2, "seconds" : 4, "ops" : [ { "ns" : "test.test", "op" : "update", "query" : { "a" : 2 }, "update" : { "a" : 3 } } ] } > testTime(updateDoc) Tue Nov 05 2013 11:36:03 GMT-0800 (PST) Tue Nov 05 2013 11:36:11 GMT-0800 (PST) { "note" : "values per second", "errCount" : NumberLong(0), "trapped" : "error: not implemented", "updateLatencyAverageMicros" : 11.86, "insert" : 0, "query" : 0, "update" : 100, "delete" : 0, "getmore" : 0, "command" : 1.75 }
Example of it getting longer when you execute it a few times in a row.
> testTime(updateDoc)
Tue Nov 05 2013 11:31:42 GMT-0800 (PST)
Tue Nov 05 2013 11:31:46 GMT-0800 (PST)
{
"note" : "values per second",
"errCount" : NumberLong(0),
"trapped" : "error: not implemented",
"updateLatencyAverageMicros" : 10.525,
"insert" : 0,
"query" : 0,
"update" : 100,
"delete" : 0,
"getmore" : 0,
"command" : 1.75
}
> testTime(updateDoc)
Tue Nov 05 2013 11:31:51 GMT-0800 (PST)
Tue Nov 05 2013 11:32:02 GMT-0800 (PST)
{
"note" : "values per second",
"errCount" : NumberLong(0),
"trapped" : "error: not implemented",
"updateLatencyAverageMicros" : 11.86,
"insert" : 0,
"query" : 0,
"update" : 50,
"delete" : 0,
"getmore" : 0,
"command" : 1.25
}
> testTime(updateDoc)
Tue Nov 05 2013 11:32:05 GMT-0800 (PST)
Tue Nov 05 2013 11:32:20 GMT-0800 (PST)
{
"note" : "values per second",
"errCount" : NumberLong(0),
"trapped" : "error: not implemented",
"updateLatencyAverageMicros" : 12.33,
"insert" : 0,
"query" : 0,
"update" : 50,
"delete" : 0,
"getmore" : 0,
"command" : 1.25
}
> testTime(updateDoc)
Tue Nov 05 2013 11:32:24 GMT-0800 (PST)
Tue Nov 05 2013 11:32:43 GMT-0800 (PST)
{
"note" : "values per second",
"errCount" : NumberLong(0),
"trapped" : "error: not implemented",
"updateLatencyAverageMicros" : 11.94,
"insert" : 0,
"query" : 0.75,
"update" : 50,
"delete" : 0,
"getmore" : 0,
"command" : 1.25
}
> testTime(updateDoc)
Tue Nov 05 2013 11:32:46 GMT-0800 (PST)
Tue Nov 05 2013 11:33:08 GMT-0800 (PST)
{
"note" : "values per second",
"errCount" : NumberLong(0),
"trapped" : "error: not implemented",
"updateLatencyAverageMicros" : 11.785,
"insert" : 0,
"query" : 0,
"update" : 50,
"delete" : 0,
"getmore" : 0,
"command" : 1.25
}
> testTime(updateDoc)
Tue Nov 05 2013 11:33:12 GMT-0800 (PST)
Tue Nov 05 2013 11:33:36 GMT-0800 (PST)
{
"note" : "values per second",
"errCount" : NumberLong(0),
"trapped" : "error: not implemented",
"updateLatencyAverageMicros" : 12.255,
"insert" : 0,
"query" : 0.75,
"update" : 50,
"delete" : 0,
"getmore" : 0,
"command" : 1.25
}
> testTime(updateDoc)
Tue Nov 05 2013 11:33:40 GMT-0800 (PST)
Tue Nov 05 2013 11:34:04 GMT-0800 (PST)
{
"note" : "values per second",
"errCount" : NumberLong(0),
"trapped" : "error: not implemented",
"updateLatencyAverageMicros" : 12.05,
"insert" : 0,
"query" : 0,
"update" : 50,
"delete" : 0,
"getmore" : 0,
"command" : 1.25
}
Seems to flatten out at 24 in this case, though that was not the behavior I had seen before.
Has been tested on OSX and linux(fedora 19)
Just for context: this was discovered when running a script that runs a series of updates in a row, I was confused about why the script was taking so long time finish.
- related to
-
SERVER-15149 benchRun write concern, write command support
-
- Closed
-