Re: [pbs-devel] [PATCH proxmox-backup] GC: log progress output for phase 2 on datastores backed by s3

[Christian Ebner <c.ebner@proxmox.com>]

On 1/13/26 12:18 PM, Fabian Grünbichler wrote:
> On December 15, 2025 2:24 pm, Christian Ebner wrote:
>> Currently there is no progress output for phase 2 of garbage
>> collection on datastores with s3 backend.
>>
>> Since spamming of the task log must be avoided and the number of
>> chunks to be processed cannot be inferred neither during phase 1, nor
>> by the S3 API, use a time based approach for this.
>>
>> Spawn a new thread for logging and keep track of the processed chunks
>> by an atomic counter. The progress handle and a channel are used to
>> abort the logging thread in case garbage collection is finished or an
>> abort has been triggered.
> 
> the reason *why* we need a separate thread is missing. I guess it is to
> because inline logging would not happen while S3 requests are blocking?

Yes, the idea was to have progress status output on regular time intervals.
> but given that if an S3 request is currently blocking, there can't be
> any progress anyway, I am not sure the overhead is worth it..
> 
> the timeout for list or delete calls is 1800s, and after the first hour
> your current implementation below already switches to once-per-hour
> logging anyway.. but see below for that..
> 
> but maybe somebody else has an opinion about the thread-or-not part?

Rethinking this now I also do not see why running this on it's own 
thread is worth it and should be better than simply doing the logging on 
the same thread, with progress output only written when actually done.

So I will pull this out and adapt the output rate changes to the values 
as suggested, these do make sense to me. Also adding the additional 
suggested values to be logged is a good idea (at least for the list 
object calls, not so sure about the delete object calls as there it 
might depend on the number of keys to be deleted, how many calls are 
being done ecc., so the variance is probably high).

