[SERVER-67773] Index build hangs after "Index build: waiting for next action before completing final phase" Created: 05/Jul/22  Updated: 07/Sep/22  Resolved: 07/Sep/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 4.4.6
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Asel Magzhanova Assignee: Chris Kelly
Resolution: Done Votes: 0
Labels: index, indexing
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongo-gridfs-1.7z     File mongo-gridfs-2.7z     File mongo-gridfs-3.7z    
Operating System: ALL
Participants:

 Description   

I have a sharded cluster with one shard (replica set of three nodes) and case of restoring data using percona-backup-mongodb.

The restore process was stuck on index creation for two days. I tried to restore gridFS collection of 400 GB in size, and index creation was performed for 3 days and didn't end. I watched adminCommand and thought, that it is becouse of cillection size. There were no information about locks:

 
rs0:PRIMARY> db.adminCommand(
...     {
...       currentOp: true,
...       $or: [
...         \{ op: "command", "command.createIndexes": { $exists: true }  },
...         \{ op: "none", "msg" : /^Index Build/ }
...       ]
...     }
... )
{
        "inprog" : [
                {
                        "type" : "op",
                        "host" : "kpak-mongo-gridfs-2:27017",
                        "desc" : "conn295769",
                        "connectionId" : 295769,
                        "client" : "127.0.0.1:59226",
                        "appName" : "mongorestore",
                        "clientMetadata" : {
                                "driver" : {
                                        "name" : "mongo-go-driver",
                                        "version" : "v1.7.0"
                                },
                                "os" : {
                                        "type" : "linux",
                                        "architecture" : "amd64"
                                },
                                "platform" : "go1.16.9",
                                "application" : {
                                        "name" : "mongorestore"
                                }
                        },
                        "active" : true,
                        "currentOpTime" : "2022-07-04T14:44:56.860+03:00",
                        "effectiveUsers" : [
                                {
                                        "user" : "pbmuser",
                                        "db" : "admin"
                                }
                        ],
                        "opid" : 362857456,
                        "lsid" : {
                                "id" : UUID("4aeb2829-b2dd-4bd2-8e4a-ea28c77ed31e"),
                                "uid" : BinData(0,"8L/kOoqHkvDRIRJTrmrrO3wwOr+ToO8WLvmn15Ql7G0=")
                        },
                        "secs_running" : NumberLong(236403),
                        "microsecs_running" : NumberLong("236403076334"),
                        "op" : "command",
                        "ns" : "file-store.fs.chunks",
                        "command" : {
                                "createIndexes" : "fs.chunks",
                                "indexes" : [
                                        {
                                                "key" : {
                                                        "files_id" : 1,
                                                        "n" : 1
                                                },
                                                "name" : "chunkFileIds",
                                                "ns" : "file-store.fs.chunks"
                                        }
                                ],
                                "ignoreUnknownIndexOptions" : true,
                                "lsid" : {
                                        "id" : UUID("4aeb2829-b2dd-4bd2-8e4a-ea28c77ed31e")
                                },
                                "$clusterTime" : {
                                        "clusterTime" : Timestamp(1656698693, 534),
                                        "signature" : {
                                                "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
                                                "keyId" : NumberLong(0)
                                        }
                                },
                                "$db" : "file-store",
                                "$readPreference" : {
                                        "mode" : "primaryPreferred"
                                }
                        },
                        "numYields" : 0,
                        "waitingForLatch" : {
                                "timestamp" : ISODate("2022-07-01T18:04:54.326Z"),
                                "captureName" : "FutureResolution"
                        },
                        "locks" : {
 
                        },
                        "waitingForLock" : false,
                        "lockStats" : {
                                "ParallelBatchWriterMode" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(3)
                                        }
                                },
                                "ReplicationStateTransition" : {
                                        "acquireCount" : {
                                                "w" : NumberLong(4)
                                        }
                                },
                                "Global" : {
                                        "acquireCount" : {
                                                "w" : NumberLong(4)
                                        }
                                },
                                "Database" : {
                                        "acquireCount" : {
                                                "w" : NumberLong(3)
                                        }
                                },
                                "Collection" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(1),
                                                "w" : NumberLong(1),
                                                "W" : NumberLong(1)
                                        }
                                },
                                "Mutex" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(3)
                                        }
                                }
                        },
                        "waitingForFlowControl" : false,
                        "flowControlStats" : {
                                "acquireCount" : NumberLong(3),
                                "timeAcquiringMicros" : NumberLong(4)
                        }
                },
                {
                        "type" : "op",
                        "host" : "kpak-mongo-gridfs-2:27017",
                        "desc" : "conn295766",
                        "connectionId" : 295766,
                        "client" : "127.0.0.1:59214",
                        "appName" : "mongorestore",
                        "clientMetadata" : {
                                "driver" : {
                                        "name" : "mongo-go-driver",
                                        "version" : "v1.7.0"
                                },
                                "os" : {
                                        "type" : "linux",
                                        "architecture" : "amd64"
                                },
                                "platform" : "go1.16.9",
                                "application" : {
                                        "name" : "mongorestore"
                                }
                        },
                        "active" : true,
                        "currentOpTime" : "2022-07-04T14:44:56.860+03:00",
                        "effectiveUsers" : [
                                {
                                        "user" : "pbmuser",
                                        "db" : "admin"
                                }
                        ],
                        "opid" : 362857455,
                        "lsid" : {
                                "id" : UUID("559b3155-422e-453a-9df1-dc158688d89c"),
                                "uid" : BinData(0,"8L/kOoqHkvDRIRJTrmrrO3wwOr+ToO8WLvmn15Ql7G0=")
                        },
                        "secs_running" : NumberLong(236403),
                        "microsecs_running" : NumberLong("236403076648"),
                        "op" : "command",
                        "ns" : "file-store.fs.files",
                        "command" : {
                                "createIndexes" : "fs.files",
                                "indexes" : [
                                        {
                                                "key" : {
                                                        "filename" : 1,
                                                        "uploadDate" : 1
                                                },
                                                "name" : "fileNames",
                                                "ns" : "file-store.fs.files"
                                        }
                                ],
                                "ignoreUnknownIndexOptions" : true,
                                "lsid" : {
                                        "id" : UUID("559b3155-422e-453a-9df1-dc158688d89c")
                                },
                                "$clusterTime" : {
                                        "clusterTime" : Timestamp(1656698693, 534),
                                        "signature" : {
                                                "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
                                                "keyId" : NumberLong(0)
                                        }
                                },
                                "$db" : "file-store",
                                "$readPreference" : {
                                        "mode" : "primaryPreferred"
                                }
                        },
                        "numYields" : 0,
                        "waitingForLatch" : {
                                "timestamp" : ISODate("2022-07-01T18:04:54.206Z"),
                                "captureName" : "FutureResolution"
                        },
                        "locks" : {
 
                        },
                        "waitingForLock" : false,
                        "lockStats" : {
                                "ParallelBatchWriterMode" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(3)
                                        }
                                },
                                "ReplicationStateTransition" : {
                                        "acquireCount" : {
                                                "w" : NumberLong(4)
                                        }
                                },
                                "Global" : {
                                        "acquireCount" : {
                                                "w" : NumberLong(4)
                                        }
                                },
                                "Database" : {
                                        "acquireCount" : {
                                                "w" : NumberLong(3)
                                        }
                                },
                                "Collection" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(1),
                                                "w" : NumberLong(1),
                                                "W" : NumberLong(1)
                                        }
                                },
                                "Mutex" : {
                                        "acquireCount" : {
                                                "r" : NumberLong(3)
                                        }
                                }
                        },
                        "waitingForFlowControl" : false,
                        "flowControlStats" : {
                                "acquireCount" : NumberLong(3),
                                "timeAcquiringMicros" : NumberLong(2)
                        }
                }
        ],
        "ok" : 1,
        "$gleStats" : {
                "lastOpTime" : Timestamp(0, 0),
                "electionId" : ObjectId("7fffffff0000000000000003")
        },
        "lastCommittedOpTime" : Timestamp(1656935091, 1),
        "$configServerState" : {
                "opTime" : {
                        "ts" : Timestamp(1656935096, 1),
                        "t" : NumberLong(1)
                }
        },
        "$clusterTime" : {
                "clusterTime" : Timestamp(1656935096, 1),
                "signature" : {
                        "hash" : BinData(0,"9aQA7SE2bdYHsIVCKODI8WjxuCg="),
                        "keyId" : NumberLong("7073745711275180033")
                }
        },
        "operationTime" : Timestamp(1656935091, 1)
}

