search

ClickHouse / ClickHouse

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

Errors while running perf test `joins_in_memory` #53635

Open tavplubix opened 1 year ago

tavplubix commented 1 year ago

https://s3.amazonaws.com/clickhouse-test-reports/0/dd1a00b97646c0b0103bf2f0d46c430f03ba91bc/performance_comparison_aarch64_[2_4]/report.html#run-errors

cc: @vdimir

vdimir commented 1 year ago 
joins_in_memory 2023-08-20 13:21:40,064: WARNING: connection: Error on localhost:9002 ping: timed out
joins_in_memory 2023-08-20 13:21:40,064: WARNING: connection: Connection was closed, reconnecting.

Looks like client really was cut off for some reason, but it successfully reconnected and continued execution of queries from joins_in_memory:

2023.08.20 13:21:40.066392 [ 470 ] {} <Debug> TCPHandler: Connected ClickHouse python-driver version 20.10.0, revision: 54441, database: default, user: default.
Piece of logs for that time ``` 2023.08.20 13:21:28.469844 [ 953 ] {} SystemLog (system.metric_log): Flushed system log up to offset 340 2023.08.20 13:21:32.651155 [ 1196 ] {joins_in_memory.query14.prewarm0} MemoryTracker: Current memory usage (for query): 1.12 GiB. 2023.08.20 13:21:34.042955 [ 1196 ] {joins_in_memory.query14.prewarm0} Aggregator: Aggregation method: without_key 2023.08.20 13:21:34.042999 [ 1196 ] {joins_in_memory.query14.prewarm0} AggregatingTransform: Aggregated. 0 to 1 rows (from 0.00 B) in 6.569988561 sec. (0.000 rows/sec., 0.00 B/sec.) 2023.08.20 13:21:34.043006 [ 1196 ] {joins_in_memory.query14.prewarm0} Aggregator: Merging aggregated data 2023.08.20 13:21:34.043017 [ 1196 ] {joins_in_memory.query14.prewarm0} Aggregator: Statistics updated for key=17800939064638209602: new sum_of_sizes=5, median_size=1 2023.08.20 13:21:34.054321 [ 737 ] {} DNSResolver: Updating DNS cache 2023.08.20 13:21:34.054519 [ 737 ] {} DNSResolver: Updated DNS cache 2023.08.20 13:21:34.312383 [ 469 ] {joins_in_memory.query14.prewarm0} executeQuery: Read 100000 rows, 976.56 KiB in 6.840584 sec., 14618.634900178115 rows/sec., 142.76 KiB/sec. 2023.08.20 13:21:34.312530 [ 469 ] {joins_in_memory.query14.prewarm0} HashJoin: (0xffff60254298) Join data is being destroyed, 3847627 bytes and 11111 rows in hash table 2023.08.20 13:21:34.312598 [ 469 ] {joins_in_memory.query14.prewarm0} MemoryTracker: Peak memory usage (for query): 1.24 GiB. 2023.08.20 13:21:34.312609 [ 469 ] {joins_in_memory.query14.prewarm0} TCPHandler: Processed in 6.841782152 sec. 2023.08.20 13:21:34.334250 [ 954 ] {} SystemLog (system.trace_log): Flushing system log, 9331 entries to flush up to offset 108519 2023.08.20 13:21:34.334470 [ 947 ] {} SystemLog (system.query_log): Flushing system log, 2 entries to flush up to offset 1936 2023.08.20 13:21:34.337365 [ 947 ] {} system.query_log (ffe5d5ef-1941-45c8-87c9-1a4f7afabe3a): Trying to reserve 1.00 MiB using storage policy from min volume index 0 2023.08.20 13:21:34.337399 [ 947 ] {} DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 90.79 GiB. 2023.08.20 13:21:34.338544 [ 947 ] {} MergedBlockOutputStream: filled checksums 202308_41_41_0 (state Temporary) 2023.08.20 13:21:34.339102 [ 947 ] {} system.query_log (ffe5d5ef-1941-45c8-87c9-1a4f7afabe3a): Renaming temporary part tmp_insert_202308_41_41_0 to 202308_42_42_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000). 2023.08.20 13:21:34.339477 [ 947 ] {} SystemLog (system.query_log): Flushed system log up to offset 1936 2023.08.20 13:21:34.340139 [ 954 ] {} system.trace_log (21065204-465f-4ee5-a249-b573eadf1c2d): Trying to reserve 1.74 MiB using storage policy from min volume index 0 2023.08.20 13:21:34.340165 [ 954 ] {} DiskLocal: Reserved 1.74 MiB on local disk `default`, having unreserved 90.79 GiB. 2023.08.20 13:21:34.342358 [ 954 ] {} MergedBlockOutputStream: filled checksums 202308_34_34_0 (state Temporary) 2023.08.20 13:21:34.342679 [ 954 ] {} system.trace_log (21065204-465f-4ee5-a249-b573eadf1c2d): Renaming temporary part tmp_insert_202308_34_34_0 to 202308_35_35_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000). 2023.08.20 13:21:34.343366 [ 954 ] {} SystemLog (system.trace_log): Flushed system log up to offset 108519 2023.08.20 13:21:35.000344 [ 974 ] {} AsynchronousMetrics: MemoryTracking: was 730.87 MiB, peak 2.59 GiB, free memory in arenas 11.53 MiB, will set to 676.49 MiB (RSS), difference: -54.38 MiB 2023.08.20 13:21:35.969934 [ 953 ] {} SystemLog (system.metric_log): Flushing system log, 7 entries to flush up to offset 347 2023.08.20 13:21:35.982245 [ 953 ] {} system.metric_log (6a0848b3-372e-4168-bbec-1c85c1f9589e): Trying to reserve 1.00 MiB using storage policy from min volume index 0 2023.08.20 13:21:35.982282 [ 953 ] {} DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 90.79 GiB. 2023.08.20 13:21:35.988367 [ 953 ] {} MergedBlockOutputStream: filled checksums 202308_46_46_0 (state Temporary) 2023.08.20 13:21:35.993547 [ 953 ] {} system.metric_log (6a0848b3-372e-4168-bbec-1c85c1f9589e): Renaming temporary part tmp_insert_202308_46_46_0 to 202308_46_46_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000). 2023.08.20 13:21:35.993798 [ 758 ] {} system.metric_log (6a0848b3-372e-4168-bbec-1c85c1f9589e) (MergerMutator): Selected 6 parts from 202308_1_41_8 to 202308_46_46_0 2023.08.20 13:21:35.993827 [ 758 ] {} system.metric_log (6a0848b3-372e-4168-bbec-1c85c1f9589e): Trying to reserve 1.00 MiB using storage policy from min volume index 0 2023.08.20 13:21:35.993843 [ 758 ] {} DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 90.79 GiB. 2023.08.20 13:21:35.993957 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTask::PrepareStage: Merging 6 parts: from 202308_1_41_8 to 202308_46_46_0 into Compact with storage Full 2023.08.20 13:21:35.995364 [ 953 ] {} SystemLog (system.metric_log): Flushed system log up to offset 347 2023.08.20 13:21:35.999749 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTask::PrepareStage: Selected MergeAlgorithm: Horizontal 2023.08.20 13:21:36.000383 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTreeSequentialSource: Reading 2 marks from part 202308_1_41_8, total 310 rows starting from the beginning of the part 2023.08.20 13:21:36.003574 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTreeSequentialSource: Reading 2 marks from part 202308_42_42_0, total 7 rows starting from the beginning of the part 2023.08.20 13:21:36.006766 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTreeSequentialSource: Reading 2 marks from part 202308_43_43_0, total 8 rows starting from the beginning of the part 2023.08.20 13:21:36.010034 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTreeSequentialSource: Reading 2 marks from part 202308_44_44_0, total 7 rows starting from the beginning of the part 2023.08.20 13:21:36.013317 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTreeSequentialSource: Reading 2 marks from part 202308_45_45_0, total 8 rows starting from the beginning of the part 2023.08.20 13:21:36.016632 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTreeSequentialSource: Reading 2 marks from part 202308_46_46_0, total 7 rows starting from the beginning of the part 2023.08.20 13:21:36.064418 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergeTask::MergeProjectionsStage: Merge sorted 347 rows, containing 668 columns (668 merged, 0 gathered) in 0.070514701 sec., 4920.95967335946 rows/sec., 5.29 MiB/sec. 2023.08.20 13:21:36.066401 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} MergedBlockOutputStream: filled checksums 202308_1_46_9 (state Temporary) 2023.08.20 13:21:36.072969 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} system.metric_log (6a0848b3-372e-4168-bbec-1c85c1f9589e): Renaming temporary part tmp_merge_202308_1_46_9 to 202308_1_46_9 with tid (1, 1, 00000000-0000-0000-0000-000000000000). 2023.08.20 13:21:36.073049 [ 899 ] {6a0848b3-372e-4168-bbec-1c85c1f9589e::202308_1_46_9} system.metric_log (6a0848b3-372e-4168-bbec-1c85c1f9589e) (MergerMutator): Merged 6 parts: [202308_1_41_8, 202308_46_46_0] -> 202308_1_46_9 2023.08.20 13:21:36.073990 [ 899 ] {} MemoryTracker: Peak memory usage background process to apply mutate/merge in table: 14.51 MiB. 2023.08.20 13:21:39.364225 [ 958 ] {} SystemLog (system.asynchronous_metric_log): Flushing system log, 235 entries to flush up to offset 8311 2023.08.20 13:21:39.364727 [ 958 ] {} system.asynchronous_metric_log (791daab2-5c17-4753-b1c2-5bda67ad5432): Trying to reserve 1.00 MiB using storage policy from min volume index 0 2023.08.20 13:21:39.364753 [ 958 ] {} DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 90.79 GiB. 2023.08.20 13:21:39.365306 [ 958 ] {} MergedBlockOutputStream: filled checksums 202308_35_35_0 (state Temporary) 2023.08.20 13:21:39.365570 [ 958 ] {} system.asynchronous_metric_log (791daab2-5c17-4753-b1c2-5bda67ad5432): Renaming temporary part tmp_insert_202308_35_35_0 to 202308_35_35_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000). 2023.08.20 13:21:39.365696 [ 802 ] {} system.asynchronous_metric_log (791daab2-5c17-4753-b1c2-5bda67ad5432) (MergerMutator): Selected 6 parts from 202308_1_30_6 to 202308_35_35_0 2023.08.20 13:21:39.365728 [ 958 ] {} SystemLog (system.asynchronous_metric_log): Flushed system log up to offset 8311 2023.08.20 13:21:39.365729 [ 802 ] {} system.asynchronous_metric_log (791daab2-5c17-4753-b1c2-5bda67ad5432): Trying to reserve 1.00 MiB using storage policy from min volume index 0 2023.08.20 13:21:39.365763 [ 802 ] {} DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 90.79 GiB. 2023.08.20 13:21:39.365876 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTask::PrepareStage: Merging 6 parts: from 202308_1_30_6 to 202308_35_35_0 into Compact with storage Full 2023.08.20 13:21:39.365971 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTask::PrepareStage: Selected MergeAlgorithm: Horizontal 2023.08.20 13:21:39.365997 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTreeSequentialSource: Reading 2 marks from part 202308_1_30_6, total 7136 rows starting from the beginning of the part 2023.08.20 13:21:39.366086 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTreeSequentialSource: Reading 2 marks from part 202308_31_31_0, total 235 rows starting from the beginning of the part 2023.08.20 13:21:39.366135 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTreeSequentialSource: Reading 2 marks from part 202308_32_32_0, total 235 rows starting from the beginning of the part 2023.08.20 13:21:39.366174 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTreeSequentialSource: Reading 2 marks from part 202308_33_33_0, total 235 rows starting from the beginning of the part 2023.08.20 13:21:39.366213 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTreeSequentialSource: Reading 2 marks from part 202308_34_34_0, total 235 rows starting from the beginning of the part 2023.08.20 13:21:39.366268 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTreeSequentialSource: Reading 2 marks from part 202308_35_35_0, total 235 rows starting from the beginning of the part 2023.08.20 13:21:39.369173 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergeTask::MergeProjectionsStage: Merge sorted 8311 rows, containing 4 columns (4 merged, 0 gathered) in 0.003353617 sec., 2478219.7847875888 rows/sec., 35.45 MiB/sec. 2023.08.20 13:21:39.369358 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} MergedBlockOutputStream: filled checksums 202308_1_35_7 (state Temporary) 2023.08.20 13:21:39.369663 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} system.asynchronous_metric_log (791daab2-5c17-4753-b1c2-5bda67ad5432): Renaming temporary part tmp_merge_202308_1_35_7 to 202308_1_35_7 with tid (1, 1, 00000000-0000-0000-0000-000000000000). 2023.08.20 13:21:39.369719 [ 892 ] {791daab2-5c17-4753-b1c2-5bda67ad5432::202308_1_35_7} system.asynchronous_metric_log (791daab2-5c17-4753-b1c2-5bda67ad5432) (MergerMutator): Merged 6 parts: [202308_1_30_6, 202308_35_35_0] -> 202308_1_35_7 2023.08.20 13:21:39.369803 [ 892 ] {} MemoryTracker: Peak memory usage background process to apply mutate/merge in table: 6.64 MiB. 2023.08.20 13:21:40.064878 [ 470 ] {} TCPHandlerFactory: TCP Request. Address: [::1]:56606 2023.08.20 13:21:40.066392 [ 470 ] {} TCPHandler: Connected ClickHouse python-driver version 20.10.0, revision: 54441, database: default, user: default. 2023.08.20 13:21:40.066418 [ 470 ] {} TCP-Session: f905ecd4-d978-424f-a364-f7c6507eff8b Authenticating user 'default' from [::1]:56606 2023.08.20 13:21:40.066433 [ 470 ] {} TCP-Session: f905ecd4-d978-424f-a364-f7c6507eff8b Authenticated with global context as user 94309d50-4f52-5250-31bd-74fecac179db 2023.08.20 13:21:40.066442 [ 470 ] {} TCP-Session: f905ecd4-d978-424f-a364-f7c6507eff8b Creating session context with user_id: 94309d50-4f52-5250-31bd-74fecac179db 2023.08.20 13:21:40.066870 [ 470 ] {} TCP-Session: f905ecd4-d978-424f-a364-f7c6507eff8b Creating query context from session context, user_id: 94309d50-4f52-5250-31bd-74fecac179db, parent context user: default 2023.08.20 13:21:40.067095 [ 470 ] {joins_in_memory.query14.run0} executeQuery: (from [::1]:56606) SELECT COUNT() FROM ints l RIGHT JOIN ints r ON l.i64 = r.i64 WHERE i32 = 20042 (stage: Complete) 2023.08.20 13:21:40.067636 [ 470 ] {joins_in_memory.query14.run0} ContextAccess (default): Access granted: SELECT(i64) ON default.ints 2023.08.20 13:21:40.067667 [ 470 ] {joins_in_memory.query14.run0} InterpreterSelectQuery: FetchColumns -> Complete 2023.08.20 13:21:40.067711 [ 470 ] {joins_in_memory.query14.run0} TableJoin: Left JOIN converting actions: empty 2023.08.20 13:21:40.067722 [ 470 ] {joins_in_memory.query14.run0} TableJoin: Right JOIN converting actions: empty ```

So, don't see something suspicious, let's keep an eye on it to see if it'll happen again