[SERVER-11668] background index build doesn't seem to resume after process shutdown/restart Created: 12/Nov/13  Updated: 11/Jul/16  Resolved: 14/Jan/14

Status: Closed
Project: Core Server
Component/s: Index Maintenance
Affects Version/s: None
Fix Version/s: 2.5.5

Type: Bug Priority: Major - P3
Reporter: Michael O'Brien Assignee: Eric Milkie
Resolution: Done Votes: 0
Labels: 26qa
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
Operating System: ALL
Participants:

 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...
 


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