[SERVER-8728] jstests/profile1.js is a race and fails randomly Created: 26/Feb/13  Updated: 26/Oct/15  Resolved: 19/May/15

Status: Closed
Project: Core Server
Component/s: Testing Infrastructure
Affects Version/s: 2.4.0-rc1
Fix Version/s: 3.0.8, 3.1.4

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

Recent failure on RHEL 64-bit


Issue Links:
Depends
Related
is related to SERVER-5373 sporadic failure in profile1.js test Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Sprint: RPL 4 06/05/15
Participants:
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:
3
3
4
4
 
 
sleep 20 times actual:
24
24
24
24
 
 
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
121
 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
121
 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
124
123
 
 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.



 Comments   
Comment by Githook User [ 26/Oct/15 ]

Author:

{u'username': u'dannenberg', u'name': u'matt dannenberg', u'email': u'matt.dannenberg@10gen.com'}

Message: SERVER-8728 rewrite profile1.js removing its inherently racey portion
Branch: v3.0
https://github.com/mongodb/mongo/commit/79fce4a989cb787e5e28e25f476eae5875882107

Comment by Githook User [ 19/May/15 ]

Author:

{u'username': u'dannenberg', u'name': u'matt dannenberg', u'email': u'matt.dannenberg@10gen.com'}

Message: SERVER-8728 rewrite profile1.js removing its inherently racey portion
Branch: master
https://github.com/mongodb/mongo/commit/2bd10ab22e77234c04b0ac42fe5cbc7539423985

Comment by Tad Marshall [ 05/Jun/13 ]

Unassigning, marking 'Needs triage'.

Comment by Tad Marshall [ 04/Apr/13 ]

Failed again, this time on FreeBSD:
http://buildbot.mongodb.org/builders/FreeBSD%2064-bit/builds/1119/steps/test_8/logs/stdio
http://buildlogs.mongodb.org/FreeBSD%2064-bit/builds/1119/test/js/profile1.js

sleep 2 time actual:
12
29
19
19
 
 
sleep 20 times actual:
39
39
29
29
 
 
sleep 120 times actual:
Thu Apr  4 19:19:32.732 [conn30] dbeval slow, time: 139ms profile1
Thu Apr  4 19:19:32.733 [conn30] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:139919 reslen:53 139ms
139
Thu Apr  4 19:19:32.893 [conn30] dbeval slow, time: 121ms profile1
Thu Apr  4 19:19:32.893 [conn30] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:155445 reslen:53 155ms
121
Thu Apr  4 19:19:33.022 [conn30] dbeval slow, time: 124ms profile1
Thu Apr  4 19:19:33.022 [conn30] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:124148 reslen:53 124ms
124
Thu Apr  4 19:19:33.152 [conn30] dbeval slow, time: 129ms profile1
Thu Apr  4 19:19:33.152 [conn30] command profile1.$cmd command: { $eval: "var x = new Date(); sleep(120); return new Date() - x;" } ntoreturn:1 keyUpdates:0 locks(micros) W:129282 reslen:53 129ms
129
 
Thu Apr  4 19:19:33.159 [conn30] CMD: drop profile1.system.profile
Thu Apr  4 19:19:33.160 [conn30] creating profile collection: profile1.system.profile
warning wanted to sleep for: 15 but took: 33
Thu Apr  4 19:19:33.332 [conn30] dbeval slow, time: 138ms profile1
Thu Apr  4 19:19:33.333 [conn30] command profile1.$cmd command: { $eval: "sleep(120)" } ntoreturn:1 keyUpdates:0 locks(micros) W:139056 reslen:45 139ms
warning wanted to sleep for: 120 but took: 144
Thu Apr  4 19:19:33.342 [conn30] CMD: drop profile1.system.profile
Thu Apr  4 19:19:33.342 [conn30] creating profile collection: profile1.system.profile
warning wanted to sleep for: 5 but took: 20
Thu Apr  4 19:19:33.492 [conn30] dbeval slow, time: 129ms profile1
warning wanted to sleep for: 120 but took: 134
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(129545)
		},
		"timeAcquiringMicros" : {
			"R" : NumberLong(0),
			"W" : NumberLong(5),
			"r" : NumberLong(0),
			"w" : NumberLong(9)
		}
	},
	"responseLength" : 45,
	"millis" : 129,
	"ts" : ISODate("2013-04-04T19:19:33.493Z"),
	"client" : "127.0.0.1",
	"allUsers" : [
		{
			"user" : "jstests_profile1_user",
			"userSource" : "profile1"
		}
	],
	"user" : "jstests_profile1_user@profile1"
} ,
 
Error: Printing Stack Trace
    at printStackTrace (src/mongo/shell/utils.js:37:15)
    at doassert (src/mongo/shell/assert.js:6:5)
    at Function.assert.eq (src/mongo/shell/assert.js:32:5)
    at /data/buildslaves/FreeBSD_64bit/mongo/jstests/profile1.js:136:12
Thu Apr  4 19:19:33.503 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(129545)
		},
		"timeAcquiringMicros" : {
			"R" : NumberLong(0),
			"W" : NumberLong(5),
			"r" : NumberLong(0),
			"w" : NumberLong(9)
		}
	},
	"responseLength" : 45,
	"millis" : 129,
	"ts" : ISODate("2013-04-04T19:19:33.493Z"),
	"client" : "127.0.0.1",
	"allUsers" : [
		{
			"user" : "jstests_profile1_user",
			"userSource" : "profile1"
		}
	],
	"user" : "jstests_profile1_user@profile1"
} ,
 at src/mongo/shell/assert.js:L7
failed to load: /data/buildslaves/FreeBSD_64bit/mongo/jstests/profile1.js

Comment by Tad Marshall [ 26/Feb/13 ]

This is the "fix" comment I added on SERVER-5373:

Tad Marshall added a comment - Aug 08 2012 10:58:22 PM EDT
Disable jstests/profile1.js on Windows. Call it "fixed" until it happens on another platform, at which point we may need to drop this test entirely.

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