Ottimizza controllo stabilita file in batch

DOCUMENTAZIONE_TECNICA.md

@@ -241,6 +241,42 @@ Conseguenza osservata:
 
 Un primo lancio puo' saltare un file come instabile. Un secondo lancio poco dopo puo' copiarlo correttamente. Questo e' comportamento previsto, non un errore.
 
+Problema prestazionale risolto:
+
+La prima implementazione controllava la stabilita' in modo sequenziale, file per file. Con 1359 file in coda e valori standard:
+
+```toml
+unchanged_check_interval_seconds = 5
+unchanged_checks_required = 2
+```
+
+il backup poteva restare fermo prima del primo `robocopy` per circa:
+
+```text
+1359 * 5 * 2 = 13590 secondi, cioe' quasi 4 ore
+```
+
+Soluzione adottata:
+
+Il controllo stabilita' ora lavora a batch:
+
+1. legge dimensione e timestamp di tutti i file candidati;
+2. attende l'intervallo configurato;
+3. ricontrolla tutti i file;
+4. ripete per il numero di controlli richiesti.
+
+Con la stessa configurazione, 1359 file richiedono circa 10 secondi di attesa stabilita' complessiva, non 10 secondi per ogni file.
+
+Sono stati aggiunti log espliciti:
+
+```text
+Found N pending files to back up
+Checking stability for N existing files
+Running X batch stability check(s) every Y second(s) for N file(s)
+Batch stability check ...
+Stability check completed: A stable, B unstable
+```
+
 ## Controllo raggiungibilita' slave
 
 Problema:

src/bakrest/backup.py

@@ -35,12 +35,15 @@ def run_backup(config: AppConfig, logger: logging.Logger) -> BackupResult:
         logger.info("No pending files to back up")
         return BackupResult(True, "Nessun file in attesa", copied_count=0)
 
+    logger.info("Found %s pending files to back up", len(pending))
     existing, skipped = _split_existing_files(pending)
     if skipped:
         logger.info("Skipped %s non-existing files", len(skipped))
         registry.mark_status([event.path for event in skipped], "ignored")
 
-    stable, unstable = _split_stable_files(existing, config)
+    logger.info("Checking stability for %s existing files", len(existing))
+    stable, unstable = _split_stable_files(existing, config, logger)
+    logger.info("Stability check completed: %s stable, %s unstable", len(stable), len(unstable))
     if unstable:
         logger.warning("Skipped %s unstable files", len(unstable))
 
