API профилирования

Раздел query содержит подробные временные метки дерева запроса, выполняемого Lucene на конкретном фрагменте. Общая структура этого дерева запроса будет напоминать ваш исходный запрос Elasticsearch, но может быть немного (или иногда очень) отличаться. Она также будет использовать аналогичные, но не всегда идентичные наименования. Используя наш предыдущий пример запроса match, давайте проанализируем раздел query:

"query": [
    {
       "type": "BooleanQuery",
       "description": "message:get message:search",
       "time_in_nanos": "11972972",
       "breakdown": {...},               
       "children": [
          {
             "type": "TermQuery",
             "description": "message:get",
             "time_in_nanos": "3801935",
             "breakdown": {...}
          },
          {
             "type": "TermQuery",
             "description": "message:search",
             "time_in_nanos": "205654",
             "breakdown": {...}
          }
       ]
    }
]

На основе структуры профиля мы видим, что наш запрос match был переписан Lucene в BooleanQuery с двумя операндами (оба содержат TermQuery). Поле type отображает имя класса Lucene и часто соответствует эквивалентному имени в Elasticsearch. Поле description отображает текст объяснения Lucene для запроса и предназначено для дифференциации частей вашего запроса (например, оба message:get и message:search являются TermQuery и в противном случае выглядели бы одинаково).

Поле time_in_nanos показывает, что выполнение всего BooleanQuery заняло ~11,9 мс. Записанное время включает в себя время всех дочерних элементов.

Поле breakdown предоставит подробную статистику о том, как распределилось время; мы рассмотрим это чуть позже. Наконец, массив children перечисляет любые подзапросы, которые могут присутствовать. Поскольку мы искали два значения ("get search"), наш BooleanQuery содержит два дочерних TermQueries. Они имеют идентичную информацию (тип, время, разбиение и т. д.). Дочерние элементы могут иметь свои собственные дочерние элементы.

Компонент breakdown перечисляет подробные статистические данные о временных метках низкого уровня выполнения Lucene:

"breakdown": {
  "set_min_competitive_score_count": 0,
  "match_count": 5,
  "shallow_advance_count": 0,
  "set_min_competitive_score": 0,
  "next_doc": 39022,
  "match": 4456,
  "next_doc_count": 5,
  "score_count": 5,
  "compute_max_score_count": 0,
  "compute_max_score": 0,
  "advance": 84525,
  "advance_count": 1,
  "score": 37779,
  "build_scorer_count": 2,
  "create_weight": 4694895,
  "shallow_advance": 0,
  "create_weight_count": 1,
  "build_scorer": 7112295
}

Временные метки указаны в наносекундах реального времени и никак не нормализованы. Все оговорки по поводу общего time_in_nanos относятся и к этому разделу. Цель разбиения — дать вам представление о том, A) какой механизм в Lucene фактически потребляет время, и B) величине различий во времени между различными компонентами. Как и общее время, разбиение по времени включает время всех дочерних элементов.

Значение статистических данных:

Раздел Collectors ответа отображает подробные сведения о выполнении на высоком уровне. Lucene работает, определяя «Collector», который отвечает за координацию обхода, оценки и сбора соответствующих документов. Collectors также позволяют одному запросу записывать результаты агрегации, выполнять несвязанные «глобальные» запросы, выполнять фильтры после запроса и т. д.

Рассмотрим предыдущий пример:

"collector": [
  {
    "name": "SimpleTopScoreDocCollector",
    "reason": "search_top_hits",
    "time_in_nanos": 775274
  }
]

Мы видим единственный коллектор с именем SimpleTopScoreDocCollector, заключенный в CancellableCollector. SimpleTopScoreDocCollector — это стандартный «оценивающий и сортирующий» Collector, используемый Elasticsearch. Поле reason пытается предоставить простое описание класса на естественном языке. time_in_nanos аналогичен времени в дереве запросов: время, прошедшее с учётом всех дочерних элементов. Аналогично, children перечисляет все подколлекторы. CancellableCollector, который оборачивает SimpleTopScoreDocCollector, используется Elasticsearch для определения, был ли текущий поиск отменён, и остановки сбора документов, как только это произойдёт.

Следует отметить, что время работы коллекторов независимо от времени запроса. Они вычисляются, комбинируются и нормализуются независимо! Из-за характера выполнения Lucene невозможно «слить» время работы коллекторов в раздел запроса, поэтому они отображаются в отдельных разделах.

Для справки, различные причины работы коллектора:

Все запросы в Lucene проходят процесс «переписывания». Запрос (и его подзапросы) могут быть переписаны один или несколько раз, и процесс продолжается до тех пор, пока запрос не перестанет изменяться. Этот процесс позволяет Lucene выполнять оптимизации, такие как удаление избыточных пунктов, замена одного запроса более эффективным путём выполнения и т. д. Например, Boolean → Boolean → TermQuery может быть переписан в TermQuery, поскольку все Boolean в этом случае излишни.

