[SERVER-11767] creating background index and then dropping doesn't seem to cancel background build on secondary Created: 18/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
related to SERVER-12164 Write commands are nesting operations... Closed
Operating System: ALL
Participants:

 Description   

started up a 2.4 replica set, and added a 2.5.3 secondary

  • create an index with {background:true}

    on a large collection, on the primary

  • immediately call dropIndexes()

From my understanding of how background indexing should now work in 2.5.x the background index build should be aborted when the dropIndexes command is sent. However it looks like the secondary is continuing to build the index to completion before dropping it.

>  m31001| Mon Nov 18 16:34:16.929 [repl writer worker 1] CMD: dropIndexes poo.test
 m27000| 2013-11-18T16:34:16.929-0500 [repl writer worker 1] CMD: dropIndexes poo.test
 m27000| 2013-11-18T16:34:17.008-0500 [conn35] end connection 127.0.0.1:63104 (2 connections now open)
 m27000| 2013-11-18T16:34:17.009-0500 [initandlisten] connection accepted from 127.0.0.1:63127 #37 (3 connections now open)
 
>
>
>  m31000| Mon Nov 18 16:34:18.231 [conn49] end connection 127.0.0.1:63105 (6 connections now open)
 m31000| Mon Nov 18 16:34:18.231 [initandlisten] connection accepted from 127.0.0.1:63128 #51 (7 connections now open)
 
>
> rs1.getPrimary().getDB("poo").test.createIndex({x:1}, {background:true})
rs1.getPrimary().getDB("poo").test.dropIndexes()
ReplSetTest Could not call ismaster on node 2: {
 
}
 m31000| Mon Nov 18 16:34:21.857 [conn1] build index poo.test { x: 1.0 } background
> rs1.getPrimary().getDB("poo").test.dropIndexes()
 m31000| Mon Nov 18 16:34:24.000 [conn1]                Background Index Build Progress: 390700/1000000 39%
 
 
 m31000| Mon Nov 18 16:34:26.213 [journal] old journal file will be removed: /data/db/test-0/journal/j._0
 m31000| Mon Nov 18 16:34:26.214 [journal] old journal file will be removed: /data/db/test-0/journal/j._1
 m31000| Mon Nov 18 16:34:27.000 [conn1]                Background Index Build Progress: 884300/1000000 88%
 m31000| Mon Nov 18 16:34:27.658 [conn1] build index done.  scanned 1000000 total records. 5.801 secs
 m31000| Mon Nov 18 16:34:27.658 [conn1] insert poo.system.indexes ninserted:1 keyUpdates:0 numYields: 67 locks(micros) w:10542174 5801ms
 m31001| Mon Nov 18 16:34:27.659 [repl writer worker 1] info: indexing in foreground on this replica; was a background index build on the primary
 m31001| Mon Nov 18 16:34:27.659 [repl writer worker 1] build index poo.test { x: 1.0 }
 m27000| 2013-11-18T16:34:27.659-0500 [repl index builder 3] build index on: poo.test properties: { "v" : 1, "key" : { "x" : 1 }, "ns" : "poo.test", "name" : "x_1", "background" : true }
ReplSetTest Could not call ismaster on node 2: {
 
}
 m31000| Mon Nov 18 16:34:27.660 [conn1] CMD: dropIndexes poo.test
{
  "nIndexesWas": 2,
  "msg": "non-_id indexes dropped for collection",
  "ok": 1
}
>
 
>
>  m27000| 2013-11-18T16:34:30.000-0500 [repl index builder 3]          Background Index Build Progress: 257800/1000000 25%
 m31001| Mon Nov 18 16:34:31.830 [conn39] end connection 127.0.0.1:63116 (2 connections now open)
 m31001| Mon Nov 18 16:34:31.830 [initandlisten] connection accepted from 127.0.0.1:63142 #41 (3 connections now open)
 m31001| Mon Nov 18 16:34:31.960 [repl writer worker 1] build index done.  scanned 1000000 total records. 4.3 secs
 m31001| Mon Nov 18 16:34:32.136 [repl writer worker 1] CMD: dropIndexes poo.test
 m31001| Mon Nov 18 16:34:32.239 [conn40] end connection 127.0.0.1:63117 (2 connections now open)
 m31001| Mon Nov 18 16:34:32.240 [initandlisten] connection accepted from 127.0.0.1:63143 #42 (3 connections now open)
 m27000| 2013-11-18T16:34:33.000-0500 [repl index builder 3]            Background Index Build Progress: 584400/1000000 58%
 m27000| 2013-11-18T16:34:36.000-0500 [repl index builder 3]            Background Index Build Progress: 911300/1000000 91%
 m27000| 2013-11-18T16:34:36.824-0500 [repl index builder 3] build index done.  scanned 1000000 total records. 9.164 secs
 m27000| 2013-11-18T16:34:36.825-0500 [repl writer worker 1] CMD: dropIndexes poo.test
 m31000| Mon Nov 18 16:34:42.382 [conn50] end connection 127.0.0.1:63125 (6 connections now open)
 m31000| Mon Nov 18 16:34:42.383 [initandlisten] connection accepted from 127.0.0.1:63150 #52 (7 connections now open)
 m27000| 2013-11-18T16:34:45.518-0500 [conn36] end connection 127.0.0.1:63126 (2 connections now open)
 m27000| 2013-11-18T16:34:45.520-0500 [initandlisten] connection accepted from 127.0.0.1:63153 #38 (3 connections now open)
 m27000| 2013-11-18T16:34:47.028-0500 [conn37] end connection 127.0.0.1:63127 (2 connections now open)
 m27000| 2013-11-18T16:34:47.029-0500 [initandlisten] connection accepted from 127.0.0.1:63154 #39 (3 connections now open)



 Comments   
