Получение Query Logs

Чтобы проанализировать выполнение запросов, выявить проблемы с производительностью или отследить упавшие джобы, можно изучить логи запросов клики.

Важно

Функциональность Query Logs доступна в CHYT начиная с версии 2.16.

Логи всех запросов сохраняются в таблицах. Они находятся в Кипарисе по адресу: //sys/strawberry/chyt/<alias>/artifacts/system_log_tables/query_log.

Папка query_log содержит:

одну или несколько таблиц с именами от 0 до n;
ссылку на последнюю таблицу latest — например, //sys/strawberry/chyt/<alias>/artifacts/system_log_tables/query_log/n.

Новые таблицы в query_log появляются при изменении схемы — например, когда добавляют новые поля или меняют тип данных. Это может произойти при повышении или понижении версии CHYT. Например, если версия CHYT в клике обновилась с 2.16 до 2.17:

автоматически создаётся новая таблица со следующим порядковым номером (если была таблица 0, появится таблица 1);
ссылка latest автоматически переключается на последнюю версию таблицы (в этом случае — на таблицу 1).

Если затем снова понизить версию CHYT до 2.16, система добавит новую таблицу под номером 2 и начнёт записывать логи в неё.

Как посмотреть логи запросов

Перейдите в веб‑интерфейс клики.
В Панели вкладок выберите вкладку Query Logs.
Перейдите на вкладку, которая откроется в браузере. В ней будет интерфейс Strawberry operation с актуальной версией таблицы логов.
Анализируйте запросы с помощью стандартных SQL‑запросов к этой таблице.

Анализ таблицы логов

Чтобы правильно искать и анализировать информацию в таблице логов, важно понимать, что запросы в CHYT обрабатываются распределённо: они разбиваются на фазы (первичные и вторичные запросы). Таблицы Query logs содержат информацию обо всех запросах: и первичных, и вторичных, поэтому при анализе нужно уметь отличать их друг от друга.

Первичный запрос пользователя приходит на инстанс клики, который называется координатором. Координатор проводит первичную подготовку запроса, после которой появляются подзапросы — вторичные запросы, которые будут отправлены с координатора на остальные инстансы.

Как найти нужные запросы в Query logs

Чтобы найти информацию только о первичных запросах, используйте фильтр:

```sql
WHERE query_id = <my_query_id> -- где <my_query_id> — идентификатор интересующего вас запроса
```

У вторичных запросов свои уникальные query_id, поэтому они не попадут в выборку. Также в первичном запросе колонка‑флаг is_initial_query будет равна 1.

Чтобы найти вторичные запросы, связанные с первичным, используйте:

```sql
WHERE initial_query_id = <my_query_id> -- отфильтрует и первичные, и вторичные запросы
AND NOT is_initial_query -- исключит первичные запросы, оставив только вторичные
```

Параметры запросов в таблице Query logs

Столбцы таблицы логов частично соответствуют столбцам таблиц логов ClickHouse и включают дополнительные параметры запросов CHYT.

Примечание

Чтобы расшифровать названия логов ClickHouse, воспользуйтесь документацией ClickHouse.

Параметры CHYT обозначены в таблице Query logs префиксом chyt_.

Опция	Тип данных	Описание
`chyt_instance_cookie`	`Optional[Int64]`	Идентификатор инстанса, которому принадлежит строка лога. Соответствует `job_cookie` джоба, в рамках которого запущен инстанс. Содержит значение из диапазона `[0, n]`, где `n` — размер клики.
`chyt_instance_id`	`Optional[String]`	Идентификатор инстанса, содержит `job_id` джоба, который уникален в рамках операции. Например, в результате перезапуск любого джоба у нового может быть тот же cookie, но новый `id`.
`chyt_instance_fqdn`	`Optional[String]`	Содержит полное доменное имя (FQDN) джоба/инстанса.
`chyt_version`	`Optional[String]`	Версия CHYT, с которой была записана эта строчка лога.
`chyt_secondary_query_ids`	`Optional[List[String]]`	Актуально только для `type = 'QueryFinish'` и `is_initial_query`, то есть для завершающей строчки лога первичного запроса. Содержит список всех `id` вторичных запросов, которые были запущены в рамках первичного.
`chyt_query_runtime_variables`	`Optional[Yson]`	Содержит YSON с `key - value` парами для простого анализа исполнения запроса. Например, используется, чтобы понять, случилась или нет оптимизация X. Актуально только для `type = 'QueryFinish'`. Пример YSON ```json { "try_optimize_distinct_read" = %false; "use_input_specs_pulling" = %false; "use_min_max_optimization" = %false; "use_read_range_inferring" = %false; } ```
`chyt_query_statistics`	`Optional[Yson]`	Содержит YSON с количественными замерами различных метрик запроса. Актуально только для `type = 'QueryFinish'`.

Параметр `chyt_query_statistics`

Этот параметр содержит объёмный YSON, и в рамках одного CHYT запроса имеет разную структуру для первичных и вторичных запросов. Самые важные опции описаны ниже.

Основные опции первичных запросов

input_fetcher — содержит количественную информацию о данных, которую координатор получил от мастера и будет распределять по остальным инстансам клики для дальнейшего выполнения. Это не сами данные, а дескрипторы, которые позволяют понять, откуда и сколько данных нужно читать. Под этим ключом может содержаться два дополнительных:
- filtered_data_slices — содержит информацию о том, сколько данных координатор отфильтровал, то есть выбросил из выборки. Происходит это в соответствии с фильтром запроса;
- data_slices — обратная величина, то есть сколько данных координатор оставил для чтения.
```
{
    "data_slices" = {
        "data_weight" = {
            "count" = 1;
            "last" = 936245229;
            "max" = 936245229;
            "min" = 936245229;
            "sum" = 936245229;
        };
        "row_count" = {
            "count" = 1;
            "last" = 9694599;
            "max" = 9694599;
            "min" = 9694599;
            "sum" = 9694599;
        };
    };
    "filtered_data_slices" = {
        "data_weight" = {
            "count" = 2;
            "last" = 243363;
            "max" = 20320269;
            "min" = 243363;
            "sum" = 20563632;
        };
        "row_count" = {
            "count" = 2;
            "last" = 2563;
            "max" = 88233;
            "min" = 2563;
            "sum" = 90796;
        };
    };
}
```
Каждый ключ содержит счётчик row_count, который показывает, сколько замеров было сделано — count и агрегаты по ним.
phase_duration_us — информация о продолжительности исполнения различных фаз запроса:
- Start — период с момента получения инстансом запроса по сети до фактического старта его исполнения;
- Preparation — фаза, когда координатор собирает метаинформацию о запросе и составляет вторичные запросы;
- Execution — фаза, которая начинается в момент, когда координатор отправляет вторичные запросы на инстансы, и заканчивается, когда координатор отправил весь результат пользователю. В неё входит время, пока координатор получает ответы от вторичных запросов и по мере необходимости обрабатывает их локально.
```
{
    "Execution" = {
        "count" = 1;
        "last" = 13367;
        "max" = 13367;
        "min" = 13367;
        "sum" = 13367;
    };
    "Preparation" = {
        "count" = 1;
        "last" = 112808;
        "max" = 112808;
        "min" = 112808;
        "sum" = 112808;
    };
    "Start" = {
        "count" = 1;
        "last" = 318883;
        "max" = 318883;
        "min" = 318883;
        "sum" = 318883;
    };
}
```

Основные опции вторичных запросов

phase_duration_us — содержит разбивку по фазам. Отличается от phase_duration_us в первичном запросе только семантикой фазы подготовки: в рамках её вторичный инстанс лишь парсит вход от координатора и готовится к исполнению;
granule_min_max_filter — в рамках чтения данных на вторичных запросах присутствует этап пропускания чанков с использованием статистик min/max. В этой опции содержится информация сколько чанков было просмотрено и как много пропущено;
```
{
    "can_skip" = {
        "count" = 92;
        "last" = 1;
        "max" = 1;
        "min" = 0;
        "sum" = 42;
    };
}
```

secondary_query_source — опция с информацией о чтении данных на вторичных запросах, содержит следующие дочерние опции:

