Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Remove unstable queries from performance/join_set_filter #50235

Merged
merged 3 commits into from Jul 4, 2023

Conversation

vdimir
Copy link
Member

@vdimir vdimir commented May 25, 2023

Changelog category (leave one):

  • Not for changelog (changelog entry is not required)

Test failed here:
https://s3.amazonaws.com/clickhouse-test-reports/0/3f892ceb12b868b1b9deb0607a7df2dde5f1a139/performance_comparison_[1_4]/report.html

Let's check execution time for each query in this test:

ubuntu@ip-172-31-42-13~/_logs $ grep 'join_set_filter.query.*.prewarm' right-server-log.log left-server-log.log | grep 'Processed in'
right-server-log.log:2023.05.24 14:30:04.612129 [ 512 ] {join_set_filter.query0.prewarm0} <Debug> TCPHandler: Processed in 0.226517489 sec.
right-server-log.log:2023.05.24 14:31:16.962484 [ 512 ] {join_set_filter.query5.prewarm0} <Debug> TCPHandler: Processed in 33.313428802 sec.
right-server-log.log:2023.05.24 14:31:45.272076 [ 512 ] {join_set_filter.query7.prewarm0} <Debug> TCPHandler: Processed in 0.493587454 sec.
right-server-log.log:2023.05.24 14:31:52.242882 [ 512 ] {join_set_filter.query1.prewarm0} <Debug> TCPHandler: Processed in 0.335373937 sec.
right-server-log.log:2023.05.24 14:31:55.943563 [ 512 ] {join_set_filter.query3.prewarm0} <Debug> TCPHandler: Processed in 0.469933564 sec.
right-server-log.log:2023.05.24 14:32:00.771681 [ 512 ] {join_set_filter.query2.prewarm0} <Debug> TCPHandler: Processed in 0.4107554 sec.
right-server-log.log:2023.05.24 14:32:05.677168 [ 512 ] {join_set_filter.query6.prewarm0} <Debug> TCPHandler: Processed in 1.001121192 sec.
right-server-log.log:2023.05.24 14:35:42.602096 [ 512 ] {join_set_filter.query4.prewarm0} <Debug> TCPHandler: Processed in 180.01542621 sec.
left-server-log.log:2023.05.24 14:30:04.385101 [ 509 ] {join_set_filter.query0.prewarm0} <Debug> TCPHandler: Processed in 0.637355368 sec.
left-server-log.log:2023.05.24 14:30:43.648150 [ 509 ] {join_set_filter.query5.prewarm0} <Debug> TCPHandler: Processed in 36.00816096 sec.
left-server-log.log:2023.05.24 14:31:44.707640 [ 509 ] {join_set_filter.query7.prewarm0} <Debug> TCPHandler: Processed in 0.895852271 sec.
left-server-log.log:2023.05.24 14:31:51.902449 [ 509 ] {join_set_filter.query1.prewarm0} <Debug> TCPHandler: Processed in 0.254638137 sec.
left-server-log.log:2023.05.24 14:31:55.472064 [ 509 ] {join_set_filter.query3.prewarm0} <Debug> TCPHandler: Processed in 0.244279989 sec.
left-server-log.log:2023.05.24 14:32:00.360105 [ 509 ] {join_set_filter.query2.prewarm0} <Debug> TCPHandler: Processed in 1.472849179 sec.
left-server-log.log:2023.05.24 14:32:04.668561 [ 509 ] {join_set_filter.query6.prewarm0} <Debug> TCPHandler: Processed in 0.814490698 sec.
left-server-log.log:2023.05.24 14:32:42.581501 [ 509 ] {join_set_filter.query4.prewarm0} <Debug> TCPHandler: Processed in 30.493933458 sec.

Prewarm for query4 and query5 are the longest. On one server it even too >180 sec end was killed by timeout:

full logs for queries

