Удивительная история про то, как быстрый запрос стал медленным

[Stepan Semiokhin]

Добрый день!

Произошла тут странная вещь при тестировании Кликхауса.

Начальные условия:

-кластер из 10 мощных машин;

-распределенная таблица на 560 млн. записей;

-довольно сложный запрос.

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

Я сразу отметил непонятный момент - хотя в очереди на выполнение было 43 запроса, top говорил, что кликхаус использует только 800% CPU (вместо 3150% при 8-секундном запросе).

После рассасывания очереди запрос начал выполняться по 40 секунд с таким же "неполным" использованием CPU.

За пару дней запрос ускорился, сначала выполнялся 30 секунд, потом 20, сейчас вот 18.

Данные не менялись, ничего на машинах не менялось, ничего в настройках кликхауса не менялось.

Покопавшись в логах (прикладываю небольшой кусок логов быстрого запроса и кусок логов медленного) я выявил следующие отличия:

1) В старом быстром логе трейс аггрегатора включает в себя конвертацию даннах до второго уровня, т.е. имеет следующий вид:

...

2016.10.18 16:17:32.699 [ 593 ] <Trace> Aggregator: Aggregation method: concat

2016.10.18 16:17:32.706 [ 593 ] <Trace> Aggregator: Converting aggregation data to two-level.

2016.10.18 16:17:32.721 [ 594 ] <Trace> Aggregator: Aggregation method: concat

2016.10.18 16:17:32.722 [ 595 ] <Trace> Aggregator: Aggregation method: concat

2016.10.18 16:17:32.726 [ 594 ] <Trace> Aggregator: Converting aggregation data to two-level.

2016.10.18 16:17:32.728 [ 596 ] <Trace> Aggregator: Aggregation method: concat

...

В то время как в новом запросе никакой конвертации нет

2) Основное торможение происходит на этапе с трейсами:

...

2016.10.18 16:17:39.232 [ 581 ] <Trace> ParallelAggregatingBlockInputStream: Aggregated. 1457082 to 199 rows (from 119.272 MiB) in 6.832 sec. (213276.275 rows/sec., 17.458 MiB/sec.)

2016.10.18 16:17:39.232 [ 581 ] <Trace> ParallelAggregatingBlockInputStream: Aggregated. 1380278 to 189 rows (from 112.282 MiB) in 6.832 sec. (202034.306 rows/sec., 16.435 MiB/sec.)

....

В новом медленном запросе время в 3 раза больше

3) Разное количество блоков данных, в быстром запросе блоков больше

4)  В логах быстрого запроса  Query pipeline почему-то пустой, в то время как в новом медленном запросе он красиво нарисован. Мелочь, но мало ли... 

Что могло случится? Выполнилась какая-то оптимизации или что?

И "как вернуть, как было"? :)

[Stepan Semiokhin]

Вот логи

[Stepan Semiokhin]

Проблему решил рестарт всех хостов, но это странное поведение, так что последний вопрос не актуален, но остальные 2 в силе.

Могу приложить лог c моментом нагрузки, после которого произошла деградация, но там ничего интересного, разве что ошибки:

....

<Error> executeQuery: Code: 210, e.displayText() = DB::NetException: Connection reset by peer while writing to socket ([::ffff:10.233.10.42]:50496), e.what() = DB::NetException

....

с пустым стектрейсом

[man...@gmail.com]

Тут довольно много деталей, легко запутаться.
Давайте сначала проверим, как влияет на выполнение запроса настройка group_by_two_level_threshold.
Попробуйте выполнить запрос с group_by_two_level_threshold = 0 и group_by_two_level_threshold = 1.

Результаты не дадут ответа на вопрос, но кое что прояснят.

[man...@gmail.com]

Ещё хочу, чтобы вы попробовали поэкспериментировать с параметром max_block_size. Например, выставить его в значение 8192 вместо 65536 по-умолчанию.

Для запроса, который возвращает сотни строк после агрегации, потребление оперативки в ~2GB - это много, и наводит на подозрения, что запрос обрабатывает длинные строковые значения.

Для отладки, попробуйте ещё сделать такой же запрос, но убрав оттуда всё лишнее. Всякий мусор типа if(toInt32(-1) = 0, 0, 1) на производительность не влияет, но без него исследовать будет проще.

[Stepan Semiokhin]

Попробовал поизменять max_block_size, 8192 действительно ускорило запрос, спасибо.

Параметр group_by_two_level_threshold на скорость не влияет никак.

Поведение при нагрузке воспроизводится, то есть: каждый раз, когда я сильно нагружаю базу с этим запросом, начинает валится ошибка с кодом 159, а после остановки "подачи нагрузки" и рассасывания всех запросов (по факту, я так понимаю, они все просто падают), каждый запрос начинает выполняться долго. Единственный спососб снова заставить его работать быстро - рестарт кликхауса на всех нодах.

