Потери данных в одном из Materialized view на одном из шардов

[Mikhail Petrov]

Привет.

Столкнулся с очень странным поведением: есть Distributed-таблица, в которую идет вставка. Три шарда, две реплики на первом, пока без реплик на 2 и 3  (будут созданы позже). internal_replication=true.

Физически вставка идет distributed-таблицы на 1 шарде, через условие хеширования распределяется на остальные.

Заметил следующие странности:

1. В предыдущей итерации кластера данные вставлялись в distributed на все хосты. И на хостах без реплик в distributed-таблице копились данные в data-каталоге. Такое ощущение, что данные, которые должны уходить на другие шарды - уходили и удалялись, а те, что должны были остаться на этом - не пурджились.

2. К реплицируемой таблице данных привязаны 5 вьюшек. При этом 4 из них работали нормально, а пятая (по размеру не самая большая) в процессе работы постоянно тормозила - в ней генерилось чудовищное количество кусков, обычно в районе 1700-1800, инсерты длинных файлов (до 6-7Gb в gzipped TSV) тормозились, часто прерывались. Создавались вьюшки почти копи-пейстом, чуть другие ключи, одинаковые данные и движки (ReplicatedAggregatingMergeTree).

3. После проверки данных оказывается, что в этой самой view данные теряются, причем постоянно, и только на том шарде, в который шла физическая вставка - даже да текущий день, когда и ошибок вставки практически не было.

Так как все таблицы реплицируемые, то прерванные вставки просто повторялись, данные в основной таблице и остальных View консистентны и совпадают с ожидаемым. Отличие только в одном view на одном шарде.

В err-логе за последние дни про этот View пусто. Есть только ошибки вставки - DB::Exception: Too many parts (300). Merges are processing significantly slower than inserts..

В detached в проблемной view пусто. После окончания insert'а количество кусков в ней довольно быстро нормализуется.

В запросе VIEW where нет (ну и на других шардах-то все ок).

В чем может быть дело? Куда копать? Версия  1.1.54327, обновлялись перед НГ.

В логах этого шарда огромное количество строк про операции очень маленькими бакетами именно про проблемную таблицу. На остальных шардах такого вроде бы нет - но там и физических вставок нет, только прилетающие от distributed.

2018.01.12 15:42:51.843892 [ 49 ] <Trace> Aggregator: Merging partially aggregated blocks (bucket = 252).

2018.01.12 15:42:51.844689 [ 49 ] <Trace> Aggregator: Merged partially aggregated blocks. 330 rows, 23.999 MiB. in 0.001 sec. (443579.390 rows/sec., 32258.967 MiB/sec.)

2018.01.12 15:42:51.854477 [ 49 ] <Debug> SrcViews..inner.TTViewDailyOther (Replicated OutputStream): Wrote block with 330 rows

2018.01.12 15:42:51.877467 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.

2018.01.12 15:42:51.920792 [ 55 ] <Trace> InterserverIOHTTPHandler-factory: HTTP Request for InterserverIOHTTPHandler-factory. Method: POST, Address: 10.247.129.196:59374, User-Agent: none

2018.01.12 15:42:51.920808 [ 55 ] <Trace> InterserverIOHTTPHandler: Request URI: ?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2F2%2FTTViewDailyOther%2Freplicas%2Fch2r1.local&part=20180112_201801

12_958248_958248_0&shard=&compress=false

2018.01.12 15:42:51.920923 [ 55 ] <Trace> SrcViews..inner.TTViewDailyOther (Replicated PartsService): Sending part 20180112_20180112_958248_958248_0

2018.01.12 15:42:51.929848 [ 55 ] <Information> InterserverIOHTTPHandler: Done processing query

2018.01.12 15:42:51.961394 [ 49 ] <Trace> SrcViews..inner.TTViewDailyOther (Data): Renaming temporary part tmp_insert_20180112_20180112_1079837_1079837_0 to 20180112_20180112_958250_958250_0.

2018.01.12 15:42:52.036461 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0005413670 - log-0005413670

2018.01.12 15:42:52.123049 [ 49 ] <Trace> Aggregator: Merging partially aggregated blocks (bucket = 253).

2018.01.12 15:42:52.123925 [ 49 ] <Trace> Aggregator: Merged partially aggregated blocks. 336 rows, 24.002 MiB. in 0.001 sec. (410909.149 rows/sec., 29353.693 MiB/sec.)

2018.01.12 15:42:52.133673 [ 49 ] <Debug> SrcViews..inner.TTViewDailyOther (Replicated OutputStream): Wrote block with 336 rows

2018.01.12 15:42:52.143005 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.

2018.01.12 15:42:52.189356 [ 211 ] <Trace> InterserverIOHTTPHandler-factory: HTTP Request for InterserverIOHTTPHandler-factory. Method: POST, Address: 10.247.129.196:59376, User-Agent: none

2018.01.12 15:42:52.189373 [ 211 ] <Trace> InterserverIOHTTPHandler: Request URI: ?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2F2%2FTTViewDailyOther%2Freplicas%2Fch2r1.local&part=20180112_20180

112_958249_958249_0&shard=&compress=false

2018.01.12 15:42:52.189489 [ 211 ] <Trace> SrcViews..inner.TTViewDailyOther (Replicated PartsService): Sending part 20180112_20180112_958249_958249_0

2018.01.12 15:42:52.198676 [ 211 ] <Information> InterserverIOHTTPHandler: Done processing query

2018.01.12 15:42:52.240614 [ 49 ] <Trace> SrcViews..inner.TTViewDailyOther (Data): Renaming temporary part tmp_insert_20180112_20180112_1079838_1079838_0 to 20180112_20180112_958251_958251_0.

