Profile API 性能分析

平时开发的过程中我们可能需要对一些查询操作进行优化，而优化之前的工作就是要对操作的性能进行分析，而ES提供了Profile API来帮助用户进行性能分析。它让用户了解如何在较低的级别执行搜索请求，这样用户就可以理解为什么某些请求比较慢，并采取措施改进它们。

需要注意的是Profile API不测量网络延迟、搜索资源获取阶段、请求在队列中花费的时间或在协调节点上合并碎片响应时花费的时间。

需要注意的是开启性能分析会给查询带来非常大的性能开销。所以不要尝试将一个开启了性能分析的请求和为开启性能分析的请求比对时间效率。

开启性能分析

需要开启性能分析，只需要在原有请求中设置”profile”: true。而当查询嵌套的内容比较多的时候返回的性能分析内容会非常冗长，所以可以在请求URI后面设置?human=true获取比较清晰的结构。

性能分析结构

下面依旧是使用之前kibana创建的kibana_sample_data_ecommerce做测试。下面是一个简单的查询请求。

  1. GET /kibana_sample_data_ecommerce/_search?human=true
  2. {
  3.     "profile": true,
  4.     "_source": false, 
  5.     "query": {
  6.         "match": {
  7.             "category": "Women's Shoes"
  8.         }
  9.     }
  10. }

返回内容
性能分析的相关报告在profile对象内。

  1. {
  2.     "took": 11,
  3.     "timed_out": false,
  4.     "_shards": {
  5.         ......
  6.     },
  7.     "hits": {
  8.         ......
  9.     },
  10.     "profile": {
  11.         "shards": [
  12.             {
  13.                 "id": "[tMhvMfVrTnGguu5QJ-1j-Q][kibana_sample_data_ecommerce][0]",
  14.                 "searches": [
  15.                     {
  16.                         "query": [
  17.                             {
  18.                                 "type": "BooleanQuery",
  19.                                 "description": "category:women's category:shoes",
  20.                                 "time": "14.6ms",
  21.                                 "time_in_nanos": 14642543,
  22.                                 "breakdown": {
  23.                                     "set_min_competitive_score_count": 0,
  24.                                     "match_count": 3372,
  25.                                     "shallow_advance_count": 0,
  26.                                     "set_min_competitive_score": 0,
  27.                                     "next_doc": 12574965,
  28.                                     "match": 182802,
  29.                                     "next_doc_count": 3378,
  30.                                     "score_count": 3372,
  31.                                     "compute_max_score_count": 0,
  32.                                     "compute_max_score": 0,
  33.                                     "advance": 0,
  34.                                     "advance_count": 0,
  35.                                     "score": 558388,
  36.                                     "build_scorer_count": 12,
  37.                                     "create_weight": 161677,
  38.                                     "shallow_advance": 0,
  39.                                     "create_weight_count": 1,
  40.                                     "build_scorer": 1154576
  41.                                 },
  42.                                 "children": [
  43.                                     {
  44.                                         "type": "TermQuery",
  45.                                         "description": "category:women's",
  46.                                         "time": "1.3ms",
  47.                                         "time_in_nanos": 1326026,
  48.                                         "breakdown": {
  49.                                             "set_min_competitive_score_count": 0,
  50.                                             "match_count": 0,
  51.                                             "shallow_advance_count": 50,
  52.                                             "set_min_competitive_score": 0,
  53.                                             "next_doc": 0,
  54.                                             "match": 0,
  55.                                             "next_doc_count": 0,
  56.                                             "score_count": 2466,
  57.                                             "compute_max_score_count": 50,
  58.                                             "compute_max_score": 248144,
  59.                                             "advance": 312952,
  60.                                             "advance_count": 2472,
  61.                                             "score": 201148,
  62.                                             "build_scorer_count": 18,
  63.                                             "create_weight": 82500,
  64.                                             "shallow_advance": 82773,
  65.                                             "create_weight_count": 1,
  66.                                             "build_scorer": 393452
  67.                                         }
  68.                                     },
  69.                                     {
  70.                                         "type": "TermQuery",
  71.                                         "description": "category:shoes",
  72.                                         "time": "1ms",
  73.                                         "time_in_nanos": 1089732,
  74.                                         "breakdown": {
  75.                                             "set_min_competitive_score_count": 0,
  76.                                             "match_count": 0,
  77.                                             "shallow_advance_count": 48,
  78.                                             "set_min_competitive_score": 0,
  79.                                             "next_doc": 0,
  80.                                             "match": 0,
  81.                                             "next_doc_count": 0,
  82.                                             "score_count": 2080,
  83.                                             "compute_max_score_count": 48,
  84.                                             "compute_max_score": 183654,
  85.                                             "advance": 454098,
  86.                                             "advance_count": 2086,
  87.                                             "score": 164281,
  88.                                             "build_scorer_count": 18,
  89.                                             "create_weight": 36149,
  90.                                             "shallow_advance": 79552,
  91.                                             "create_weight_count": 1,
  92.                                             "build_scorer": 167717
  93.                                         }
  94.                                     }
  95.                                 ]
  96.                             }
  97.                         ],
  98.                         "rewrite_time": 12723,
  99.                         "collector": [
  100.                             {
  101.                                 "name": "CancellableCollector",
  102.                                 "reason": "search_cancelled",
  103.                                 "time": "1.1ms",
  104.                                 "time_in_nanos": 1112587,
  105.                                 "children": [
  106.                                     {
  107.                                         "name": "SimpleTopScoreDocCollector",
  108.                                         "reason": "search_top_hits",
  109.                                         "time": "739.7micros",
  110.                                         "time_in_nanos": 739707
  111.                                     }
  112.                                 ]
  113.                             }
  114.                         ]
  115.                     }
  116.                 ],
  117.                 "aggregations": [
  119.                 ]
  120.             }
  121.         ]
  122.     }
  123. }