Вот, что пишется в логи, когда начинают валиться запросы:

В clickhouse.log:

......

2016.10.26 16:56:01.074 [ 634 ] <Error> executeQuery: Code: 159, e.displayText() = DB::Exception: Timeout exceeded: elapsed 48.864352586 seconds, maximum: 40, e.what() = DB::Exception (from ::ffff:10.255.4.121) (in query: select ... limit 1000 FORMAT TabSeparatedWithNamesAndTypes), Stack trace:

0. clickhouse-server(StackTrace::StackTrace()+0x16) [0xfea856]

1. clickhouse-server(DB::Exception::Exception(std::string const&, int)+0x1f) [0xfadbbf]

2. clickhouse-server(DB::IProfilingBlockInputStream::checkLimits()+0x54a) [0x11e709a]

3. clickhouse-server(DB::IProfilingBlockInputStream::read()+0x1d6) [0x11e8456]

4. clickhouse-server(DB::ParallelInputsProcessor<DB::UnionBlockInputStream<(DB::StreamUnionMode)0>::Handler, (DB::StreamUnionMode)0>::loop(unsigned long)+0x10b) [0x133219b]

5. clickhouse-server(DB::ParallelInputsProcessor<DB::UnionBlockInputStream<(DB::StreamUnionMode)0>::Handler, (DB::StreamUnionMode)0>::thread(MemoryTracker*, unsigned long)+0x56) [0x1332a66]

6. clickhouse-server(execute_native_thread_routine+0x20) [0x32ecd00]

7. /lib/x86_64-linux-gnu/libpthread.so.0(+0x8184) [0x7f8973217184]

8. /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f897283237d]

2016.10.26 16:56:01.074 [ 634 ] <Trace> UnionBlockInputStream: Waiting for threads to finish

2016.10.26 16:56:01.202 [ 1402 ] <Trace> RemoteBlockInputStream: (control002:9000, 10.233.10.43) Cancelling query

2016.10.26 16:56:01.497 [ 1402 ] <Trace> RemoteBlockInputStream: (control003:9000, 10.233.10.44) Cancelling query

2016.10.26 16:56:01.567 [ 1403 ] <Trace> Aggregator: Aggregation method: concat

2016.10.26 16:56:01.619 [ 1404 ] <Trace> Aggregator: Aggregation method: concat

2016.10.26 16:56:01.631 [ 1402 ] <Trace> RemoteBlockInputStream: (control004:9000, 10.233.10.45) Cancelling query

2016.10.26 16:56:01.670 [ 1405 ] <Trace> Aggregator: Aggregation method: concat

2016.10.26 16:56:02.002 [ 1402 ] <Trace> RemoteBlockInputStream: (control005:9000, 10.233.10.46) Cancelling query

2016.10.26 16:56:02.314 [ 1406 ] <Trace> Aggregator: Aggregation method: concat

2016.10.26 16:56:02.338 [ 1407 ] <Trace> Aggregator: Aggregation method: concat

2016.10.26 16:56:02.427 [ 1402 ] <Trace> RemoteBlockInputStream: (control006:9000, 10.233.10.47) Cancelling query

2016.10.26 16:56:02.427 [ 1402 ] <Trace> RemoteBlockInputStream: (control007:9000, 10.233.10.48) Cancelling query

.....

В clickhouse.err.log тоже самое:

.....

2016.10.26 16:58:54.778 [ 1800 ] <Error> HTTPHandler: Code: 159, e.displayText() = DB::Exception: Timeout exceeded: elapsed 137.316989926 seconds, maximum: 40, e.what() = DB::Exception, Stack trace:

0. clickhouse-server(StackTrace::StackTrace()+0x16) [0xfea856]

1. clickhouse-server(DB::Exception::Exception(std::string const&, int)+0x1f) [0xfadbbf]

2. clickhouse-server(DB::IProfilingBlockInputStream::checkLimits()+0x54a) [0x11e709a]

3. clickhouse-server(DB::IProfilingBlockInputStream::read()+0x1d6) [0x11e8456]

4. clickhouse-server(DB::ParallelInputsProcessor<DB::UnionBlockInputStream<(DB::StreamUnionMode)0>::Handler, (DB::StreamUnionMode)0>::loop(unsigned long)+0x10b) [0x133219b]

5. clickhouse-server(DB::ParallelInputsProcessor<DB::UnionBlockInputStream<(DB::StreamUnionMode)0>::Handler, (DB::StreamUnionMode)0>::thread(MemoryTracker*, unsigned long)+0x56) [0x1332a66]

