all lists on lists.proxmox.com
 help / color / mirror / Atom feed
* [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; 2+ 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] 2+ 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
  0 siblings, 0 replies; 2+ 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] 2+ messages in thread

end of thread, other threads:[~2026-01-13 11:19 UTC | newest]

Thread overview: 2+ 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

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.
Service provided by Proxmox Server Solutions GmbH | Privacy | Legal