上面是一个非常简单的查询并不存在聚合内容，返回的分析报告相对也是比较简单的。

参数解析

image.png

shards

因为针对一个索引的搜索可能涉及一个或者多个碎片。所以分析报告中shards是一个对象数组，每个分片都列出其ID，用来标识不同的分片。ID的命名格式节点ID+索引名称+分片索引

query

其是对基础Lucene索引执行的查询。用户提交的大多数搜索请求都只针对Lucene索引执行一次搜索。但是偶尔会执行多个搜索，比如包含一个全局聚合(需要为全局上下文执行第二个“match_all”查询)。

查询分析
query部分包含Lucene在特定碎片上执行查询树的详细时间。这个查询树的结构会类似于最初请求数据时候的查询结构。其会在description字段中提供类似的解释。下面看下上面例子的分析报告

  1. "query" : [
  2.   {
  3.     "type" : "BooleanQuery",
  4.     "description" : "category:women's category:shoes",
  5.     "time" : "3.5ms",
  6.     "time_in_nanos" : 3540328,
  7.     "breakdown" : {
  8.         ......
  9.     },
  10.     "children" : [
  11.             {
  12.                 "type": "TermQuery",
  13.                 "description": "category:women's",
  14.                 "time": "1.3ms",
  15.                 "time_in_nanos": 1326026,
  16.                 "breakdown": {
  17.                     "set_min_competitive_score_count": 0,
  18.                     "match_count": 0,
  19.                     "shallow_advance_count": 50,
  20.                     "set_min_competitive_score": 0,
  21.                     "next_doc": 0,
  22.                     "match": 0,
  23.                     "next_doc_count": 0,
  24.                     "score_count": 2466,
  25.                     "compute_max_score_count": 50,
  26.                     "compute_max_score": 248144,
  27.                     "advance": 312952,
  28.                     "advance_count": 2472,
  29.                     "score": 201148,
  30.                     "build_scorer_count": 18,
  31.                     "create_weight": 82500,
  32.                     "shallow_advance": 82773,
  33.                     "create_weight_count": 1,
  34.                     "build_scorer": 393452
  35.                 }
  36.             },
  37.             {
  38.                 "type": "TermQuery",
  39.                 "description": "category:shoes",
  40.                 "time": "1ms",
  41.                 "time_in_nanos": 1089732,
  42.                 "breakdown": {
  43.                     ......
  44.                 }
  45.             }
  46.     ]
  47.   }
  48. ],

上面的查询条件被Lucene重写为一个带有两个子句，type字段显示Lucene类名，description字段显示了查询的Lucene解释文本，用于帮助区分查询的各个部分。time_in_nanos字段显示整个查询的花费（注意计时是以纳秒为单位列出的）。然后子数组列出可能存在的所有子查询。

breakdown

细分组件列出了底层Lucene执行的详细时间统计

  1. "breakdown" : {
  2.     "set_min_competitive_score_count": 0,
  3.     "match_count": 0,
  4.     "shallow_advance_count": 50,
  5.     "set_min_competitive_score": 0,
  6.     "next_doc": 0,
  7.     "match": 0,
  8.     "next_doc_count": 0,
  9.     "score_count": 2466,
  10.     "compute_max_score_count": 50,
  11.     "compute_max_score": 248144,
  12.     "advance": 312952,
  13.     "advance_count": 2472,
  14.     "score": 201148,
  15.     "build_scorer_count": 18,
  16.     "create_weight": 82500,
  17.     "shallow_advance": 82773,
  18.     "create_weight_count": 1,
  19.     "build_scorer": 393452
  20. },

breakdown参数的意义
image.png

collector

Lucene为查询定义了一个收集器（Collector），负责协调遍历、评分以及匹配文档的收集。

  1. "collector": [
  2.     {
  3.         "name": "CancellableCollector",
  4.         "reason": "search_cancelled",
  5.         "time": "1.1ms",
  6.         "time_in_nanos": 1112587,
  7.         "children": [
  8.             {
  9.                 "name": "SimpleTopScoreDocCollector",
  10.                 "reason": "search_top_hits",
  11.                 "time": "739.7micros",
  12.                 "time_in_nanos": 739707
  13.             }
  14.         ]
  15.     }
  16. ]

collector收集器
reason字段尝试给出收集器类名的简单英文描述。而目前官方网站列出的收集器包含下面内容
image.png

search_top_hits以及search_cancelled

关于这两个官方案例使用的收集器，在其文档中并没有说明，而我查询了stackoverflow也没有发现相关内容。后来我在lucene文档中查到了org.apache.lucene.search.TopDocsCollector类似的收集器类，主要是返回指定top数的文档。

rewrite_time（重写时间）

Lucene中的所有查询都要经历一次或者多次“重写”过程。这个过程将一直持续下去，直到查询停止变化。这个过程允许Lucene执行优化，例如删除冗余子句，替换一个查询以获得更有效的执行路径等等。这个值是包含所有被重写查询的总时间。

aggregations Section 聚合性能分析

使用聚合的查询时，其聚合内容的分析存在于aggregations对象中，其嵌套结构类似于查询请求时的嵌套结构。使用聚合的性能分析可以查看查询中聚合内容消耗资源的详情。

现在再次发出请求，此请求除了包含query还覆盖了aggs聚合以及嵌套聚合。

  1. GET /kibana_sample_data_ecommerce/_search
  2. {
  3.   "profile": true,
  4.   "query": {
  5.     "term": {
  6.       "currency": {
  7.         "value": "EUR"
  8.       }
  9.     }
  10.   },
  11.   "aggs": {
  12.     "week": {
  13.       "terms": {
  14.         "field": "day_of_week"
  15.       }
  16.     },
  17.     "gender_agg": {
  18.       "global": {},
  19.       "aggs": {
  20.         "gender": {
  21.           "terms": {
  22.             "field": "customer_gender"
  23.           }
  24.         }
  25.       }
  26.     }
  27.   },
  28.   "post_filter": {
  29.     "match": {
  30.       "message": "some"
  31.     }
  32.   }
  33. }

