Q: mongotop / mongostat reporting & where Mongo spends its processing time

130 views

Skip to first unread message

J-EC

unread,

Mar 28, 2019, 11:46:50 AM3/28/19

to mongodb-user

Hi,

I'd really appreciate some help about 'mongotop' reporting running MongoDB v3.6.

The test Mongo configuration is:

Sharded with 2 shards (rs0 & rs1) using in-memory storage
4 mongos instances
1 config-server replica set
All test collections configured with hashed sharding + indexes (no COLLSCAN)
Kubernetes containerized environment on OpenStack (no NUMA and THP disabled)

Consider this 'mongotop' output which was collected over a 60 second period of time:

$ mongotop --host mongo1:27020,mongo2:27021,mongo3:27022,mongo4:27023,mongo5:27024,mongo6:27025 60
2019-03-22T13:02:19.392+0000    connected to: mongo1:27020,mongo2:27021,mongo3:27022,mongo4:27023,mongo5:27024,mongo6:27025

                             ns      total      read     write    2019-03-22T13:03:19Z
                      db1_collA    11700ms    2834ms    8865ms
                      db1_collB     7223ms    3514ms    3708ms
                      db2_collA     5705ms     943ms    4762ms
                 local.oplog.rs     3772ms    3772ms       0ms
                      db1_collC     3179ms     410ms    2769ms
         config.system.sessions       11ms       0ms      11ms
   config.cache.chunks.db1_coll        4ms       4ms       0ms
   config.cache.chunks.db1_coll        4ms       4ms       0ms
                      db1_collD        3ms       3ms       0ms
                      db2_collC        3ms       3ms       0ms
                                   =======
                                      31.6 seconds

The above tells me that Mongo was processing the above namespaces for 31.6 seconds, which included 'local.oplog.rs' processing.

Questions:

1. How do I figure out what Mongo was doing the remaining 28.4 seconds?

2. I think 'mongotop' only reports processing from primaries, even if secondaries are included in the --host list?

If this helps answer the question, below is 'mongostat' output shortly after the capture above (the operations executing against Mongo are static, so aren't varying over time):

$ mongostat --host mongo1:27020,mongo2:27021,mongo3:27022,mongo4:27023,mongo5:27024,mongo6:27025 60
        host insert query update delete getmore command flushes vsize   res qrw arw net_in net_out conn set repl                time
mongo1:27020     *0 1183   1573    167    1250   662|0       0 7.22G 5.41G 0|0 0|0 6.23m   9.79m 103 rs0 PRI Mar 22 13:05:57.094
mongo2:27021   *168    *0 *1217   *167       0     1|0       0 6.94G 5.47G 0|0 0|0   387b   2.13k   17 rs0 SEC Mar 22 13:05:57.093
mongo3:27022   *168    *0 *1217   *167       0     1|0       0 6.99G 5.51G 0|0 0|0   387b   2.13k   17 rs0 SEC Mar 22 13:05:57.093
mongo4:27023     *0   631   1173    167    1246   653|0       0 7.25G 5.39G 0|0 0|0 4.55m   6.79m   97 rs1 PRI Mar 22 13:05:57.091
mongo5:27024   *168    *0   *792   *167       0     1|0       0 7.06G 5.41G 0|0 0|1   387b   2.13k   17 rs1 SEC Mar 22 13:05:57.094
mongo6:27025   *168    *0   *792   *167       0     1|0       0 6.99G 5.40G 0|0 0|0   387b   2.13k   17 rs1 SEC Mar 22 13:05:57.092

The two primaries (mongo1 & mongo4) are executing 4835 + 3870 = 8705 operations/sec: the vast majority of 'getmore' are from the secondaries it seems; not sure about the 'command'.

It looks like 'mongostat' averages the ops/second over the time period (e.g. 60 seconds), where 'mongotop' aggregates the processing time.

Thanks!

Kevin Adistambha

unread,

Mar 31, 2019, 9:41:15 PM3/31/19

to mongodb-user

Hi,

How do I figure out what Mongo was doing the remaining 28.4 seconds?

In mongotop 60 (print an output every 60 seconds), it’s not a straightforward calculation of 60 - 31.6. Rather, it’s the total time spent on that namespace. Depending on how many threads you use, this number can be higher than 60 seconds. For example:

$ mongotop 60
2019-04-01T12:25:08.067+1100    connected to: 127.0.0.1

                                   ns      total       read      write    2019-04-01T12:26:08+11:00
                        POCDB.POCCOLL    73449ms    31452ms    41996ms
                       local.oplog.rs       63ms       63ms        0ms
               config.system.sessions       10ms        0ms       10ms
                    admin.system.keys        0ms        0ms        0ms
                   admin.system.roles        0ms        0ms        0ms
                 admin.system.version        0ms        0ms        0ms
                  config.transactions        0ms        0ms        0ms
               local.replset.election        0ms        0ms        0ms
               local.replset.minvalid        0ms        0ms        0ms
local.replset.oplogTruncateAfterPoint        0ms        0ms        0ms

This example output shows 73.449 seconds spent in the POCDB.POCCOLL namespace using mongotop 60. This is because I used 4 threads to do reads and writes to the POCDB.POCCOLL namespace. In total, all 4 threads are using 73 seconds.

In short, mongotop allows you to determine “hot” collections in your database, where MongoDB spent most of its time processing. This will vary depending on how many threads being used, and is not a linear measurement.

I think ‘mongotop’ only reports processing from primaries, even if secondaries are included in the —host list?

Correct. This is mentioned in the host part of mongotop manual: When specifying the replica set list format, mongotop always connects to the primary..