mongod hang during EVG 3.0.7-pre patch testing

Setup/Test Details

• 3 node replSet cluster
• wiredTiger
• SHA: 180db3d2ca3191d1257800d9efb759fbc2e889e8
• Build: https://evergreen.mongodb.com/task/mongodb_mongo_v3.0_linux_64_compile_180db3d2ca3191d1257800d9efb759fbc2e889e8_15_10_01_06_15_32

Observation

• mongod hang during YCSB 50 read/50 update test
• CPU usage on the primary is low
• shell will hang if do insert/find
• looked at pending request, lots of “aw” from mongostat

  [ec2-user@ip-10-2-0-100 ~]$ ./mongodb-linux-x86_64-3.0.7-pre-/bin/mongostat
  insert query update delete getmore command % dirty % used flushes vsize   res qr|qw ar|aw netIn netOut conn set repl     time
      *0    *0     *0     *0       0     5|0    35.7   40.8       0 13.2G 12.6G   1|7  1|58  414b    63k   76 rs0  PRI 22:17:29
      *0    *0     *0     *0       0     6|0    35.7   40.8       0 13.2G 12.6G   1|7  1|58  472b    63k   76 rs0  PRI 22:17:30
      *0    *0     *0     *0       0     5|0    35.7   40.8       0 13.2G 12.6G   1|6  1|59  414b    63k   76 rs0  PRI 22:17:31
  

• output from YCSB

   [2015/10/01 18:00:24.904]  100 sec: 7926293 operations; 88118.59 current ops/sec; [UPDATE AverageLatency(us)=1036.89] [READ AverageLatency(us)=406.35]
   [2015/10/01 18:00:34.897]  110 sec: 8724240 operations; 79794.7 current ops/sec; [UPDATE AverageLatency(us)=1158.45] [READ AverageLatency(us)=432.6]
   [2015/10/01 18:00:44.897]  120 sec: 9584935 operations; 86060.89 current ops/sec; [UPDATE AverageLatency(us)=1062.74] [READ AverageLatency(us)=416.89]
   [2015/10/01 18:00:54.898]  130 sec: 10387888 operations; 80287.27 current ops/sec; [UPDATE AverageLatency(us)=1138.84] [READ AverageLatency(us)=445.68]
   [2015/10/01 18:01:04.898]  140 sec: 11229191 operations; 84130.3 current ops/sec; [UPDATE AverageLatency(us)=1097.95] [READ AverageLatency(us)=413.37]
   [2015/10/01 18:01:14.899]  150 sec: 12017060 operations; 78779.02 current ops/sec; [UPDATE AverageLatency(us)=1155.19] [READ AverageLatency(us)=462.05]
   [2015/10/01 18:01:24.899]  160 sec: 12087119 operations; 7005.9 current ops/sec; [UPDATE AverageLatency(us)=1683.19] [READ AverageLatency(us)=535.9]
   [2015/10/01 18:01:34.899]  170 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:01:44.899]  180 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:01:54.899]  190 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:02:04.899]  200 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:02:14.899]  210 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:02:24.899]  220 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:02:34.900]  230 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:02:44.900]  240 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:02:54.900]  250 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:03:04.901]  260 sec: 12087119 operations; 0 current ops/sec;
   [2015/10/01 18:03:14.901]  270 sec: 12087119 operations; 0 current ops/sec;