6. clickhouse-server(execute_native_thread_routine+0x20) [0x32ecd00]

7. /lib/x86_64-linux-gnu/libpthread.so.0(+0x8184) [0x7f8973217184]

8. /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f897283237d]

2016.10.26 16:58:54.784 [ 2201 ] <Trace> RemoteBlockInputStream: (control007:9000, 10.233.10.48) Cancelling query

2016.10.26 16:58:54.810 [ 2034 ] <Trace> RemoteBlockInputStream: (control003:9000, 10.233.10.44) Cancelling query

2016.10.26 16:58:54.827 [ 2034 ] <Trace> RemoteBlockInputStream: (control004:9000, 10.233.10.45) Cancelling query

2016.10.26 16:58:54.847 [ 2201 ] <Trace> RemoteBlockInputStream: (control008:9000, 10.233.10.49) Cancelling query

2016.10.26 16:58:54.847 [ 2201 ] <Trace> RemoteBlockInputStream: (control009:9000, 10.233.10.50) Cancelling query

2016.10.26 16:58:54.884 [ 2201 ] <Trace> RemoteBlockInputStream: (control010:9000, 10.233.10.51) Cancelling query

2016.10.26 16:58:54.884 [ 2187 ] <Trace> UnionBlockInputStream: Waited for threads to finish

2016.10.26 16:58:54.889 [ 2187 ] <Debug> MemoryTracker: Peak memory usage (for query): 672.90 MiB.

2016.10.26 16:58:54.890 [ 2034 ] <Trace> RemoteBlockInputStream: (control005:9000, 10.233.10.46) Cancelling query

2016.10.26 16:58:54.895 [ 2187 ] <Error> HTTPHandler: Code: 159, e.displayText() = DB::Exception: Timeout exceeded: elapsed 117.036843666 seconds, maximum: 40, e.what() = DB::Exception, Stack trace:

0. clickhouse-server(StackTrace::StackTrace()+0x16) [0xfea856]

1. clickhouse-server(DB::Exception::Exception(std::string const&, int)+0x1f) [0xfadbbf]

2. clickhouse-server(DB::IProfilingBlockInputStream::checkLimits()+0x54a) [0x11e709a]

3. clickhouse-server(DB::IProfilingBlockInputStream::read()+0x1d6) [0x11e8456]

4. clickhouse-server(DB::ParallelInputsProcessor<DB::UnionBlockInputStream<(DB::StreamUnionMode)0>::Handler, (DB::StreamUnionMode)0>::loop(unsigned long)+0x10b) [0x133219b]

5. clickhouse-server(DB::ParallelInputsProcessor<DB::UnionBlockInputStream<(DB::StreamUnionMode)0>::Handler, (DB::StreamUnionMode)0>::thread(MemoryTracker*, unsigned long)+0x56) [0x1332a66]

6. clickhouse-server(execute_native_thread_routine+0x20) [0x32ecd00]

7. /lib/x86_64-linux-gnu/libpthread.so.0(+0x8184) [0x7f8973217184]

8. /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f897283237d]

......

[Stepan Semiokhin]

Хм, я думал 40 секунд (о которых нам говорит исключение) - это параметр max_execution_time , ан нет...

[man...@gmail.com]

Для дальнейших разбирательств надо максимально изолировать проблему.

1. Попробуйте воспроизвести на локальном запросе (использующем один сервер).
2. Посмотрите по top-у, в течение какого времени выполнения, сколько CPU использует запрос, в быстром и в медленном случае.
3. Подавая нагрузку, в отдельном терминале запустите sudo perf record. После окончания - sudo perf report. Сравните репорты для быстрого и медленного случая.

[Stepan Semiokhin]

По порядку:

1. В медленном варианте запрос на одном хосте отличается  от запроса на распределенную таблицу на 1 секунду, так же, как и в быстром варианте, так что дело не в стадии мерджа.

2. По top-у (актуально и для запросов в распределенную таблицу и на один сервер): 

быстрый - до 3500% cpu

медленный - до 980% cpu

Вот здесь видимо и собака зарыта.

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

четверг, 27 октября 2016 г., 7:55:47 UTC+3 пользователь man...@gmail.com написал:

[man...@gmail.com]

Также имеет смысл сравнить время, проведённое в ядре. Оно отображается в top-е как "sy": %Cpu(s):  3.4 us,  1.1 sy.

По репортам видно, что в медленном случае чаще вызывается функция tcmalloc::PageHeap::allocLarge.
perf report имеет смысл делать по всей системе: perf report -a. Например, если вы там увидите page_fault, clear_page и т. п. - значит проблема в том, что аллокатор слишком часто вызывает mmap.

