* [pbs-devel] [PATCH proxmox-backup] GC: log progress output for phase 2 on datastores backed by s3 @ 2025-12-15 13:24 Christian Ebner 2026-01-13 11:19 ` Fabian Grünbichler 0 siblings, 1 reply; 3+ messages in thread From: Christian Ebner @ 2025-12-15 13:24 UTC (permalink / raw) To: pbs-devel 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. 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"); + } + } + }) + } + }); + 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 ^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [pbs-devel] [PATCH proxmox-backup] GC: log progress output for phase 2 on datastores backed by s3 2025-12-15 13:24 [pbs-devel] [PATCH proxmox-backup] GC: log progress output for phase 2 on datastores backed by s3 Christian Ebner @ 2026-01-13 11:19 ` Fabian Grünbichler 2026-01-14 12:47 ` Christian Ebner 0 siblings, 1 reply; 3+ messages in thread From: Fabian Grünbichler @ 2026-01-13 11:19 UTC (permalink / raw) To: Proxmox Backup Server development discussion 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? 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? > > 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 ^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [pbs-devel] [PATCH proxmox-backup] GC: log progress output for phase 2 on datastores backed by s3 2026-01-13 11:19 ` Fabian Grünbichler @ 2026-01-14 12:47 ` Christian Ebner 0 siblings, 0 replies; 3+ messages in thread From: Christian Ebner @ 2026-01-14 12:47 UTC (permalink / raw) To: Proxmox Backup Server development discussion, Fabian Grünbichler 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 ^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2026-01-14 12:47 UTC | newest] Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2025-12-15 13:24 [pbs-devel] [PATCH proxmox-backup] GC: log progress output for phase 2 on datastores backed by s3 Christian Ebner 2026-01-13 11:19 ` Fabian Grünbichler 2026-01-14 12:47 ` Christian Ebner
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox