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

benchRun updates are far slower than expected

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 2.6.0
    • Affects Version/s: None
    • Component/s: Performance
    • 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.

            Assignee:
            davide.italiano Davide Italiano
            Reporter:
            andrew.emil@10gen.com Andrew Emil (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: