jstests/profile4.js fails on fast machine in Windows 64-bit

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Done
    • Priority: Major - P3
    • 2.4.0-rc2
    • Affects Version/s: 2.4.0-rc0
    • Component/s: None
    • None
    • Environment:
      Tested locally with SpiderMonkey and V8 builds
    • Windows
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      The test wants to see lockStats.timeAcquiringMicros.r greater than zero, but it is always zero on my machine.

      Test modified to print lastOp() just before asserts that fail:

      cwd [G:\Visual Studio 2010 Projects\mongodev]
      removing: /data/db/sconsTests/journal/j._0
      removing: /data/db/sconsTests/_tmp/1359107656205515
      removing: /data/db/sconsTests//local.0
      removing: /data/db/sconsTests//local.ns
      removing: /data/db/sconsTests//mongod.lock
      removing: /data/db/sconsTests//profile4.0
      removing: /data/db/sconsTests//profile4.ns
      Fri Jan 25 05:16:02.361 [initandlisten] MongoDB starting : pid=7680 port=27999 dbpath=/data/db/sconsTests 64-bit host=MissLucy
      Fri Jan 25 05:16:02.361 [initandlisten] 
      Fri Jan 25 05:16:02.361 [initandlisten] ** NOTE: This is a development version (2.3.3-pre-) of MongoDB.
      Fri Jan 25 05:16:02.361 [initandlisten] **       Not recommended for production.
      Fri Jan 25 05:16:02.361 [initandlisten] 
      Fri Jan 25 05:16:02.361 [initandlisten] db version v2.3.3-pre-, pdfile version 4.5
      Fri Jan 25 05:16:02.361 [initandlisten] git version: 62d05a0803d7d3246f0be3f9d2549c9db22de771
      Fri Jan 25 05:16:02.361 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
      Fri Jan 25 05:16:02.361 [initandlisten] allocator: system
      Fri Jan 25 05:16:02.361 [initandlisten] options: { dbpath: "/data/db/sconsTests/", port: 27999, setParameter: [ "enableTestCommands=1" ] }
      Fri Jan 25 05:16:02.362 [initandlisten] journal dir=/data/db/sconsTests\journal
      Fri Jan 25 05:16:02.362 [initandlisten] recover : no journal files present, no recovery needed
      Fri Jan 25 05:16:02.368 [FileAllocator] allocating new datafile /data/db/sconsTests\local.ns, filling with zeroes...
      Fri Jan 25 05:16:02.368 [FileAllocator] creating directory /data/db/sconsTests\_tmp
      Fri Jan 25 05:16:02.398 [FileAllocator] done allocating datafile /data/db/sconsTests\local.ns, size: 16MB,  took 0.029 secs
      Fri Jan 25 05:16:02.398 [FileAllocator] allocating new datafile /data/db/sconsTests\local.0, filling with zeroes...
      Fri Jan 25 05:16:02.515 [FileAllocator] done allocating datafile /data/db/sconsTests\local.0, size: 64MB,  took 0.117 secs
      Fri Jan 25 05:16:02.516 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0  reslen:37 147ms
      Fri Jan 25 05:16:02.516 [initandlisten] waiting for connections on port 27999
      Fri Jan 25 05:16:02.516 [websvr] admin web console waiting for connections on port 28999
      running G:\Visual Studio 2010 Projects\mongodev\mongod.exe --port 27999 --dbpath /data/db/sconsTests/ --setParameter enableTestCommands=1
       *******************************************
               Test : profile4.js ...
      Fri Jan 25 05:16:03.097 [initandlisten] connection accepted from 127.0.0.1:65206 #1 (1 connection now open)
            Command : G:\Visual Studio 2010 Projects\mongodev\mongo.exe --port 27999 --authenticationMechanism MONGO-CR G:\Visual Studio 2010 Projects\mongodev\jstests\profile4.js --eval TestData = new Object();TestData.testPath = "G:\\Visual Studio 2010 Projects\\mongodev\\jstests\\profile4.js";TestData.testFile = "profile4.js";TestData.testName = "profile4";TestData.noJournal = false;TestData.noJournalPrealloc = false;TestData.auth = false;TestData.keyFile = null;TestData.keyFileData = null;
               Date : Fri Jan 25 05:16:03 2013
      Fri Jan 25 05:16:03.097 [conn1] end connection 127.0.0.1:65206 (0 connections now open)
      MongoDB shell version: 2.3.3-pre-
      connecting to: 127.0.0.1:27999/test
      Fri Jan 25 05:16:03.313 [initandlisten] connection accepted from 127.0.0.1:65207 #2 (1 connection now open)
      null
      Fri Jan 25 05:16:03.315 [conn2] CMD: drop profile4.profile4
      Fri Jan 25 05:16:03.316 [FileAllocator] allocating new datafile /data/db/sconsTests\profile4.ns, filling with zeroes...
      {
      	"user" : "jstests_profile4_user",
      	"readOnly" : false,
      	"pwd" : "b2f822e50e64926f59d0e7c13fe1c979",
      	"_id" : ObjectId("51025b63a141579f69676a84")
      }
      Fri Jan 25 05:16:03.346 [FileAllocator] done allocating datafile /data/db/sconsTests\profile4.ns, size: 16MB,  took 0.029 secs
      Fri Jan 25 05:16:03.346 [FileAllocator] allocating new datafile /data/db/sconsTests\profile4.0, filling with zeroes...
      Fri Jan 25 05:16:03.464 [FileAllocator] done allocating datafile /data/db/sconsTests\profile4.0, size: 64MB,  took 0.117 secs
      Fri Jan 25 05:16:03.464 [FileAllocator] allocating new datafile /data/db/sconsTests\profile4.1, filling with zeroes...
      Fri Jan 25 05:16:03.464 [conn2] build index profile4.system.users { _id: 1 }
      Fri Jan 25 05:16:03.465 [conn2] build index done.  scanned 0 total records. 0 secs
      Fri Jan 25 05:16:03.465 [conn2] build index profile4.system.users { user: 1, userSource: 1 }
      Fri Jan 25 05:16:03.465 [conn2] build index done.  scanned 0 total records. 0 secs
      Fri Jan 25 05:16:03.465 [conn2] insert profile4.system.users ninserted:1 keyUpdates:0 locks(micros) w:149487 149ms
      Fri Jan 25 05:16:03.466 [conn2]  authenticate db: profile4 { authenticate: 1, nonce: "5c4b81f6d3e56d8e", user: "jstests_profile4_user", key: "cf020d1eb033b4e5fce15e733e0a056f" }
      Fri Jan 25 05:16:03.467 [conn2] CMD: drop profile4.system.profile
      Fri Jan 25 05:16:03.467 [conn2] creating profile collection: profile4.system.profile
      Fri Jan 25 05:16:03.468 [conn2] build index profile4.profile4 { _id: 1 }
      Fri Jan 25 05:16:03.469 [conn2] build index done.  scanned 0 total records. 0 secs
      lastOp() = {
      	"op" : "query",
      	"ns" : "profile4.system.profile",
      	"query" : {
      		"query" : {
      			"user" : "jstests_profile4_user@profile4"
      		},
      		"orderby" : {
      			"$natural" : -1
      		}
      	},
      	"ntoreturn" : 0,
      	"ntoskip" : 0,
      	"nscanned" : 3,
      	"keyUpdates" : 0,
      	"numYield" : 0,
      	"lockStats" : {
      		"timeLockedMicros" : {
      			"r" : NumberLong(32),
      			"w" : NumberLong(0)
      		},
      		"timeAcquiringMicros" : {
      			"r" : NumberLong(0),
      			"w" : NumberLong(1)
      		}
      	},
      	"nreturned" : 3,
      	"responseLength" : 1336,
      	"millis" : 0,
      	"ts" : ISODate("2013-01-25T10:16:03.469Z"),
      	"client" : "127.0.0.1",
      	"allUsers" : [
      		{
      			"user" : "jstests_profile4_user",
      			"userSource" : "profile4"
      		}
      	],
      	"user" : "jstests_profile4_user@profile4"
      }
      assert: 0 is not less than 0 : undefined
      Error: Printing Stack Trace
          at printStackTrace (src/mongo/shell/utils.js:37:7)
          at doassert (src/mongo/shell/assert.js:6:1)
          at Function.assert.lt (src/mongo/shell/assert.js:179:1)
          at G:\Visual Studio 2010 Projects\mongodev\jstests\profile4.js:68:12
      Fri Jan 25 05:16:03.473 javascript execution failed src/mongo/shell/assert.js:7 0 is not less than 0 : undefined
      throw msg;
            ^
      
      failed to load: G:\Visual Studio 2010 Projects\mongodev\jstests\profile4.js
      Fri Jan 25 05:16:03.474 [conn2] end connection 127.0.0.1:65207 (0 connections now open)
                        378.0000 ms
      test G:\Visual Studio 2010 Projects\mongodev\jstests\profile4.js exited with status -3
      0 tests succeeded
      The following tests failed (with exit code):
      G:\Visual Studio 2010 Projects\mongodev\jstests\profile4.js	-3
      

      Marking as affecting 2.4.0-rc0 although that hasn't been pushed yet, and marking as fix-by 2.4.0-rc1 for triage.

            Assignee:
            Tad Marshall
            Reporter:
            Tad Marshall
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: