Skip to content

Fix race condition in DETACH and background merge#13746

Merged
alexey-milovidov merged 1 commit intomasterfrom
fix-race-condition-detach-merge
Aug 15, 2020
Merged

Fix race condition in DETACH and background merge#13746
alexey-milovidov merged 1 commit intomasterfrom
fix-race-condition-detach-merge

Conversation

@alexey-milovidov
Copy link
Copy Markdown
Member

@alexey-milovidov alexey-milovidov commented Aug 15, 2020

Changelog category (leave one):

  • Bug Fix

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):
Fix race condition between DETACH and background merges. Parts may revive after detach. This is continuation of #8602 that did not fix the issue but introduced a test that started to fail in very rare cases, demonstrating the issue.

@alexey-milovidov alexey-milovidov added the testing Special issue with list of bugs found by CI label Aug 15, 2020
@robot-clickhouse robot-clickhouse added the pr-bugfix Pull request with bugfix, not backported by default label Aug 15, 2020
alexey-milovidov
alexey-milovidov commented Aug 15, 2020
View reviewed changes
src/Storages/StorageMergeTree.cpp
/// This protects against "revival" of data for a removed partition after completion of merge.
auto merge_blocker = merger_mutator.merges_blocker.cancel();

{
Copy link
Copy Markdown
Member Author

@alexey-milovidov alexey-milovidov Aug 15, 2020

Choose a reason for hiding this comment

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

This is what changed. We have not only to ask merges for cancel. But to actually wait that they are finished.

@alexey-milovidov
Copy link
Copy Markdown
Member Author

alexey-milovidov commented Aug 15, 2020 •
edited
Loading

#13680
#12508

@alexey-milovidov
Copy link
Copy Markdown
Member Author

alexey-milovidov commented Aug 15, 2020

00933_test_fix_extra_seek_on_compressed_cache: #13747

This was referenced Aug 15, 2020
Merged
Merged
@alexey-milovidov
Copy link
Copy Markdown
Member Author

alexey-milovidov commented Aug 15, 2020

Stress test (undefined) — Server failed to start

Fixed in #13743

@alexey-milovidov
Copy link
Copy Markdown
Member Author

alexey-milovidov commented Aug 15, 2020

test_storage_rabbitmq

Known bad test.

@alexey-milovidov
Copy link
Copy Markdown
Member Author

alexey-milovidov commented Aug 15, 2020

00933_test_fix_extra_seek_on_compressed_cache

Fixed in #13747

@alexey-milovidov alexey-milovidov merged commit 8c34cc3 into master Aug 15, 2020
@alexey-milovidov alexey-milovidov deleted the fix-race-condition-detach-merge branch August 15, 2020 12:53
@alexey-milovidov alexey-milovidov mentioned this pull request Aug 15, 2020
Merged
This was referenced Aug 15, 2020
Merged
Closed
Merged
Closed
robot-clickhouse pushed a commit that referenced this pull request Aug 15, 2020
Backport #13746 to 20.7: Fix race condition in DETACH and background …
b0e8fa5 
…merge
@robot-clickhouse robot-clickhouse mentioned this pull request Aug 15, 2020
Merged
robot-clickhouse pushed a commit that referenced this pull request Aug 15, 2020
Backport #13746 to 20.6: Fix race condition in DETACH and background …
797b961 
…merge
@robot-clickhouse robot-clickhouse mentioned this pull request Aug 15, 2020
Merged
This was referenced Aug 15, 2020
Merged
Merged
@azat azat mentioned this pull request Aug 15, 2020
Merged
alexey-milovidov added a commit that referenced this pull request Aug 20, 2020
@alexey-milovidov
Merge pull request #13772 from ClickHouse/backport/20.6/13746
e8906e0 
Backport #13746 to 20.6: Fix race condition in DETACH and background merge
alexey-milovidov added a commit that referenced this pull request Aug 20, 2020
@alexey-milovidov
Merge pull request #13771 from ClickHouse/backport/20.7/13746
5628175 
Backport #13746 to 20.7: Fix race condition in DETACH and background merge
@azat azat mentioned this pull request Jun 22, 2021
Merged
azat added a commit to azat/ClickHouse that referenced this pull request Jun 30, 2021
@azat
Fix race between DETACH and merges
fc46eff 
CI reports failure of the 01442_merge_detach_attach test [1]:

<details>

    2021-06-21 02:25:43 01442_merge_detach_attach:                                              [ FAIL ] 122.37 sec. - result differs with reference:
    2021-06-21 02:25:43 --- /usr/share/clickhouse-test/queries/0_stateless/01442_merge_detach_attach.reference	2021-06-21 00:43:12.000000000 +0300
    2021-06-21 02:25:43 +++ /tmp/clickhouse-test/0_stateless/01442_merge_detach_attach.stdout	2021-06-21 02:25:43.211212197 +0300
    2021-06-21 02:25:43 @@ -0,0 +1 @@
    2021-06-21 02:25:43 +2

    2021.06.21 02:25:08.930896 [ 100543 ] {16eb4fe5-2d6b-4c81-a6be-c6a3b293edd3} <Debug> executeQuery: (from [::1]:36540, using production parser) (comment: '/usr/share/clickhouse-test/queries/0_stateless/01442_merge_detach_attach.sh') ALTER TABLE t DETACH PARTITION tuple()
    2021.06.21 02:25:08.931245 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> executeQuery: (from [::1]:36542, using production parser) (comment: '/usr/share/clickhouse-test/queries/0_stateless/01442_merge_detach_attach.sh') OPTIMIZE TABLE t FINAL
    2021.06.21 02:25:08.931826 [ 100543 ] {16eb4fe5-2d6b-4c81-a6be-c6a3b293edd3} <Trace> ContextAccess (default): Access granted: ALTER DELETE ON test_89nl0v.t
    2021.06.21 02:25:08.932159 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Trace> ContextAccess (default): Access granted: OPTIMIZE ON test_89nl0v.t
    2021.06.21 02:25:08.932889 [ 100543 ] {16eb4fe5-2d6b-4c81-a6be-c6a3b293edd3} <Information> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249): Detaching all_143_143_0
    2021.06.21 02:25:08.932921 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (MergerMutator): Selected 2 parts from all_143_143_0 to all_144_144_0
    2021.06.21 02:25:08.933530 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 4.60 TiB.
    2021.06.21 02:25:08.933705 [ 100543 ] {16eb4fe5-2d6b-4c81-a6be-c6a3b293edd3} <Information> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249): Detaching all_144_144_0
    2021.06.21 02:25:08.934215 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (MergerMutator): Merging 2 parts: from all_143_143_0 to all_144_144_0 into Compact
    2021.06.21 02:25:08.934280 [ 100543 ] {16eb4fe5-2d6b-4c81-a6be-c6a3b293edd3} <Information> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249): Detached 2 parts.
    2021.06.21 02:25:08.934948 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (MergerMutator): Selected MergeAlgorithm: Horizontal
    2021.06.21 02:25:08.936090 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> MergeTreeSequentialSource: Reading 2 marks from part all_143_143_0, total 1 rows starting from the beginning of the part, column x
    2021.06.21 02:25:08.937621 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> MergeTreeSequentialSource: Reading 2 marks from part all_144_144_0, total 1 rows starting from the beginning of the part, column x
    2021.06.21 02:25:08.938124 [ 100543 ] {16eb4fe5-2d6b-4c81-a6be-c6a3b293edd3} <Debug> MemoryTracker: Peak memory usage (for query): 0.00 B.
    2021.06.21 02:25:08.939928 [ 100543 ] {} <Debug> TCPHandler: Processed in 0.018537432 sec.
    2021.06.21 02:25:08.942140 [ 100543 ] {} <Debug> TCPHandler: Done processing connection.
    2021.06.21 02:25:08.948343 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (MergerMutator): Merge sorted 2 rows, containing 1 columns (1 merged, 0 gathered) in 0.014203821 sec., 140.80718139154246 rows/sec., 140.81 B/sec.
    2021.06.21 02:25:08.952021 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Trace> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249): Renaming temporary part tmp_merge_all_143_144_1 to all_143_144_1.
    2021.06.21 02:25:08.952869 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Warning> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (MergerMutator): Unexpected number of parts removed when adding all_143_144_1: 0 instead of 2
    2021.06.21 02:25:08.953264 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Trace> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (MergerMutator): Merged 2 parts: from all_143_143_0 to all_144_144_0
    2021.06.21 02:25:08.953913 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> MemoryTracker: Peak memory usage: 4.01 MiB.
    2021.06.21 02:25:08.958369 [ 100540 ] {bd4b710d-cd27-44ea-9dc9-e45d6ace0bd7} <Debug> MemoryTracker: Peak memory usage (for query): 4.01 MiB.
    ...
    2021.06.21 02:25:09.216075 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Debug> executeQuery: (from [::1]:36544, using production parser) (comment: '/usr/share/clickhouse-test/queries/0_stateless/01442_merge_detach_attach.sh') SELECT count() FROM t HAVING count() > 0
    2021.06.21 02:25:09.229491 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Trace> ContextAccess (default): Access granted: SELECT(x) ON test_89nl0v.t
    2021.06.21 02:25:09.232000 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
    2021.06.21 02:25:09.239907 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Debug> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (SelectExecutor): Key condition: unknown
    2021.06.21 02:25:09.240358 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Debug> test_89nl0v.t (efd364af-6721-4249-afd3-64af67214249) (SelectExecutor): Selected 1/1 parts by partition key, 1 parts by primary key, 1/1 marks by primary key, 1 marks to read from 1 ranges
    2021.06.21 02:25:09.241560 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Debug> MergeTreeSelectProcessor: Reading 1 ranges from part all_143_144_1, approx. 2 rows starting from 0
    2021.06.21 02:25:09.256053 [ 58403 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Trace> AggregatingTransform: Aggregating
    2021.06.21 02:25:09.256410 [ 58403 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Trace> Aggregator: Aggregation method: without_key
    2021.06.21 02:25:09.257576 [ 58403 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Debug> AggregatingTransform: Aggregated. 2 to 1 rows (from 2.00 B) in 0.013910412 sec. (143.777 rows/sec., 143.78 B/sec.)
    2021.06.21 02:25:09.257911 [ 58403 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Trace> Aggregator: Merging aggregated data
    2021.06.21 02:25:09.262595 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Information> executeQuery: Read 2 rows, 2.00 B in 0.045805192 sec., 43 rows/sec., 43.66 B/sec.
    2021.06.21 02:25:09.263337 [ 100543 ] {1699b404-b132-4b96-b04a-1c28cd062a79} <Debug> MemoryTracker: Peak memory usage (for query): 0.00 B.

</details>

  [1]: https://clickhouse-test-reports.s3.yandex.net/25513/b96df135aee40b1a54a4fc3f0d4db89e11385564/functional_stateless_tests_(memory).html#fail1

The problem here is that there is a tiny race window between DETACH
and OPTIMIZE.

DETACH cancel merges, and checks that there no merges for parts
currently under lock, and later changes the state of parts. After it
allows merges.

However OPTIMIZE get parts for processing under lock and only when it
starts writing temporary part it checks that merges are not canceled.

So suppose the following scenario:

      T#OPTIMIZE                       T#DETACH

                                       - cancel merges
                                           - lock
                                             - check that no merges are in progress
                                           - unlock
    - lock
      - get parts

          *<--Here, state of the parts are not changed yet,
              and lock is not held,
              so OPTIMIZE may (and will) get those parts. -->*

      - write temporary part
        - check merges not canceled
    - unlock
                                           - change the parts state
                                       - allows merges

Plus this patch will also fail merges earlier in case of concurrent
DETACH.

Refs: ClickHouse#13746
Refs: ClickHouse#23315
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

pr-bugfix Pull request with bugfix, not backported by default testing Special issue with list of bugs found by CI

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@alexey-milovidov @robot-clickhouse