Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-18179

"top" reports inaccurate counts for multi-document operations

    • Type: Icon: Bug Bug
    • Resolution: Unresolved
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.0.2
    • Component/s: Diagnostics
    • Query Execution
    • ALL
    • Hide

      Both mongorestore and mongod are version 3.0.2 and the restore was run against a standalone.

      Here's some data collected during this period:

      mongorestore - Ran:

      mongorestore dump/
      2015-04-22T15:36:14.077-0400	building a list of dbs and collections to restore from /Users/bedrich/Downloads/dump/ dir
      2015-04-22T15:36:14.084-0400	reading metadata file from /Users/bedrich/Downloads/dump/support/issues.metadata.json
      2015-04-22T15:36:14.087-0400	restoring support.issues from file /Users/bedrich/Downloads/dump/support/issues.bson
      2015-04-22T15:36:17.080-0400	[#.......................]  support.issues  190.0 MB/2.8 GB  (6.5%)
      2015-04-22T15:36:20.082-0400	[###.....................]  support.issues  439.3 MB/2.8 GB  (15.1%)
      2015-04-22T15:36:23.083-0400	[#####...................]  support.issues  637.2 MB/2.8 GB  (21.9%)
      2015-04-22T15:36:26.081-0400	[#######.................]  support.issues  861.1 MB/2.8 GB  (29.7%)
      2015-04-22T15:36:29.079-0400	[########................]  support.issues  1.0 GB/2.8 GB  (36.3%)
      2015-04-22T15:36:32.080-0400	[########................]  support.issues  1.0 GB/2.8 GB  (36.3%)
      2015-04-22T15:36:35.082-0400	[########................]  support.issues  1.1 GB/2.8 GB  (37.4%)
      2015-04-22T15:36:38.081-0400	[##########..............]  support.issues  1.2 GB/2.8 GB  (44.0%)
      2015-04-22T15:36:41.080-0400	[###########.............]  support.issues  1.4 GB/2.8 GB  (48.4%)
      2015-04-22T15:36:44.083-0400	[###########.............]  support.issues  1.4 GB/2.8 GB  (48.4%)
      2015-04-22T15:36:47.080-0400	[############............]  support.issues  1.5 GB/2.8 GB  (53.9%)
      2015-04-22T15:36:50.084-0400	[##############..........]  support.issues  1.7 GB/2.8 GB  (61.6%)
      2015-04-22T15:36:53.081-0400	[################........]  support.issues  1.9 GB/2.8 GB  (67.1%)
      2015-04-22T15:36:56.079-0400	[################........]  support.issues  1.9 GB/2.8 GB  (67.1%)
      2015-04-22T15:36:59.083-0400	[#################.......]  support.issues  2.0 GB/2.8 GB  (71.5%)
      2015-04-22T15:37:02.083-0400	[#################.......]  support.issues  2.0 GB/2.8 GB  (71.5%)
      2015-04-22T15:37:05.081-0400	[##################......]  support.issues  2.2 GB/2.8 GB  (75.9%)
      2015-04-22T15:37:08.080-0400	[###################.....]  support.issues  2.3 GB/2.8 GB  (82.5%)
      2015-04-22T15:37:11.082-0400	[#####################...]  support.issues  2.5 GB/2.8 GB  (89.1%)
      2015-04-22T15:37:14.080-0400	[#######################.]  support.issues  2.7 GB/2.8 GB  (96.2%)
      

      mongostat - Ran:

      mongostat
       1574    *0     *0     *0       0     3|0       0   8.5G 19.8G 4.1G      0          0   0|1   0|1   34m    11k    6 15:36:45
        5702    *0     *0     *0       0     4|0       0   8.5G 19.8G 4.2G      0          0   0|0   0|1  101m    11k    6 15:36:46
        3438    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.6G      0          0   0|0   0|0   67m    11k    6 15:36:47
        3780    *0     *0     *0       0     3|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|1   67m    10k    6 15:36:48
        5989    *0     *0     *0       0     6|0       0   8.5G 19.8G 3.8G      0          0   0|1   0|1  101m    11k    6 15:36:49
      insert query update delete getmore command flushes mapped vsize  res faults idx miss % qr|qw ar|aw netIn netOut conn     time
        4683    *0     *0     *0       0     3|0       0   8.5G 19.8G 3.6G      0          0   0|0   0|0   67m    10k    6 15:36:50
        6036    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0  101m    11k    6 15:36:51
        1855    *0     *0     *0       0     3|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0   34m    10k    6 15:36:52
          *0    *0     *0     *0       0     1|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0   79b    10k    6 15:36:53
          *0    *0     *0     *0       0     2|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0  133b    10k    6 15:36:54
          *0    *0     *0     *0       0     1|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0   79b    10k    6 15:36:55
          *0    *0     *0     *0       0     1|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0   79b    10k    6 15:36:56
        1692    *0     *0     *0       0     3|0       0   8.5G 19.8G 3.6G      0          0   0|0   0|0   33m    10k    6 15:36:57
        4976    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0  101m    11k    6 15:36:58
          *0    *0     *0     *0       0     2|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0  133b    10k    6 15:36:59
      insert query update delete getmore command flushes mapped vsize  res faults idx miss % qr|qw ar|aw netIn netOut conn     time
          *0    *0     *0     *0       0     1|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0   79b    10k    6 15:37:00
          *0    *0     *0     *0       0     1|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0   79b    10k    6 15:37:01
          *0    *0     *0     *0       0     2|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0  133b    10k    6 15:37:02
          *0    *0     *0     *0       0     2|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0  136b    23k    6 15:37:03
        4990    *0     *0     *0       0     5|0       0   8.5G 19.8G 3.8G      0          0   0|0   0|0  101m    23k    6 15:37:04
        1691    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.7G      0          0   0|1   0|1   33m    23k    6 15:37:05
        3341    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.6G      0          0   0|1   0|1   67m    23k    6 15:37:06
        3298    *0     *0     *0       0     5|0       0   8.5G 19.8G 3.7G      0          0   0|1   0|1   67m    23k    6 15:37:07
        3172    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.5G      0          0   0|1   0|1   67m    23k    6 15:37:08
        3022    *0     *0     *0       0     5|0       0   8.5G 19.8G 3.6G      0          0   0|1   0|1   67m    23k    6 15:37:09
      insert query update delete getmore command flushes mapped vsize  res faults idx miss % qr|qw ar|aw netIn netOut conn     time
        5145    *0     *0     *0       0     5|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|0  101m    23k    6 15:37:10
        2655    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.6G      0          0   0|0   0|0   67m    23k    6 15:37:11
        3253    *0     *0     *0       0     5|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|1   67m    23k    6 15:37:12
        2962    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.7G      0          0   0|1   0|1   67m    23k    6 15:37:13
        4958    *0     *0     *0       0     6|0       0   8.5G 19.8G 3.6G      0          0   0|0   0|0  101m    23k    6 15:37:14
        3284    *0     *0     *0       0     5|0       0   8.5G 19.8G 3.7G      0          0   0|0   0|1   67m    23k    6 15:37:15
        1914    *0     *0     *0       0     4|0       0   8.5G 19.8G 3.9G      1          0   1|0   1|1   30m    23k    6 15:37:16

      top - Ran

      while(true){printjson(db.runCommand("top")["totals"]["support.issues"]["insert"]);printjson(new Date());sleep(1000)}
      Wisdoms-MacBook-Pro(mongod-3.0.2) admin> while(true){printjson(db.runCommand("top")["totals"]["support.issues"]["insert"]);printjson(new Date());sleep(1000)}
      {
        "count": 65,
        "time": 13880654
      }
      ISODate("2015-04-22T19:37:03.192Z")
      {
        "count": 67,
        "time": 14114514
      }
      ISODate("2015-04-22T19:37:04.198Z")
      {
        "count": 69,
        "time": 14350828
      }
      ISODate("2015-04-22T19:37:05.205Z")
      {
        "count": 71,
        "time": 14569963
      }
      ISODate("2015-04-22T19:37:06.211Z")
      {
        "count": 73,
        "time": 15274439
      }
      ISODate("2015-04-22T19:37:07.215Z")
      {
        "count": 75,
        "time": 15605750
      }
      ISODate("2015-04-22T19:37:08.218Z")
      {
        "count": 77,
        "time": 15843429
      }
      ISODate("2015-04-22T19:37:09.222Z")
      {
        "count": 79,
        "time": 16439871
      }
      ISODate("2015-04-22T19:37:10.228Z")
      {
        "count": 81,
        "time": 16820034
      }
      ISODate("2015-04-22T19:37:11.230Z")
      {
        "count": 83,
        "time": 17090708
      }
      ISODate("2015-04-22T19:37:12.235Z")
      {
        "count": 86,
        "time": 17589414
      }
      ISODate("2015-04-22T19:37:13.237Z")
      {
        "count": 88,
        "time": 17866561
      }
      ISODate("2015-04-22T19:37:14.242Z")
      {
        "count": 91,
        "time": 18252756
      }
      ISODate("2015-04-22T19:37:15.244Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:16.246Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:17.251Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:18.254Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:19.259Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:20.261Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:21.262Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:22.266Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:23.269Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:24.273Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:25.278Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:26.280Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:27.281Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:28.284Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:29.285Z")
      {
        "count": 92,
        "time": 18443123
      }
      ISODate("2015-04-22T19:37:30.286Z")
      {
        "count": 92,
        "time": 18443123
      }
      
      Show
      Both mongorestore and mongod are version 3.0.2 and the restore was run against a standalone. Here's some data collected during this period: mongorestore - Ran: mongorestore dump/ 2015-04-22T15:36:14.077-0400 building a list of dbs and collections to restore from /Users/bedrich/Downloads/dump/ dir 2015-04-22T15:36:14.084-0400 reading metadata file from /Users/bedrich/Downloads/dump/support/issues.metadata.json 2015-04-22T15:36:14.087-0400 restoring support.issues from file /Users/bedrich/Downloads/dump/support/issues.bson 2015-04-22T15:36:17.080-0400 [#.......................] support.issues 190.0 MB/2.8 GB (6.5%) 2015-04-22T15:36:20.082-0400 [###.....................] support.issues 439.3 MB/2.8 GB (15.1%) 2015-04-22T15:36:23.083-0400 [#####...................] support.issues 637.2 MB/2.8 GB (21.9%) 2015-04-22T15:36:26.081-0400 [#######.................] support.issues 861.1 MB/2.8 GB (29.7%) 2015-04-22T15:36:29.079-0400 [########................] support.issues 1.0 GB/2.8 GB (36.3%) 2015-04-22T15:36:32.080-0400 [########................] support.issues 1.0 GB/2.8 GB (36.3%) 2015-04-22T15:36:35.082-0400 [########................] support.issues 1.1 GB/2.8 GB (37.4%) 2015-04-22T15:36:38.081-0400 [##########..............] support.issues 1.2 GB/2.8 GB (44.0%) 2015-04-22T15:36:41.080-0400 [###########.............] support.issues 1.4 GB/2.8 GB (48.4%) 2015-04-22T15:36:44.083-0400 [###########.............] support.issues 1.4 GB/2.8 GB (48.4%) 2015-04-22T15:36:47.080-0400 [############............] support.issues 1.5 GB/2.8 GB (53.9%) 2015-04-22T15:36:50.084-0400 [##############..........] support.issues 1.7 GB/2.8 GB (61.6%) 2015-04-22T15:36:53.081-0400 [################........] support.issues 1.9 GB/2.8 GB (67.1%) 2015-04-22T15:36:56.079-0400 [################........] support.issues 1.9 GB/2.8 GB (67.1%) 2015-04-22T15:36:59.083-0400 [#################.......] support.issues 2.0 GB/2.8 GB (71.5%) 2015-04-22T15:37:02.083-0400 [#################.......] support.issues 2.0 GB/2.8 GB (71.5%) 2015-04-22T15:37:05.081-0400 [##################......] support.issues 2.2 GB/2.8 GB (75.9%) 2015-04-22T15:37:08.080-0400 [###################.....] support.issues 2.3 GB/2.8 GB (82.5%) 2015-04-22T15:37:11.082-0400 [#####################...] support.issues 2.5 GB/2.8 GB (89.1%) 2015-04-22T15:37:14.080-0400 [#######################.] support.issues 2.7 GB/2.8 GB (96.2%) mongostat - Ran: mongostat 1574 *0 *0 *0 0 3|0 0 8.5G 19.8G 4.1G 0 0 0|1 0|1 34m 11k 6 15:36:45 5702 *0 *0 *0 0 4|0 0 8.5G 19.8G 4.2G 0 0 0|0 0|1 101m 11k 6 15:36:46 3438 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.6G 0 0 0|0 0|0 67m 11k 6 15:36:47 3780 *0 *0 *0 0 3|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|1 67m 10k 6 15:36:48 5989 *0 *0 *0 0 6|0 0 8.5G 19.8G 3.8G 0 0 0|1 0|1 101m 11k 6 15:36:49 insert query update delete getmore command flushes mapped vsize res faults idx miss % qr|qw ar|aw netIn netOut conn time 4683 *0 *0 *0 0 3|0 0 8.5G 19.8G 3.6G 0 0 0|0 0|0 67m 10k 6 15:36:50 6036 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 101m 11k 6 15:36:51 1855 *0 *0 *0 0 3|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 34m 10k 6 15:36:52 *0 *0 *0 *0 0 1|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 79b 10k 6 15:36:53 *0 *0 *0 *0 0 2|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 133b 10k 6 15:36:54 *0 *0 *0 *0 0 1|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 79b 10k 6 15:36:55 *0 *0 *0 *0 0 1|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 79b 10k 6 15:36:56 1692 *0 *0 *0 0 3|0 0 8.5G 19.8G 3.6G 0 0 0|0 0|0 33m 10k 6 15:36:57 4976 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 101m 11k 6 15:36:58 *0 *0 *0 *0 0 2|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 133b 10k 6 15:36:59 insert query update delete getmore command flushes mapped vsize res faults idx miss % qr|qw ar|aw netIn netOut conn time *0 *0 *0 *0 0 1|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 79b 10k 6 15:37:00 *0 *0 *0 *0 0 1|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 79b 10k 6 15:37:01 *0 *0 *0 *0 0 2|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 133b 10k 6 15:37:02 *0 *0 *0 *0 0 2|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 136b 23k 6 15:37:03 4990 *0 *0 *0 0 5|0 0 8.5G 19.8G 3.8G 0 0 0|0 0|0 101m 23k 6 15:37:04 1691 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.7G 0 0 0|1 0|1 33m 23k 6 15:37:05 3341 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.6G 0 0 0|1 0|1 67m 23k 6 15:37:06 3298 *0 *0 *0 0 5|0 0 8.5G 19.8G 3.7G 0 0 0|1 0|1 67m 23k 6 15:37:07 3172 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.5G 0 0 0|1 0|1 67m 23k 6 15:37:08 3022 *0 *0 *0 0 5|0 0 8.5G 19.8G 3.6G 0 0 0|1 0|1 67m 23k 6 15:37:09 insert query update delete getmore command flushes mapped vsize res faults idx miss % qr|qw ar|aw netIn netOut conn time 5145 *0 *0 *0 0 5|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|0 101m 23k 6 15:37:10 2655 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.6G 0 0 0|0 0|0 67m 23k 6 15:37:11 3253 *0 *0 *0 0 5|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|1 67m 23k 6 15:37:12 2962 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.7G 0 0 0|1 0|1 67m 23k 6 15:37:13 4958 *0 *0 *0 0 6|0 0 8.5G 19.8G 3.6G 0 0 0|0 0|0 101m 23k 6 15:37:14 3284 *0 *0 *0 0 5|0 0 8.5G 19.8G 3.7G 0 0 0|0 0|1 67m 23k 6 15:37:15 1914 *0 *0 *0 0 4|0 0 8.5G 19.8G 3.9G 1 0 1|0 1|1 30m 23k 6 15:37:16 top - Ran while(true){printjson(db.runCommand("top")["totals"]["support.issues"]["insert"]);printjson(new Date());sleep(1000)} Wisdoms-MacBook-Pro(mongod-3.0.2) admin> while ( true ){printjson(db.runCommand( "top" )[ "totals" ][ "support.issues" ][ "insert" ]);printjson( new Date());sleep(1000)} { "count" : 65, "time" : 13880654 } ISODate( "2015-04-22T19:37:03.192Z" ) { "count" : 67, "time" : 14114514 } ISODate( "2015-04-22T19:37:04.198Z" ) { "count" : 69, "time" : 14350828 } ISODate( "2015-04-22T19:37:05.205Z" ) { "count" : 71, "time" : 14569963 } ISODate( "2015-04-22T19:37:06.211Z" ) { "count" : 73, "time" : 15274439 } ISODate( "2015-04-22T19:37:07.215Z" ) { "count" : 75, "time" : 15605750 } ISODate( "2015-04-22T19:37:08.218Z" ) { "count" : 77, "time" : 15843429 } ISODate( "2015-04-22T19:37:09.222Z" ) { "count" : 79, "time" : 16439871 } ISODate( "2015-04-22T19:37:10.228Z" ) { "count" : 81, "time" : 16820034 } ISODate( "2015-04-22T19:37:11.230Z" ) { "count" : 83, "time" : 17090708 } ISODate( "2015-04-22T19:37:12.235Z" ) { "count" : 86, "time" : 17589414 } ISODate( "2015-04-22T19:37:13.237Z" ) { "count" : 88, "time" : 17866561 } ISODate( "2015-04-22T19:37:14.242Z" ) { "count" : 91, "time" : 18252756 } ISODate( "2015-04-22T19:37:15.244Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:16.246Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:17.251Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:18.254Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:19.259Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:20.261Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:21.262Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:22.266Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:23.269Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:24.273Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:25.278Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:26.280Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:27.281Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:28.284Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:29.285Z" ) { "count" : 92, "time" : 18443123 } ISODate( "2015-04-22T19:37:30.286Z" ) { "count" : 92, "time" : 18443123 }

      For example, while running a bulk insert operation with several documents, simultaneously running db.runCommand("top") on the admin database indicates only 1 insert is occurring - even though a number of documents are being inserted.

      Monitoring applications that rely on this count are therefore unable to report accurate counts when clients perform multi-document operations.

            Assignee:
            backlog-query-execution [DO NOT USE] Backlog - Query Execution
            Reporter:
            adinoyi.omuya@mongodb.com Adinoyi Omuya
            Votes:
            0 Vote for this issue
            Watchers:
            18 Start watching this issue

              Created:
              Updated: