[SERVER-17464] Check for shutdown state more regularly during clone Created: 04/Mar/15  Updated: 04/May/16  Resolved: 27/Jul/15

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 3.0.0
Fix Version/s: 3.1.6

Type: Improvement Priority: Major - P3
Reporter: Steve Briskin (Inactive) Assignee: Scott Hernandez (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File shutdown.log     File threaddump.log    
Issue Links:
Duplicate
is duplicated by SERVER-18521 replica in STARTUP2 state cannot be s... Closed
is duplicated by SERVER-24036 initial sync doesn't stop when perfor... Closed
Related
related to SERVER-18039 Add Initial Sync Skeleton to DataRepl... Closed
Backwards Compatibility: Fully Compatible
Participants:

 Description   

Attempted a shutdown during initial sync on MongoDB 3.0.0 mmapv1 during an initial sync, but mongo continued doing an initial sync.

Mongo log and thread dump attached.
Shutdown command issued at 2015-03-04T15:19:56.992+0000,
kill issued at 2015-03-04T15:28:24.108+0000,
kill -9 issued shortly after that

Related to SERVER-16120?



 Comments   
Comment by Githook User [ 28/Jul/15 ]

Author:

{u'username': u'scotthernandez', u'name': u'Scott Hernandez', u'email': u'scotthernandez@gmail.com'}

Message: SERVER-17464: check for interrupts (like during shutdown) in cloner
Branch: master
https://github.com/mongodb/mongo/commit/63fb7ac01638dfb81c1bca170ae58dc6ca276f4b

Comment by Githook User [ 20/Jul/15 ]

Author:

{u'username': u'scotthernandez', u'name': u'Scott Hernandez', u'email': u'scotthernandez@gmail.com'}

Message: SERVER-17464: check for interrupts (like during shutdown) in cloner
Branch: master
https://github.com/mongodb/mongo/commit/63fb7ac01638dfb81c1bca170ae58dc6ca276f4b

Comment by Scott Hernandez (Inactive) [ 04/Mar/15 ]

I believe we have that as a goal in the re-write, but creating an issue for it isn't a bad idea too. The other thing that goes with this would be resuming, and that we should probably only exist initial sync if we can do that safely.

Comment by Andy Schwerin [ 04/Mar/15 ]

Should we turn this into a feature request to check for shutdown state more regularly during clone?

Comment by Scott Hernandez (Inactive) [ 04/Mar/15 ]

Not at all points during initial sync will the system shutdown immediately, if it is doing work for example. In this case it was in the middle of cloning a database so it didn't stop during that operation.

2015-03-04T15:20:01.979+0000 I STORAGE  [conn194] got request after shutdown()
2015-03-04T15:20:02.863+0000 I STORAGE  [conn3276] got request after shutdown()
2015-03-04T15:20:04.497+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.8, filling with zeroes...
2015-03-04T15:20:04.498+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.8, size: 2047MB,  took 0 secs
2015-03-04T15:20:07.029+0000 I STORAGE  [conn3313] got request after shutdown()
2015-03-04T15:20:07.995+0000 I STORAGE  [conn3312] got request after shutdown()
2015-03-04T15:20:13.422+0000 I STORAGE  [rsSync] clone 4d63f8b4e528c81a1fd9dc1c.oplog_messageD 2047
2015-03-04T15:20:19.380+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_messageD properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_messageD" }
2015-03-04T15:20:19.380+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:20:19.394+0000 I INDEX    [rsSync] build index done.  scanned 2132 total records. 0 secs
2015-03-04T15:20:19.395+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_messageB properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_messageB" }
2015-03-04T15:20:19.395+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:20:19.395+0000 I INDEX    [rsSync] build index done.  scanned 0 total records. 0 secs
2015-03-04T15:20:19.397+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_messageE properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_messageE" }
2015-03-04T15:20:19.397+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:20:19.397+0000 I INDEX    [rsSync] build index done.  scanned 0 total records. 0 secs
2015-03-04T15:20:20.660+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_config-aac1f49d5b41d88ddfe345b9af2ff6cf properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_config-aac1f49d5b41d88ddfe345b9af2ff6cf" }
2015-03-04T15:20:20.660+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:20:20.666+0000 I INDEX    [rsSync] build index done.  scanned 1860 total records. 0 secs
2015-03-04T15:21:28.173+0000 I STORAGE  [rsSync] 1474 objects cloned so far from collection 4d63f8b4e528c81a1fd9dc1c.oplog_profile008
2015-03-04T15:21:32.032+0000 I STORAGE  [rsSync] clone 4d63f8b4e528c81a1fd9dc1c.oplog_profile008 1535
2015-03-04T15:21:34.066+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.9, filling with zeroes...
2015-03-04T15:21:34.068+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.9, size: 2047MB,  took 0 secs
2015-03-04T15:21:54.713+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_profile008 properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_profile008" }
2015-03-04T15:21:54.713+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:21:54.722+0000 I INDEX    [rsSync] build index done.  scanned 1872 total records. 0 secs
2015-03-04T15:22:21.216+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.10, filling with zeroes...
2015-03-04T15:22:21.217+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.10, size: 2047MB,  took 0 secs
2015-03-04T15:23:06.844+0000 I STORAGE  [rsSync] 1380 objects cloned so far from collection 4d63f8b4e528c81a1fd9dc1c.oplog_profile028
2015-03-04T15:23:10.671+0000 I STORAGE  [rsSync] clone 4d63f8b4e528c81a1fd9dc1c.oplog_profile028 1407
2015-03-04T15:23:13.667+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.11, filling with zeroes...
2015-03-04T15:23:13.669+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.11, size: 2047MB,  took 0 secs
2015-03-04T15:23:29.925+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_profile028 properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_profile028" }
2015-03-04T15:23:29.925+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:23:29.935+0000 I INDEX    [rsSync] build index done.  scanned 1864 total records. 0 secs
2015-03-04T15:23:59.190+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.12, filling with zeroes...
2015-03-04T15:23:59.191+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.12, size: 2047MB,  took 0 secs
2015-03-04T15:24:33.264+0000 I STORAGE  [rsSync] 1294 objects cloned so far from collection 4d63f8b4e528c81a1fd9dc1c.oplog_profile005
2015-03-04T15:24:37.709+0000 I STORAGE  [rsSync] clone 4d63f8b4e528c81a1fd9dc1c.oplog_profile005 1407
2015-03-04T15:25:03.749+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_profile005 properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_profile005" }
2015-03-04T15:25:03.749+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:25:03.759+0000 I INDEX    [rsSync] build index done.  scanned 1865 total records. 0 secs
2015-03-04T15:25:21.706+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.13, filling with zeroes...
2015-03-04T15:25:21.708+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.13, size: 2047MB,  took 0 secs
2015-03-04T15:26:10.782+0000 I STORAGE  [rsSync] clone 4d63f8b4e528c81a1fd9dc1c.oplog_profile001 1279
2015-03-04T15:26:13.315+0000 I STORAGE  [rsSync] 1334 objects cloned so far from collection 4d63f8b4e528c81a1fd9dc1c.oplog_profile001
2015-03-04T15:26:21.299+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.14, filling with zeroes...
2015-03-04T15:26:21.300+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.14, size: 2047MB,  took 0 secs
2015-03-04T15:26:36.969+0000 I INDEX    [rsSync] build index on: 4d63f8b4e528c81a1fd9dc1c.oplog_profile001 properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "4d63f8b4e528c81a1fd9dc1c.oplog_profile001" }
2015-03-04T15:26:36.969+0000 I INDEX    [rsSync] 	 building index using bulk method
2015-03-04T15:26:36.981+0000 I INDEX    [rsSync] build index done.  scanned 1862 total records. 0 secs
2015-03-04T15:27:22.858+0000 I STORAGE  [FileAllocator] allocating new datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.15, filling with zeroes...
2015-03-04T15:27:22.859+0000 I STORAGE  [FileAllocator] done allocating datafile /srv/10gen/mongod-oplog1-prod/4d63f8b4e528c81a1fd9dc1c.15, size: 2047MB,  took 0 secs
2015-03-04T15:28:24.108+0000 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-03-04T15:28:30.229+0000 I STORAGE  [rsSync] 869 objects cloned so far from collection 4d63f8b4e528c81a1fd9dc1c.oplog_profile021
2015-03-04T15:28:32.539+0000 I STORAGE  [rsSync] clone 4d63f8b4e528c81a1fd9dc1c.oplog_profile021 895
2015-03-04T15:33:00.166+0000 I CONTROL  ***** SERVER RESTARTED *****

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