[SERVER-8728] jstests/profile1.js is a race and fails randomly - MongoDB Jira

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Major - P3
Resolution: Done
Affects Version/s: 2.4.0-rc1
Fix Version/s: 3.0.8, 3.1.4
Component/s: Testing Infrastructure
Labels:
None
Environment:
Recent failure on RHEL 64-bit

Backwards Compatibility:
Fully Compatible
Operating System:
ALL
Backport Completed:

3.0.8
Sprint:
RPL 4 06/05/15
Linked BF Score:
0

Description

This test has been failing off-and-on for a long time ... see ~~SERVER-5373~~ from March 2012.

The problem is that it is running a race between the client and the server. The operating assumption is that the client can time an event on the server and see durations that match in a predictable way. On a general purpose operating system like Linux, Mac OS/X or Windows, it is always possible for scheduling to introduce a delay on one side but not the other such that this assumption fails.

Here's one recent failure:
http://buildbot.mongodb.org/builders/Linux%20RHEL%2064-bit/builds/1079/steps/test_10/logs/stdio
http://buildlogs.mongodb.org/Linux%20RHEL%2064-bit/builds/1079/test/durability/dur_passthrough.js

 *******************************************

         Test : jstests/profile1.js ...

profile1.js BEGIN

	"user" : "jstests_profile1_user",

	"readOnly" : false,

	"pwd" : "2a6e511239a4e136518316c33d5473db",

	"_id" : ObjectId("512c06ad0fac5674fd477086")

 m30200| Mon Feb 25 19:49:49.493 [FileAllocator] allocating new datafile /data/db/dur_passthrough/profile1.ns, filling with zeroes...

 m30200| Mon Feb 25 19:49:49.522 [FileAllocator] done allocating datafile /data/db/dur_passthrough/profile1.ns, size: 16MB,  took 0.028 secs

 m30200| Mon Feb 25 19:49:49.522 [FileAllocator] allocating new datafile /data/db/dur_passthrough/profile1.0, filling with zeroes...

 m30200| Mon Feb 25 19:49:49.556 [FileAllocator] done allocating datafile /data/db/dur_passthrough/profile1.0, size: 16MB,  took 0.033 secs

 m30200| Mon Feb 25 19:49:49.558 [conn1] build index profile1.system.users { _id: 1 }

 m30200| Mon Feb 25 19:49:49.559 [conn1] build index done.  scanned 0 total records. 0 secs

 m30200| Mon Feb 25 19:49:49.559 [conn1] build index profile1.system.users { user: 1, userSource: 1 }

 m30200| Mon Feb 25 19:49:49.560 [conn1] build index done.  scanned 0 total records. 0 secs

 m30200| Mon Feb 25 19:49:49.561 [FileAllocator] allocating new datafile /data/db/dur_passthrough/profile1.1, filling with zeroes...

 m30200| Mon Feb 25 19:49:49.586 [conn1]  authenticate db: profile1 { authenticate: 1, nonce: "df944c3145756283", user: "jstests_profile1_user", key: "1ce9e5f43468a73ee87f1b705b18cc31" }

 m30200| Mon Feb 25 19:49:49.588 [conn1] CMD: drop profile1.system.profile

 m30200| Mon Feb 25 19:49:49.623 [conn1] CMD: drop profile1.system.profile

 m30200| Mon Feb 25 19:49:49.624 [FileAllocator] done allocating datafile /data/db/dur_passthrough/profile1.1, size: 32MB,  took 0.062 secs

 m30200| Mon Feb 25 19:49:49.624 [conn1] CMD: drop profile1.system.profile

 m30200| Mon Feb 25 19:49:49.625 [conn1] profile1.system.profile exists but isn't capped

 m30200| Mon Feb 25 19:49:49.626 [conn1] CMD: drop profile1.system.profile

 m30200| Mon Feb 25 19:49:49.627 [conn1] creating profile collection: profile1.system.profile

 m30200| Mon Feb 25 19:49:49.662 [conn1] CMD: drop profile1.system.profile

 m30200| Mon Feb 25 19:49:49.663 [conn1] creating profile collection: profile1.system.profile

 m30200| Mon Feb 25 19:49:49.813 [conn1] dbeval slow, time: 123ms profile1

 m30200| Mon Feb 25 19:49:49.813 [conn1] command profile1.$cmd command: { $eval: "sleep(120)" } ntoreturn:1 keyUpdates:0 locks(micros) W:123663 reslen:45 123ms

sleep 2 time actual:

sleep 20 times actual:

sleep 120 times actual:

 m30200| Mon Feb 25 19:49:50.053 [conn1] dbeval slow, time: 120ms profile1

 m30200| Mon Feb 25 19:49:50.054 [conn1] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:121818 reslen:53 121ms

 m30200| Mon Feb 25 19:49:50.205 [conn1] dbeval slow, time: 121ms profile1

 m30200| Mon Feb 25 19:49:50.205 [conn1] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:150517 reslen:53 150ms

 m30200| Mon Feb 25 19:49:50.333 [conn1] dbeval slow, time: 124ms profile1

 m30200| Mon Feb 25 19:49:50.333 [conn1] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:124270 reslen:53 124ms

 m30200| Mon Feb 25 19:49:50.457 [conn1] dbeval slow, time: 123ms profile1

 m30200| Mon Feb 25 19:49:50.457 [conn1] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:123206 reslen:53 123ms

 m30200| Mon Feb 25 19:49:50.460 [conn1] CMD: drop profile1.system.profile

 m30200| Mon Feb 25 19:49:50.461 [conn1] creating profile collection: profile1.system.profile

 m30200| Mon Feb 25 19:49:50.605 [conn1] dbeval slow, time: 123ms profile1

 m30200| Mon Feb 25 19:49:50.605 [conn1] command profile1.$cmd command: { $eval: "sleep(120)" } ntoreturn:1 keyUpdates:0 locks(micros) W:123568 reslen:45 123ms

