Details
-
Bug
-
Resolution: Done
-
Major - P3
-
None
-
ALL
Description
tested by:
- creating a collection with 1e6 records.
- triggering an index build on the collection with {background:true}
- sleep for a moment to allow the index build to start progress
- stop the mongod process
- restart the mongod process
According to the 2.5.3 release notes, expected behavior is that we should see the background index build continue.
However, based on log output it looks like the index build is abandoned.
Script:
//start up mongod, create test collection
|
var mongod = MongoRunner.runMongod({binVersion:"2.5.3"})
|
setVerboseShell(false)
|
var db = mongod.getDB("test")
|
for(var i=0;i<1000000;i++){
|
db.test.insert({x:i})
|
}
|
printjson(mongod.getDB("test").test.getIndexes())
|
|
|
//Start a background index build, kill it after a few moments
|
printjson("MAKING BG INDEX")
|
db.test.createIndex({x:1}, {background:true})
|
sleep(2500)
|
MongoRunner.stopMongod(mongod)
|
|
|
//Restart the mongod
|
mongod = MongoRunner.runMongod({restart:mongod, binVersion:"2.5.3"})
|
printjson("indexes are:")
|
printjson(mongod.getDB("test").test.getIndexes())
|
sleep(10000)
|
printjson("sleeping a bit")
|
sleep(60000)
|
printjson(mongod.getDB("test").test.getIndexes())
|
|
|
Logs
|
|
MongoDB shell version: 2.4.1
|
Resetting db path '/data/db/mongod-27000'
|
Tue Nov 12 15:49:44.266 shell: started program mongod-2.5.3 --port 27000 --dbpath /data/db/mongod-27000
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] MongoDB starting : pid=27452 port=27000 dbpath=/data/db/mongod-27000 64-bit host=mikes-MacBook-Pro.local
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten]
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] ** NOTE: This is a development version (2.5.3) of MongoDB.
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] ** Not recommended for production.
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten]
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten]
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] db version v2.5.3
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] git version: 78a5cc81af2209e10e1357a41e02f1689b60ef1e
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] build info: Darwin bs-osx-106-x86-64-2.10gen.cc 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun 7 16:32:41 PDT 2011; root:xnu-1504.15.3~1/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] allocator: system
|
m27000| 2013-11-12T15:49:44.294-0500 [initandlisten] options: { dbpath: "/data/db/mongod-27000", port: 27000 }
|
m27000| 2013-11-12T15:49:44.295-0500 [initandlisten] journal dir=/data/db/mongod-27000/journal
|
m27000| 2013-11-12T15:49:44.295-0500 [initandlisten] recover : no journal files present, no recovery needed
|
m27000| 2013-11-12T15:49:44.307-0500 [FileAllocator] allocating new datafile /data/db/mongod-27000/local.ns, filling with zeroes...
|
m27000| 2013-11-12T15:49:44.307-0500 [FileAllocator] creating directory /data/db/mongod-27000/_tmp
|
m27000| 2013-11-12T15:49:44.338-0500 [FileAllocator] done allocating datafile /data/db/mongod-27000/local.ns, size: 16MB, took 0.03 secs
|
m27000| 2013-11-12T15:49:44.381-0500 [FileAllocator] allocating new datafile /data/db/mongod-27000/local.0, filling with zeroes...
|
m27000| 2013-11-12T15:49:44.667-0500 [FileAllocator] done allocating datafile /data/db/mongod-27000/local.0, size: 64MB, took 0.286 secs
|
m27000| 2013-11-12T15:49:44.712-0500 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0 reslen:37 404ms
|
m27000| 2013-11-12T15:49:44.712-0500 [initandlisten] waiting for connections on port 27000
|
m27000| 2013-11-12T15:49:44.712-0500 [initandlisten] connection accepted from 127.0.0.1:60624 #1 (1 connection now open)
|
m27000| 2013-11-12T15:49:44.713-0500 [FileAllocator] allocating new datafile /data/db/mongod-27000/test.ns, filling with zeroes...
|
m27000| 2013-11-12T15:49:44.742-0500 [FileAllocator] done allocating datafile /data/db/mongod-27000/test.ns, size: 16MB, took 0.029 secs
|
m27000| 2013-11-12T15:49:44.839-0500 [FileAllocator] allocating new datafile /data/db/mongod-27000/test.0, filling with zeroes...
|
m27000| 2013-11-12T15:49:45.030-0500 [initandlisten] connection accepted from 127.0.0.1:60625 #2 (2 connections now open)
|
m27000| 2013-11-12T15:49:45.106-0500 [FileAllocator] done allocating datafile /data/db/mongod-27000/test.0, size: 64MB, took 0.266 secs
|
m27000| 2013-11-12T15:49:45.204-0500 [conn1] build index on: test.test properties: { "v" : 1, "key" : { "_id" : 1 }, "ns" : "test.test", "name" : "_id_" }
|
m27000| 2013-11-12T15:49:45.205-0500 [conn1] have free list for test.$freelist
|
m27000| 2013-11-12T15:49:45.205-0500 [conn1] build index done. scanned 0 total records. 0 secs
|
m27000| 2013-11-12T15:49:45.205-0500 [conn1] insert test.test ninserted:1 keyUpdates:0 locks(micros) w:493141 491ms
|
m27000| 2013-11-12T15:49:45.205-0500 [conn2] command admin.$cmd command: { serverStatus: 1 } ntoreturn:1 keyUpdates:0 locks(micros) r:20 reslen:2861 175ms
|
m27000| 2013-11-12T15:49:59.201-0500 [conn1] insert test.test ninserted:1 keyUpdates:0 locks(micros) w:32 145ms
|
m27000| 2013-11-12T15:50:02.140-0500 [FileAllocator] allocating new datafile /data/db/mongod-27000/test.1, filling with zeroes...
|
m27000| 2013-11-12T15:50:02.770-0500 [FileAllocator] done allocating datafile /data/db/mongod-27000/test.1, size: 128MB, took 0.63 secs
|
m27000| 2013-11-12T15:50:02.820-0500 [conn1] insert test.test ninserted:1 keyUpdates:0 locks(micros) w:680389 680ms
|
m27000| 2013-11-12T15:50:02.821-0500 [conn2] command admin.$cmd command: { serverStatus: 1 } ntoreturn:1 keyUpdates:0 locks(micros) r:20 reslen:2927 598ms
|
[
|
{
|
"v" : 1,
|
"key" : {
|
"_id" : 1
|
},
|
"ns" : "test.test",
|
"name" : "_id_"
|
}
|
]
|
"MAKING BG INDEX"
|
m27000| 2013-11-12T15:50:17.872-0500 [conn1] build index on: test.test properties: { "v" : 1, "key" : { "x" : 1 }, "ns" : "test.test", "name" : "x_1", "background" : true }
|
m27000| 2013-11-12T15:50:20.000-0500 [conn1] Background Index Build Progress: 196000/1000000 19%
|
m27000| 2013-11-12T15:50:20.373-0500 [signalProcessingThread] got signal 15 (Terminated: 15), will terminate after current cmd ends
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] now exiting
|
m27000| 2013-11-12T15:50:20.374-0500 [conn1] insert test.system.indexes keyUpdates:0 exception: interrupted at shutdown code:11600 numYields:23 locks(micros) w:4550364 2501ms
|
m27000| dbexit: 2013-11-12T15:50:20.374-0500 [signalProcessingThread] shutdown: going to close listening sockets...
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] closing listening socket: 10
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] closing listening socket: 11
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] removing socket file: /tmp/mongodb-27000.sock
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] shutdown: going to flush diaglog...
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] shutdown: going to close sockets...
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] shutdown: waiting for fs preallocator...
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] shutdown: lock for final commit...
|
m27000| 2013-11-12T15:50:20.374-0500 [signalProcessingThread] shutdown: final commit...
|
m27000| 2013-11-12T15:50:20.374-0500 [conn2] end connection 127.0.0.1:60625 (0 connections now open)
|
m27000| 2013-11-12T15:50:20.937-0500 [signalProcessingThread] shutdown: closing all files...
|
m27000| 2013-11-12T15:50:20.939-0500 [signalProcessingThread] closeAllFiles() finished
|
m27000| 2013-11-12T15:50:20.939-0500 [signalProcessingThread] journalCleanup...
|
m27000| 2013-11-12T15:50:20.939-0500 [signalProcessingThread] removeJournalFiles
|
m27000| 2013-11-12T15:50:20.943-0500 [signalProcessingThread] shutdown: removing fs lock...
|
Tue Nov 12 15:50:21.374 shell: stopped mongo program on port 27000
|
Tue Nov 12 15:50:21.375 shell: started program mongod-2.5.3 --port 27000 --dbpath /data/db/mongod-27000
|
m27000| 2013-11-12T15:50:21.399-0500 [initandlisten] MongoDB starting : pid=27459 port=27000 dbpath=/data/db/mongod-27000 64-bit host=mikes-MacBook-Pro.local
|
m27000| 2013-11-12T15:50:21.399-0500 [initandlisten]
|
m27000| 2013-11-12T15:50:21.399-0500 [initandlisten] ** NOTE: This is a development version (2.5.3) of MongoDB.
|
m27000| 2013-11-12T15:50:21.399-0500 [initandlisten] ** Not recommended for production.
|
m27000| 2013-11-12T15:50:21.399-0500 [initandlisten]
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten]
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] db version v2.5.3
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] git version: 78a5cc81af2209e10e1357a41e02f1689b60ef1e
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] build info: Darwin bs-osx-106-x86-64-2.10gen.cc 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun 7 16:32:41 PDT 2011; root:xnu-1504.15.3~1/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] allocator: system
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] options: { dbpath: "/data/db/mongod-27000", port: 27000 }
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] journal dir=/data/db/mongod-27000/journal
|
m27000| 2013-11-12T15:50:21.400-0500 [initandlisten] recover : no journal files present, no recovery needed
|
m27000| 2013-11-12T15:50:21.418-0500 [initandlisten] have free list for local.$freelist
|
m27000| 2013-11-12T15:50:21.440-0500 [initandlisten] waiting for connections on port 27000
|
m27000| 2013-11-12T15:50:21.576-0500 [initandlisten] connection accepted from 127.0.0.1:60751 #1 (1 connection now open)
|
"indexes are:"
|
[
|
{
|
"v" : 1,
|
"key" : {
|
"_id" : 1
|
},
|
"ns" : "test.test",
|
"name" : "_id_"
|
}
|
]
|
m27000| 2013-11-12T15:50:21.845-0500 [initandlisten] connection accepted from 127.0.0.1:60752 #2 (2 connections now open)
|
"sleeping a bit"
|
m27000| 2013-11-12T15:51:21.443-0500 [clientcursormon] mem (MB) res:36 virt:3084
|
m27000| 2013-11-12T15:51:21.443-0500 [clientcursormon] mapped (incl journal view):576
|
m27000| 2013-11-12T15:51:21.443-0500 [clientcursormon] connections:2
|
[
|
{
|
"v" : 1,
|
"key" : {
|
"_id" : 1
|
},
|
"ns" : "test.test",
|
"name" : "_id_"
|
}
|
]
|
m27000| 2013-11-12T15:51:31.579-0500 [signalProcessingThread] got signal 15 (Terminated: 15), will terminate after current cmd ends
|
m27000| 2013-11-12T15:51:31.579-0500 [signalProcessingThread] now exiting
|
m27000| dbexit: 2013-11-12T15:51:31.579-0500 [signalProcessingThread] shutdown: going to close listening sockets...
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] closing listening socket: 11
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] closing listening socket: 12
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] removing socket file: /tmp/mongodb-27000.sock
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] shutdown: going to flush diaglog...
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] shutdown: going to close sockets...
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] shutdown: waiting for fs preallocator...
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] shutdown: lock for final commit...
|
m27000| 2013-11-12T15:51:31.580-0500 [signalProcessingThread] shutdown: final commit...
|
m27000| 2013-11-12T15:51:31.580-0500 [conn2] end connection 127.0.0.1:60752 (1 connection now open)
|
m27000| 2013-11-12T15:51:31.580-0500 [conn1] end connection 127.0.0.1:60751 (1 connection now open)
|
m27000| 2013-11-12T15:51:31.603-0500 [signalProcessingThread] shutdown: closing all files...
|
m27000| 2013-11-12T15:51:31.603-0500 [signalProcessingThread] closeAllFiles() finished
|
m27000| 2013-11-12T15:51:31.603-0500 [signalProcessingThread] journalCleanup...
|
m27000| 2013-11-12T15:51:31.603-0500 [signalProcessingThread] removeJournalFiles
|
m27000| 2013-11-12T15:51:31.603-0500 [signalProcessingThread] shutdown: removing fs lock...
|
|
|