Mongodb replication locks and general slowness

Pretty new to Mongo and have a question or two around slow performance, i have followed the tips
using Mongo 3.7, the following query took about 84 seconds though if Mongos stats are correct the
time to read from storage was 803946 micros (should i believe this?). If the storage figures are to be believed then it took 82 seconds or so to parse the rturned docs in memory ?
It’s no small chunk at 1,729,965,030 bytes im wondering if even that was the compressed size.

Im wondering if the replication locking is normal in a standalone env i searched and could not find much:
ReplicationStateTransition: { acquireCount: { w: 72619 } } and could this cause a delay in processing?
Other than that any hints on speeding this up would be greatly appreciated !

command: aggregate { aggregate: “query.hourly”, pipeline: [ { $match: { endTime: { $gt: new Date(1686355200000) } } }, { $group: { _id: “$contextId” } }, { $project: { contextId: “$_id”, _id: 0 } }, { $sort: { contextId: 1 } }, { $skip: 0 }, { $limit: 10000 } ], allowDiskUse: true, cursor: { batchSize: 2147483647 }, $db: “presidio”, $readPreference: { mode: “primaryPreferred” } } planSummary: IXSCAN { endTime: 1 } keysExamined:9182654 docsExamined:9182654 hasSortStage:1 usedDisk:1 cursorExhausted:1 numYields:71985 nreturned:10000 queryHash:96AD493D planCacheKey:5A080EEB reslen:629010 locks:{ ReplicationStateTransition: { acquireCount: { w: 72619 } }, Global: { acquireCount: { r: 72619 } }, Database: { acquireCount: { r: 72619 } }, Collection: { acquireCount: { r: 72619 } }, Mutex: { acquireCount: { r: 634 } } } storage:{ data: { bytesRead: 1729965030, timeReadingMicros: 803946 } } protocol:op_msg 83971ms

MongoDB 3.7 is not a version of MongoDB so what do you mean by this?

Are you using a standalone or a sharded cluster?

Could you provide some clarity of what type of deployment and the mongodb version you are using? Also if you provide the query with the .explain(“executionStats”) output that would be helpful.

1 Like
Mongo db version v4.2.17

Here are my execution stats:

execution stats


