Re: Locked rate is 0% but all operations are blocked

[William Zola]

Hi Eason!

I'll need some additional information to diagnose this problem.  Please let me know the following:

 - What operating system and OS version are you using to host MongoDB?
 - Are you running this OS on a physical machine or a virtual machine?
 - What type of hardware are you using?  How much RAM do you have?  How much disk space do you have?
 - What file system type are you using for your database files? 
 - What type of hard drives are you using?  Is this physical storage, network storage, a SAN, a NAS, or some other method?
 - If this is network storage, what type of network drive are you using?  (NFS, XFS, SMB, etc.)
 - What network card are you using?  Do you have a firewall installed?

If you're using a virtual machine, please let me know the following:
 - What Virtual Machine software are you using?
 - Are these hosts all using the same physical machine, or different physical machines?
 - Are there other hosts using the same underlying physical machine?
 - Do the virtual machines have all of their RAM and CPU time fully dedicated to that machine, or are they shared among multiple virtual machines?

Once I have this information, I can move forward with my diagnosis.  I look forward to hearing from you soon.  Have a great day!

 -William


On Friday, October 5, 2012 4:17:26 AM UTC-7, 林逸珅 wrote:

Hi all,

The following is my environments:

Version: mongo 2.0.6

Arch:

2 mongo shard

3 repl per shard

3 mongo config

4 mongos

I got a strange situation that Locked rate was 0% but all operations were blocked.

From the mongostat output, you can see that all operations are blocked with 180 qr at 07:43:22, but the locked rate is 0%

I expected there should have a lot of profiling log in mongo.log at 07:43:25, because there were a lot of operation that were blocked for 3 seconds. 

But I was wrong. 

There were only 2 profiling log at 07:43:25. The following is mongo.log from 07:43:19 to 07:44:32

Oct  5 07:43:19 xxx mongod-shard: Fri Oct  5 07:43:18 [conn270713] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:19 xxx mongod-shard: Fri Oct  5 07:43:19 [conn282879] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:16700 nscanned:19443 scanAndOrder:1 nreturned:16700 reslen:2890771 443ms

Oct  5 07:43:20 xxx mongod-shard: Fri Oct  5 07:43:19 [conn281907] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:16800 nscanned:19443 scanAndOrder:1 nreturned:16800 reslen:2908036 418ms

Oct  5 07:43:20 xxx mongod-shard: Fri Oct  5 07:43:20 [conn269985] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:20 xxx mongod-shard: Fri Oct  5 07:43:20 [conn267405] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:16900 nscanned:19443 scanAndOrder:1 nreturned:16900 reslen:2925148 469ms

Oct  5 07:43:20 xxx mongod-shard: Fri Oct  5 07:43:20 [conn283069] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:17000 nscanned:19443 scanAndOrder:1 nreturned:17000 reslen:2942355 507ms

Oct  5 07:43:21 xxx mongod-shard: Fri Oct  5 07:43:21 [conn284814] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:22 xxx mongod-shard: Fri Oct  5 07:43:22 [initandlisten] connection accepted from 127.0.0.1:61617 #288906

Oct  5 07:43:22 xxx mongod-shard: Fri Oct  5 07:43:22 [conn288906] end connection 127.0.0.1:61617

Oct  5 07:43:25 xxx mongod-shard: Fri Oct  5 07:43:24 [conn283069] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:25 xxx mongod-shard: Fri Oct  5 07:43:25 [conn274691] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:17100 nscanned:19443 scanAndOrder:1 nreturned:17100 reslen:2959467 630ms

Oct  5 07:43:25 xxx mongod-shard: Fri Oct  5 07:43:25 [conn280838] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:25 xxx mongod-shard: Fri Oct  5 07:43:25 [conn280985] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:17200 nscanned:19443 scanAndOrder:1 nreturned:17200 reslen:2976775 462ms

Oct  5 07:43:26 xxx mongod-shard: Fri Oct  5 07:43:26 [conn264932] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:17300 nscanned:19443 scanAndOrder:1 nreturned:17300 reslen:2994061 457ms

Oct  5 07:43:27 xxx mongod-shard: Fri Oct  5 07:43:26 [conn283069] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:17400 nscanned:19443 scanAndOrder:1 nreturned:17400 reslen:3011062 471ms

Oct  5 07:43:27 xxx mongod-shard: Fri Oct  5 07:43:27 [conn275023] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:27 xxx mongod-shard: Fri Oct  5 07:43:27 [conn278446] query db1.bucket1 query: { $query: { vid: "id1" }, $orderby: { cid: 1 }, $maxScan: 1000000 } ntoreturn:17500 nscanned:19443 scanAndOrder:1 nreturned:17500 reslen:3028223 464ms

Oct  5 07:43:28 xxx mongod-shard: Fri Oct  5 07:43:28 [conn288904] end connection 10.42.91.216:11413

Oct  5 07:43:28 xxx mongod-shard: Fri Oct  5 07:43:28 [initandlisten] connection accepted from 10.42.91.216:11418 #288907

Oct  5 07:43:29 xxx mongod-shard: Fri Oct  5 07:43:29 [conn282037] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:31 xxx mongod-shard: Fri Oct  5 07:43:30 [conn288905] end connection 10.42.91.214:18556

Oct  5 07:43:31 xxx mongod-shard: Fri Oct  5 07:43:30 [initandlisten] connection accepted from 10.42.91.214:18561 #288908

Oct  5 07:43:31 xxx mongod-shard: Fri Oct  5 07:43:30 [conn275111] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

Oct  5 07:43:32 xxx mongod-shard: Fri Oct  5 07:43:32 [conn278446] info DFM::findAll(): extent 71:29901000 was empty, skipping ahead. ns:db2.online

And from the log, there was no operation about index, because as I know, mongo write log about index when there are index created

From the mongotop, the results were missed from 07:43:20 to 07:43:23. It's seems that mongotop couldn't get information.

ns    total   read    write           2012-10-05T07:43:20

local.oplog.rs    1724ms  1724ms  0ms

db1.bucket1    985ms   985ms   0ms

db2.online    111ms   0ms     89ms

db2.session    40ms    38ms    1ms

db1.dcron_task    0ms     0ms     0ms

db3.dcron_task    0ms     0ms     0ms

db3.device    0ms     0ms     0ms

db3.pns_metric    0ms     0ms     0ms

db3.policy    0ms     0ms     0ms

ns    total   read    write           2012-10-05T07:43:24

local.oplog.rs    6977ms  6977ms  0ms

db2.online    44ms    0ms     32ms

db2.session    18ms    17ms    0ms

db1.dcron_task    0ms     0ms     0ms

db3.dcron_task    0ms     0ms     0ms

db3.pns_metric    0ms     0ms     0ms

db3.policy    0ms     0ms     0ms

db3.resetpwd    0ms     0ms     0ms

db3.stratuscommand    0ms     0ms     0ms

Please give me suggestions to trouble shoot with this.

Thank you,

Best wishes,

Eason Lin