@@ -95,38 +98,74 @@ def _split_existing_files(events: list[ChangeEvent]) -> tuple[list[ChangeEvent],
     return existing, skipped
 
 
-def _split_stable_files(events: list[ChangeEvent], config: AppConfig) -> tuple[list[ChangeEvent], list[ChangeEvent]]:
-    stable: list[ChangeEvent] = []
+def _split_stable_files(
+    events: list[ChangeEvent],
+    config: AppConfig,
+    logger: logging.Logger | None = None,
+) -> tuple[list[ChangeEvent], list[ChangeEvent]]:
+    candidates: list[ChangeEvent] = []
     unstable: list[ChangeEvent] = []
+    signatures: dict[str, tuple[int, int]] = {}
+    now = time.time()
+
     for event in events:
-        if _is_file_stable(Path(event.path), config):
-            stable.append(event)
-        else:
-            unstable.append(event)
-    return stable, unstable
-
-
-def _is_file_stable(path: Path, config: AppConfig) -> bool:
+        path = Path(event.path)
         try:
             stat = path.stat()
         except OSError:
-        return False
+            unstable.append(event)
+            continue
 
-    if time.time() - stat.st_mtime < config.stability.min_age_seconds:
-        return False
+        if now - stat.st_mtime < config.stability.min_age_seconds:
+            unstable.append(event)
+            continue
 
-    previous = (stat.st_size, stat.st_mtime_ns)
-    for _ in range(config.stability.unchanged_checks_required):
+        candidates.append(event)
+        signatures[event.path] = (stat.st_size, stat.st_mtime_ns)
+
+    checks_required = config.stability.unchanged_checks_required
+    if candidates and checks_required > 0 and logger:
+        logger.info(
+            "Running %s batch stability check(s) every %s second(s) for %s file(s)",
+            checks_required,
+            config.stability.unchanged_check_interval_seconds,
+            len(candidates),
+        )
+
+    for check_index in range(checks_required):
         time.sleep(config.stability.unchanged_check_interval_seconds)
+        next_candidates: list[ChangeEvent] = []
+        next_signatures: dict[str, tuple[int, int]] = {}
+
+        for event in candidates:
             try:
-            current_stat = path.stat()
+                current_stat = Path(event.path).stat()
             except OSError:
-            return False
+                unstable.append(event)
+                continue
+
             current = (current_stat.st_size, current_stat.st_mtime_ns)
-        if current != previous:
-            return False
-        previous = current
-    return True
+            if current != signatures[event.path]:
+                unstable.append(event)
+                continue
+
+            next_candidates.append(event)
+            next_signatures[event.path] = current
+
+        candidates = next_candidates
+        signatures = next_signatures
+        if logger:
+            logger.info(
+                "Batch stability check %s/%s completed: %s candidate file(s) remain",
+                check_index + 1,
+                checks_required,
+                len(candidates),
+            )
+
+        if not candidates:
+            break
+
+    return candidates, unstable
 
 
 def _build_rsync_command(config: AppConfig, events: list[ChangeEvent]) -> list[str]:

tests/test_backup.py

@@ -10,6 +10,7 @@ from bakrest.backup import (
     _run_command,
     _run_robocopy,
     _split_existing_files,
+    _split_stable_files,
 )
 from bakrest.config import parse_config
 from bakrest.registry import ChangeEvent, ChangeRegistry
@@ -161,6 +162,51 @@ def test_robocopy_marks_each_file_copied_after_all_destinations(
     assert pending_counts_after_commands == [2, 2, 1, 1]
 
 
+def test_stability_check_waits_per_batch_not_per_file(tmp_path: Path, monkeypatch) -> None:
+    source = tmp_path / "Lavori"
+    source.mkdir()
+    files = []
+    for index in range(3):
+        path = source / f"file-{index}.docx"
+        path.write_text("ok", encoding="utf-8")
+        files.append(path)
+
+    config = parse_config(
+        {
+            "watch": {
+                "include_dirs": [str(source)],
+                "include_extensions": [".docx"],
+                "exclude_dirs": [],
+                "exclude_patterns": [],
+            },
+            "backup": {
+                "engine": "robocopy",
+                "remote_destinations": ["\\\\server\\Backup1"],
+                "server_check": {"type": "tcp", "port": 445, "interval_seconds": 1800, "timeout_seconds": 1},
+            },
+            "stability": {
+                "min_age_seconds": 0,
+                "unchanged_check_interval_seconds": 5,
+                "unchanged_checks_required": 2,
+            },
+        },
+        tmp_path / "config.toml",
+    )
+    events = [ChangeEvent(path=str(path), event_type="modified") for path in files]
+    sleeps: list[int] = []
+
+    def fake_sleep(seconds):
+        sleeps.append(seconds)
+
+    monkeypatch.setattr("bakrest.backup.time.sleep", fake_sleep)
+
+    stable, unstable = _split_stable_files(events, config, _NullLogger())
+
+    assert [event.path for event in stable] == [str(path) for path in files]
+    assert unstable == []
+    assert sleeps == [5, 5]
+
+
 class _NullLogger:
     def info(self, *args, **kwargs) -> None:
         pass

tests/test_task_xml.py

@@ -27,5 +27,6 @@ def test_notifier_task_runs_every_30_minutes() -> None:
 def test_backup_task_uses_logoff_event_and_nogui_backup() -> None:
     xml = (Path("tasks") / "BakRestBackupOnLogoff.xml").read_text(encoding="utf-8")
 
-    assert "EventID=4647" in xml
+    assert "Microsoft-Windows-Winlogon" in xml
+    assert "EventID=7002" in xml
     assert "-m bakrest.tray_app --nogui" in xml