> 
>>
>> Signed-off-by: Christian Ebner <c.ebner@proxmox.com>
>> ---
>>   pbs-datastore/Cargo.toml       |  1 +
>>   pbs-datastore/src/datastore.rs | 47 +++++++++++++++++++++++++++++++---
>>   2 files changed, 45 insertions(+), 3 deletions(-)
>>
>> diff --git a/pbs-datastore/Cargo.toml b/pbs-datastore/Cargo.toml
>> index 8ce930a94..80e06cb0e 100644
>> --- a/pbs-datastore/Cargo.toml
>> +++ b/pbs-datastore/Cargo.toml
>> @@ -38,6 +38,7 @@ proxmox-http.workspace = true
>>   proxmox-human-byte.workspace = true
>>   proxmox-io.workspace = true
>>   proxmox-lang.workspace=true
>> +proxmox-log.workspace=true
>>   proxmox-s3-client = { workspace = true, features = [ "impl" ] }
>>   proxmox-schema = { workspace = true, features = [ "api-macro" ] }
>>   proxmox-serde = { workspace = true, features = [ "serde_json" ] }
>> diff --git a/pbs-datastore/src/datastore.rs b/pbs-datastore/src/datastore.rs
>> index 9c57aaac1..84866a529 100644
>> --- a/pbs-datastore/src/datastore.rs
>> +++ b/pbs-datastore/src/datastore.rs
>> @@ -3,6 +3,8 @@ use std::io::{self, Write};
>>   use std::os::unix::ffi::OsStrExt;
>>   use std::os::unix::io::AsRawFd;
>>   use std::path::{Path, PathBuf};
>> +use std::sync::atomic::{AtomicUsize, Ordering};
>> +use std::sync::mpsc::RecvTimeoutError;
>>   use std::sync::{Arc, LazyLock, Mutex};
>>   use std::time::{Duration, SystemTime};
>>   
>> @@ -15,6 +17,7 @@ use tokio::io::AsyncWriteExt;
>>   use tracing::{info, warn};
>>   
>>   use proxmox_human_byte::HumanByte;
>> +use proxmox_log::LogContext;
>>   use proxmox_s3_client::{
>>       S3Client, S3ClientConf, S3ClientOptions, S3ObjectKey, S3PathPrefix, S3RateLimiterOptions,
>>   };
>> @@ -1682,7 +1685,7 @@ impl DataStore {
>>           info!("Start GC phase2 (sweep unused chunks)");
>>   
>>           if let Some(ref s3_client) = s3_client {
>> -            let mut chunk_count = 0;
>> +            let chunk_count = Arc::new(AtomicUsize::new(0));
>>               let prefix = S3PathPrefix::Some(".chunks/".to_string());
>>               // Operates in batches of 1000 objects max per request
>>               let mut list_bucket_result =
>> @@ -1692,6 +1695,34 @@ impl DataStore {
>>               let mut delete_list = Vec::with_capacity(S3_DELETE_BATCH_LIMIT);
>>               let mut delete_list_age = epoch_i64();
>>   
>> +            let (abort_tx, abort_rx) = std::sync::mpsc::channel();
>> +            let counter = Arc::clone(&chunk_count);
>> +            let log_context = LogContext::current();
>> +
>> +            let progress_log_handle = std::thread::spawn(move || {
>> +                if let Some(log_context) = log_context {
>> +                    log_context.sync_scope(|| {
>> +                        let mut timeout = Duration::from_secs(60);
>> +                        let mut iterations = 0;
>> +                        while let Err(RecvTimeoutError::Timeout) = abort_rx.recv_timeout(timeout) {
>> +                            let count = counter.load(Ordering::SeqCst);
>> +                            info!("sweeped chunks: {count}");
>> +
>> +                            iterations += 1;
>> +                            if iterations >= 60 && timeout < Duration::from_secs(60 * 60) {
>> +                                timeout = timeout.saturating_mul(60);
>> +                                info!("log output reduced to once per hour");
>> +                            } else if iterations >= 60 * 60
>> +                                && timeout < Duration::from_secs(24 * 60 * 60)
>> +                            {
>> +                                timeout = timeout.saturating_mul(24);
>> +                                info!("log output reduced to once per day");
>> +                            }
> 
> I think this is a bit aggressive.. the purpose of backing off is to not
> make log files explode while still giving valuable information. an
> update once per hour is already not very helpful, an update once per day
> is useless (even if the task takes 5 days).
> 
> IMHO a progression like:
> - every 30s for the first hour (120 lines, still gives meaningful
>    progress if the GC proceeds fast)
> - every minute for the second hour (+60 lines)
> - every 5 minutes for hours 3..24 (+12 lines per hour, +264 lines total)
> 
> is totally fine. that means a GC running a full day will log 444 lines
> (for this part). then maybe after the first day we could switch to every
> 15 minutes (which adds 96 lines per additional day).
> 
> we could of course also include additional information:
> - handled chunk count
> - current list batch size
> - current delete list size
> 
> and maybe even keep track of those two sizes and list/delete request
> times and print averages? those would be helpful when debugging S3 GC
> performance I think?
> 
>> +                        }
>> +                    })
>> +                }
>> +            });
>> +
>>               let s3_delete_batch = |delete_list: &mut Vec<(S3ObjectKey, BackupLockGuard)>,
>>                                      s3_client: &Arc<S3Client>|
>>                -> Result<(), Error> {
>> @@ -1800,7 +1831,7 @@ impl DataStore {
>>                           );
>>                       }
>>   
>> -                    chunk_count += 1;
>> +                    chunk_count.fetch_add(1, Ordering::SeqCst);
>>   
>>                       // drop guard because of async S3 call below
>>                       drop(_guard);
>> @@ -1831,7 +1862,17 @@ impl DataStore {
>>                   s3_delete_batch(&mut delete_list, s3_client)?;
>>               }
>>   
>> -            info!("processed {chunk_count} total chunks");
>> +            abort_tx
>> +                .send(())
>> +                .context("failed to abort progress logging")?;
>> +            progress_log_handle
>> +                .join()
>> +                .map_err(|_err| format_err!("failed to join progress log handle"))?;
>> +
>> +            info!(
>> +                "processed {} total chunks",
>> +                chunk_count.load(Ordering::SeqCst),
>> +            );
>>   
>>               // Phase 2 GC of Filesystem backed storage is phase 3 for S3 backed GC
>>               info!("Start GC phase3 (sweep unused chunk markers)");
>> -- 
>> 2.47.3
>>
>>
>>
>> _______________________________________________
>> pbs-devel mailing list
>> pbs-devel@lists.proxmox.com
>> https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel
>>
>>
>>
> 
> 
> _______________________________________________
> pbs-devel mailing list
> pbs-devel@lists.proxmox.com
> https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel
> 
> 



_______________________________________________
pbs-devel mailing list
pbs-devel@lists.proxmox.com
https://lists.proxmox.com/cgi-bin/mailman/listinfo/pbs-devel