Later I found in mongod logs that index creation hung after the phase "Index build: waiting for next action before completing final phase". 

All nodes of replica set were alive. Сould you explain what the problem was? I use 4.4 version of mongodb.



 Comments   
Comment by Chris Kelly [ 07/Sep/22 ]

Asik,

Glad to hear you were able to resolve the issue! I'll go ahead and close this ticket for now.

 

Comment by Asel Magzhanova [ 01/Sep/22 ]

Hi!

Sorry for the long answer.
We decided to try to remove the secondary nodes from the replica set, after we restore and return them back. This helped us. We decided to use this method for large databases. Thanks a lot for your help! You really helped us figure out what's going on.

Comment by Chris Kelly [ 22/Aug/22 ]

Hi Asel!

Just wanted to check in - did this end up resolving your issue? If so, we can go ahead and close this ticket.

Christopher

Comment by Chris Kelly [ 01/Aug/22 ]

Hi Asel,

About 10 minutes before another index build starts at ~ 2022-07-01T21:00:00+03:00 , node 0 goes into rollback and then gets stuck in a recovery state because it's moved to maintenance mode. It stays this way for the remainder of the time FTDC is logged. (multiple hours). The logs show that this node is too stale for days after the event happens. This requires an initial sync to fix.

 

{"t":{"$date":"2022-07-01T20:52:42.275+03:00"},"s":"E",  "c":"REPL",     "id":21126,   "ctx":"BackgroundSync","msg":"Too stale to catch up. Entering maintenance mode. See http://dochub.mongodb.org/core/resyncingaverystalereplicasetmember","attr":{"lastOpTimeFetched":{"ts":{"$timestamp":{"t":1656697347,"i":1173}},"t":3},"earliestOpTimeSeen":{"ts":{"$timestamp":{"t":1656697559,"i":178}},"t":3}}}
{"t":{"$date":"2022-07-01T20:52:42.276+03:00"},"s":"I",  "c":"REPL",     "id":21350,   "ctx":"BackgroundSync","msg":"Going into maintenance mode","attr":{"otherMaintenanceModeTasksInProgress":0}}
{"t":{"$date":"2022-07-01T20:52:42.276+03:00"},"s":"I",  "c":"REPL",     "id":21358,   "ctx":"BackgroundSync","msg":"Replica set state transition","attr":{"newState":"RECOVERING","oldState":"SECONDARY"}}
{"t":{"$date":"2022-07-01T20:52:42.276+03:00"},"s":"I",  "c":"REPL",     "id":21106,   "ctx":"BackgroundSync","msg":"Resetting sync source to empty","attr":{"previousSyncSource":":27017"}}

 

