search

ClickHouse / ClickHouse

ClickHouse® is a real-time analytics DBMS
https://clickhouse.com
Apache License 2.0
36.83k stars 6.81k forks source link

From 24.3, Kafka table Engine frequently timeout: consumers had been closed (due to 60000000 usec timeout) #66415

Open spff opened 2 months ago

spff commented 2 months ago

Affected versions: From 24.3 Tested versions: 24.6.2.17, 24.5.1.1763, 24.4.3.25, 24.3.5.46, 24.3.1.2672

Create table query

CREATE TABLE kafka.mykafkatable (...)
ENGINE = Kafka
SETTINGS kafka_broker_list = '...', kafka_topic_list = 'mykafkatable', kafka_group_name = '...', kafka_format = 'JSONEachRow', kafka_thread_per_consumer = 1, kafka_num_consumers = 1, kafka_skip_broken_messages = 1, kafka_max_block_size = 270000

I have the tables like Kafka -> MaterializedView -> Null -> MaterializedViews -> remoteTables

One remoteTable be like

CREATE TABLE a.b_remote
(...) AS remoteSecure(...)

Unexpected

Under version 24.3.1.2672 clickhouse-server.log I found a lot of

<Trace> StorageKafka (mykafkatable): Closing #0 consumer (id: ClickHouse-myhostname-kafka-mykafkatable-...)
<Trace> StorageKafka (mykafkatable): Rebalance initiated. Revoking partitions: [ mykafkatable[0:#] ]
<Trace> StorageKafka (mykafkatable): 1 consumers had been closed (due to 60000000 usec timeout). Took 1 ms.

Full clickhouse-server.log

2024.07.11 09:53:37.115050 [ 1853079 ] {} <Warning> StorageKafka (mykafkatable): sasl.kerberos.kinit.cmd configuration parameter is ignored.
2024.07.11 09:53:37.116649 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Created #0 consumer
2024.07.11 09:53:37.116784 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: []
2024.07.11 09:53:37.116804 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 09:53:37.146123 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 09:53:37.641112 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 56568 messages. Offsets position: [ mykafkatable[0:19050352261] ]
2024.07.11 09:53:39.207397 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 817 messages. Offsets position: [ mykafkatable[0:19050353078] ]
2024.07.11 09:53:39.725422 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 179 messages. Offsets position: [ mykafkatable[0:19050353257] ]
2024.07.11 09:53:40.146925 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Rebalance initiated. Revoking partitions: [ mykafkatable[0:#] ]
2024.07.11 09:53:40.150340 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 09:53:40.237000 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Rewind last poll after rebalance. Returned to committed position: [ mykafkatable[0:19050295693] ]
2024.07.11 09:53:40.256027 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Polled offset INVALID (topic: mykafkatable, partition: 0)
2024.07.11 09:53:40.256080 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 09:53:40.256109 [ 1853079 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 59212 ms.
2024.07.11 09:53:40.262210 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 09:53:40.262248 [ 1853079 ] {} <Trace> StorageKafka (mykafkatable): Execution took 59219 ms.
2024.07.11 09:53:40.762424 [ 1853010 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 09:54:40.533301 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): Closing #0 consumer (id: ClickHouse-myhostname-kafka-mykafkatable-d45fd36d-6027-4587-8a32-6c60d3ff045a)
2024.07.11 09:54:40.548048 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): Rebalance initiated. Revoking partitions: [ mykafkatable[0:#] ]
2024.07.11 09:54:40.638994 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): 1 consumers had been closed (due to 60000000 usec timeout). Took 5 ms.
2024.07.11 09:54:40.691552 [ 1853010 ] {} <Warning> StorageKafka (mykafkatable): sasl.kerberos.kinit.cmd configuration parameter is ignored.
2024.07.11 09:54:40.692923 [ 1853010 ] {} <Trace> StorageKafka (mykafkatable): Created #0 consumer
2024.07.11 09:54:40.693000 [ 1853010 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: []
2024.07.11 09:54:40.693013 [ 1853010 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 09:54:55.700775 [ 1853010 ] {} <Warning> StorageKafka (mykafkatable): Can't get assignment. Will keep trying.
2024.07.11 09:54:55.715999 [ 1853010 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 09:54:55.716022 [ 1853010 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 74952 ms.
2024.07.11 09:54:55.721402 [ 1853010 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 09:54:55.721432 [ 1853010 ] {} <Trace> StorageKafka (mykafkatable): Execution took 74957 ms.
2024.07.11 09:54:56.221720 [ 1852975 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 09:55:53.377482 [ 1852975 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 09:55:53.377499 [ 1852975 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 09:55:53.427834 [ 1852975 ] {} <Warning> StorageKafka (mykafkatable): Can't get assignment. Will keep trying.
2024.07.11 09:55:53.440134 [ 1852975 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 09:55:53.440180 [ 1852975 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 57217 ms.
2024.07.11 09:55:53.445440 [ 1852975 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 09:55:53.445468 [ 1852975 ] {} <Trace> StorageKafka (mykafkatable): Execution took 57222 ms.
2024.07.11 09:55:53.945917 [ 1853060 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 09:56:51.182990 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 09:56:51.183007 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 09:56:51.183177 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 09:56:51.235592 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 7883 messages. Offsets position: [ mykafkatable[0:19050303576] ]
2024.07.11 09:56:51.451515 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 36346 messages. Offsets position: [ mykafkatable[0:19050339922] ]
2024.07.11 09:56:52.186014 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 60508 messages. Offsets position: [ mykafkatable[0:19050400430] ]
2024.07.11 09:56:53.390945 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 49368 messages. Offsets position: [ mykafkatable[0:19050449798] ]
2024.07.11 09:56:54.385603 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 495 messages. Offsets position: [ mykafkatable[0:19050450293] ]
2024.07.11 09:56:54.449465 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 150 messages. Offsets position: [ mykafkatable[0:19050450443] ]
2024.07.11 09:56:54.504924 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.555291 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.605631 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.655914 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.706214 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.756487 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.806804 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.857106 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.907456 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:56:54.957777 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:59:10.622425 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Polled offset 19050450443 (topic: mykafkatable, partition: 0)
2024.07.11 09:59:10.630529 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Committed offset 19050450443 (topic: mykafkatable, partition: 0)
2024.07.11 09:59:10.630556 [ 1853060 ] {} <Debug> StorageKafka (mykafkatable): Pushing 154.75 thousand rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 196681 ms.
2024.07.11 09:59:10.640539 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 09:59:10.640572 [ 1853060 ] {} <Trace> StorageKafka (mykafkatable): Execution took 196691 ms.
2024.07.11 09:59:11.211923 [ 1853022 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:00:10.739404 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): Closing #0 consumer (id: ClickHouse-myhostname-kafka-mykafkatable-be11050f-5e0e-48dd-a758-1476d8e9090d)
2024.07.11 10:00:10.751574 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): Rebalance initiated. Revoking partitions: [ mykafkatable[0:#] ]
2024.07.11 10:00:10.842811 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): 1 consumers had been closed (due to 60000000 usec timeout). Took 2 ms.
2024.07.11 10:00:11.179455 [ 1853022 ] {} <Warning> StorageKafka (mykafkatable): sasl.kerberos.kinit.cmd configuration parameter is ignored.
2024.07.11 10:00:11.325447 [ 1853022 ] {} <Trace> StorageKafka (mykafkatable): Created #0 consumer
2024.07.11 10:00:11.325650 [ 1853022 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: []
2024.07.11 10:00:11.325670 [ 1853022 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 10:00:26.340546 [ 1853022 ] {} <Warning> StorageKafka (mykafkatable): Can't get assignment. Will keep trying.
2024.07.11 10:00:26.354000 [ 1853022 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 10:00:26.354060 [ 1853022 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 75140 ms.
2024.07.11 10:00:26.369945 [ 1853022 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 10:00:26.369988 [ 1853022 ] {} <Trace> StorageKafka (mykafkatable): Execution took 75227 ms.
2024.07.11 10:00:26.870266 [ 1853056 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:01:26.364960 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): Closing #0 consumer (id: ClickHouse-myhostname-kafka-mykafkatable-0efbff23-a486-43aa-8802-b394a14da8e5)
2024.07.11 10:01:26.469322 [ 1853303 ] {} <Trace> StorageKafka (mykafkatable): 1 consumers had been closed (due to 60000000 usec timeout). Took 4 ms.
2024.07.11 10:01:27.433501 [ 1853056 ] {} <Warning> StorageKafka (mykafkatable): sasl.kerberos.kinit.cmd configuration parameter is ignored.
2024.07.11 10:01:27.434576 [ 1853056 ] {} <Trace> StorageKafka (mykafkatable): Created #0 consumer
2024.07.11 10:01:27.434618 [ 1853056 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: []
2024.07.11 10:01:27.434625 [ 1853056 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 10:01:27.488362 [ 1853056 ] {} <Warning> StorageKafka (mykafkatable): Can't get assignment. Will keep trying.
2024.07.11 10:01:27.504449 [ 1853056 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 10:01:27.504483 [ 1853056 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 60633 ms.
2024.07.11 10:01:27.528948 [ 1853056 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 10:01:27.528978 [ 1853056 ] {} <Trace> StorageKafka (mykafkatable): Execution took 60657 ms.
2024.07.11 10:01:28.096631 [ 1853020 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:02:24.627409 [ 1853020 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 10:02:24.627427 [ 1853020 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 10:02:24.677828 [ 1853020 ] {} <Warning> StorageKafka (mykafkatable): Can't get assignment. Will keep trying.
2024.07.11 10:02:24.693596 [ 1853020 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 10:02:24.693615 [ 1853020 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 56594 ms.
2024.07.11 10:02:24.716464 [ 1853020 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 10:02:24.716515 [ 1853020 ] {} <Trace> StorageKafka (mykafkatable): Execution took 56686 ms.
2024.07.11 10:02:25.216806 [ 1853049 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:03:21.763434 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 10:03:21.763471 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 10:03:21.764063 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 10:03:21.818255 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 8188 messages. Offsets position: [ mykafkatable[0:19050458631] ]
2024.07.11 10:03:22.043640 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 40698 messages. Offsets position: [ mykafkatable[0:19050499329] ]
2024.07.11 10:03:22.905633 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 60353 messages. Offsets position: [ mykafkatable[0:19050559682] ]
2024.07.11 10:03:24.274091 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 61244 messages. Offsets position: [ mykafkatable[0:19050620926] ]
2024.07.11 10:03:25.661390 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 40866 messages. Offsets position: [ mykafkatable[0:19050661792] ]
2024.07.11 10:03:26.811539 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 555 messages. Offsets position: [ mykafkatable[0:19050662347] ]
2024.07.11 10:03:26.874234 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:26.924753 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:26.975168 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:27.030627 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:27.081521 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 181 messages. Offsets position: [ mykafkatable[0:19050662528] ]
2024.07.11 10:03:27.139844 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:27.190191 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:27.240545 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:27.290982 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:27.341383 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:03:27.391635 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 10:06:05.332083 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Polled offset 19050662528 (topic: mykafkatable, partition: 0)
2024.07.11 10:06:05.334485 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Committed offset 19050662528 (topic: mykafkatable, partition: 0)
2024.07.11 10:06:05.334519 [ 1853049 ] {} <Debug> StorageKafka (mykafkatable): Pushing 212.09 thousand rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 220113 ms.
2024.07.11 10:06:05.350177 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 10:06:05.350227 [ 1853049 ] {} <Trace> StorageKafka (mykafkatable): Execution took 220129 ms.
2024.07.11 10:06:05.850766 [ 1853037 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:07:04.093765 [ 1853037 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 10:07:04.093798 [ 1853037 ] {} <Trace> StorageKafka (mykafkatable): Already assigned to: [ mykafkatable[0:#] ]
2024.07.11 10:07:04.094419 [ 1853037 ] {} <Trace> StorageKafka (mykafkatable): Rebalance initiated. Revoking partitions: [ mykafkatable[0:#] ]
2024.07.11 10:07:04.161121 [ 1853037 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 10:07:04.161149 [ 1853037 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (c7c95b36-ae0f-4646-984b-5150d2547e16) took 58309 ms.
2024.07.11 10:07:04.170160 [ 1853037 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 10:07:04.170215 [ 1853037 ] {} <Trace> StorageKafka (mykafkatable): Execution took 58318 ms.
2024.07.11 10:07:04.670639 [ 1853109 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:08:02.364031 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 10:08:02.364050 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 10:08:02.364609 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 10:08:02.669909 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 65409 messages. Offsets position: [ mykafkatable[0:19050727937] ]
2024.07.11 10:08:04.092441 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 65409 messages. Offsets position: [ mykafkatable[0:19050793346] ]
2024.07.11 10:08:05.839737 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 24344 messages. Offsets position: [ mykafkatable[0:19050817690] ]
2024.07.11 10:08:06.795434 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 581 messages. Offsets position: [ mykafkatable[0:19050818271] ]
2024.07.11 10:08:07.309726 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 373 messages. Offsets position: [ mykafkatable[0:19050818644] ]
2024.07.11 10:08:07.826769 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 187 messages. Offsets position: [ mykafkatable[0:19050818831] ]
2024.07.11 10:08:08.334273 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 363 messages. Offsets position: [ mykafkatable[0:19050819194] ]
2024.07.11 10:08:08.848079 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 164 messages. Offsets position: [ mykafkatable[0:19050819358] ]
2024.07.11 10:08:09.365497 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 337 messages. Offsets position: [ mykafkatable[0:19050819695] ]
2024.07.11 10:08:09.888004 [ 1853109 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 173 messages. Offsets position: [ mykafkatable[0:19050819868] ]

And in the Kafka's log, there are

INFO - [GroupCoordinator 1]: Preparing to rebalance group ... in state PreparingRebalance with old generation 5389 (__consumer_offsets-13) (reason: Removing member ClickHouse-myhostname-kafka-mykafkatable-... on LeaveGroup; client reason: not provided)
INFO - [GroupCoordinator 1]: Member MemberMetadata(memberId=ClickHouse-myhostname-kafka-mykafkatable-..., groupInstanceId=None, clientId=ClickHouse-myhostname-kafka-mykafkatable, clientHost=/xx.xx.xx.xx, sessionTimeoutMs=10000, rebalanceTimeoutMs=300000, supportedProtocols=List(range, roundrobin)) has left group ... through explicit `LeaveGroup`; client reason: not provided

Expected

Under version 23.7.5.30 clickhouse-server.log

2024.07.11 09:23:26.106253 [ 1850030 ] {} <Warning> StorageKafka (mykafkatable): sasl.kerberos.kinit.cmd configuration parameter is ignored.
2024.07.11 09:23:26.613515 [ 1849614 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 09:23:27.181204 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: []
2024.07.11 09:23:27.181239 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 09:23:30.306394 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 09:23:30.706642 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 51053 messages. Offsets position: [ mykafkatable[0:19040685928] ]
2024.07.11 09:23:32.476543 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 65409 messages. Offsets position: [ mykafkatable[0:19040751337] ]
2024.07.11 09:23:34.482006 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 65409 messages. Offsets position: [ mykafkatable[0:19040816746] ]
2024.07.11 09:25:26.060627 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Polled offset 19040816746 (topic: mykafkatable, partition: 0)
2024.07.11 09:25:26.063499 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Committed offset 19040816746 (topic: mykafkatable, partition: 0)
2024.07.11 09:25:26.063547 [ 1849614 ] {} <Debug> StorageKafka (mykafkatable): Pushing 181.87 thousand rows to kafka.mykafkatable (b39e46c8-fbc0-4402-a85f-2eb33ef71445) took 119447 ms.
2024.07.11 09:25:26.078914 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Thread work duration limit exceeded. Reschedule.
2024.07.11 09:25:26.078944 [ 1849614 ] {} <Trace> StorageKafka (mykafkatable): Execution took 119463 ms.
2024.07.11 09:25:26.579305 [ 1849616 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 09:25:27.056496 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 09:25:27.056538 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Already assigned to: [ mykafkatable[0:#] ]
2024.07.11 09:25:27.613263 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 63913 messages. Offsets position: [ mykafkatable[0:19040880659] ]
2024.07.11 09:25:29.870087 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 1249 messages. Offsets position: [ mykafkatable[0:19040881908] ]
2024.07.11 09:25:30.395290 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 172 messages. Offsets position: [ mykafkatable[0:19040882080] ]
2024.07.11 09:25:30.906748 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 551 messages. Offsets position: [ mykafkatable[0:19040882631] ]
2024.07.11 09:25:31.435084 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 173 messages. Offsets position: [ mykafkatable[0:19040882804] ]
2024.07.11 09:25:31.942536 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 373 messages. Offsets position: [ mykafkatable[0:19040883177] ]
2024.07.11 09:25:32.458527 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 185 messages. Offsets position: [ mykafkatable[0:19040883362] ]
2024.07.11 09:25:32.965833 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 354 messages. Offsets position: [ mykafkatable[0:19040883716] ]
2024.07.11 09:25:33.490986 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 168 messages. Offsets position: [ mykafkatable[0:19040883884] ]
2024.07.11 09:25:33.995867 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 326 messages. Offsets position: [ mykafkatable[0:19040884210] ]
2024.07.11 09:25:34.514263 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 174 messages. Offsets position: [ mykafkatable[0:19040884384] ]
2024.07.11 09:25:35.023981 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 364 messages. Offsets position: [ mykafkatable[0:19040884748] ]
2024.07.11 09:26:11.506607 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled offset 19040884748 (topic: mykafkatable, partition: 0)
2024.07.11 09:26:11.508873 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Committed offset 19040884748 (topic: mykafkatable, partition: 0)
2024.07.11 09:26:11.508913 [ 1849616 ] {} <Debug> StorageKafka (mykafkatable): Pushing 68.00 thousand rows to kafka.mykafkatable (b39e46c8-fbc0-4402-a85f-2eb33ef71445) took 44928 ms.
2024.07.11 09:26:11.622513 [ 1849616 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 09:26:12.113685 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 09:26:12.113752 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Already assigned to: [ mykafkatable[0:#] ]
2024.07.11 09:26:12.639413 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 18864 messages. Offsets position: [ mykafkatable[0:19040903612] ]
2024.07.11 09:26:13.562415 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 493 messages. Offsets position: [ mykafkatable[0:19040904105] ]
2024.07.11 09:26:14.078087 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 336 messages. Offsets position: [ mykafkatable[0:19040904441] ]
2024.07.11 09:26:14.591824 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 167 messages. Offsets position: [ mykafkatable[0:19040904608] ]
2024.07.11 09:26:15.108825 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 340 messages. Offsets position: [ mykafkatable[0:19040904948] ]
2024.07.11 09:26:15.624671 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 168 messages. Offsets position: [ mykafkatable[0:19040905116] ]
2024.07.11 09:26:16.132532 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 485 messages. Offsets position: [ mykafkatable[0:19040905601] ]
2024.07.11 09:26:16.653109 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Stalled
2024.07.11 09:26:17.166683 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 515 messages. Offsets position: [ mykafkatable[0:19040906116] ]
2024.07.11 09:26:17.690824 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 169 messages. Offsets position: [ mykafkatable[0:19040906285] ]
2024.07.11 09:26:18.203140 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 346 messages. Offsets position: [ mykafkatable[0:19040906631] ]
2024.07.11 09:26:18.718073 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 166 messages. Offsets position: [ mykafkatable[0:19040906797] ]
2024.07.11 09:26:19.225477 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 316 messages. Offsets position: [ mykafkatable[0:19040907113] ]
2024.07.11 09:26:19.738089 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 147 messages. Offsets position: [ mykafkatable[0:19040907260] ]
2024.07.11 09:26:37.330987 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Polled offset 19040907260 (topic: mykafkatable, partition: 0)
2024.07.11 09:26:37.333494 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Committed offset 19040907260 (topic: mykafkatable, partition: 0)
2024.07.11 09:26:37.333524 [ 1849616 ] {} <Debug> StorageKafka (mykafkatable): Pushing 22.51 thousand rows to kafka.mykafkatable (b39e46c8-fbc0-4402-a85f-2eb33ef71445) took 25710 ms.
2024.07.11 09:26:37.402502 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Thread work duration limit exceeded. Reschedule.
2024.07.11 09:26:37.402553 [ 1849616 ] {} <Trace> StorageKafka (mykafkatable): Execution took 70822 ms.

Under version 24.2.3.70 clickhouse-server.log

2024.07.11 10:17:08.866450 [ 1856531 ] {} <Warning> StorageKafka (mykafkatable): sasl.kerberos.kinit.cmd configuration parameter is ignored.
2024.07.11 10:17:08.867796 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Created #0 consumer
2024.07.11 10:17:08.867888 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: []
2024.07.11 10:17:08.867901 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): No assignment
2024.07.11 10:17:08.884623 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 10:17:09.315802 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 65409 messages. Offsets position: [ mykafkatable[0:19042372899] ]
2024.07.11 10:17:11.663423 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 54052 messages. Offsets position: [ mykafkatable[0:19042426951] ]
2024.07.11 10:17:12.905094 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Rebalance initiated. Revoking partitions: [ mykafkatable[0:#] ]
2024.07.11 10:17:12.912855 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Topics/partitions assigned: [ mykafkatable[0:#] ]
2024.07.11 10:17:13.321150 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Rewind last poll after rebalance. Returned to committed position: [ mykafkatable[0:19042307490] ]
2024.07.11 10:17:13.338136 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Polled offset INVALID (topic: mykafkatable, partition: 0)
2024.07.11 10:17:13.338151 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Nothing to commit.
2024.07.11 10:17:13.338163 [ 1856531 ] {} <Debug> StorageKafka (mykafkatable): Pushing 0.00 rows to kafka.mykafkatable (b39e46c8-fbc0-4402-a85f-2eb33ef71445) took 5072 ms.
2024.07.11 10:17:13.348118 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Stream(s) stalled. Reschedule.
2024.07.11 10:17:13.348155 [ 1856531 ] {} <Trace> StorageKafka (mykafkatable): Execution took 5082 ms.
2024.07.11 10:17:13.848410 [ 1856528 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:17:14.328544 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 10:17:14.328591 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Already assigned to: [ mykafkatable[0:#] ]
2024.07.11 10:17:14.851864 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 56087 messages. Offsets position: [ mykafkatable[0:19042363577] ]
2024.07.11 10:17:16.845880 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 55781 messages. Offsets position: [ mykafkatable[0:19042419358] ]
2024.07.11 10:17:18.584473 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 55838 messages. Offsets position: [ mykafkatable[0:19042475196] ]
2024.07.11 10:17:20.267912 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 11982 messages. Offsets position: [ mykafkatable[0:19042487178] ]
2024.07.11 10:17:21.047005 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 196 messages. Offsets position: [ mykafkatable[0:19042487374] ]
2024.07.11 10:17:21.553459 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 581 messages. Offsets position: [ mykafkatable[0:19042487955] ]
2024.07.11 10:17:22.073612 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 185 messages. Offsets position: [ mykafkatable[0:19042488140] ]
2024.07.11 10:19:00.244430 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Polled offset 19042488140 (topic: mykafkatable, partition: 0)
2024.07.11 10:19:00.247465 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Committed offset 19042488140 (topic: mykafkatable, partition: 0)
2024.07.11 10:19:00.247500 [ 1856528 ] {} <Debug> StorageKafka (mykafkatable): Pushing 180.65 thousand rows to kafka.mykafkatable (b39e46c8-fbc0-4402-a85f-2eb33ef71445) took 106397 ms.
2024.07.11 10:19:00.289208 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Thread work duration limit exceeded. Reschedule.
2024.07.11 10:19:00.289248 [ 1856528 ] {} <Trace> StorageKafka (mykafkatable): Execution took 106439 ms.
2024.07.11 10:19:00.789713 [ 1856575 ] {} <Debug> StorageKafka (mykafkatable): Started streaming to 1 attached views
2024.07.11 10:19:01.333533 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Already subscribed to topics: [mykafkatable]
2024.07.11 10:19:01.333631 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Already assigned to: [ mykafkatable[0:#] ]
2024.07.11 10:19:01.863971 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 53063 messages. Offsets position: [ mykafkatable[0:19042541203] ]
2024.07.11 10:19:03.609925 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 3443 messages. Offsets position: [ mykafkatable[0:19042544646] ]
2024.07.11 10:19:04.216448 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 593 messages. Offsets position: [ mykafkatable[0:19042545239] ]
2024.07.11 10:19:04.729335 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 190 messages. Offsets position: [ mykafkatable[0:19042545429] ]
2024.07.11 10:19:05.239589 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 354 messages. Offsets position: [ mykafkatable[0:19042545783] ]
2024.07.11 10:19:05.749097 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 190 messages. Offsets position: [ mykafkatable[0:19042545973] ]
2024.07.11 10:19:06.256658 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 397 messages. Offsets position: [ mykafkatable[0:19042546370] ]
2024.07.11 10:19:06.780121 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 184 messages. Offsets position: [ mykafkatable[0:19042546554] ]
2024.07.11 10:19:07.293234 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 366 messages. Offsets position: [ mykafkatable[0:19042546920] ]
2024.07.11 10:19:07.810356 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 193 messages. Offsets position: [ mykafkatable[0:19042547113] ]
2024.07.11 10:19:08.321382 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 378 messages. Offsets position: [ mykafkatable[0:19042547491] ]
2024.07.11 10:19:08.865867 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled batch of 202 messages. Offsets position: [ mykafkatable[0:19042547693] ]
2024.07.11 10:19:40.707187 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Polled offset 19042547693 (topic: mykafkatable, partition: 0)
2024.07.11 10:19:40.710773 [ 1856575 ] {} <Trace> StorageKafka (mykafkatable): Committed offset 19042547693 (topic: mykafkatable, partition: 0)
2024.07.11 10:19:40.710848 [ 1856575 ] {} <Debug> StorageKafka (mykafkatable): Pushing 59.55 thousand rows to kafka.mykafkatable (b39e46c8-fbc0-4402-a85f-2eb33ef71445) took 39920 ms.
spff commented 2 months ago

I found the issue happens from time to time under 24.2.3.70, but it never happened on 23.7

bun4uk commented 2 weeks ago

Have you checked if this behaviour is repeated in new versions of ClickHouse?

spff commented 2 weeks ago

I didn't check for 24.7 or above, but I can check them if you think there are commits resolving the problem.

bun4uk commented 2 weeks ago

We faced a similar issue after updating from 23.8 to 24.3. I haven't checked if a newer version fixes the issue, so I decided to ask here

spff commented 2 weeks ago

Got it. Welcome to share your findings with newer versions :D