left-server-log.log:2023.05.24 14:32:12.833552 [ 1265 ] {join_set_filter.query4.prewarm0} <Debug> FilterBySetOnTheFlyTransform: Finished create set and filter right joined stream: bypass 7240966 rows
left-server-log.log:2023.05.24 14:32:40.478315 [ 1265 ] {join_set_filter.query4.prewarm0} <Debug> MergingSortedTransform: Merge sorted 16 blocks, 999908 rows in 28.384107487 sec., 35227.74145560013 rows/sec., 559.19 KiB/sec
left-server-log.log:2023.05.24 14:32:42.577095 [ 1260 ] {join_set_filter.query4.prewarm0} <Debug> MergingSortedTransform: Merge sorted 1529 blocks, 100000000 rows in 30.484114273 sec., 3280397.098123029 rows/sec., 50.16 MiB/sec
left-server-log.log:2023.05.24 14:32:42.577947 [ 1260 ] {join_set_filter.query4.prewarm0} <Trace> MergeJoinAlgorithm: Finished pocessing in 30.484114273 seconds, left: 16 blocks, 999908 rows; right: 1529 blocks, 100000000 rows, max blocks loaded to memory: 3
left-server-log.log:2023.05.24 14:32:42.580244 [ 509 ] {join_set_filter.query4.prewarm0} <Debug> executeQuery: Read 200000000 rows, 2.98 GiB in 30.491888 sec., 6559121.560462245 rows/sec., 100.08 MiB/sec.
left-server-log.log:2023.05.24 14:32:42.581488 [ 509 ] {join_set_filter.query4.prewarm0} <Debug> MemoryTracker: Peak memory usage (for query): 1.56 GiB.
left-server-log.log:2023.05.24 14:32:42.581501 [ 509 ] {join_set_filter.query4.prewarm0} <Debug> TCPHandler: Processed in 30.493933458 sec.
right-server-log.log:2023.05.24 14:32:43.414046 [ 2975 ] {join_set_filter.query4.prewarm0} <Debug> FilterBySetOnTheFlyTransform: Finished create set and filter right joined stream: bypass 5111808 rows
right-server-log.log:2023.05.24 14:32:43.418308 [ 1328 ] {join_set_filter.query4.prewarm0} <Debug> FilterBySetOnTheFlyTransform: Finished create set and filter right joined stream: bypass 8224768 rows
right-server-log.log:2023.05.24 14:35:42.595315 [ 512 ] {join_set_filter.query4.prewarm0} <Error> executeQuery: Code: 159. DB::Exception: Timeout exceeded: elapsed 180.005253741 seconds, maximum: 180. (TIMEOUT_EXCEEDED) (version 23.5.1.1953 (official build)) (from [::1]:57524) (in query: SELECT * FROM t1 JOIN t2 ON t1.x = t2.x WHERE t1.y % 100 = 0), Stack trace (when copying this message, always include the lines below):
right-server-log.log:2023.05.24 14:35:42.602059 [ 512 ] {join_set_filter.query4.prewarm0} <Error> TCPHandler: Code: 159. DB::Exception: Timeout exceeded: elapsed 180.005253741 seconds, maximum: 180. (TIMEOUT_EXCEEDED), Stack trace (when copying this message, always include the lines below):
right-server-log.log:2023.05.24 14:35:42.602096 [ 512 ] {join_set_filter.query4.prewarm0} <Debug> TCPHandler: Processed in 180.01542621 sec.
right-server-log.log:2023.05.24 14:35:42.602130 [ 512 ] {join_set_filter.query4.prewarm0} <Debug> MemoryTracker: Peak memory usage (for query): 1.57 GiB.

Optimization FilterBySetOnTheFlyTransform that this tests should check not used in this query and most of the execution time takes reading the table and sorting them. I compared traces and profile event for query that executed successful (on left server) and one that was killed by timeout (on right) and haven't found anything suspicious.

traces for query from left
traces for query from right
profile events