block_bytes, block_rows, block_columns — агрегаты по прочитанным данным, которые в итоге ушли в движок ClickHouse, в разных метриках;
steps — CHYT может читать и конвертировать различные колонки поэтапно. Эта логика похожа на предикат PREWHERE в ClickHouse, когда сперва читаются фильтрующие колонки, а потом, в зависимости от их содержимого, остальные. В этом разделе можно увидеть, сколько шагов было выполнено и сколько через них прошло данных;
columnar_conversion_cpu_time_us, columnar_conversion_wall_time_us — CHYT вынужден конвертировать прочитанные данные из YTsaurus формата в формат ClickHouse. На конвертацию иногда уходит значимая часть времени, и эти опции позволяют показать, сколько именно;
chunk_reader — основная секция с информацией о чтении данных из YTsaurus, основными подопциями являются data_bytes_read_from_cache и data_bytes_read_from_disk, которые показывают сколько данных взято из кеша, а сколько читалось с дисков;
wait_ready_event_time_us — эта опция семантически связана с chunk_reader и показывает, сколько времени заняло ожидание следующей порции данных, чтобы начать её конвертировать.

{
    "block_bytes" = {
        "count" = 3661;
        "max" = 4080068;
        "min" = 0;
        "sum" = 7888434964;
    };
    "block_columns" = {
        "count" = 3661;
        "max" = 8;
        "min" = 0;
        "sum" = 29272;
    };
    "block_rows" = {
        "count" = 3661;
        "max" = 10000;
        "min" = 0;
        "sum" = 31148625;
    };
    "chunk_reader" = {
        "data_bytes_read_from_cache" = {
            "count" = 2;
            "max" = 297136447;
            "min" = 149780474;
            "sum" = 446916921;
        };
        "data_bytes_read_from_disk" = {
            "count" = 2;
            "max" = 0;
            "min" = 0;
            "sum" = 0;
        };
        "data_bytes_transmitted" = {
            "count" = 2;
            "max" = 0;
            "min" = 0;
            "sum" = 0;
        };
        "data_io_requests" = {
            "count" = 2;
            "max" = 0;
            "min" = 0;
            "sum" = 0;
        };
        "meta_bytes_read_from_disk" = {
            "count" = 2;
            "max" = 0;
            "min" = 0;
            "sum" = 0;
        };
    };
    "columnar_conversion_cpu_time_us" = {
        "count" = 3659;
        "max" = 14601;
        "min" = 36;
        "sum" = 4846058;
    };
    "conversion_sync_wait_time_us" = {
        "count" = 3659;
        "max" = 19267;
        "min" = 106;
        "sum" = 6489348;
    };
    "idle_time_us" = {
        "count" = 3663;
        "max" = 4150;
        "min" = 8;
        "sum" = 145923;
    };
    "processed_reader_count" = {
        "count" = 2;
        "max" = 2;
        "min" = 1;
        "sum" = 3;
    };
    "read_count" = {
        "count" = 2;
        "max" = 2441;
        "min" = 1220;
        "sum" = 3661;
    };
    "read_impl_us" = {
        "count" = 3661;
        "max" = 34904;
        "min" = 122;
        "sum" = 6904768;
    };
    "step_count" = {
        "count" = 2;
        "max" = 1;
        "min" = 1;
        "sum" = 2;
    };
    "steps" = {
        "0" = {
            "block_bytes" = {
                "count" = 3659;
                "max" = 4080068;
                "min" = 6268;
                "sum" = 7888434964;
            };
            "block_columns" = {
                "count" = 3659;
                "max" = 8;
                "min" = 8;
                "sum" = 29272;
            };
            "block_rows" = {
                "count" = 3659;
                "max" = 10000;
                "min" = 30;
                "sum" = 31148625;
            };
        };
    };
    "total_rows" = {
        "count" = 3661;
        "max" = 10000;
        "min" = 0;
        "sum" = 31148625;
    };
    "wait_ready_event_time_us" = {
        "count" = 36;
        "max" = 32988;
        "min" = 2;
        "sum" = 144348;
    };
}

Управление правами доступа

Получение версий CHYT и ClickHouse