[SERVER-4305] Deadlock of secondary trying to sync the oplog if index versions are mixed on master Created: 17/Nov/11  Updated: 14/May/12  Resolved: 14/May/12

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

Type: Bug Priority: Blocker - P1
Reporter: Steffen Assignee: Kristina Chodorow (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: index, replication, stale
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux 2.6.32-35-server, Ubuntu 10.04, MongoDB 2.0.1, Replicaset with 3 Nodes, NUMA, 2x XEON E5620 , 24 GB RAM


Attachments: Text File iostat.txt     Text File mongostat.txt     Zip Archive secondary-14-nov-repair.log.zip     Zip Archive secondary-15-nov.log.zip     Text File secondary.log.txt     Text File strace.txt    
Operating System: ALL
Participants:

 Description   

What we want to do:
upgrade all indexes to version 2.0 (v:1) in our replicaset

How we do this:
we start with one secondary, shut it down, change port and remove repset param, start it with repair command to reindex all indexes.
after repair reset configuration and connect it to the repset. Wait until the slave is up2date to proceed with the next secondary.

What is the problem:
The secondary is not able to catch up with the master. It has a single process running with 100% cpu usage and almost idle io. (cpu bound)
It falls slowly more and more behind. (all hosts have the same hardware)

What we suspect:
We have a database which has some indexes with the old version and some with the new. If a secondary upgrades the indexes, it has all indexes on the latest version and this locks the replay/resync of the oplog from the master which still has the mixed version indexes.

We downgraded the indexes again with an older mongod binary (1.8.4). After this was finished, we connected the secondary to the replicaset again and it replayed the oplog without a problem and is now in sync again.

All hosts have the mongod binary version 2.0.1.

I've attached iostat and mongostat output. The host with the problem is mn01.
In the mongod.log is no error message just some reoccurring message about the cursor:
Wed Nov 16 06:32:56 [rsSync] repl: old cursor isDead, will initiate a new one

Regards,
Steffen



 Comments   
Comment by Ian Whalen (Inactive) [ 14/May/12 ]

Closing as Cannot Reproduce - please reopen if you continue to run into the same problem.

Comment by Steffen [ 18/Jan/12 ]

Hello,

we tried another run to upgrade the indexes.
this time I used compact command on each collection in each database starting on the secondaries. Switched master to secondary and upgraded indexes there too.
All went fine so far. No problems with the oplog sync.

Maybe -repair startup parameter doesn't work, but compact does.

Comment by Steffen [ 27/Dec/11 ]

We will try another rebuild of the indexes next year. I will report then about the results.

Comment by Kristina Chodorow (Inactive) [ 13/Dec/11 ]

Sorry about the delay, consulting with coworkers.

Can you attach gdb and get a stack trace for all threads at a few different times, so that we can see what code is running when the CPU is pegged?

To get a backtrace of all threads in gdb, run:

(gdb) thread apply all bt

Comment by Steffen [ 01/Dec/11 ]

Yes, already posted:
secondary-14-nov-repair.log.zip

Comment by Kristina Chodorow (Inactive) [ 30/Nov/11 ]

Unfortunately, MMS doesn't give us that kind of insight (it's just statistics about your data, not the data or queries themselves).

That does look like something weird is happening during the repair, do you happen to have the log from when you did the repair?

Comment by Steffen [ 23/Nov/11 ]

Can you read from mms the operations happening?

The obvious difference between this two replicasets, we are using, is just the index versions of the databases.
Since we suspect the index version mix, I will show you the index output from the database which has both versions. Maybe in the repair something gets messed up. I hope you can reproduce the problem with this indexes.

{ "name" : "_id_", "ns" : "exstream.objects", "key" : { "_id" : 1 }, "v" : 0 }
{ "name" : "_id_", "ns" : "exstream.connections", "key" : { "_id" : 1 }, "v" : 0 }
{ "name" : "uniqueIndex", "ns" : "exstream.connections", "unique" : true, "dropDups" : true, "key" : { "parentId" : 1, "objectId" : 1 }, "v" : 0 }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.index.subscription", "name" : "_id_" }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.filter.subscription", "name" : "_id_" }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.likes", "name" : "_id_" }
{ "v" : 1, "key" : { "parentId" : 1, "objectId" : 1, "created" : 1, "updated" : 1 }, "unique" : true, "ns" : "exstream.likes", "name" : "uniqueIndex", "dropDups" : true }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.comments", "name" : "_id_" }
{ "v" : 1, "key" : { "parentId" : 1, "objectId" : 1, "created" : 1, "updated" : 1 }, "unique" : true, "ns" : "exstream.comments", "name" : "uniqueIndex", "dropDups" : true }
{ "name" : "_id_", "ns" : "exstream.filter.follow", "key" : { "_id" : 1 }, "v" : 0 }
{ "name" : "_id_", "ns" : "exstream.index.follow", "key" : { "_id" : 1 }, "v" : 0 }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.connection.subscribe", "name" : "_id_" }
{ "v" : 1, "key" : { "s" : 1, "e" : 1 }, "unique" : true, "ns" : "exstream.connection.subscribe", "name" : "uniqueIndex.connection", "dropDups" : true }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.connection.block", "name" : "_id_" }
{ "v" : 1, "key" : { "s" : 1, "e" : 1 }, "unique" : true, "ns" : "exstream.connection.block", "name" : "uniqueIndex.connection", "dropDups" : true }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.kv.lastRead", "name" : "_id_" }
{ "v" : 1, "key" : { "key" : 1 }, "ns" : "exstream.kv.lastRead", "name" : "key_1" }
{ "v" : 1, "key" : { "_id" : 1 }, "ns" : "exstream.kv.count", "name" : "_id_" }
{ "v" : 1, "key" : { "key" : 1 }, "ns" : "exstream.kv.count", "name" : "key_1" }
{ "v" : 1, "key" : { "uid" : 1, "s" : 1 }, "ns" : "exstream.filter.follow", "name" : "idx2" }
{ "v" : 1, "key" : { "uid" : 1, "s" : 1 }, "ns" : "exstream.filter.subscription", "name" : "idx2" }
{ "v" : 1, "key" : { "uid" : 1, "c" : 1, "v" : 1, "s" : 1 }, "ns" : "exstream.filter.follow", "name" : "idx1" }
{ "v" : 1, "key" : { "uid" : 1, "c" : 1, "v" : 1, "s" : 1 }, "ns" : "exstream.filter.subscription", "name" : "idx1" }
{ "v" : 1, "key" : { "k" : 1, "p" : 1, "vi" : 1, "ac" : 1 }, "ns" : "exstream.index.follow", "name" : "idx_asc" }
{ "v" : 1, "key" : { "k" : 1, "p" : -1, "vi" : 1, "ac" : 1 }, "ns" : "exstream.index.follow", "name" : "idx_desc" }
{ "v" : 1, "key" : { "k" : 1, "p" : 1, "vi" : 1, "ac" : 1 }, "ns" : "exstream.index.subscription", "name" : "idx_asc" }
{ "v" : 1, "key" : { "k" : 1, "p" : -1, "vi" : 1, "ac" : 1 }, "ns" : "exstream.index.subscription", "name" : "idx_desc" }

Comment by Kristina Chodorow (Inactive) [ 22/Nov/11 ]

Okay, thanks. I have been unable to reproduce so far. Can you describe what kinds of operations are happening on the primary?

Comment by Steffen [ 22/Nov/11 ]

Should be the 15th.
Are you able to reproduce the problem?

Comment by Kristina Chodorow (Inactive) [ 21/Nov/11 ]

Was the mongostat taken on the 15th? 16th?

Comment by Steffen [ 18/Nov/11 ]

log of repair process and first start after repair.

Comment by Steffen [ 18/Nov/11 ]

Log of the secondary from nov 15

Comment by Kristina Chodorow (Inactive) [ 18/Nov/11 ]

Thanks for all the information. I'm not sure what day mongostat was from, but from MMS, it looks like it was up to November 15th that would be of interest, log-wise. Do you have the secondary's log from then? Or was the lock up after that spike?

(Also, please don't mark comments viewable by Users only, it just messes us up (and they're still visible to everyone).)

Comment by Steffen [ 17/Nov/11 ]

log of the secondary which is behind the master and tries to catch up.

Comment by Steffen [ 17/Nov/11 ]

all data on this replicaset uses 125 GB.

We have tried this with another node which did a full resync but we ran into this bug: https://jira.mongodb.org/browse/SERVER-4294
If we don't hit the edge case the node also locks with 100% not catching up.

We have another replicaset with all indexes at version 1.8 (v:0). We added there also a clean node for backup purposes which has the new indexes from the initial sync and it works without problems.

Comment by Eliot Horowitz (Inactive) [ 17/Nov/11 ]

Can you attach the log from the secondary when it can't keep up?

How big is the data set?

Have you tried not doing a repair, but just letting a secondary do a full resync?

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