ClickHouse / ClickHouse/ClickHouse

Backup ON CLUSTER spends a long time cleaning its state in Keeper

Open
#81,968 4 comments 0 reactions 0 assignees View on GitHub
comp-backup external unexpected behaviour
Dominant language
C++
Stars
49.9k
Forks
9k
Avg merge
21h 32m
Merged PRs (30d)
515

Description

### Company or project name

_No response_

### Describe the unexpected behaviour

I run BACKUP ON CLUSTER to an NFS mounted folder.
It takes 20 minutes to create a backup and then an hour to clean up Keeper.
```
event_time_microseconds | id | status | num_files | total_size | num_entries
---------------------------+-----------------------------------------------+-----------------+-----------+-----------------+------------
-- the backup is initiated
2025-06-16 11:58:31.687726 | 70aef0a1-60b3-4b74-9d5e-5241195da04b | CREATING_BACKUP | 0 | 0 | 0
-- the 8 shards are starting the backup
2025-06-16 11:58:32.705726 | internal-42ba8ffc-47c1-4334-a784-63cc2c5f5884 | CREATING_BACKUP | 0 | 0 | 0
2025-06-16 11:58:32.708229 | internal-cb76e2ae-e9b0-418a-8ed9-825d85fb350d | CREATING_BACKUP | 0 | 0 | 0
2025-06-16 11:58:32.708547 | internal-25020c51-5783-4d09-abd9-23674b55ddf2 | CREATING_BACKUP | 0 | 0 | 0
2025-06-16 11:58:32.709061 | internal-88899603-01f4-421d-8ea1-8a15c5a0ef72 | CREATING_BACKUP | 0 | 0 | 0
2025-06-16 11:58:32.712409 | internal-953dc209-0e19-4de1-9232-8a0846b18e95 | CREATING_BACKUP | 0 | 0 | 0
2025-06-16 11:58:32.715475 | internal-a9f0155f-1652-4c9a-bb71-946841651cf7 | CREATING_BACKUP | 0 | 0 | 0
2025-06-16 11:58:32.717034 | internal-2d70c1ae-c60a-4d63-87be-9a7829f1dd5b | CREATING_BACKUP | 0 | 0 | 0
2025-06-16 11:58:32.737901 | internal-c764d263-2f6a-43ee-a168-5c534c5d02fb | CREATING_BACKUP | 0 | 0 | 0
-- 20 minutes later
-- the 8 shards have completed the backup
2025-06-16 12:19:37.726595 | internal-cb76e2ae-e9b0-418a-8ed9-825d85fb350d | BACKUP_CREATED | 0 | 0 | 0
2025-06-16 12:19:45.593553 | internal-c764d263-2f6a-43ee-a168-5c534c5d02fb | BACKUP_CREATED | 0 | 0 | 0
2025-06-16 12:20:23.580793 | internal-a9f0155f-1652-4c9a-bb71-946841651cf7 | BACKUP_CREATED | 0 | 0 | 0
2025-06-16 12:21:01.048866 | internal-953dc209-0e19-4de1-9232-8a0846b18e95 | BACKUP_CREATED | 0 | 0 | 0
2025-06-16 12:21:15.053541 | internal-42ba8ffc-47c1-4334-a784-63cc2c5f5884 | BACKUP_CREATED | 0 | 0 | 0
2025-06-16 12:21:35.981334 | internal-88899603-01f4-421d-8ea1-8a15c5a0ef72 | BACKUP_CREATED | 0 | 0 | 0
2025-06-16 12:22:31.219713 | internal-2d70c1ae-c60a-4d63-87be-9a7829f1dd5b | BACKUP_CREATED | 0 | 0 | 0
2025-06-16 12:22:41.536394 | internal-25020c51-5783-4d09-abd9-23674b55ddf2 | BACKUP_CREATED | 0 | 0 | 0
-- 60 minutes later
-- the initiator completed the cleanup
2025-06-16 13:19:19.886752 | 70aef0a1-60b3-4b74-9d5e-5241195da04b | BACKUP_CREATED | 218,824 | 114,240,571,544 | 131,314
```
Here are ProfileEvents from the initiating/cleaning up query:
```
Query: 1
InitialQuery: 1
QueriesWithSubqueries: 1
FileOpen: 5
ReadBufferFromFileDescriptorRead: 6
ReadBufferFromFileDescriptorReadBytes: 108
WriteBufferFromFileDescriptorWrite: 50
WriteBufferFromFileDescriptorWriteBytes: 51,202,748
ReadCompressedBytes: 36
CompressedReadBufferBlocks: 1
CompressedReadBufferBytes: 10
OpenedFileCacheMisses: 3
OpenedFileCacheMicroseconds: 6
IOBufferAllocs: 7
IOBufferAllocBytes: 3,146,351
CreatedReadBufferOrdinary: 3
DiskReadElapsedMicroseconds: 11,685
DiskWriteElapsedMicroseconds: 26,815
NetworkSendElapsedMicroseconds: 188
NetworkSendBytes: 4,527
GlobalThreadPoolJobs: 3
LocalThreadPoolExpansions: 2
LocalThreadPoolThreadCreationMicroseconds: 946
LocalThreadPoolJobs: 2
LocalReadThrottlerBytes: 108
ZooKeeperTransactions: 146,823
ZooKeeperList: 131,759
ZooKeeperCreate: 12
ZooKeeperRemove: 2
ZooKeeperExists: 257
ZooKeeperGet: 13,426
ZooKeeperMulti: 1,366
ZooKeeperSync: 1
SelectedRows: 1
SelectedBytes: 46
ContextLock: 24
RealTimeMicroseconds: 11,150,670,709
UserTimeMicroseconds: 2,372,468
SystemTimeMicroseconds: 487,971
SoftPageFaults: 32,880
HardPageFaults: 5
OSIOWaitMicroseconds: 450,000
OSCPUWaitMicroseconds: 722,832
OSCPUVirtualTimeMicroseconds: 2,860,437
OSReadBytes: 913,408
OSWriteBytes: 51,224,576
OSReadChars: 2,157
OSWriteChars: 51,226,496
BackupsOpenedForWrite: 1
BackupWriteMetadataMicroseconds: 3,028,999
LogTrace: 101
LogDebug: 1
LogInfo: 7
LoggerElapsedNanoseconds: 2,428,857
InterfaceNativeSendBytes: 4,527
ConcurrencyControlSlotsGranted: 1
ConcurrencyControlSlotsAcquired: 1
```

### Which ClickHouse versions are affected?

I am running ClickHouse 24.12 and Keeper 25.4.

### How to reproduce

`BACKUP TABLE PARTITION ID '' ON CLUSTER {cluster} TO File('/backup/table/partition')`

### Expected behavior

It would be great if the cleanup part could run faster.

### Error message and/or stacktrace

_No response_

### Additional context

_No response_

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.