mloginfo --queries returns impossible 95%-ile (greater than sum)

[ScubaDrew]

Expected behavior

running mloginfo --queries should return 95%-ile (ms) that is accurate. It must be less than the sum (ms) field, right?

Actual/current behavior

95%-ile (ms) is very large (157083118 in first line below) and is much larger than the sum (ms) field

➜ mloginfo ~/mongo-n02-logs --queries --rounding 2
     source: /Users/d/mongo-n02-logs
      host: unknown
      start: 2020 Feb 26 00:17:18.717
      end: 2020 Feb 26 20:46:22.650
date format: iso8601-local
   timezone: UTC
     length: 766272
     binary: unknown
    version: >= 3.0 (iso8601 format, level, component)
    storage: unknown

QUERIES

namespace         operation  pattern                                                                                                                                     count    min (ms)    max (ms)    mean (ms)    95%-ile (ms)    sum (ms)    allowDiskUse

n.orders    find       {"$or": [{"order_number": 1}, {"brand": 1, "external_id": 1}], "brand": 1, "shipments.shipment_info.tracking_numbers": 1, "status": {"$nin": 1}}   29809         100       53596      18988.8       157083118     5269.65    None
n.orders    find       None                                                                                                                                                7578         100      897178      10785.2        25704933     3392.05    None
n.orders    find       {"$or": [{"order_number": 1}, {"brand": 1, "external_id": 1}], "brand": 1, "status": {"$nin": 1}}                                                   9125         100       66958      13069.4        24420760     2676.25    None
n.products  find       {"_id": 1, "archived": {"$ne": 1}, "brand": 1, "hero": 1, "images.0": 1}                                                                           52092         100       28228      1435.45        21515505      413.03    None
n.orders    find       {"$or": [{"status": 1}, {"ship_end": 1}], "archived": 1, "brand": 1, "draft_type": {"$ne": 1}, "line_items.product": 1, "status": 1}                6985         100       27310       6363.2         9016369     1290.82    None

Example Log Entry:

2020-02-26T02:28:09.599+0000 I COMMAND  [conn13084154] command n.orders command: find { find: "orders", filter: { $or: [ { order_number: "432222" }, { brand: ObjectId('56f47ac79b3be6e226d2619e'), external_id: "52414615" } ], status: { $nin: [ "working", "draft" ] }, brand: ObjectId('56f47ac79b3be6e226d2619e'), shipments.shipment_info.tracking_numbers: "1Z04Wxxxx303953922" }, projection: {}, limit: 1, singleBatch: true, batchSize: 1, returnKey: false, showRecordId: false } planSummary: IXSCAN { brand: 1, status: -1, _id: -1, draft_type: -1 } keysExamined:44883 docsExamined:44880 cursorExhausted:1 numYields:365 nreturned:0 reslen:102 locks:{ Global: { acquireCount: { r: 732 } }, Database: { acquireCount: { r: 366 } }, Collection: { acquireCount: { r: 366 } } } protocol:op_query 1472ms

Environment

mloginfo --version
mtools version 1.6.3 || Python 3.7.6 (default, Dec 30 2019, 19:38:26) [Clang 11.0.0 (clang-1100.0.33.16)]

Software	Version
MongoDB server	3.6
Operating system	MacOS

[stennie]

@ScubaDrew Thanks for the bug report. 95%-ile and max should be less than the sum, so something is definitely amiss.

[ScubaDrew]

Added example log entry. Maybe we have some bizarre log format throwing things off.

[Kaarel]

Same problem

mloginfo --version
mtools version 1.6.3 || Python 3.6.9 (default, Nov 7 2019, 10:44:02) [GCC
8.3.0]

count    min (ms)    max (ms)    mean (ms)    95%-ile (ms)    sum (ms)    allowDiskUse
  300         202        2441       1358.8          165223       550.7    None
   57         216       17783      12231.0          180802      3172.0    None
    2         214         257        254.8             471       235.5    None

Have sum and 95%-ile swapped positions perhaps?

Docs say the table is sorted by sum but mine is sorted by 95%-ile

[ArekBe]

Same problem - even count*min would give way bigger values
mtools version 1.6.3 || Python 3.6.9 (default, Apr 18 2020, 01:56:04) [GCC 8.4.0]

[stennie]

Some of the column headings are mismatched.

Corrected order:

-                 'mean (ms)', '95%-ile (ms)', 'sum (ms)',
+                 '95%-ile (ms)', 'sum (ms)', 'mean (ms)',

This will be fixed in the mtools 1.6.4 release