Comment by Githook User [ 15/Jan/14 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-11767 allow more time for records to replicate, on slower builders
Branch: master
https://github.com/mongodb/mongo/commit/26a8aaf0e660c247c2667e0f182bc4964096735b

Comment by Githook User [ 14/Jan/14 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-11767 allow more time for records to replicate, on slower builders
Branch: master
https://github.com/mongodb/mongo/commit/9f99f49ceb00fdd2bfdc895baf91a90a24e223c4

Comment by Githook User [ 14/Jan/14 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-11767 display interrupted index builds nicely
Branch: master
https://github.com/mongodb/mongo/commit/2fdf989382a6911d75afbb885c5d400d187fbb2b

Comment by Michael O'Brien [ 18/Nov/13 ]

Also a similar behavior with dropping the database while the secondary is building its index.

 m31000| Mon Nov 18 16:43:55.985 [conn1] build index poo.test { x: 1.0 } background
> rs1.getPrimary().getDB("poo").dropDatabase()
 m31000| Mon Nov 18 16:43:56.602 [FileAllocator] allocating new datafile /data/db/test-0/poo.3, filling with zeroes...
 m31000| Mon Nov 18 16:43:57.420 [FileAllocator] done allocating datafile /data/db/test-0/poo.3, size: 128MB,  took 0.818 secs
 m31000| Mon Nov 18 16:43:58.000 [conn1]                Background Index Build Progress: 200000/1000000 20%
 m31000| Mon Nov 18 16:43:59.150 [journal] old journal file will be removed: /data/db/test-0/journal/j._0
 m31000| Mon Nov 18 16:43:59.410 [journal] DR101 latency warning on journal file open 253ms
 m31000| Mon Nov 18 16:44:01.000 [conn1]                Background Index Build Progress: 665400/1000000 66%
 m31000| Mon Nov 18 16:44:02.964 [conn1] build index done.  scanned 1000000 total records. 6.978 secs
 m31000| Mon Nov 18 16:44:02.964 [conn1] insert poo.system.indexes ninserted:1 keyUpdates:0 numYields: 68 locks(micros) w:12015831 6978ms
 m31001| Mon Nov 18 16:44:02.964 [repl writer worker 1] info: indexing in foreground on this replica; was a background index build on the primary
 m31001| Mon Nov 18 16:44:02.965 [repl writer worker 1] build index poo.test { x: 1.0 }
 m27000| 2013-11-18T16:44:02.965-0500 [repl index builder 0] build index on: poo.test properties: { "v" : 1, "key" : { "x" : 1 }, "ns" : "poo.test", "name" : "x_1", "background" : true }
ReplSetTest Could not call ismaster on node 2: {
 
}
 m31000| Mon Nov 18 16:44:02.966 [conn1] dropDatabase poo starting
 m31000| Mon Nov 18 16:44:03.091 [conn1] removeJournalFiles
 m31000| Mon Nov 18 16:44:03.120 [conn1] dropDatabase poo finished
 m31000| Mon Nov 18 16:44:03.120 [conn1] command poo.$cmd command: { dropDatabase: 1.0 } ntoreturn:1 keyUpdates:0 locks(micros) W:154386 reslen:54 154ms
{
  "dropped": "poo",
  "ok": 1
}
>  m27000| 2013-11-18T16:44:03.972-0500 [FileAllocator] allocating new datafile /data/db/test-3/poo.3, filling with zeroes...
 m27000| 2013-11-18T16:44:04.621-0500 [FileAllocator] done allocating datafile /data/db/test-3/poo.3, size: 128MB,  took 0.649 secs
 m27000| 2013-11-18T16:44:05.020-0500 [repl index builder 0]            Background Index Build Progress: 142000/1000000 14%
 m31001| Mon Nov 18 16:44:05.168 [FileAllocator] allocating new datafile /data/db/test-1/poo.3, filling with zeroes...
 m31001| Mon Nov 18 16:44:05.904 [FileAllocator] done allocating datafile /data/db/test-1/poo.3, size: 128MB,  took 0.736 secs
 m31001| Mon Nov 18 16:44:07.952 [conn11] end connection 127.0.0.1:63914 (2 connections now open)
 m31001| Mon Nov 18 16:44:07.953 [initandlisten] connection accepted from 127.0.0.1:63939 #13 (3 connections now open)
 m27000| 2013-11-18T16:44:08.000-0500 [repl index builder 0]            Background Index Build Progress: 446900/1000000 44%
 m31001| Mon Nov 18 16:44:08.113 [repl writer worker 1] build index done.  scanned 1000000 total records. 5.148 secs
 m31001| Mon Nov 18 16:44:08.188 [conn12] end connection 127.0.0.1:63915 (2 connections now open)
 m31001| Mon Nov 18 16:44:08.188 [initandlisten] connection accepted from 127.0.0.1:63940 #14 (3 connections now open)
 m31001| Mon Nov 18 16:44:08.381 [repl writer worker 1] dropDatabase poo starting
 m31001| Mon Nov 18 16:44:08.530 [repl writer worker 1] removeJournalFiles
 m31001| Mon Nov 18 16:44:08.552 [repl writer worker 1] dropDatabase poo finished
 m27000| 2013-11-18T16:44:11.000-0500 [repl index builder 0]            Background Index Build Progress: 734600/1000000 73%
 
>
>
>  m27000| 2013-11-18T16:44:13.488-0500 [repl index builder 0] build index done.  scanned 1000000 total records. 10.523 secs

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