`> db.getCollection("test").explain("executionStats").aggregate([ { $match: { endTime: { $gt: new Date(1686355200000) } } },{ $group: { _id: "$contextId" }}, { $project: { contextId: "$_id", _id: 0 } }], {"allowDiskUse" : true})
{
        "stages" : [
                {
                        "$cursor" : {
                                "query" : {
                                        "endTime" : {
                                                "$gt" : ISODate("2023-06-10T00:00:00Z")
                                        }
                                },
                                "fields" : {
                                        "contextId" : 1,
                                        "_id" : 0
                                },
                                "queryPlanner" : {
                                        "plannerVersion" : 1,
                                        "namespace" : "mydb.test",
                                        "indexFilterSet" : false,
                                        "parsedQuery" : {
                                                "endTime" : {
                                                        "$gt" : ISODate("2023-06-10T00:00:00Z")
                                                }
                                        },
                                        "queryHash" : "96AD493D",
                                        "planCacheKey" : "5A080EEB",
                                        "winningPlan" : {
                                                "stage" : "FETCH",
                                                "inputStage" : {
                                                        "stage" : "IXSCAN",
                                                        "keyPattern" : {
                                                                "endTime" : 1
                                                        },
                                                        "indexName" : "end",
                                                        "isMultiKey" : false,
                                                        "multiKeyPaths" : {
                                                                "endTime" : [ ]
                                                        },
                                                        "isUnique" : false,
                                                        "isSparse" : false,
                                                        "isPartial" : false,
                                                        "indexVersion" : 2,
                                                        "direction" : "forward",
                                                        "indexBounds" : {
                                                                "endTime" : [
                                                                        "(new Date(1686355200000), new Date(9223372036854775807)]"
                                                                ]
                                                        }
                                                }
                                        },
                                        "rejectedPlans" : [ ]
                                },
                                "executionStats" : {
                                        "executionSuccess" : true,
                                        "nReturned" : 10227381,
                                        "executionTimeMillis" : 91474,
                                        "totalKeysExamined" : 10227381,
                                        "totalDocsExamined" : 10227381,
                                        "executionStages" : {
                                                "stage" : "FETCH",
                                                "nReturned" : 10227381,
                                                "executionTimeMillisEstimate" : 3196,
                                                "works" : 10227382,
                                                "advanced" : 10227381,
                                                "needTime" : 0,
                                                "needYield" : 0,
                                                "saveState" : 80872,
                                                "restoreState" : 80872,
                                                "isEOF" : 1,
                                                "docsExamined" : 10227381,
                                                "alreadyHasObj" : 0,
                                                "inputStage" : {
                                                        "stage" : "IXSCAN",
                                                        "nReturned" : 10227381,
                                                        "executionTimeMillisEstimate" : 1560,
                                                        "works" : 10227382,
                                                        "advanced" : 10227381,
                                                        "needTime" : 0,
                                                        "needYield" : 0,
                                                        "saveState" : 80872,
                                                        "restoreState" : 80872,
                                                        "isEOF" : 1,
                                                        "keyPattern" : {
                                                                "endTime" : 1
                                                        },
                                                        "indexName" : "end",
                                                        "isMultiKey" : false,
                                                        "multiKeyPaths" : {
                                                                "endTime" : [ ]
                                                        },
                                                        "isUnique" : false,
                                                        "isSparse" : false,
                                                        "isPartial" : false,
                                                        "indexVersion" : 2,
                                                        "direction" : "forward",
                                                        "indexBounds" : {
                                                                "endTime" : [
                                                                        "(new Date(1686355200000), new Date(9223372036854775807)]"
                                                                ]
                                                        },
                                                        "keysExamined" : 10227381,
                                                        "seeks" : 1,
                                                        "dupsTested" : 0,
                                                        "dupsDropped" : 0
                                                }
                                        }
                                }
                        }
                },
                {
                        "$group" : {
                                "_id" : "$contextId"
                        }
                },
                {
                        "$project" : {
                                "_id" : false,
                                "contextId" : "$_id"
                        }
                }
        ],
        "serverInfo" : {
                "host" : "MY-DB-HOST",
                "port" : 27017,
                "version" : "4.2.17",
                "gitVersion" : "be089838c55d33b6f6039c4219896ee4a3cd704f"
        },
        "ok" : 1
}
>
 `

