[SERVER-8331] jstests/profile4.js fails on fast machine in Windows 64-bit Created: 25/Jan/13  Updated: 11/Jul/16  Resolved: 26/Feb/13

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 2.4.0-rc0
Fix Version/s: 2.4.0-rc2

Type: Bug Priority: Major - P3
Reporter: Tad Marshall Assignee: Tad Marshall
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Tested locally with SpiderMonkey and V8 builds


Issue Links:
Tested
Operating System: Windows
Participants:

 Description   

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.



 Comments   
Comment by Githook User [ 09/Jun/14 ]

Author:

{u'username': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: SERVER-8331: fix lock reporting on fast ops
Branch: master
https://github.com/mongodb/mongo/commit/45e33c698933239d7f83a5f7fd0b21e140ac37ec

Comment by auto [ 26/Feb/13 ]

Author:

{u'date': u'2013-02-26T09:14:21Z', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-8331 Remove checks that assume lock acquisition takes at least 1 microsecond

On a fast machine in Windows, a lock can be acquired in 919 nanoseconds (which is
truncated to 0 microseconds by the Timer code) so we can't check these times against
zero. Also, put checks in the same order in similar sections ("r" before "w").
Branch: master
https://github.com/mongodb/mongo/commit/5bbdfa31eba4680f8aee37300db852706b9289cb

Comment by Tad Marshall [ 26/Feb/13 ]

I modified the code to report nanoseconds instead of microseconds and retested on my home machine (3.3 GHz Intel Core i7 980X) in Windows 7.

Here are the results of three runs:

Total times in nanoseconds:
        "timeAcquiringMicros" : {
                "r" : NumberLong(1225),
                "w" : NumberLong(919)
        }
        "timeAcquiringMicros" : {
                "r" : NumberLong(919),
                "w" : NumberLong(1225)
        }
        "timeAcquiringMicros" : {
                "r" : NumberLong(919),
                "w" : NumberLong(1225)
        }

In another modification I added 1 for each call to Lock::ScopedLock::acquireFinished() to see how many times each lock was acquired:

        "timeAcquiringMicros" : {
                "r" : NumberLong(1),
                "w" : NumberLong(1)
        }

So, it seems clear that on a fast machine you can't count on a truncating conversion of measured time to microseconds to produce results greater than zero. Unless we increase the resolution of the timing, all of the checks for "time greater than zero" have to be removed.

Comment by Tad Marshall [ 22/Feb/13 ]

Testing on non-virtualized hardware (Intel Core i7 860 at 2.8 GHz on Samsung 840 Pro SSD) I compared Windows 64-bit release build on Windows 7 with Linux 64-bit release build in Ubuntu 12.04. Windows shows 0 for lockStats.timeAcquiringMicros.r while Linux shows 1. Either this is a bug/feature of time accounting between the platforms or Windows is faster. I will look at the accounting code to see if there is a difference that could account for this.

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