warning wanted to sleep for: 120 but took: 1556

 m30200| Mon Feb 25 19:49:52.040 [conn1] CMD: drop profile1.system.profile

 m30200| Mon Feb 25 19:49:52.042 [conn1] creating profile collection: profile1.system.profile

warning wanted to sleep for: 5 but took: 70

 m30200| Mon Feb 25 19:49:52.236 [conn1] dbeval slow, time: 123ms profile1

 m30200| Mon Feb 25 19:49:52.236 [conn1] command profile1.$cmd command: { $eval: "sleep(120)" } ntoreturn:1 keyUpdates:0 locks(micros) W:123599 reslen:45 123ms

assert: [2] != [1] are not equal : X3 :

	"op" : "command",

	"ns" : "profile1.$cmd",

	"command" : {

		"$eval" : "sleep(120)"

},

	"ntoreturn" : 1,

	"keyUpdates" : 0,

	"numYield" : 0,

	"lockStats" : {

		"timeLockedMicros" : {

			"R" : NumberLong(0),

			"W" : NumberLong(123599)

},

		"timeAcquiringMicros" : {

			"R" : NumberLong(0),

			"W" : NumberLong(2),

			"r" : NumberLong(0),

			"w" : NumberLong(6)

},

	"responseLength" : 45,

	"millis" : 123,

	"ts" : ISODate("2013-02-26T00:49:52.236Z"),

	"client" : "127.0.0.1",

	"allUsers" : [

			"user" : "super",

			"userSource" : "admin"

},

			"user" : "someone else",

			"userSource" : "connection_status"

},

			"user" : "jstests_evalb_user",

			"userSource" : "evalb"

},

			"user" : "jstests_profile1_user",

			"userSource" : "profile1"

],

	"user" : "jstests_profile1_user@profile1"

} ,

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.eq (src/mongo/shell/assert.js:32:1)

    at jstests/profile1.js:136:12

    at /data/buildslaves/Linux_RHEL_64bit/mongo/jstests/dur/dur_passthrough.js:35:68

    at Function.Date.timeFunc (src/mongo/shell/types.js:27:9)

    at /data/buildslaves/Linux_RHEL_64bit/mongo/jstests/dur/dur_passthrough.js:35:45

    at Array.forEach (native)

    at doTest (/data/buildslaves/Linux_RHEL_64bit/mongo/jstests/dur/dur_passthrough.js:18:11)

    at /data/buildslaves/Linux_RHEL_64bit/mongo/jstests/dur/dur_passthrough.js:51:9

Mon Feb 25 19:49:52.243 JavaScript execution failed: [2] != [1] are not equal : X3 :

	"op" : "command",

	"ns" : "profile1.$cmd",

	"command" : {

		"$eval" : "sleep(120)"

},

	"ntoreturn" : 1,

	"keyUpdates" : 0,

	"numYield" : 0,

	"lockStats" : {

		"timeLockedMicros" : {

			"R" : NumberLong(0),

			"W" : NumberLong(123599)

},

		"timeAcquiringMicros" : {

			"R" : NumberLong(0),

			"W" : NumberLong(2),

			"r" : NumberLong(0),

			"w" : NumberLong(6)

},

	"responseLength" : 45,

	"millis" : 123,

	"ts" : ISODate("2013-02-26T00:49:52.236Z"),

	"client" : "127.0.0.1",

	"allUsers" : [

			"user" : "super",

			"userSource" : "admin"

},

			"user" : "someone else",

			"userSource" : "connection_status"

},

			"user" : "jstests_evalb_user",

			"userSource" : "evalb"

},

			"user" : "jstests_profile1_user",

			"userSource" : "profile1"

],

	"user" : "jstests_profile1_user@profile1"

} ,

 at src/mongo/shell/assert.js:L7

Mon Feb 25 19:49:52.243 JavaScript execution failed: Error: error loading js file: jstests/profile1.js at /data/buildslaves/Linux_RHEL_64bit/mongo/jstests/dur/dur_passthrough.js:L35

failed to load: /data/buildslaves/Linux_RHEL_64bit/mongo/jstests/dur/dur_passthrough.js

Check out this line from the excerpt:

warning wanted to sleep for: 120 but took: 1556

It is not possible to make this test reliable if a sleep() can take 13 times as long as what we ask for.

Attachments

Issue Links

is related to

SERVER-5373 sporadic failure in profile1.js test

Closed

Activity

People

Assignee:: Matt Dannenberg

Reporter:: Tad Marshall

Participants:: Githook User, Matt Dannenberg, Tad Marshall

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: Feb 26 2013 10:33:12 AM UTC

Updated:: Oct 26 2015 02:07:00 PM UTC

Resolved:: May 19 2015 08:23:02 PM UTC