Процесс переписывания сложный и трудно отображаемый, так как запросы могут сильно меняться. Вместо отображения промежуточных результатов отображается общее время переписывания (в наносекундах). Это значение является кумулятивным и содержит общее время переписывания всех запросов.

Для демонстрации несколько более сложного запроса и связанных результатов мы можем проанализировать следующий запрос:

GET /my-index-000001/_search
{
  "profile": true,
  "query": {
    "term": {
      "user.id": {
        "value": "elkbee"
      }
    }
  },
  "aggs": {
    "my_scoped_agg": {
      "terms": {
        "field": "http.response.status_code"
      }
    },
    "my_global_agg": {
      "global": {},
      "aggs": {
        "my_level_agg": {
          "terms": {
            "field": "http.response.status_code"
          }
        }
      }
    }
  },
  "post_filter": {
    "match": {
      "message": "search"
    }
  }
}

В этом примере:

API возвращает следующий результат:

{
  ...
  "profile": {
    "shards": [
      {
        "id": "[P6-vulHtQRWuD4YnubWb7A][my-index-000001][0]",
        "searches": [
          {
            "query": [
              {
                "type": "TermQuery",
                "description": "message:search",
                "time_in_nanos": 141618,
                "breakdown": {
                  "set_min_competitive_score_count": 0,
                  "match_count": 0,
                  "shallow_advance_count": 0,
                  "set_min_competitive_score": 0,
                  "next_doc": 0,
                  "match": 0,
                  "next_doc_count": 0,
                  "score_count": 0,
                  "compute_max_score_count": 0,
                  "compute_max_score": 0,
                  "advance": 3942,
                  "advance_count": 4,
                  "score": 0,
                  "build_scorer_count": 2,
                  "create_weight": 38380,
                  "shallow_advance": 0,
                  "create_weight_count": 1,
                  "build_scorer": 99296
                }
              },
              {
                "type": "TermQuery",
                "description": "user.id:elkbee",
                "time_in_nanos": 163081,
                "breakdown": {
                  "set_min_competitive_score_count": 0,
                  "match_count": 0,
                  "shallow_advance_count": 0,
                  "set_min_competitive_score": 0,
                  "next_doc": 2447,
                  "match": 0,
                  "next_doc_count": 4,
                  "score_count": 4,
                  "compute_max_score_count": 0,
                  "compute_max_score": 0,
                  "advance": 3552,
                  "advance_count": 1,
                  "score": 5027,
                  "build_scorer_count": 2,
                  "create_weight": 107840,
                  "shallow_advance": 0,
                  "create_weight_count": 1,
                  "build_scorer": 44215
                }
              }
            ],
            "rewrite_time": 4769,
            "collector": [
              {
                "name": "MultiCollector",
                "reason": "search_multi",
                "time_in_nanos": 1945072,
                "children": [
                  {
                    "name": "FilteredCollector",
                    "reason": "search_post_filter",
                    "time_in_nanos": 500850,
                    "children": [
                      {
                        "name": "SimpleTopScoreDocCollector",
                        "reason": "search_top_hits",
                        "time_in_nanos": 22577
                      }
                    ]
                  },
                  {
                    "name": "MultiBucketCollector: [[my_scoped_agg, my_global_agg]]",
                    "reason": "aggregation",
                    "time_in_nanos": 867617
                  }
                ]
              }
            ]
          }
        ],
        "aggregations": [...], 
        "fetch": {...}
      }
    ]
  }
}

Как вы можете видеть, вывод значительно более подробный, чем раньше. Представлены все основные части запроса:

Дерево коллекторов достаточно простое, демонстрируя, как один CancellableCollector оборачивает MultiCollector, который также оборачивает FilteredCollector для выполнения постфильтра (и в свою очередь оборачивает обычный оценивающий SimpleCollector), BucketCollector для выполнения всех агрегаций в рамках области видимости.

Необходимо сделать особое замечание относительно запросов класса MultiTermQuery. Это включает запросы с подстановкой, регулярными выражениями и с fuzzy-сопоставлением. Эти запросы генерируют очень подробные ответы и не сильно структурированы.

В сущности, эти запросы переписываются для каждого сегмента. Если представить себе запрос с подстановкой b*, он технически может соответствовать любому токену, начинающемуся с буквы «b». Было бы невозможно перечислить все возможные комбинации, поэтому Lucene переписывает запрос в контексте оцениваемого сегмента, например, один сегмент может содержать токены [bar, baz], поэтому запрос переписывается в сочетание BooleanQuery «bar» и «baz». Другой сегмент может содержать только токен [bakery], поэтому запрос переписывается в одиночный TermQuery для «bakery».

