All queries waiting for lock in mongodb

Question

I have 1 primary, 1 secondary and 1 arbiter instance in my mongo cluster and no sharding. The priority of secondary is lower than priority of primary to keep the same machine as primary.

During a very high load today, I saw 1176 queries in db.currentOp(). All of these queries except 1 are waiting for some lock. And these queries are on various collections (not just on 1 collection). One such query waiting for the lock is

        {
        "desc" : "conn802243",
        "threadId" : "0x2055e1a0",
        "connectionId" : 802243,
        "opid" : 946990251,
        "active" : false,
        "op" : "query",
        "ns" : "db.collection",
        "query" : {
            "foo" : "bar",
        },
        "client" : "10.240.0.14:49355",
        "numYields" : 0,
        "locks" : {
            "Global" : "r",
            "MMAPV1Journal" : "r"
        },
        "waitingForLock" : true,
        "lockStats" : {
            "Global" : {
                "acquireCount" : {
                    "r" : NumberLong(2)
                }
            },
            "MMAPV1Journal" : {
                "acquireCount" : {
                    "r" : NumberLong(1)
                },
                "acquireWaitCount" : {
                    "r" : NumberLong(1)
                }
            }
        }
    } 

The only query which is not waiting for the lock is a "dbstat" query which was fired by the arbiter("client" is the arbiter's ip in the below sample) and is running for more than 5 seconds.

{
        "desc" : "conn909",
        "threadId" : "0x7f53dc0",
        "connectionId" : 909,
        "opid" : 946985942,
        "active" : true,
        "secs_running" : 5,
        "microsecs_running" : NumberLong(5239773),
        "op" : "query",
        "ns" : "tb_dev",
        "query" : {
            "dbstats" : 1
        },
        "client" : "10.240.0.3:44403",
        "numYields" : 0,
        "locks" : {
            "Global" : "r",
            "MMAPV1Journal" : "r",
            "Database" : "R"
        },
        "waitingForLock" : false,
        "lockStats" : {
            "Global" : {
                "acquireCount" : {
                    "r" : NumberLong(2)
                }
            },
            "MMAPV1Journal" : {
                "acquireCount" : {
                    "r" : NumberLong(1)
                }
            },
            "Database" : {
                "acquireCount" : {
                    "R" : NumberLong(1)
                }
            }
        }
    }

Also, this looks to be a db level lock even though I am using 3.0(with mmapv1 as the storage engine).What is causing this db level lock to be held for so long?

Answer 1

In MMAPv1 write locks are collection level (version 3.0 and forward; Before 3.0, locks where database level). So, if you have 1174 clients reading "db.collection" and one client who is writing that same collection, readers will wait! Especially if you have write concern w:2 (or w:"majority") and you (only) secondary is lagging.

With wiredTiger locking mechanism is on document level.

You check here how concurrency works.

Answer 2

OK, spent some time digesting documentation today and figured I could update this with references to support the algorithms and any lost souls that find their way here.

Let's first look at your query that's allegedly (until proven guilty) blocking everyone else.

First off, it's been running about 5 seconds which is too long in my opinion. Discerned from here:

        "active" : true,
        "secs_running" : 5,
        "microsecs_running" : NumberLong(5239773),

So then, is it really blocking everyone else? Well lets look at the locks:

        "locks" : {
            "Global" : "r",
            "MMAPV1Journal" : "r",
            "Database" : "R"
        }

r and R are two very different beasts. An r lock is an "Intent Shared" lock meaning it wants everyone to know that it intends to take a lock at a lower scope. It would be like your room mate saying "Hey, I'm going to get some nachos from the fridge in the basement," meaning I intend to use something in the basement and you will later find out that the true lock is the fridge. Kind of a "look out I'm coming through" lock.

In your database's case there are Intent Shared locks on Global and MMAPV1Journal which are pretty broad scopes. Its basically everything on the physical database unit. Since these are Intent Shared locks they won't lock those resources from other folks who need locks scoped below this level, but would prevent someone from claiming a shared (R) or exclusive (W) on Global or MMAPV1Journal. Over simplification of course, but you get the idea. (I'm not particularly sure why it acquired 2 r locks on Global though).

The real thorn in your whole operation is the R lock on the conceptual Database level! This means other queries that play nice with an R or r lock on the Database level can continue to run, but any W and I'm assuming w locks will have to wait their turn. If you're not sure what I mean by database its the thing that groups collections as seen here.

In practice I'm not 100% how this works since MongoDB doesn't support transactions. I'm assuming there's a query queue and it operates on a first come first serve basis. So maybe you have this R lock on your database and the next query in the queue needs a W on some collection, but can't because of the R lock at the database level; preventing all other queries behind the W from running. Maybe?

The Query That Waited

So now that we know all of this lets look at the query that's waiting

        "waitingForLock" : true,
        "lockStats" : {
            "Global" : {
                "acquireCount" : {
                    "r" : NumberLong(2)
                }
            },
            "MMAPV1Journal" : {
                "acquireCount" : {
                    "r" : NumberLong(1)
                },
                "acquireWaitCount" : {
                    "r" : NumberLong(1)
                }
            }
        }

Yes, it is waiting for locks, but it has a Global lock already and it had to wait for an r on MMAPV1Journal. I'm pretty sure this will also try to get an r on the Database level and an R on the collection level, but since there is an R on the database it has to wait.

This part I'm not so sure about because I would assume it would have a timer of all the locks it is waiting for and not just show the ones it has acquired. The query will definitely need the locks I pointed out, but I'm not sure why this output doesn't include them.

Sources:

Databases and Collections - MongoDB

Database Profiler Output - MongoDB