and my collection stats
`db.getCollection("test").stats()
{
        "ns" : "mydb.test",
        "size" : 4002064919,
        "count" : 10227409,
        "avgObjSize" : 391,
        "storageSize" : 1337253888,
        "capped" : false,
        "wiredTiger" : {
                "metadata" : {
                        "formatVersion" : 1
                },
                "creationString" : "access_pattern_hint=none,allocation_size=4KB,app_metadata=(formatVersion=1),assert=(commit_timestamp=none,durable_timestamp=none,read_timestamp=none),block_allocation=best,block_compressor=snappy,cache_resident=false,checksum=on,colgroups=,collator=,columns=,dictionary=0,encryption=(keyid=,name=),exclusive=false,extractor=,format=btree,huffman_key=,huffman_value=,ignore_in_memory_cache_size=false,immutable=false,internal_item_max=0,internal_key_max=0,internal_key_truncate=true,internal_page_max=4KB,key_format=q,key_gap=10,leaf_item_max=0,leaf_key_max=0,leaf_page_max=32KB,leaf_value_max=64MB,log=(enabled=true),lsm=(auto_throttle=true,bloom=true,bloom_bit_count=16,bloom_config=,bloom_hash_count=8,bloom_oldest=false,chunk_count_limit=0,chunk_max=5GB,chunk_size=10MB,merge_custom=(prefix=,start_generation=0,suffix=),merge_max=15,merge_min=0),memory_page_image_max=0,memory_page_max=10m,os_cache_dirty_max=0,os_cache_max=0,prefix_compression=false,prefix_compression_min=4,source=,split_deepen_min_child=0,split_deepen_per_child=0,split_pct=90,type=file,value_format=u",
                "type" : "file",
                "uri" : "statistics:table:collection-1560--5498070625033782530",
                "LSM" : {
                        "bloom filter false positives" : 0,
                        "bloom filter hits" : 0,
                        "bloom filter misses" : 0,
                        "bloom filter pages evicted from cache" : 0,
                        "bloom filter pages read into cache" : 0,
                        "bloom filters in the LSM tree" : 0,
                        "chunks in the LSM tree" : 0,
                        "highest merge generation in the LSM tree" : 0,
                        "queries that could have benefited from a Bloom filter that did not exist" : 0,
                        "sleep for LSM checkpoint throttle" : 0,
                        "sleep for LSM merge throttle" : 0,
                        "total size of bloom filters" : 0
                },
                "block-manager" : {
                        "allocations requiring file extension" : 0,
                        "blocks allocated" : 1960,
                        "blocks freed" : 1122,
                        "checkpoint size" : 710680576,
                        "file allocation unit size" : 4096,
                        "file bytes available for reuse" : 626548736,
                        "file magic number" : 120897,
                        "file major version number" : 1,
                        "file size in bytes" : 1337253888,
                        "minor version number" : 0
                },
                "btree" : {
                        "btree checkpoint generation" : 323,
                        "btree clean tree checkpoint expiration time" : NumberLong("9223372036854775807"),
                        "column-store fixed-size leaf pages" : 0,
                        "column-store internal pages" : 0,
                        "column-store variable-size RLE encoded values" : 0,
                        "column-store variable-size deleted values" : 0,
                        "column-store variable-size leaf pages" : 0,
                        "fixed-record size" : 0,
                        "maximum internal page key size" : 368,
                        "maximum internal page size" : 4096,
                        "maximum leaf page key size" : 2867,
                        "maximum leaf page size" : 32768,
                        "maximum leaf page value size" : 67108864,
                        "maximum tree depth" : 5,
                        "number of key/value pairs" : 0,
                        "overflow pages" : 0,
                        "pages rewritten by compaction" : 0,
                        "row-store empty values" : 0,
                        "row-store internal pages" : 0,
                        "row-store leaf pages" : 0
                },
                "cache" : {
                        "bytes currently in the cache" : 4519654858,
                        "bytes dirty in the cache cumulative" : 131064624,
                        "bytes read into cache" : 10085864857,
                        "bytes written from cache" : 178306687,
                        "checkpoint blocked page eviction" : 0,
                        "data source pages selected for eviction unable to be evicted" : 114,
                        "eviction walk passes of a file" : 19408,
                        "eviction walk target pages histogram - 0-9" : 7309,
                        "eviction walk target pages histogram - 10-31" : 9991,
                        "eviction walk target pages histogram - 128 and higher" : 0,
                        "eviction walk target pages histogram - 32-63" : 2108,
                        "eviction walk target pages histogram - 64-128" : 0,
                        "eviction walks abandoned" : 1811,
                        "eviction walks gave up because they restarted their walk twice" : 3062,
                        "eviction walks gave up because they saw too many pages and found no candidates" : 2340,
                        "eviction walks gave up because they saw too many pages and found too few candidates" : 233,
                        "eviction walks reached end of tree" : 9774,
                        "eviction walks started from root of tree" : 7451,
                        "eviction walks started from saved location in tree" : 11957,
                        "hazard pointer blocked page eviction" : 6,
                        "in-memory page passed criteria to be split" : 18,
                        "in-memory page splits" : 9,
                        "internal pages evicted" : 2752,
                        "internal pages split during eviction" : 0,
                        "leaf pages split during eviction" : 10,
                        "modified pages evicted" : 10,
                        "overflow pages read into cache" : 0,
                        "page split during eviction deepened the tree" : 0,
                        "page written requiring cache overflow records" : 0,
                        "pages read into cache" : 88141,
                        "pages read into cache after truncate" : 0,
                        "pages read into cache after truncate in prepare state" : 0,
                        "pages read into cache requiring cache overflow entries" : 0,
                        "pages requested from the cache" : 27656375,
                        "pages seen by eviction walk" : 422674,
                        "pages written from cache" : 1798,
                        "pages written requiring in-memory restoration" : 0,
                        "tracked dirty bytes in the cache" : 1483332,
                        "unmodified pages evicted" : 53517
                },
                "cache_walk" : {
                        "Average difference between current eviction generation when the page was last considered" : 0,
                        "Average on-disk page image size seen" : 0,
                        "Average time in cache for pages that have been visited by the eviction server" : 0,
                        "Average time in cache for pages that have not been visited by the eviction server" : 0,
                        "Clean pages currently in cache" : 0,
                        "Current eviction generation" : 0,
                        "Dirty pages currently in cache" : 0,
                        "Entries in the root page" : 0,
                        "Internal pages currently in cache" : 0,
                        "Leaf pages currently in cache" : 0,
                        "Maximum difference between current eviction generation when the page was last considered" : 0,
                        "Maximum page size seen" : 0,
                        "Minimum on-disk page image size seen" : 0,
                        "Number of pages never visited by eviction server" : 0,
                        "On-disk page image sizes smaller than a single allocation unit" : 0,
                        "Pages created in memory and never written" : 0,
                        "Pages currently queued for eviction" : 0,
                        "Pages that could not be queued for eviction" : 0,
                        "Refs skipped during cache traversal" : 0,
                        "Size of the root page" : 0,
                        "Total number of pages currently in cache" : 0
                },
                "compression" : {
                        "compressed page maximum internal page size prior to compression" : 4096,
                        "compressed page maximum leaf page size prior to compression " : 131072,
                        "compressed pages read" : 85133,
                        "compressed pages written" : 1551,
                        "page written failed to compress" : 0,
                        "page written was too small to compress" : 247
                },
                "cursor" : {
                        "bulk loaded cursor insert calls" : 0,
                        "cache cursors reuse count" : 177959,
                        "close calls that result in cache" : 0,
                        "create calls" : 22,
                        "insert calls" : 172003,
                        "insert key and value bytes" : 68688868,
                        "modify" : 0,
                        "modify key and value bytes affected" : 0,
                        "modify value bytes modified" : 0,
                        "next calls" : 202,
                        "open cursor count" : 1,
                        "operation restarted" : 0,
                        "prev calls" : 1,
                        "remove calls" : 1093,
                        "remove key bytes removed" : 5465,
                        "reserve calls" : 0,
                        "reset calls" : 6710744,
                        "search calls" : 803663619,
                        "search near calls" : 0,
                        "truncate calls" : 0,
                        "update calls" : 0,
                        "update key and value bytes" : 0,
                        "update value size change" : 0
                },
                "reconciliation" : {
                        "dictionary matches" : 0,
                        "fast-path pages deleted" : 0,
                        "internal page key bytes discarded using suffix compression" : 2404,
                        "internal page multi-block writes" : 5,
                        "internal-page overflow keys" : 0,
                        "leaf page key bytes discarded using prefix compression" : 0,
                        "leaf page multi-block writes" : 15,
                        "leaf-page overflow keys" : 0,
                        "maximum blocks required for a page" : 1,
                        "overflow values written" : 0,
                        "page checksum matches" : 144,
                        "page reconciliation calls" : 1211,
                        "page reconciliation calls for eviction" : 3,
                        "pages deleted" : 1
                },
                "session" : {
                        "object compaction" : 0
                },
                "transaction" : {
                        "update conflicts" : 0
                }
        },
        "nindexes" : 5,
        "indexBuilds" : [ ],
        "totalIndexSize" : 2992058368,
        "indexSizes" : {
                "_id_" : 224673792,
                "sessionEnd" : 125272064,
                "end" : 86822912,
                "sessionCtxEnd" : 1283137536,
                "ctxEnd" : 1272152064
        },
        "scaleFactor" : 1,
        "ok" : 1
}

Thanks !

also It’s a standalone non-sharded setup running with 128GB memory