分析GeminiDB Mongo数据库的慢请求

GeminiDB Mongo数据库服务默认开启了慢请求Profiling ，系统自动将请求时间超过500ms的执行情况记录到对应数据库下的“system.profile”集合中。

1. 通过Mongo Shell连接GeminiDB Mongo实例。
2. 执行以下命令，进入指定数据库，以“test”为例。

   use test

3. 查看是否生成慢sql集合“system.profile”。

   show collections;

   • 回显中有“system.profile”，说明产生了慢SQL，继续执行下一步。

   

   • 回显中没有“system.profile”，说明未产生慢SQL，该数据库不涉及慢请求分析。

   

4. 查看数据下的慢请求日志。

   db.system.profile.find().pretty()

5. 分析慢请求日志，查找CPU使用率升高的原因。

   下面是某个慢请求日志示例，可查看到该请求进行了全表扫描，扫描了1561632个文档，没有通过索引进行查询。

   {
           "op" : "query",
           "ns" : "taiyiDatabase.taiyiTables$10002e",
           "query" : {
                   "find" : "taiyiTables",
                   "filter" : {
                           "filed19" : NumberLong("852605039766")
                   },
                   "shardVersion" : [
                           Timestamp(1, 1048673),
                           ObjectId("5da43185267ad9c374a72fd5")
                   ],
                   "chunkId" : "10002e"
           },
           "keysExamined" : 0,
           "docsExamined" : 1561632,
           "cursorExhausted" : true,
           "numYield" : 12335,
           "locks" : {
                   "Global" : {
                           "acquireCount" : {
                                   "r" : NumberLong(24672)
                           }
                   },
                   "Database" : {
                           "acquireCount" : {
                                   "r" : NumberLong(12336)
                           }
                   },
                   "Collection" : {
                           "acquireCount" : {
                                   "r" : NumberLong(12336)
                           }
                   }
           },
           "nreturned" : 0,
           "responseLength" : 157,
           "protocol" : "op_command",
           "millis" : 44480,
           "planSummary" : "COLLSCAN",
           "execStats" : {
                 "stage" : "SHARDING_FILTER",                                                                                                                                       [3/1955]
                   "nReturned" : 0,
                   "executionTimeMillisEstimate" : 43701,
                   "works" : 1561634,
                   "advanced" : 0,
                   "needTime" : 1561633,
                   "needYield" : 0,
                   "saveState" : 12335,
                   "restoreState" : 12335,
                   "isEOF" : 1,
                   "invalidates" : 0,
                   "chunkSkips" : 0,
                   "inputStage" : {
                           "stage" : "COLLSCAN",
                           "filter" : {
                                   "filed19" : {
                                           "$eq" : NumberLong("852605039766")
                                   }
                           },
                           "nReturned" : 0,
                           "executionTimeMillisEstimate" : 43590,
                           "works" : 1561634,
                           "advanced" : 0,
                           "needTime" : 1561633,
                           "needYield" : 0,
                           "saveState" : 12335,
                           "restoreState" : 12335,
                           "isEOF" : 1,
                           "invalidates" : 0,
                           "direction" : "forward",
                           "docsExamined" : 1561632
                   }
           },
           "ts" : ISODate("2019-10-14T10:49:52.780Z"),
           "client" : "xxx.xxx.xxx.xxx",
           "appName" : "MongoDB Shell",
           "allUsers" : [
                   {
                           "user" : "__system",
                           "db" : "local"
                   }
           ],
          "user" : "__system@local"
   }

   在慢请求日志中，您需要重点关注以下关键字。

   • 全集合（全表）扫描：COLLSCAN

     当一个操作请求（如QUERY、UPDATE、DELETE）需要全表扫描时，将大量占用CPU资源。在查看慢请求日志时，发现COLLSCAN关键字，很可能是这些查询占用了CPU资源。

     如果该类操作请求较为频繁，建议您对查询的字段建立索引进行优化。

   • 全集合（全表）扫描：docsExamined

     通过查看参数“docsExamined”的值，可以查看一个查询扫描了多少文档。该值越大，请求的CPU使用率越高。

   • 不合理的索引：IXSCAN、keysExamined
     • 索引不是越多越好，过多索引会影响写入和更新的性能。
     • 如果您的应用偏向于写操作，建立索引可能会降低写操作的性能。

     通过查看参数“keysExamined”的值，可以查看一个使用了索引的查询，扫描了多少条索引。该值越大，请求的CPU使用率越高。

     如果索引建立不太合理，或者匹配的结果很多。该场景下，即便使用了索引，请求的CPU使用率也不会降低很多，执行的速度也会很慢。

     示例：对于某个集合的数据，a字段的取值很少（只有1和2），而b字段的取值很多。

     

     如下所示，要实现 {a: 1, b: 2} 这样的查询。

     db.createIndex( {a: 1} )        效果不好,因为a相同取值太多
     
     db.createIndex( {a: 1, b: 1} )  效果不好,因为a相同取值太多
     
     db.createIndex( {b: 1 } )       效果好,因为b相同取值很少
     
     db.createIndex( {b: 1, a: 1 })  效果好,因为b相同取值少

     关于{a: 1}与{b: 1, a: 1}的区别，可参考官方文档。

   • 大量数据排序：SORT、hasSortStage

     当查询请求中包含排序时，“system.profile”集合中的参数“hasSortStage”的值为“true”。如果排序无法通过索引实现，将在查询结果中进行排序。由于排序将占用大量CPU资源，该场景下，需要通过对经常排序的字段建立索引进行优化。

     当您在“system.profile”集合中发现SORT关键字时，可以考虑通过索引来优化排序。

     其他操作如建立索引、Aggregation（遍历、查询、更新、排序等动作的组合）也可能占用大量CPU资源，但本质上也适用以上几种场景。更多Profiling的设置，请参见官方文档。