4

I migrated from MongoDB to AWS DocumentDB and I'm having some issues with query performance. Running a profile I found several queries taking a laaaarge amount of time, far beyond a couple of seconds. I tried to understand with the doc what some of those stages mean like LIMIT_SKIP and understand why they're taking so long. Specially those that are updates against _id.

As context I'm using Mongoid 6.4.4 with AWS Document DB.

Here are the profile I get and below the models stats:

    {
    "op": "update",
    "ts": 1592322527421,
    "ns": "mytable.paths",
    "command": {
        "q": {
            "_id": "5ee8e93217f3830001cf9765"
        },
        "u": {
            "$set": {
                "last_active_at": "2020-06-16T15:48:19.774Z",
                "updated_at": "2020-06-16T15:48:19.774Z"
            }
        }
    },
    "nMatched": 1,
    "nModified": 1,
    "protocol": "op_query",
    "millis": 27643,
    "planSummary": "IXSCAN",
    "execStats": {
        "stage": "UPDATE",
        "nReturned": "0",
        "executionTimeMillisEstimate": "27638.070",
        "inputStages": [
            {
                "stage": "LIMIT_SKIP",
                "nReturned": "1",
                "executionTimeMillisEstimate": "27637.167",
                "inputStage": {
                    "stage": "IXSCAN",
                    "nReturned": "1",
                    "executionTimeMillisEstimate": "0.046",
                    "indexName": "_id_",
                    "direction": "forward"
                }
            },
            {
                "stage": "IXSCAN",
                "nReturned": "1",
                "executionTimeMillisEstimate": "27637.510",
                "indexName": "_id_",
                "direction": "forward"
            }
        ]
    },
    "client": "10.70.11.85:53788",
    "user": "avion_admin"
}

Another very similar:

    "op": "update",
    "ts": 1592336823405,
    "ns": "mytable.groups",
    "command": {
        "q": {
            "_id": "5cf599047ce44a2eb43f8bb9"
        },
        "u": {
            "$set": {
                "empty": false
            }
        }
    },
    "nMatched": 1,
    "nModified": 0,
    "protocol": "op_query",
    "millis": 158338,
    "planSummary": "IXSCAN",
    "execStats": {
        "stage": "UPDATE",
        "nReturned": "0",
        "executionTimeMillisEstimate": "158329.635",
        "inputStages": [
            {
                "stage": "LIMIT_SKIP",
                "nReturned": "1",
                "executionTimeMillisEstimate": "2.686",
                "inputStage": {
                    "stage": "IXSCAN",
                    "nReturned": "1",
                    "executionTimeMillisEstimate": "2.672",
                    "indexName": "_id_",
                    "direction": "forward"
                }
            },
            {
                "stage": "IXSCAN",
                "nReturned": "1",
                "executionTimeMillisEstimate": "6.390",
                "indexName": "_id_",
                "direction": "forward"
            }
        ]
    },
    "client": "10.70.13.122:44162",
    "user": "avion_admin"
}

And this one I can't even get where is being done:

{"op":"query","ts":1592372335740,"ns":"mytable.devices","command":{"$truncated":"{\"find\":\"devices\",\"find\":\"devices\",\"filter\":{\"$and\":[{\"_id\":{\"$in\":[ObjectId('5c35814ce5e09d5b6e5ca432')...},"cursorExhausted":true,"nreturned":1,"responseLength":25,"protocol":"op_query","millis":97669,"planSummary":"IXSCAN","execStats":{"stage":"SUBSCAN","nReturned":"1","executionTimeMillisEstimate":"24956.315","inputStage":{"stage":"LIMIT_SKIP","nReturned":"1","executionTimeMillisEstimate":"24956.247","inputStage":{"stage":"IXSCAN","nReturned":"1","executionTimeMillisEstimate":"24956.246","indexName":"status_1","direction":"forward"}}},"client":"10.70.11.237:45532","user":"avion_admin"}

Models:

{
    "ns" : "mytable.paths",
    "count" : 60192,
    "size" : 16974144.0,
    "avgObjSize" : 282.5631,
    "storageSize" : 45039616.0,
    "capped" : false,
    "nindexes" : 4,
    "totalIndexSize" : 68542464.0,
    "indexSizes" : {
        "_id_" : 17072128.0,
        "device_id_1" : 15196160.0,
        "location_id_1" : 18317312.0,
        "registration_id_1" : 17956864.0
    },
    "ok" : 1
}

{
    "ns" : "mytabke.devices",
    "count" : 78450,
    "size" : 57739200.0,
    "avgObjSize" : 736.49595,
    "storageSize" : 217628672.0,
    "capped" : false,
    "nindexes" : 9,
    "totalIndexSize" : 1194442752.0,
    "indexSizes" : {
        "_id_" : 30179328.0,
        "energy_changed_at_1_intervals_up_to_1" : 83402752.0,
        "group_ids_1" : 168148992.0,
        "location_id_1" : 21880832.0,
        "location_id_1_avid_1" : 51593216.0,
        "pinged_at_1_features_1" : 148955136.0,
        "status_1" : 163741696.0,
        "status_1_features_1_last_active_at_1_pinged_at_1" : 264159232.0,
        "status_1_last_active_at_1_since_active_at_1" : 262381568.0
    },
    "ok" : 1
}

{
    "ns" : "concourse.groups",
    "count" : 11198,
    "size" : 6456828.0,
    "avgObjSize" : 576.605465261654,
    "storageSize" : 38461440.0,
    "capped" : false,
    "nindexes" : 5,
    "totalIndexSize" : 810500096.0,
    "indexSizes" : {
        "_id_" : 1794048.0,
        "device_ids_1" : 785743872.0,
        "dim_1_mixed_1" : 15261696.0,
        "location_id_1" : 3129344.0,
        "location_id_1_avid_1" : 4571136.0
    },
    "ok" : 1
}
blanchma
  • 61
  • 3
  • 1
    You should tag your question "documentdb". – D. SM Jun 17 '20 at 22:43
  • 2
    for the 1st query, i see a LIMIT_SKIP in one of the stages. This could mean that the query was paged/swapped out. for the 2nd query, what was the CPU utilization and memory usage for your DocumentDB instance like? It might be that your cluster is overloading and either the CPU/memory is the bottleneck. for the 3rd query, it looks liek you have an index on status, is this a low cardinality index? I work on DocumentDB and can further help you troubleshoot this - feel free to email me at mbh@amazon.com – meet-bhagdev Jun 18 '20 at 20:03

0 Answers0