2018.01.12 15:42:52.302056 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0005413671 - log-0005413671

2018.01.12 15:42:52.402625 [ 49 ] <Trace> Aggregator: Merging partially aggregated blocks (bucket = 254).

2018.01.12 15:42:52.403477 [ 49 ] <Trace> Aggregator: Merged partially aggregated blocks. 339 rows, 24.004 MiB. in 0.001 sec. (428215.755 rows/sec., 30321.414 MiB/sec.)

2018.01.12 15:42:52.408605 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.

2018.01.12 15:42:52.414108 [ 49 ] <Debug> SrcViews..inner.TTViewDailyOther (Replicated OutputStream): Wrote block with 339 rows

2018.01.12 15:42:52.455785 [ 66 ] <Trace> InterserverIOHTTPHandler-factory: HTTP Request for InterserverIOHTTPHandler-factory. Method: POST, Address: 10.247.129.196:59378, User-Agent: none

2018.01.12 15:42:52.455802 [ 66 ] <Trace> InterserverIOHTTPHandler: Request URI: ?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2F2%2FTTViewDailyOther%2Freplicas%2Fch2r1.local&part=20180112_201801

12_958250_958250_0&shard=&compress=false

2018.01.12 15:42:52.455926 [ 66 ] <Trace> SrcViews..inner.TTViewDailyOther (Replicated PartsService): Sending part 20180112_20180112_958250_958250_0

2018.01.12 15:42:52.465401 [ 66 ] <Information> InterserverIOHTTPHandler: Done processing query

2018.01.12 15:42:52.520984 [ 49 ] <Trace> SrcViews..inner.TTViewDailyOther (Data): Renaming temporary part tmp_insert_20180112_20180112_1079839_1079839_0 to 20180112_20180112_958252_958252_0.

2018.01.12 15:42:52.682985 [ 49 ] <Trace> Aggregator: Merging partially aggregated blocks (bucket = 255).

2018.01.12 15:42:52.683881 [ 49 ] <Trace> Aggregator: Merged partially aggregated blocks. 327 rows, 23.997 MiB. in 0.001 sec. (397008.956 rows/sec., 29135.084 MiB/sec.)

2018.01.12 15:42:52.693699 [ 49 ] <Debug> SrcViews..inner.TTViewDailyOther (Replicated OutputStream): Wrote block with 327 rows

2018.01.12 15:42:52.722277 [ 213 ] <Trace> InterserverIOHTTPHandler-factory: HTTP Request for InterserverIOHTTPHandler-factory. Method: POST, Address: 10.247.129.196:59380, User-Agent: none

2018.01.12 15:42:52.722393 [ 213 ] <Trace> InterserverIOHTTPHandler: Request URI: ?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2F2%2FTTViewDailyOther%2Freplicas%2Fch2r1.local&part=20180112_20180

112_958251_958251_0&shard=&compress=false

2018.01.12 15:42:52.722518 [ 213 ] <Trace> SrcViews..inner.TTViewDailyOther (Replicated PartsService): Sending part 20180112_20180112_958251_958251_0

2018.01.12 15:42:52.726356 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0005413672 - log-0005413672

2018.01.12 15:42:52.732093 [ 213 ] <Information> InterserverIOHTTPHandler: Done processing query

2018.01.12 15:42:52.800652 [ 49 ] <Trace> SrcViews..inner.TTViewDailyOther (Data): Renaming temporary part tmp_insert_20180112_20180112_1079840_1079840_0 to 20180112_20180112_958253_958253_0.

2018.01.12 15:42:52.832713 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulled 1 entries to queue.

2018.01.12 15:42:52.886208 [ 136 ] <Debug> SrcViews..inner.TTViewDailyOther (Merger): Selected 41 parts from 20180112_20180112_958145_958145_0 to 20180112_20180112_958185_958185_0

2018.01.12 15:42:52.961929 [ 49 ] <Trace> MergingAggregatedMemoryEfficientBlockInputStream: Waiting for threads to finish

2018.01.12 15:42:52.961956 [ 49 ] <Trace> MergingAggregatedMemoryEfficientBlockInputStream: Waited for threads to finish

2018.01.12 15:42:52.988555 [ 58 ] <Trace> InterserverIOHTTPHandler-factory: HTTP Request for InterserverIOHTTPHandler-factory. Method: POST, Address: 10.247.129.196:59382, User-Agent: none

2018.01.12 15:42:52.988576 [ 58 ] <Trace> InterserverIOHTTPHandler: Request URI: ?endpoint=DataPartsExchange%3A%2Fclickhouse%2Ftables%2F2%2FTTViewDailyOther%2Freplicas%2Fch2r1.local&part=20180112_201801

12_958252_958252_0&shard=&compress=false

2018.01.12 15:42:52.988910 [ 58 ] <Trace> SrcViews..inner.TTViewDailyOther (Replicated PartsService): Sending part 20180112_20180112_958252_958252_0

2018.01.12 15:42:52.991653 [ 46 ] <Debug> SrcViews..inner.TTViewDailyOther (ReplicatedMergeTreeQueue): Pulling 1 entries to queue: log-0005413673 - log-0005413673

2018.01.12 15:42:52.997649 [ 58 ] <Information> InterserverIOHTTPHandler: Done processing query

--
MIkhail Petrov

[Mikhail Petrov]

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

Вставка в distributed-таблицу при больших объемах файлов получается в 3-4 раза дольше, чем в обычную таблицу. На мелких объемах (сотни Mb сжатых данных) - ночью - скорость примерно идентична.

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

12 января 2018 г., 16:06 пользователь Mikhail Petrov <m...@perfiq.ru> написал:

--

--
MIkhail Petrov