Link to job: https://s3.amazonaws.com/clickhouse-test-reports/57001/3544ee1e5f2826d21a8fa68ed4036f02f1dab595/stateless_tests__tsan__[3_5].html

Query id: a557cbc9-1c34-4bca-8205-1307b15ebbc7

2023.11.20 22:05:02.760236 [ 12452 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Debug> executeQuery: (from [::1]:48810) (comment: 01451_dist_logs.sh) select * from remote('127.{2,3}', system.numbers) where number = 10 limit 1; (stage: Complete)
2023.11.20 22:05:02.762189 [ 12452 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> ContextAccess (default): Access granted: CREATE TEMPORARY TABLE, REMOTE ON *.*
2023.11.20 22:05:02.763001 [ 12452 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> Connection (127.2:9000): Connecting. Database: (not specified). User: default
2023.11.20 22:05:02.763413 [ 12474 ] {} <Trace> TCPHandlerFactory: TCP Request. Address: [::ffff:127.0.0.1]:56600
2023.11.20 22:05:02.764152 [ 12474 ] {} <Debug> TCPHandler: Connected ClickHouse server version 23.11.0, revision: 54466, user: default.
2023.11.20 22:05:02.764305 [ 12474 ] {} <Debug> TCP-Session: f8fb4dc9-47fd-4e97-a313-9619c70c9b16 Authenticating user 'default' from [::ffff:127.0.0.1]:56600
2023.11.20 22:05:02.764469 [ 12474 ] {} <Debug> TCP-Session: f8fb4dc9-47fd-4e97-a313-9619c70c9b16 Authenticated with global context as user 94309d50-4f52-5250-31bd-74fecac179db
2023.11.20 22:05:02.764573 [ 12474 ] {} <Debug> TCP-Session: f8fb4dc9-47fd-4e97-a313-9619c70c9b16 Creating session context with user_id: 94309d50-4f52-5250-31bd-74fecac179db
2023.11.20 22:05:02.765952 [ 12452 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> Connection (127.2:9000): Connected to ClickHouse server version 23.11.1.
2023.11.20 22:05:02.768697 [ 12474 ] {} <Trace> TCP-Session: f8fb4dc9-47fd-4e97-a313-9619c70c9b16 Creating query context from session context, user_id: 94309d50-4f52-5250-31bd-74fecac179db, parent context user: default
2023.11.20 22:05:02.769940 [ 12474 ] {694c0c92-003e-4b29-84a1-e7dec589aebb} <Debug> executeQuery: (from [::ffff:127.0.0.1]:56600, initial_query_id: a557cbc9-1c34-4bca-8205-1307b15ebbc7) (comment: 01451_dist_logs.sh) DESC TABLE system.numbers (stage: Complete)
2023.11.20 22:05:02.770584 [ 12474 ] {694c0c92-003e-4b29-84a1-e7dec589aebb} <Trace> ContextAccess (default): Access granted: SHOW COLUMNS ON system.numbers
2023.11.20 22:05:02.774194 [ 12474 ] {694c0c92-003e-4b29-84a1-e7dec589aebb} <Debug> executeQuery: Read 1 rows, 75.00 B in 0.004469 sec., 223.76370552696352 rows/sec., 16.39 KiB/sec.
2023.11.20 22:05:02.774501 [ 12474 ] {694c0c92-003e-4b29-84a1-e7dec589aebb} <Debug> MemoryTracker: Peak memory usage (for query): 1.08 MiB.
2023.11.20 22:05:02.774606 [ 12474 ] {694c0c92-003e-4b29-84a1-e7dec589aebb} <Debug> TCPHandler: Processed in 0.006596685 sec.
2023.11.20 22:05:02.782688 [ 12452 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> InterpreterSelectQuery: WithMergeableStateAfterAggregationAndLimit -> Complete
2023.11.20 22:05:02.788573 [ 18735 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> Connection (127.3:9000): Connecting. Database: (not specified). User: default
2023.11.20 22:05:02.789152 [ 2514 ] {} <Trace> TCPHandlerFactory: TCP Request. Address: [::ffff:127.0.0.1]:32790
2023.11.20 22:05:02.789789 [ 2514 ] {} <Debug> TCPHandler: Connected ClickHouse server version 23.11.0, revision: 54466, user: default.
2023.11.20 22:05:02.789943 [ 2514 ] {} <Debug> TCP-Session: 4e3d0a41-adaa-46e5-92c6-54a93d30d651 Authenticating user 'default' from [::ffff:127.0.0.1]:32790
2023.11.20 22:05:02.790076 [ 2514 ] {} <Debug> TCP-Session: 4e3d0a41-adaa-46e5-92c6-54a93d30d651 Authenticated with global context as user 94309d50-4f52-5250-31bd-74fecac179db
2023.11.20 22:05:02.790166 [ 2514 ] {} <Debug> TCP-Session: 4e3d0a41-adaa-46e5-92c6-54a93d30d651 Creating session context with user_id: 94309d50-4f52-5250-31bd-74fecac179db
2023.11.20 22:05:02.791349 [ 18463 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Debug> Connection (127.2:9000): Sent data for 2 scalars, total 2 rows in 0.000320101 sec., 6174 rows/sec., 68.00 B (204.95 KiB/sec.), compressed 0.4594594594594595 times to 148.00 B (445.93 KiB/sec.)
2023.11.20 22:05:02.792017 [ 12474 ] {} <Trace> TCP-Session: f8fb4dc9-47fd-4e97-a313-9619c70c9b16 Creating query context from session context, user_id: 94309d50-4f52-5250-31bd-74fecac179db, parent context user: default
2023.11.20 22:05:02.793993 [ 12474 ] {8dedbbc4-26ed-4bf9-9018-d791958c00eb} <Debug> executeQuery: (from [::ffff:127.0.0.1]:56600, initial_query_id: a557cbc9-1c34-4bca-8205-1307b15ebbc7) (comment: 01451_dist_logs.sh) SELECT `number` FROM `system`.`numbers` WHERE `number` = 10 LIMIT 1 (stage: WithMergeableStateAfterAggregationAndLimit)
2023.11.20 22:05:02.796632 [ 12474 ] {8dedbbc4-26ed-4bf9-9018-d791958c00eb} <Trace> ContextAccess (default): Access granted: SELECT(number) ON system.numbers
2023.11.20 22:05:02.797050 [ 12474 ] {8dedbbc4-26ed-4bf9-9018-d791958c00eb} <Trace> InterpreterSelectQuery: FetchColumns -> WithMergeableStateAfterAggregationAndLimit
2023.11.20 22:05:02.809088 [ 18463 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> StorageDistributed (remote): (127.2:9000) Cancelling query because enough data has been read
2023.11.20 22:05:02.809494 [ 12474 ] {8dedbbc4-26ed-4bf9-9018-d791958c00eb} <Debug> executeQuery: Read 70559 rows, 551.24 KiB in 0.016315 sec., 4324793.135151701 rows/sec., 33.00 MiB/sec.
2023.11.20 22:05:02.809983 [ 12474 ] {8dedbbc4-26ed-4bf9-9018-d791958c00eb} <Debug> MemoryTracker: Peak memory usage (for query): 2.73 MiB.
2023.11.20 22:05:02.810138 [ 12474 ] {8dedbbc4-26ed-4bf9-9018-d791958c00eb} <Debug> TCPHandler: Processed in 0.018853316 sec.
2023.11.20 22:05:02.811578 [ 12474 ] {} <Information> TCPHandler: Change cancellation status from NOT_CANCELLED to FULLY_CANCELLED. Log message: Received 'Cancel' packet from the client, canceling the query.
2023.11.20 22:05:02.854560 [ 1084 ] {} <Trace> system.metric_log (df3f650e-5869-4196-8d49-2bc5d6cfa545): Renaming temporary part tmp_insert_202311_57_57_0 to 202311_57_57_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000).
2023.11.20 22:05:02.871042 [ 6906 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> AggregatingTransform: Aggregating
2023.11.20 22:05:02.871204 [ 6906 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> Aggregator: An entry for key=3162812090643963271 found in cache: sum_of_sizes=2, median_size=1
2023.11.20 22:05:02.871285 [ 6906 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> Aggregator: Aggregation method: without_key
2023.11.20 22:05:02.871876 [ 18412 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> AggregatingTransform: Aggregating
2023.11.20 22:05:02.872019 [ 18412 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> Aggregator: An entry for key=3162812090643963271 found in cache: sum_of_sizes=2, median_size=1
2023.11.20 22:05:02.872084 [ 18412 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> Aggregator: Aggregation method: without_key
2023.11.20 22:05:02.872106 [ 6906 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> AggregatingTransform: Aggregated. 1440 to 1 rows (from 1.41 KiB) in 0.012837331 sec. (112172.850 rows/sec., 109.54 KiB/sec.)
2023.11.20 22:05:02.872630 [ 18412 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> AggregatingTransform: Aggregated. 1440 to 1 rows (from 1.41 KiB) in 0.013436501 sec. (107170.758 rows/sec., 104.66 KiB/sec.)
2023.11.20 22:05:02.872718 [ 18412 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Trace> Aggregator: Merging aggregated data
2023.11.20 22:05:02.877775 [ 1546 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Debug> executeQuery: Read 10000 rows, 39.06 KiB in 0.222552 sec., 44933.31895467127 rows/sec., 175.52 KiB/sec.
2023.11.20 22:05:02.880726 [ 1546 ] {2e6e48b9-a167-45ed-9ce0-694d8afacf01} <Debug> TCPHandler: Processed in 0.227444032 sec.
2023.11.20 22:05:02.884430 [ 1546 ] {} <Debug> TCPHandler: Done processing connection.
2023.11.20 22:05:02.885360 [ 1546 ] {} <Debug> TCP-Session: 62c1fb73-3937-44fa-adc4-96cc7d53779e Logout, user_id: 94309d50-4f52-5250-31bd-74fecac179db
2023.11.20 22:05:02.966906 [ 18463 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> Connection (127.3:9000): Connected to ClickHouse server version 23.11.1.
2023.11.20 22:05:02.970499 [ 18463 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Debug> Connection (127.3:9000): Sent data for 2 scalars, total 2 rows in 0.000405861 sec., 4819 rows/sec., 68.00 B (160.00 KiB/sec.), compressed 0.4594594594594595 times to 148.00 B (348.03 KiB/sec.)
2023.11.20 22:05:02.971289 [ 18463 ] {a557cbc9-1c34-4bca-8205-1307b15ebbc7} <Trace> StorageDistributed (remote): (127.3:9000) Cancelling query because enough data has been read
2023.11.20 22:05:02.971500 [ 2514 ] {} <Trace> TCP-Session: 4e3d0a41-adaa-46e5-92c6-54a93d30d651 Creating query context from session context, user_id: 94309d50-4f52-5250-31bd-74fecac179db, parent context user: default
2023.11.20 22:05:02.973627 [ 2514 ] {b49fd57a-76fa-45e9-b779-1893e3c10e7b} <Debug> executeQuery: (from [::ffff:127.0.0.1]:32790, initial_query_id: a557cbc9-1c34-4bca-8205-1307b15ebbc7) (comment: 01451_dist_logs.sh) SELECT `number` FROM `system`.`numbers` WHERE `number` = 10 LIMIT 1 (stage: WithMergeableStateAfterAggregationAndLimit)
2023.11.20 22:05:02.976398 [ 2514 ] {b49fd57a-76fa-45e9-b779-1893e3c10e7b} <Trace> ContextAccess (default): Access granted: SELECT(number) ON system.numbers
2023.11.20 22:05:02.976852 [ 2514 ] {b49fd57a-76fa-45e9-b779-1893e3c10e7b} <Trace> InterpreterSelectQuery: FetchColumns -> WithMergeableStateAfterAggregationAndLimit
2023.11.20 22:05:02.983634 [ 817 ] {} <Debug> DNSResolver: Updating DNS cache
2023.11.20 22:05:02.988365 [ 817 ] {} <Debug> DNSResolver: Updated DNS cache
2023.11.20 22:05:02.988535 [ 817 ] {} <Information> DNSCacheUpdater: IPs of some hosts have been changed. Will reload cluster config.
2023.11.20 22:05:02.988922 [ 2514 ] {b49fd57a-76fa-45e9-b779-1893e3c10e7b} <Debug> executeQuery: Read 70559 rows, 551.24 KiB in 0.016014 sec., 4406082.178094167 rows/sec., 33.62 MiB/sec.
2023.11.20 22:05:02.990164 [ 2514 ] {b49fd57a-76fa-45e9-b779-1893e3c10e7b} <Debug> MemoryTracker: Peak memory usage (for query): 2.73 MiB.
2023.11.20 22:07:40.693088 [ 787 ] {} <Fatal> Application: Child process was terminated by signal 6.

The query is pretty straightforward: select * from remote('127.{2,3}', system.numbers) where number = 10 limit 1;

Running 01451_dist_logs.sh under tsan many times doesn't reproduce it. I'll investigate further.

Data race in PipelineExecutor #57009

Description

Metadata

Metadata

Assignees

Labels

Type

Fields

Projects

Milestone

Relationships

Development

Issue actions