From what I can tell, there are multiple indexes being created at the same time as well. There's a lot of load during this process, and your secondary got out of sync, and requires a resync to catch back up. Starting in 4.4, the primary waits for all nodes to report back before committing the index build. This is described in the commit quorum defaults for the createIndex command. 

Possible mitigations for this could be to:

 

Let me know if any of these options resolve your issue.

Regards,
Christopher

Comment by Asel Magzhanova [ 15/Jul/22 ]

Unfortunately, we saved diagnostic.data on only one node of the replica set. The replica set consists of three nodes, I have attached 3 archives, respectively. The problem arose on 2022-07-01 in the evening. Fragment of the log, after which the creation of the index hung:

{"t":\{"$date":"2022-07-01T21:25:07.601+03:00"},"s":"I", "c":"STORAGE", "id":3856203, "ctx":"IndexBuildsCoordinatorMongod-2","msg":"Index build: waiting for next action before completing final phase","attr":\{"buildUUID":{"uuid":{"$uuid":"faa6d31c -bda0-419e-b877-e90a24856b43"}}}}

Comment by Chris Kelly [ 05/Jul/22 ]

Asel,

Thanks for your report. For each node in the replica set spanning a time period that includes the incident, would you please archive (tar or zip) and upload to the ticket:

  • the mongod logs
  • the $dbpath/diagnostic.data directory (the contents are described here)
  • point out the timestamp you are experiencing this issue

Christopher

Generated at Thu Feb 08 06:09:01 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.