diff --git a/DOCUMENTAZIONE_TECNICA.md b/DOCUMENTAZIONE_TECNICA.md index 1a20c07..ddfb119 100644 --- a/DOCUMENTAZIONE_TECNICA.md +++ b/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: diff --git a/src/bakrest/backup.py b/src/bakrest/backup.py index 11e591d..7e680fb 100644 --- a/src/bakrest/backup.py +++ b/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: - try: - stat = path.stat() - except OSError: - return False - - if time.time() - stat.st_mtime < config.stability.min_age_seconds: - return False - - previous = (stat.st_size, stat.st_mtime_ns) - for _ in range(config.stability.unchanged_checks_required): - time.sleep(config.stability.unchanged_check_interval_seconds) + path = Path(event.path) try: - current_stat = path.stat() + stat = path.stat() except OSError: - return False - current = (current_stat.st_size, current_stat.st_mtime_ns) - if current != previous: - return False - previous = current - return True + unstable.append(event) + continue + + if now - stat.st_mtime < config.stability.min_age_seconds: + unstable.append(event) + continue + + 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(event.path).stat() + except OSError: + unstable.append(event) + continue + + current = (current_stat.st_size, current_stat.st_mtime_ns) + 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]: diff --git a/tests/test_backup.py b/tests/test_backup.py index faf6518..67f7b10 100644 --- a/tests/test_backup.py +++ b/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 diff --git a/tests/test_task_xml.py b/tests/test_task_xml.py index 4d9b494..d38faac 100644 --- a/tests/test_task_xml.py +++ b/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