@robot-ch-test-poll robot-ch-test-poll added the pr-not-for-changelog This PR should not be mentioned in the changelog label May 25, 2023
@robot-ch-test-poll
Copy link
Contributor

robot-ch-test-poll commented May 25, 2023

This is an automated comment for commit 737cff7 with description of existing statuses. It's updated for the latest CI running
The full report is available here
The overall status of the commit is 🔴 failure

Check nameDescriptionStatus
AST fuzzerRuns randomly generated queries to catch program errors. The build type is optionally given in parenthesis. If it fails, ask a maintainer for help🟢 success
CI runningA meta-check that indicates the running CI. Normally, it's in success or pending state. The failed status indicates some problems with the PR🟢 success
ClickHouse build checkBuilds ClickHouse in various configurations for use in further steps. You have to fix the builds that fail. Build logs often has enough information to fix the error, but you might have to reproduce the failure locally. The cmake options can be found in the build log, grepping for cmake. Use these options and follow the general build process🟢 success
Compatibility checkChecks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help🟢 success
Docker image for serversThe check to build and optionally push the mentioned image to docker hub🟢 success
Fast testNormally this is the first check that is ran for a PR. It builds ClickHouse and runs most of stateless functional tests, omitting some. If it fails, further checks are not started until it is fixed. Look at the report to see which tests fail, then reproduce the failure locally as described here🟢 success
Flaky testsChecks if new added or modified tests are flaky by running them repeatedly, in parallel, with more randomization. Functional tests are run 100 times with address sanitizer, and additional randomization of thread scheduling. Integrational tests are run up to 10 times. If at least once a new test has failed, or was too long, this check will be red. We don't allow flaky tests, read the doc🟢 success
Install packagesChecks that the built packages are installable in a clear environment🟢 success
Integration testsThe integration tests report. In parenthesis the package type is given, and in square brackets are the optional part/total tests🟢 success
Mergeable CheckChecks if all other necessary checks are successful🟢 success
Performance ComparisonMeasure changes in query performance. The performance test report is described in detail here. In square brackets are the optional part/total tests🔴 failure
Push to DockerhubThe check for building and pushing the CI related docker images to docker hub🟢 success
SQLancerFuzzing tests that detect logical bugs with SQLancer tool🟢 success
SqllogicRun clickhouse on the sqllogic test set against sqlite and checks that all statements are passed🟢 success
Stateful testsRuns stateful functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc🟢 success
Stateless testsRuns stateless functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc🔴 failure
Stress testRuns stateless functional tests concurrently from several clients to detect concurrency-related errors🟢 success
Style CheckRuns a set of checks to keep the code style clean. If some of tests failed, see the related log from the report🟢 success
Unit testsRuns the unit tests for different release types🟢 success
Upgrade checkRuns stress tests on server version from last release and then tries to upgrade it to the version from the PR. It checks if the new server can successfully startup without any errors, crashes or sanitizer asserts🟢 success

Copy link
Member

@SmitaRKulkarni SmitaRKulkarni left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@SmitaRKulkarni
Copy link
Member

@vdimir : The performance test fails with 'Errors while building the report' are because this these queries exist in master & not in this branch right ?. Then I guess they are expected to fail.

@vdimir
Copy link
Member Author

vdimir commented May 31, 2023

@vdimir vdimir force-pushed the vdimir/fix_test_join_set_filter branch from bd505fa to 9fb6bd6 Compare May 31, 2023 11:22
@vdimir vdimir force-pushed the vdimir/fix_test_join_set_filter branch from 8dc1751 to 737cff7 Compare July 3, 2023 15:00
@alexey-milovidov alexey-milovidov merged commit 2575db1 into master Jul 4, 2023
255 of 260 checks passed
@alexey-milovidov alexey-milovidov deleted the vdimir/fix_test_join_set_filter branch July 4, 2023 23:05
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
pr-not-for-changelog This PR should not be mentioned in the changelog
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants