Backoff policy for failed mutation. #58036

MikhailBurdukov · 2023-12-19T14:55:39Z

Changelog category (leave one):

Improvement

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Enabled a backoff logic (e.g. exponential). Will provide an ability for reduced CPU usage, memory usage and log file sizes.

Documentation entry for user-facing changes

Documentation is written (mandatory for new features)

If mutation query is incorrect or can't be performed right now then it will hang in infinite loop with high resources usage:
Example (from #55946):

CREATE TABLE main (id Int8) ENGINE=MergeTree() ORDER BY id;
INSERT INTO main SELECT * FROM system.numbers LIMIT 2;

ALTER TABLE main DELETE WHERE id IN (SELECT id FROM nonexistent);

Have a backoff logic (e.g. exponential) will provide an ability for reduced CPU usage, memory usage and log file sizes.

Information about CI checks: https://clickhouse.com/docs/en/development/continuous-integration/

robot-clickhouse-ci-1 · 2023-12-19T14:58:26Z

This is an automated comment for commit fa5747a with description of existing statuses. It's updated for the latest CI running

❌ Click here to open a full report in a separate page

Successful checks

Check name	Description	Status
AST fuzzer	Runs randomly generated queries to catch program errors. The build type is optionally given in parenthesis. If it fails, ask a maintainer for help	✅ success
ClickBench	Runs [ClickBench](https://github.com/ClickHouse/ClickBench/) with instant-attach table	✅ success
ClickHouse build check	Builds 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 check	Checks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help	✅ success
Docker keeper image	The check to build and optionally push the mentioned image to docker hub	✅ success
Docker server image	The check to build and optionally push the mentioned image to docker hub	✅ success
Docs check	Builds and tests the documentation	✅ success
Fast test	Normally 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 tests	Checks 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 packages	Checks that the built packages are installable in a clear environment	✅ success
Mergeable Check	Checks if all other necessary checks are successful	✅ success
Performance Comparison	Measure changes in query performance. The performance test report is described in detail here. In square brackets are the optional part/total tests	✅ success
Push to Dockerhub	The check for building and pushing the CI related docker images to docker hub	✅ success
SQLTest	There's no description for the check yet, please add it to tests/ci/ci_config.py:CHECK_DESCRIPTIONS	✅ success
SQLancer	Fuzzing tests that detect logical bugs with SQLancer tool	✅ success
Sqllogic	Run clickhouse on the sqllogic test set against sqlite and checks that all statements are passed	✅ success
Stateful tests	Runs stateful functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	✅ success
Stress test	Runs stateless functional tests concurrently from several clients to detect concurrency-related errors	✅ success
Style check	Runs a set of checks to keep the code style clean. If some of tests failed, see the related log from the report	✅ success
Unit tests	Runs the unit tests for different release types	✅ success
Upgrade check	Runs 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

Check name	Description	Status
A Sync	There's no description for the check yet, please add it to tests/ci/ci_config.py:CHECK_DESCRIPTIONS	❌ failure
CI running	A meta-check that indicates the running CI. Normally, it's in success or pending state. The failed status indicates some problems with the PR	⏳ pending
Integration tests	The integration tests report. In parenthesis the package type is given, and in square brackets are the optional part/total tests	❌ failure
Stateless tests	Runs stateless functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc	❌ failure

myrrc · 2023-12-20T11:11:37Z

src/Storages/StorageMergeTree.cpp

@@ -516,6 +516,7 @@ void StorageMergeTree::updateMutationEntriesErrors(FutureMergedMutatedPartPtr re
        for (auto it = mutations_begin_it; it != mutations_end_it; ++it)
        {
            MergeTreeMutationEntry & entry = it->second;
+            auto failed_part = result_part->parts.at(0);


Suggested change

auto failed_part = result_part->parts.at(0);

auto & failed_part = result_part->parts.at(0);

myrrc · 2023-12-20T11:18:05Z

src/Storages/StorageMergeTree.cpp

+    if (exist_posponed_failed_part)
+        mutation_wait_event.notify_all();


All other usages of mutation_wait_event notify it under
std::lock_guard lock(mutation_wait_mutex). Generally you should not notify a condition variable while holding a mutex (as waiting threads will be notified just to sleep again) but maybe there is some other semantics here you could investigate

myrrc · 2024-01-21T11:23:13Z

Resolves: #57089

myrrc · 2024-01-21T11:28:01Z

src/Interpreters/Context.cpp

+    return config.getUInt("max_postpone_time_for_failed_mutations", 0ull);
+}


You can add this setting here
and query it like getSettingsRef().max_postpone_time...

myrrc · 2024-01-21T11:31:24Z

src/Storages/MergeTree/MergeTreeData.h

+        explicit PartMutationBackoffPolicy(ContextPtr global_context_)
+            : WithContext(global_context_)
+        {
+            size_t max_pospone_time_ms =  global_context_->getMaxPostponeTimeForFailedMutations();


Maybe we could store context.getSettings() instead of storing the context ptr itself? Except for the setting, we don't use the context

myrrc · 2024-01-21T11:32:25Z

src/Storages/MergeTree/MergeTreeData.h

+            if (max_pospone_time_ms == 0)
+                max_pospone_power = 0;


typo: posTpone

myrrc · 2024-01-21T11:34:52Z

tests/integration/test_failed_mutations/test.py

+    # Executing incorrect mutation.
+    node.query(
+        "ALTER TABLE test_mutations DELETE WHERE x IN (SELECT x  FROM notexist_table) SETTINGS allow_nondeterministic_mutations=1"


If this setting will be present in Settings.h, we could change the setting in runtime via SETTINGS max_postpone_time=12345.
Please consider adding a test case changing the setting in runtime

myrrc · 2024-01-21T11:35:14Z

tests/integration/test_failed_mutations/test.py

+    )
+
+    time.sleep(5)
+    assert node_no_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG) == False


Suggested change

assert node_no_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG) == False

assert not node_no_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG)

myrrc · 2024-01-21T11:35:53Z

tests/integration/test_failed_mutations/test.py

+
+    time.sleep(5)
+    assert node_no_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG) == False
+    assert node_with_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG) == True


Suggested change

assert node_with_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG) == True

assert node_with_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG)

tavplubix · 2024-02-12T19:50:41Z

src/Storages/MergeTree/MergeTreeData.h

+            Poco::Timestamp latest_fail_time;
+            UInt64 mutation_failure_version;
+            size_t max_postpone_time_ms;


Why do we have time both in Poco::Timestamp and size_t?

tavplubix · 2024-02-12T19:54:55Z

src/Storages/MergeTree/MergeTreeData.h

+
+            PartMutationInfo(UInt64 mutation_failure_version_, size_t max_postpone_time_ms_)
+                            : retry_count(0ull)
+                            , latest_fail_time(std::move(Poco::Timestamp()))


Isn't Poco::Timestamp a POD type? What's the point of moving it, then?

tavplubix · 2024-02-12T20:01:54Z

src/Storages/MergeTree/MergeTreeData.h

+            {
+                if (max_postpone_time_ms == 0)
+                    return Poco::Timestamp();
+                return  latest_fail_time +  (1 << retry_count) * 1000ul;


Double whitespace after "return" and after "+"

It's unclear what the precision of latest_fail_time is when it's implicitly converted to an integer (milliseconds? microseconds? nanoseconds?). Having * 1000ul doesn't make it more clear (although it's clear that it's not seconds). I would prefer having everything in integers with the same precision and a clear suffix like _ms. Poco::Timestamp (as well as Poco::Timespan) with implicit conversions are error-prone

tavplubix · 2024-02-12T23:39:18Z

src/Storages/MergeTree/MergeTreeData.h

+            }
+        }
+
+        void removePartFromFailed(const String& part_name)


Suggested change

void removePartFromFailed(const String& part_name)

void removePartFromFailed(const String & part_name)

And in other places as well
(it's interesting why the Style Check did not fail)

tavplubix · 2024-02-12T23:40:23Z

src/Storages/MergeTree/MergeTreeData.h

@@ -1364,6 +1364,100 @@ class MergeTreeData : public IStorage, public WithMutableContext
        const MergeListEntry * merge_entry,
        std::shared_ptr<ProfileEvents::Counters::Snapshot> profile_counters);

+    class PartMutationBackoffPolicy : public WithContext


Looks like the context is never used

tavplubix · 2024-02-13T00:00:06Z

src/Storages/MergeTree/ReplicatedMergeTreeQueue.cpp

+                        constexpr auto fmt_string = "Not executing log entry {} of type {} for part {} "
+                           "because recently it has failed. According to exponential backoff policy, put aside this log entry.";
+
+                        LOG_DEBUG(LogToStr(out_postpone_reason, log), fmt_string, entry.znode_name, entry.typeToString(), entry.new_part_name);


It would be nice to also print the number of (milli)seconds til the next attempt, but it's not necessary

tavplubix · 2024-02-13T00:08:51Z

src/Storages/StorageMergeTree.cpp

+    if (exist_postponed_failed_part)
+    {
+        std::lock_guard lock(mutation_wait_mutex);
+        mutation_wait_event.notify_all();
+    }


This is unexpected, could you please add a comment explaining why we need to notify here? Introducing a backoff affects only timings and should not affect any synchronization

Yes, you are right. Removed it.

tavplubix · 2024-02-13T00:16:11Z

src/Storages/StorageMergeTree.cpp

@@ -835,6 +845,8 @@ CancellationCode StorageMergeTree::killMutation(const String & mutation_id)
        }
    }

+    mutation_backoff_policy.removeFromFailedByVersion(mutation_version);


Do we need the same for ReplicatedMergeTree?

Feels like it will not work because multiple mutations may be merged together and executed at once. For example, if there's a faulty mutation with version 42 and another mutation with version 137, then a part all_1_2_3 can be mutated directly to all_1_2_3_137 (and this will fail due to the mutation 42). So according to the if (static_cast<UInt64>(result_part->part_info.mutation) == it->first) condition, addPartMutationFailure will be called for the version 137, and killing the faulty mutation 42 will not reset the backoff. Please add the corresponding test. Consider removing all the logic around the mutation version for simplicity and resetting all backoffs when killing any mutation

tavplubix · 2024-02-13T00:22:19Z

tests/integration/test_failed_mutations/test.py

+    assert node.contains_in_log(POSPONE_MUTATION_LOG) == found_in_log
+    node.rotate_logs()
+
+    time.sleep(5)


Tests with sleep are flaky and unreliable

tavplubix · 2024-02-13T00:29:03Z

tests/integration/test_failed_mutations/test.py

+        REPLICATED_POSPONE_MUTATION_LOG if replicated_table else POSPONE_MUTATION_LOG
+    )
+
+    node.restart_clickhouse()


Please use functional tests whenever possible: #39359 (comment)

In this case, restart_clickhouse can be replaced with DETACH/ATTACH TABLE, and wait_for_log_line with reading from system.text_log.

It's just FYI, it's not necessary to rewrite the test.

MikhailBurdukov · 2024-02-19T08:18:08Z

@tavplubix
Hi! I have fixed the changes you requested. There are a lot of test failures, but I'm not sure if my changes caused them. Сould you check it please?

Also there is one more thing to discuss:

In general, the change is good and it makes sense to enable it by default. What will be a good default value in your opinion?

For sure it depends on the usage scenario, but I think in general 5s-10s is totally okey. Can I set 5s as default value?

tavplubix · 2024-02-19T15:25:05Z

The CI is completely broken by #60013
Although, Upgrade check failures are related to the changes: <Error> Application: Code: 115. DB::Exception: Unknown setting max_postpone_time_for_failed_mutations_ms: in MergeTree config. (UNKNOWN_SETTING)
You can fix it by removing the new config here:

ClickHouse/docker/test/upgrade/run.sh

Line 80 in cef109a

# it contains some new settings, but we can safely remove it

5s-10s is totally okey

Isn't it too small? Imagine we have a mutation that converts a String column to UInt64, and it fails because it cannot parse some number in the middle. If the part is quite big, the mutation may work for a few minutes before failing. So it will wait for 5 seconds and then work again for a few minutes, so it will not reduce CPU usage. Maybe we can set it to 5 minutes.

MikhailBurdukov · 2024-02-20T14:08:42Z

Set 5 minutes as default. Thanks for the help!

tavplubix · 2024-02-21T20:05:37Z

Integration tests:

test_replicated_database/test.py::test_startup_without_zk - Do not retry queries if container is down in integration tests #60109 (comment)
test_backup_restore_s3/test.py::test_user_specific_auth - Support specifying users for S3 settings #60144 (comment)
test_replicated_table_attach/test.py::test_startup_with_small_bg_pool_partitioned - Do not retry queries if container is down in integration tests #60109 (comment)

Stateless tests - 00984_parser_stack_overflow is broken in master (not clear why)

alexey-milovidov · 2024-02-27T01:10:13Z

@MikhailBurdukov it failed: https://s3.amazonaws.com/clickhouse-test-reports/60370/a66a11933fbb12e614f5ac4facde42ede9ac3233/integration_tests__tsan__[2_6].html

azat · 2024-03-06T21:02:06Z

src/Storages/StorageMergeTree.cpp

@@ -556,14 +559,21 @@ void StorageMergeTree::updateMutationEntriesErrors(FutureMergedMutatedPartPtr re
                    entry.latest_failed_part_info = MergeTreePartInfo();
                    entry.latest_fail_time = 0;
                    entry.latest_fail_reason.clear();
+                    if (static_cast<UInt64>(result_part->part_info.mutation) == it->first)
+                        mutation_backoff_policy.removePartFromFailed(failed_part->name);


Should this be called from the killMutation as well? (so as for ReplicatedMergeTree)

No, we call resetMutationFailures instead, see the review comments.

However, I've just realized that for RMT it will be only called on the initiator, and not on other replicas (I'm not sure what's the best way to fix it)

robot-clickhouse-ci-1 added the pr-feature Pull request with new product feature label Dec 19, 2023

robot-ch-test-poll added pr-improvement Pull request with some product improvements and removed pr-feature Pull request with new product feature labels Dec 19, 2023

MikhailBurdukov marked this pull request as ready for review December 20, 2023 07:35

myrrc reviewed Dec 20, 2023

View reviewed changes

MikhailBurdukov added 4 commits January 18, 2024 15:43

Backoff policy for failed mutation.

f6fb20d

Fix style

be58c1f

typo

97e0e5f

Review

ee5d8c0

MikhailBurdukov force-pushed the backoff_for_failed_mutations branch from cdf3c5f to ee5d8c0 Compare January 19, 2024 09:04

myrrc reviewed Jan 21, 2024

View reviewed changes

Enable per query setting

5e84517

MikhailBurdukov force-pushed the backoff_for_failed_mutations branch from 14b59f8 to 5e84517 Compare January 30, 2024 12:42

MikhailBurdukov and others added 3 commits January 30, 2024 16:08

Merge branch 'master' into backoff_for_failed_mutations

778efb8

Move setting to mergetree

b90a5b9

remove old config

97ee8c0

tavplubix self-assigned this Feb 12, 2024

tavplubix reviewed Feb 13, 2024

View reviewed changes

MikhailBurdukov added 2 commits February 18, 2024 13:37

Review changes

b227e5d

Style

94fa87d

MikhailBurdukov force-pushed the backoff_for_failed_mutations branch from 07b4c2a to 94fa87d Compare February 18, 2024 14:47

Merge branch 'master' into backoff_for_failed_mutations

c3ab907

MikhailBurdukov and others added 2 commits February 20, 2024 08:39

Enable setting by default

7cdfeda

Merge branch 'master' into backoff_for_failed_mutations

c2d641c

Fix stress tests

fa5747a

tavplubix approved these changes Feb 21, 2024

View reviewed changes

tavplubix merged commit ef3b191 into ClickHouse:master Feb 23, 2024
245 of 272 checks passed

robot-ch-test-poll1 added the pr-synced-to-cloud The PR is synced to the cloud repo label Feb 23, 2024

vitlibar mentioned this pull request Feb 28, 2024

Use multiple threads while reading the metadata of tables to restore #60040

Merged

azat reviewed Mar 6, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Backoff policy for failed mutation. #58036

Backoff policy for failed mutation. #58036

MikhailBurdukov commented Dec 19, 2023 •

edited

robot-clickhouse-ci-1 commented Dec 19, 2023 •

edited by robot-ch-test-poll2

myrrc Dec 20, 2023

myrrc Dec 20, 2023

myrrc commented Jan 21, 2024

myrrc Jan 21, 2024

myrrc Jan 21, 2024

myrrc Jan 21, 2024

myrrc Jan 21, 2024

myrrc Jan 21, 2024

myrrc Jan 21, 2024

tavplubix Feb 12, 2024

tavplubix Feb 12, 2024

tavplubix Feb 12, 2024

tavplubix Feb 12, 2024

tavplubix Feb 12, 2024

tavplubix Feb 13, 2024

tavplubix Feb 13, 2024

MikhailBurdukov Feb 19, 2024

tavplubix Feb 13, 2024

tavplubix Feb 13, 2024

tavplubix Feb 13, 2024

MikhailBurdukov commented Feb 19, 2024 •

edited

tavplubix commented Feb 19, 2024

MikhailBurdukov commented Feb 20, 2024

tavplubix commented Feb 21, 2024

alexey-milovidov commented Feb 27, 2024

azat Mar 6, 2024

tavplubix Mar 6, 2024

	auto failed_part = result_part->parts.at(0);
	auto & failed_part = result_part->parts.at(0);

		if (exist_posponed_failed_part)
		mutation_wait_event.notify_all();

		return config.getUInt("max_postpone_time_for_failed_mutations", 0ull);
		}

	assert node_no_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG) == False
	assert not node_no_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG)

	assert node_with_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG) == True
	assert node_with_backoff.contains_in_log(REPLICATED_POSPONE_MUTATION_LOG)

	void removePartFromFailed(const String& part_name)
	void removePartFromFailed(const String & part_name)

Backoff policy for failed mutation. #58036

Backoff policy for failed mutation. #58036

Conversation

MikhailBurdukov commented Dec 19, 2023 • edited

Changelog category (leave one):

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Documentation entry for user-facing changes

robot-clickhouse-ci-1 commented Dec 19, 2023 • edited by robot-ch-test-poll2

Choose a reason for hiding this comment

Choose a reason for hiding this comment

myrrc commented Jan 21, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MikhailBurdukov commented Feb 19, 2024 • edited

tavplubix commented Feb 19, 2024

MikhailBurdukov commented Feb 20, 2024

tavplubix commented Feb 21, 2024

alexey-milovidov commented Feb 27, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

MikhailBurdukov commented Dec 19, 2023 •

edited

robot-clickhouse-ci-1 commented Dec 19, 2023 •

edited by robot-ch-test-poll2

MikhailBurdukov commented Feb 19, 2024 •

edited