Duplicate Key Error on local.slaves

We have been getting user assertion errors showing up on our 5 node replica set for a while.

image

Initially these assertion errors were not showing up in the mongo logs, so we enabled increased logging – details can be found here – https://dbamohsin.wordpress.com/2015/03/31/set-additional-logging-and-tracing/

The assertion errors turned out to be related to the local.slaves collection:

[slaveTracking] User Assertion: 11000:E11000 duplicate key error index: local.slaves.$id dup key: { : ObjectId(‘4def89b415e7ee0aa29fd64b’) }
[slaveTracking] update local.slaves query: { _id: ObjectId(‘4def89b415e7ee0aa29fd64b’), host: "10.90.47.183", ns: "local.oplog.rs" }
update: { $set: { syncedTo: Timestamp 1323652648000|784 } }
exception 11000 E11000 duplicate key error index: local.slaves.$id dup key: { : ObjectId(‘4def89b415e7ee0aa29fd64b’) } 0ms

Taken from Mongo Docs:

The duplicate key on local.slaves error, occurs when a secondary or slave changes its hostname and the primary or master tries to update its local.slaves collection with the new name. The update fails because it contains the same _id value as the document containing the previous hostname. The error itself will resemble the following.

This is a benign error and does not affect replication operations on the secondary or slave.

To prevent the error from appearing, drop the local.slaves collection from the primary or master, with the following sequence of operations in the mongo shell:

use local
db.slaves.drop()

This should resolve the assertion errors and the new config will be picked up next time the replica syncs:

use local
db.slaves.find()

This topic is also discussed in Jira – https://jira.mongodb.org/browse/SERVER-4473

db.currentOp Queries in mongodb

Return active sessions running for more than x seconds:

db.currentOp().inprog.forEach(
  function(op) {
    if(op.secs_running > 5) printjson(op);
  }
)

Waiting for a lock and not a read:

db.currentOp().inprog.forEach(
   function(d){
     if(d.waitingForLock && d.lockType != "read") 
       printjson(d)
     })

Finding active writes:

db.currentOp().inprog.forEach(
   function(d){
     if(d.active && d.lockType == "write") 
       printjson(d)
     })

Finding active reads:

db.currentOp().inprog.forEach(
   function(d){
     if(d.active && d.lockType == "read") 
       printjson(d)
     })

Set additional logging and tracing in mongodb

logLevel Parameter

To set logging on an ad hoc basis, the parameter can be set in the admin database:

--Current log level:
use admin;
db.runCommand({ getParameter: 1, logLevel: 1 })


Logging can be set between 0 and 5, with 5 being the most verbose logging:

--Set log level to 3
use admin;
db.runCommand( { setParameter: 1, logLevel: 3 } )

LogLevel can also be set at instance startup in the mongod.conf under the systemLog.verbosity parameter:

For more details – http://docs.mongodb.org/manual/reference/configuration-options/#systemLog.verbosity

Database Profiling

The database profiler collects fine grained data about MongoDB write operations, cursors, database commands on a running mongod instance. You can enable profiling on a per-database or per-instance basis. The database profiling is also configurable when enabling profiling

--get the tracing level and current slow ops threshold
db.getProfilingStatus()

--set the profiling level to 2
db.setProfilingLevel(2)


See here for full profiling details – http://docs.mongodb.org/manual/tutorial/manage-the-database-profiler/

// last few entries
show profile                                                     
 
// sort by natural order (time in)
db.system.profile.find({}).sort({$natural:-1})
 
// sort by slow queries first
db.system.profile.find({}).sort({$millis:-1})Alimit(10);
 
// anything > 20ms                  
db.system.profile.find({"millis":{$gt:20}})
 
// single coll order by response time                      
db.system.profile.find({"ns":"test.foo"}).sort({"millis":-1})
 
// regular expression on namespace
db.system.profile.find( { "ns": /test.foo/ } ).sort({millis:-1,$ts:-1})
 
// anything thats moved    
db.system.profile.find({"moved":true})
 
// large scans                           
db.system.profile.find({"nscanned":{$gt:10000}})
 
// anything doing range or full scans                 
db.system.profile.find({"nreturned":{$gt:1}})

Aggregation framework queries:

--response time by operation type
db.system.profile.aggregate(
{ $group : { 
   _id :"$op", 
   count:{$sum:1},
   "max response time":{$max:"$millis"},
   "avg response time":{$avg:"$millis"}
}});
 
--slowest by namespace
db.system.profile.aggregate(
{ $group : {
  _id :"$ns",
  count:{$sum:1}, 
  "max response time":{$max:"$millis"}, 
  "avg response time":{$avg:"$millis"}  
}},
{$sort: {
 "max response time":-1}
}); 
 
--slowest by client
db.system.profile.aggregate(
{$group : { 
  _id :"$client", 
  count:{$sum:1}, 
  "max response time":{$max:"$millis"}, 
  "avg response time":{$avg:"$millis"}  
}},
{$sort: { 
  "max response time":-1} 
});