客户报告我们一个API在查询到第11页时老是出现504Gateway Timout ERROR
问题排查
根据Code我们发现该API是一个mongo的SQL 语句
db['sxaimsubscriber'].find({'organizationId': '12615054', 'flowDiscovered': true, 'mappedBy': {'$regex': '.*DHCP.*'}, 'ipAddress': {'$exists': 1}, 'deletedTime': {'$exists': 0}},projection={'_id': 1, 'ipAddress': 1}).sort({'_id':1}).skip(30000).limit(3000)ionStats")
但奇怪的是，同样的SQL，在调用分页1～10页的时候都可以在5s内返回数据，但到第11页5分钟也不返回。
同时测试过，如果不分页，总查询数据量也就在5W左右，在2分钟之内也能返回数据。
根据官方文档https://docs.mongodb.com/manual/reference/method/cursor.skip/#cursor.skip ，skip可能会引发慢查询，于是我们分析查询计划
db['sxaimsubscriber'].find({'organizationId': '12615054', 'flowDiscovered': true, 'mappedBy': {'$regex': '.*DHCP.*'}, 'ipAddress': {'$exists': 1}, 'deletedTime': {'$exists': 0}},projection={'_id': 1, 'ipAddress': 1}).sort({'_id':1}).skip(10000).limit(3000).explain("executionStats")
当我们skip10000条的时候，执行计划中发现是走了Index的
"executionStats" : { "executionSuccess" : true, "nReturned" : 3000, "executionTimeMillis" : 17843, "totalKeysExamined" : 151864, "totalDocsExamined" : 53312, "executionStages" : { "stage" : "SKIP", "nReturned" : 3000, "executionTimeMillisEstimate" : 1136, "works" : 164866, "advanced" : 3000, "needTime" : 161865, "needYield" : 0, "saveState" : 13470, "restoreState" : 13470, "isEOF" : 1, "invalidates" : 50, "skipAmount" : 0, "inputStage" : { "stage" : "PROJECTION", "nReturned" : 13000, "executionTimeMillisEstimate" : 1106, "works" : 164866, "advanced" : 13000, "needTime" : 151865, "needYield" : 0, "saveState" : 13470, "restoreState" : 13470, "isEOF" : 1, "invalidates" : 50, "transformBy" : { "_id" : 1, "ipAddress" : 1 }, "inputStage" : { "stage" : "SORT", "nReturned" : 13000, "executionTimeMillisEstimate" : 1056, "works" : 164866, "advanced" : 13000, "needTime" : 151865, "needYield" : 0, "saveState" : 13470, "restoreState" : 13470, "isEOF" : 1, "invalidates" : 50, "sortPattern" : { "_id" : -1 }, "memUsage" : 13239001, "memLimit" : 33554432, "limitAmount" : 13000, "inputStage" : { "stage" : "KEEP_MUTATIONS", "nReturned" : 46369, "executionTimeMillisEstimate" : 806, "works" : 151865, "advanced" : 46369, "needTime" : 105495, "needYield" : 0, "saveState" : 13470, "restoreState" : 13470, "isEOF" : 1, "invalidates" : 50, "inputStage" : { "stage" : "SORT_KEY_GENERATOR", "nReturned" : 0, "executionTimeMillisEstimate" : 796, "works" : 151865, "advanced" : 0, "needTime" : 105495, "needYield" : 0, "saveState" : 13470, "restoreState" : 13470, "isEOF" : 1, "invalidates" : 50, "inputStage" : { "stage" : "FETCH", "filter" : { "$and" : [ { "flowDiscovered" : { "$eq" : true } }, { "ipAddress" : { "$exists" : true } }, { "$not" : { "deletedTime" : { "$exists" : true } } } ] }, "nReturned" : 46369, "executionTimeMillisEstimate" : 707, "works" : 151864, "advanced" : 46369, "needTime" : 105494, "needYield" : 0, "saveState" : 13470, "restoreState" : 13470, "isEOF" : 1, "invalidates" : 50, "docsExamined" : 53312, "alreadyHasObj" : 0, "inputStage" : { "stage" : "IXSCAN", "filter" : { "mappedBy" : /.*DHCP.*/ }, "nReturned" : 53312, "executionTimeMillisEstimate" : 467, "works" : 151864, "advanced" : 53312, "needTime" : 98551, "needYield" : 0, "saveState" : 13470, "restoreState" : 13470, "isEOF" : 1, "invalidates" : 50, "keyPattern" : { "organizationId" : 1, "mappedBy" : 1 }, "indexName" : "organizationId_mapped", "isMultiKey" : false, "isUnique" : false, "isSparse" : false, "isPartial" : false, "indexVersion" : 1, "direction" : "forward", "indexBounds" : { "organizationId" : [ "[\"12615054\", \"12615054\"]" ], "mappedBy" : [ "[\"\", {})", "[/.*DHCP.*/, /.*DHCP.*/]" ] }, "keysExamined" : 151864, "dupsTested" : 0, "dupsDropped" : 0, "seenInvalidated" : 0 } } } } } } } }