Из-за этой динамической переписывки для каждого сегмента структура дерева искажается и больше не соответствует чистой «родословной», показывающей, как один запрос переписывается в другой. На данный момент мы можем только извиниться и предложить свернуть детали для дочерних элементов этого запроса, если это слишком запутанно. К счастью, все статистические данные по времени правильные, просто не физическая структура ответа, поэтому достаточно проанализировать верхний MultiTermQuery и игнорировать его дочерние элементы, если подробности слишком сложны для интерпретации.

Надеемся, что это будет исправлено в будущих версиях, но это сложная проблема, которую предстоит решить.

Компонент breakdown предоставляет подробную статистику о низкоуровневом выполнении:

"breakdown": {
  "reduce": 0,
  "build_aggregation": 30885,
  "build_aggregation_count": 1,
  "initialize": 2623,
  "initialize_count": 1,
  "reduce_count": 0,
  "collect": 45786,
  "collect_count": 4,
  "build_leaf_collector": 18211,
  "build_leaf_collector_count": 1
}

Каждая свойство в компоненте breakdown соответствует внутреннему методу агрегирования. Например, свойство build_leaf_collector измеряет наносекунды, потраченные на выполнение метода getLeafCollector() агрегирования. Свойства, оканчивающиеся на _count, записывают количество вызовов данного метода. Например, "collect_count": 2 означает, что агрегирование вызвало метод collect() для двух различных документов. Свойство reduce зарезервировано для будущего использования и всегда возвращает 0.

Временные затраты указаны в наносекундах реального времени и никак не нормированы. Здесь применимы все оговорки, касающиеся общих временных затрат time. Цель детализации — дать представление о том, какие компоненты Elasticsearch фактически занимают время и о величине различий во времени между различными компонентами. Как и общее время, детализация включает в себя время всех дочерних компонентов.

У всех фрагментов, из которых извлекаются документы, в профиле будет раздел fetch. Давайте выполним небольшой поиск и посмотрим на профиль извлечения:

GET /my-index-000001/_search?filter_path=profile.shards.fetch
{
  "profile": true,
  "query": {
    "term": {
      "user.id": {
        "value": "elkbee"
      }
    }
  }
}

И вот профиль извлечения:

{
  "profile": {
    "shards": [
      {
        "fetch": {
          "type": "fetch",
          "description": "",
          "time_in_nanos": 660555,
          "breakdown": {
            "next_reader": 7292,
            "next_reader_count": 1,
            "load_stored_fields": 299325,
            "load_stored_fields_count": 5
          },
          "debug": {
            "stored_fields": ["_id", "_routing", "_source"]
          },
          "children": [
            {
              "type": "FetchSourcePhase",
              "description": "",
              "time_in_nanos": 20443,
              "breakdown": {
                "next_reader": 745,
                "next_reader_count": 1,
                "process": 19698,
                "process_count": 5
              },
              "debug": {
                "fast_path": 4
              }
            }
          ]
        }
      }
    ]
  }
}

Поскольку это отладочная информация о том, как Elasticsearch выполняет извлечение, она может меняться от запроса к запросу и от версии к версии. Даже исправления могут изменить вывод здесь. Именно это отсутствие согласованности делает его полезным для отладки.

В любом случае! time_in_nanos измеряет общее время фазы извлечения. breakdown подсчитывает и измеряет время подготовки каждого сегмента в next_reader и время загрузки хранимых полей в load_stored_fields. Раздел Debug содержит различную информацию, не связанную с измерением времени, в частности, stored_fields перечисляет хранимые поля, которые извлечение должно загрузить. Если это пустой список, то извлечение полностью пропустит загрузку хранимых полей.

Раздел children перечисляет подфазы, выполняющие фактическую работу по извлечению, а breakdown содержит подсчеты и временные затраты на подготовку каждого сегмента в next_reader и извлечение каждого документа в process.

Как и любой профилировщик, API профиля вносит неотъемлемую задержку в выполнение поиска. Действие инструментирования вызовов низкоуровневых методов, таких как collect, advance и next_doc, может быть достаточно дорогим, так как эти методы вызываются в узких циклах. Поэтому профилирование не должно включаться по умолчанию в производственных условиях и не должно сравниваться с временем выполнения запросов без профилирования. Профилирование — это просто инструмент диагностики.

Также есть случаи, когда специальные оптимизации Lucene отключены, так как они не подходят для профилирования. Это может привести к тому, что некоторые запросы покажут более высокие относительные времена, чем их не-профилированные аналоги, но в целом это не должно иметь существенного влияния по сравнению с другими компонентами в профилируемом запросе.