Насчёт вашего запроса. Видно, что больше всего тормозит функция concat.
Также тормозит выполнение оператора IN (Set::executeImpl). Хотя он у вас используется в выражениях вида
dictGetString('pay_type', 'name', toUInt64(pay_type)), ']') IN 'pay_type'
- здесь множество из одного элемента.
ClickHouse не умеет сам преобразовывать это в равенство. Если вы сами напишете равенство, будет лучше.

Также было бы хорошо, если бы ClickHouse понял, что
concat('[Type].[', dictGetString('pay_type', 'name', toUInt64(pay_type)), ']') IN 'pay_type'
- это заведомо невозможное условие и выкинул бы его.

Также он не понимает, что
inn LIKE concat('%', '', '%')
- всегда выполнено.
Хотя константные выражения сворачиваются - это выражение эквивалентно
inn LIKE '%%'
но дальше ClickHouse не может понять, что проверять LIKE '%%' не имеет смысла.

[Stepan Semiokhin]

Все эти условия так выглядят, потому что это пользовательские запросы, в которые переменные подставляются через Pentaho.

В принципе, могу это оптимизировать на уровне генерации конечного запроса, но суть не в этом.

Меня устраивает и то время, которое есть сейчас (когда все работает корректно), оно отличное и даже не страшно, если нагрузку тут не особо держит, она не сильно нужна, но не хотелось бы, чтобы после 20 почти одновременных запросах, деградировало использование CPU... Каждый раз перезагружать кликхаус на всех машинах кластера - это, конечно, не выход.

system.settings при быстром и медленном варианте одинаковые, так что, как я понял, никакого магического механизма "оптимизации настроек под нагрузку" не срабатывает. Тогда что это может быть? Нет идей, куда смотреть?

четверг, 27 октября 2016 г., 18:11:14 UTC+3 пользователь man...@gmail.com написал:

[Mike Eremin]

Прошу прощения, что не по теме, а можно меня ткнуть веткой, как подружили пентаху и кликхаус?

Спасибо!

понедельник, 24 октября 2016 г., 2:17:04 UTC+3 пользователь Stepan Semiokhin написал:

[Stepan Semiokhin]

Конечно, вот тут описал: https://groups.google.com/forum/#!searchin/clickhouse/%D0%94%D0%BE%D0%B1%D1%80%D1%8B%D0%B9$20%D0%B4%D0%B5%D0%BD%D1%8C$2C$20%D0%B5%D1%81%D0%BB%D0%B8$20%D0%B2%D0%BE%D0%BF%D1%80%D0%BE%D1%81$20%D0%B5%D1%89%D0%B5$20%D0%B0%D0%BA%D1%82%D1%83%D0%B0%D0%BB%D0%B5%D0%BD%7Csort:relevance/clickhouse/y_Gx27UAd1U/-oRqHn_NAQAJ

пятница, 28 октября 2016 г., 0:19:42 UTC+3 пользователь Mike Eremin написал:

[man...@gmail.com]

Есть вопрос - вы используете ClickHouse из пакета или собирали самостоятельно?

Если собирали самостоятельно, не могло ли быть так, что вы случайно использовали tcmalloc из системного пакета или установленный вручную, вместо того, который размещён в дереве исходников: https://github.com/yandex/ClickHouse/tree/master/contrib/libtcmalloc

Дело в том, что наш tcmalloc содержит маленький патч, который как раз исправляет проблему, что tcmalloc слишком часто зовёт mmap при аллокациях "среднего" размера.
Я как раз наблюдал деградацию производительности, связанную с этим.

Также замечу, что вы не привели результат perf record -a (или просто запустите perf top); поищите там функции clear_page_c и page_fault.

[Stepan Semiokhin]

Собран из пакета, версия 1.1.54020 под Ubuntu 14.04 . Привел результаты как раз perf record -a , но только верхушку, записи page_fault там были ниже, но были и в быстром, и в медленном случае, поэтому особого значения не придал. Вечером скину более полный репорт.

пятница, 28 октября 2016 г., 22:41:04 UTC+3 пользователь man...@gmail.com написал:

[Stepan Semiokhin]

Еще раз помониторил perf repot и единственное, что бросается в глаза - это больший процент работы swapper-а при медленном запросе, clear_page и page_fault есть и там, и там, вообще вот репорты: https://drive.google.com/file/d/0BzC4KvvQ_6JULVhoN2pCMmFZaEU/view?usp=sharing

пятница, 28 октября 2016 г., 22:41:04 UTC+3 пользователь man...@gmail.com написал:

Есть вопрос - вы используете ClickHouse из пакета или собирали самостоятельно?