最后返回的性能信息的聚合部分如下面的内容

  1. {
  2.     "profile": {
  3.         "shards": [
  4.             {
  5.                 "id": "[tMhvMfVrTnGguu5QJ-1j-Q][kibana_sample_data_ecommerce][0]",
  6.                 "aggregations": [
  7.                     {
  8.                         "type": "LowCardinality",
  9.                         "description": "week",
  10.                         "time_in_nanos": 1121184,
  11.                         "breakdown": {
  12.                             "reduce": 0,
  13.                             "build_aggregation": 129073,
  14.                             "build_aggregation_count": 1,
  15.                             "initialize": 3620,
  16.                             "initialize_count": 1,
  17.                             "reduce_count": 0,
  18.                             "collect": 983814,
  19.                             "collect_count": 4675
  20.                         }
  21.                     },
  22.                     {
  23.                         "type": "GlobalAggregator",
  24.                         "description": "gender_agg",
  25.                         "time_in_nanos": 8733554,
  26.                         "breakdown": {
  27.                             "reduce": 0,
  28.                             "build_aggregation": 34655,
  29.                             "build_aggregation_count": 1,
  30.                             "initialize": 12318,
  31.                             "initialize_count": 1,
  32.                             "reduce_count": 0,
  33.                             "collect": 8681904,
  34.                             "collect_count": 4675
  35.                         },
  36.                         "children": [
  37.                             {
  38.                                 "type": "GlobalOrdinalsStringTermsAggregator",
  39.                                 "description": "gender",
  40.                                 "time_in_nanos": 6729126,
  41.                                 "breakdown": {
  42.                                     "reduce": 0,
  43.                                     "build_aggregation": 29463,
  44.                                     "build_aggregation_count": 1,
  45.                                     "initialize": 3148,
  46.                                     "initialize_count": 1,
  47.                                     "reduce_count": 0,
  48.                                     "collect": 6691838,
  49.                                     "collect_count": 4675
  50.                                 }
  51.                             }
  52.                         ]
  53.                     }
  54.                 ]
  55.             }
  56.         ]
  57.     }
  58. }

可以看到上面week聚合部分使用了LowCardinality，在同一层级上gender_agg使用的是GlobalAggregator。在time_in_nanos中详细给出了每个聚合所消耗的时间。

时间分析（Timing Breakdown）

Timing Breakdown对象内的数据分析了底层Lucene执行的详细时间消耗。以week的时间分析为例子。

"breakdown": {
    "reduce": 0,
    "build_aggregation": 129073,
    "build_aggregation_count": 1,
    "initialize": 3620,
    "initialize_count": 1,
    "reduce_count": 0,
    "collect": 983814,
    "collect_count": 4675
}

统计的意义如下:
参数描述
image.png

Profiling使用时需要注意的内容

使用时需要注意
使用性能分析API会给搜索执行引入了较大的开销。所以除非需要调试，其不应该在生产环境中被启用。
一些简单方法如collect, advance,next_doc开销可能更大，因为这些方法是在循环中调用的。
因为分析带来的额外消耗，所以不应该将启用性能分析和未启用性能分析的查询进行比较。

Profiling存在的局限

  1. 性能分析不能获取搜索数据获取以及网络开销
  2. 性能分析也不考虑在队列中花费的时间、合并协调节点上的shard响应，或诸如构建全局序数之类的额外工作
  3. 性能分析目前无法应用于搜索建议（suggestions），高亮搜索（highlighting）
  4. 目前reduce阶段无法使用性能分析统计结果
  5. 性能分析是个实验性的功能