Sun Jun 10 15:13:20 [initandlisten] MongoDB starting : pid=22063 port=27999 dbpath=/data/db/sconsTests/ 64-bit host=bs-linuxv8
|
Sun Jun 10 15:13:20 [initandlisten]
|
Sun Jun 10 15:13:20 [initandlisten] ** NOTE: This is a development version (2.1.2-pre-) of MongoDB.
|
Sun Jun 10 15:13:20 [initandlisten] ** Not recommended for production.
|
Sun Jun 10 15:13:20 [initandlisten]
|
Sun Jun 10 15:13:20 [initandlisten] db version v2.1.2-pre-, pdfile version 4.5
|
Sun Jun 10 15:13:20 [initandlisten] git version: edbdfe32ce35e47b2fd11f7ca413353017f138c1
|
Sun Jun 10 15:13:20 [initandlisten] build info: Linux bs-linuxv8 2.6.35.14-97.44.amzn1.x86_64 #1 SMP Mon Oct 24 16:03:08 UTC 2011 x86_64 BOOST_LIB_VERSION=1_49
|
Sun Jun 10 15:13:20 [initandlisten] options: { dbpath: "/data/db/sconsTests/", port: 27999 }
|
Sun Jun 10 15:13:21 [initandlisten] journal dir=/data/db/sconsTests/journal
|
Sun Jun 10 15:13:21 [initandlisten] recover : no journal files present, no recovery needed
|
[Errno 111] Connection refused
|
[Errno 111] Connection refused
|
[Errno 111] Connection refused
|
[Errno 111] Connection refused
|
Sun Jun 10 15:13:25 [initandlisten] preallocateIsFaster=true 74.92
|
Sun Jun 10 15:13:25 [initandlisten] preallocateIsFaster check took 4.216 secs
|
Sun Jun 10 15:13:25 [initandlisten] waiting for connections on port 27999
|
// ... snip ...
|
*******************************************
|
Test : query_yield2.js ...
|
Command : /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/mongo --port 27999 --nodb /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js --eval TestData = new Object();TestData.testPath = "/data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js";TestData.testFile = "query_yield2.js";TestData.testName = "query_yield2";TestData.noJournal = false;TestData.noJournalPrealloc = false;TestData.auth = false;TestData.keyFile = null;TestData.keyFileData = null;
|
Date : Sun Jun 10 16:07:20 2012
|
Sun Jun 10 16:07:20 [conn17] end connection 127.0.0.1:60383 (0 connections now open)
|
MongoDB shell version: 2.1.2-pre-
|
null
|
Sun Jun 10 16:07:21 shell: started program /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/mongod --port 30201 --dbpath /data/db/query_yield2 --smallfiles --nojournal
|
m30201| Sun Jun 10 16:07:21 [initandlisten] MongoDB starting : pid=23912 port=30201 dbpath=/data/db/query_yield2 64-bit host=bs-linuxv8
|
m30201| Sun Jun 10 16:07:21 [initandlisten]
|
m30201| Sun Jun 10 16:07:21 [initandlisten] ** NOTE: This is a development version (2.1.2-pre-) of MongoDB.
|
m30201| Sun Jun 10 16:07:21 [initandlisten] ** Not recommended for production.
|
m30201| Sun Jun 10 16:07:21 [initandlisten]
|
m30201| Sun Jun 10 16:07:21 [initandlisten] db version v2.1.2-pre-, pdfile version 4.5
|
m30201| Sun Jun 10 16:07:21 [initandlisten] git version: edbdfe32ce35e47b2fd11f7ca413353017f138c1
|
m30201| Sun Jun 10 16:07:21 [initandlisten] build info: Linux bs-linuxv8 2.6.35.14-97.44.amzn1.x86_64 #1 SMP Mon Oct 24 16:03:08 UTC 2011 x86_64 BOOST_LIB_VERSION=1_49
|
m30201| Sun Jun 10 16:07:21 [initandlisten] options: { dbpath: "/data/db/query_yield2", nojournal: true, port: 30201, smallfiles: true }
|
m30201| Sun Jun 10 16:07:21 [websvr] admin web console waiting for connections on port 31201
|
m30201| Sun Jun 10 16:07:21 [initandlisten] waiting for connections on port 30201
|
m30201| Sun Jun 10 16:07:21 [initandlisten] connection accepted from 127.0.0.1:38248 #1 (1 connection now open)
|
m30201| Sun Jun 10 16:07:21 [conn1] CMD: drop test.query_yield2
|
Shell ==== Creating test.query_yield2 collection ...
|
Shell ==== Adding documents until a time-wasting query takes over 2 seconds to complete
|
Shell ==== Adding document IDs from 0 to 199
|
m30201| Sun Jun 10 16:07:21 [FileAllocator] allocating new datafile /data/db/query_yield2/test.ns, filling with zeroes...
|
m30201| Sun Jun 10 16:07:21 [FileAllocator] creating directory /data/db/query_yield2/_tmp
|
m30201| Sun Jun 10 16:07:21 [FileAllocator] done allocating datafile /data/db/query_yield2/test.ns, size: 16MB, took 0.001 secs
|
Shell ==== Running warm-up query 1
|
m30201| Sun Jun 10 16:07:21 [FileAllocator] allocating new datafile /data/db/query_yield2/test.0, filling with zeroes...
|
m30201| Sun Jun 10 16:07:21 [FileAllocator] done allocating datafile /data/db/query_yield2/test.0, size: 16MB, took 0.001 secs
|
m30201| Sun Jun 10 16:07:21 [FileAllocator] allocating new datafile /data/db/query_yield2/test.1, filling with zeroes...
|
m30201| Sun Jun 10 16:07:21 [conn1] build index test.query_yield2 { _id: 1 }
|
m30201| Sun Jun 10 16:07:21 [conn1] build index done. scanned 0 total records. 0 secs
|
m30201| Sun Jun 10 16:07:21 [FileAllocator] done allocating datafile /data/db/query_yield2/test.1, size: 32MB, took 0.001 secs
|
Shell ==== Running warm-up query 2
|
Shell ==== Running timed query ...
|
Shell ==== Query across 200 documents took 17 ms
|
Shell ==== Did not reach 2000 ms, increasing fill point to 400 documents
|
Shell ==== Adding document IDs from 200 to 399
|
Shell ==== Running warm-up query 1
|
Shell ==== Running warm-up query 2
|
Shell ==== Running timed query ...
|
Shell ==== Query across 400 documents took 33 ms
|
Shell ==== Did not reach 2000 ms, increasing fill point to 800 documents
|
Shell ==== Adding document IDs from 400 to 799
|
Shell ==== Running warm-up query 1
|
Shell ==== Running warm-up query 2
|
Shell ==== Running timed query ...
|
Shell ==== Query across 800 documents took 68 ms
|
Shell ==== Did not reach 2000 ms, increasing fill point to 1600 documents
|
Shell ==== Adding document IDs from 800 to 1599
|
Shell ==== Running warm-up query 1
|
m30201| Sun Jun 10 16:07:21 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:1600 keyUpdates:0 nreturned:0 reslen:20 137ms
|
Shell ==== Running warm-up query 2
|
m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:1600 keyUpdates:0 nreturned:0 reslen:20 134ms
|
Shell ==== Running timed query ...
|
m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:1600 keyUpdates:0 nreturned:0 reslen:20 146ms
|
Shell ==== Query across 1600 documents took 147 ms
|
Shell ==== Did not reach 2000 ms, increasing fill point to 3200 documents
|
Shell ==== Adding document IDs from 1600 to 3199
|
Shell ==== Running warm-up query 1
|
m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:3200 keyUpdates:0 nreturned:0 reslen:20 273ms
|
Shell ==== Running warm-up query 2
|
m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:3200 keyUpdates:0 nreturned:0 reslen:20 274ms
|
Shell ==== Running timed query ...
|
m30201| Sun Jun 10 16:07:23 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:3200 keyUpdates:0 nreturned:0 reslen:20 281ms
|
Shell ==== Query across 3200 documents took 282 ms
|
Shell ==== Did not reach 2000 ms, increasing fill point to 6400 documents
|
Shell ==== Adding document IDs from 3200 to 6399
|
Shell ==== Running warm-up query 1
|
m30201| Sun Jun 10 16:07:23 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:6400 keyUpdates:0 nreturned:0 reslen:20 549ms
|
Shell ==== Running warm-up query 2
|
m30201| Sun Jun 10 16:07:24 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:6400 keyUpdates:0 nreturned:0 reslen:20 548ms
|
Shell ==== Running timed query ...
|
m30201| Sun Jun 10 16:07:24 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:6400 keyUpdates:0 nreturned:0 reslen:20 544ms
|
Shell ==== Query across 6400 documents took 545 ms
|
Shell ==== Did not reach 2000 ms, increasing fill point to 12800 documents
|
Shell ==== Adding document IDs from 6400 to 12799
|
Shell ==== Running warm-up query 1
|
m30201| Sun Jun 10 16:07:26 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:12800 keyUpdates:0 nreturned:0 reslen:20 1127ms
|
Shell ==== Running warm-up query 2
|
m30201| Sun Jun 10 16:07:27 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:12800 keyUpdates:0 nreturned:0 reslen:20 1055ms
|
Shell ==== Running timed query ...
|
m30201| Sun Jun 10 16:07:28 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:12800 keyUpdates:0 nreturned:0 reslen:20 1073ms
|
Shell ==== Query across 12800 documents took 1074 ms
|
Shell ==== Did not reach 2000 ms, increasing fill point to 25600 documents
|
Shell ==== Adding document IDs from 12800 to 25599
|
Shell ==== Running warm-up query 1
|
m30201| Sun Jun 10 16:07:30 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:25600 keyUpdates:0 nreturned:0 reslen:20 2201ms
|
Shell ==== Running warm-up query 2
|
m30201| Sun Jun 10 16:07:33 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:25600 keyUpdates:0 nreturned:0 reslen:20 2162ms
|
Shell ==== Running timed query ...
|
m30201| Sun Jun 10 16:07:35 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:25600 keyUpdates:0 nreturned:0 reslen:20 2267ms
|
Shell ==== Query across 25600 documents took 2268 ms
|
Shell ==== Reached desired 2000 ms mark (at 2268 ms), proceding to next step
|
Shell ==== Testing db.currentOp to make sure nothing is in progress
|
Shell ==== Dump of db.currentOp:
|
{ "inprog" : [ ] }
|
Shell ==== The test is working so far: db.currentOp().inprog.length is 0
|
Shell ==== Starting parallel shell to test if slow query will yield to write
|
Sun Jun 10 16:07:35 shell: started program /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/mongo --eval TestData = {
|
"testPath" : "/data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js",
|
"testFile" : "query_yield2.js",
|
"testName" : "query_yield2",
|
"noJournal" : false,
|
"noJournalPrealloc" : false,
|
"auth" : false,
|
"keyFile" : null,
|
"keyFileData" : null
|
};jsTest.authenticate(db.getMongo());print( 0 == db.query_yield2.find( function(){ var x=this.n; for ( var i=0; i<50000; i++ ){ x = x * 2; } return false; } ).itcount() ); 127.0.0.1:30201
|
Shell ==== Waiting until db.currentOp().inprog becomes non-empty
|
sh23926| MongoDB shell version: 2.1.2-pre-
|
m30201| Sun Jun 10 16:07:35 [initandlisten] connection accepted from 127.0.0.1:38249 #2 (2 connections now open)
|
Shell ==== Wait satisfied: db.currentOp().inprog.length is 1
|
Shell ==== Dump of db.currentOp:
|
{
|
"inprog" : [
|
{
|
"opid" : 25626,
|
"active" : false,
|
"waitingForLock" : false,
|
"op" : "query",
|
"ns" : "",
|
"query" : {
|
"whatsmyuri" : 1
|
},
|
"client" : "127.0.0.1:38249",
|
"desc" : "conn",
|
"threadId" : "0x7f03d46f9700",
|
"connectionId" : 2,
|
"numYields" : 0
|
}
|
]
|
}
|
Shell ==== Now that db.currentOp().inprog is non-empty, we start the real test
|
Shell ==== Starting loop 0, inserting 1 document
|
Shell ==== Time to insert document 0 was 1 ms, db.currentOp().inprog.length is 0
|
Shell ==== TEST FAILED! db.currentOp().inprog.length is 0
|
Shell ==== Dump of db.currentOp:
|
{ "inprog" : [ ] }
|
Sun Jun 10 16:07:35 exec error: /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js:99 TEST FAILED!
|
throw "TEST FAILED!";
|
^
|
|
failed to load: /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js
|
15484.485865ms
|
Sun Jun 10 16:07:36 got signal 15 (Terminated), will terminate after current cmd ends
|
Sun Jun 10 16:07:36 [interruptThread] now exiting
|
Sun Jun 10 16:07:36 dbexit:
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: going to close listening sockets...
|
Sun Jun 10 16:07:36 [interruptThread] closing listening socket: 6
|
Sun Jun 10 16:07:36 [interruptThread] closing listening socket: 7
|
Sun Jun 10 16:07:36 [interruptThread] closing listening socket: 8
|
Sun Jun 10 16:07:36 [interruptThread] removing socket file: /tmp/mongodb-27999.sock
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: going to flush diaglog...
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: going to close sockets...
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: waiting for fs preallocator...
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: lock for final commit...
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: final commit...
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: closing all files...
|
Sun Jun 10 16:07:36 [interruptThread] closeAllFiles() finished
|
Sun Jun 10 16:07:36 [interruptThread] journalCleanup...
|
Sun Jun 10 16:07:36 [interruptThread] removeJournalFiles
|
Sun Jun 10 16:07:36 [interruptThread] shutdown: removing fs lock...
|
Sun Jun 10 16:07:36 dbexit: really exiting now
|
test /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js exited with status 253
|
16 tests succeeded
|
3 tests didn't get run
|
The following tests failed (with exit code):
|
/data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js 253
|