Add better time tracking

CHANGELOG.rst

@@ -7,6 +7,30 @@ Release Notes
 0.12 Series
 ...........
 
+0.12.19 (2026-07-27)
+--------------------
+
+General:
+
+* Add execution time profiling to the ABC-SMC run, reporting pure simulation
+  time, parallel-pipeline setup time, and in-between-iteration time,
+  including population-size calculation and distance-function adaptation.
+  The timings are also returned by ``run_generation``. Resolves #325.
+* Minor bug fixes and improved typesetting.
+
+Visualization:
+
+* ``plot_walltime`` and ``plot_total_walltime`` now report the actual
+  per-generation walltimes and no longer include the idle time that passed
+  between a stored analysis and a later resumed run. Resolves #667.
+
+Storage:
+
+* Store the per-generation walltime in the database (new ``wall_time`` column,
+  database version 2). Databases created with older pyABC versions must be
+  migrated via ``abc-migrate`` before they can be resumed; for such databases
+  the walltime plots fall back to the previous, end-time-based behavior.
+
 0.12.18 (2026-04-14)
 --------------------
 

pyabc/distance/base.py

@@ -224,7 +224,7 @@ class FunctionDistance(Distance):
         statistics x and x_0. Returns the distance between both.
     """
 
-    def __init__(self, fun):
+    def __init__(self, fun: Callable):
         super().__init__()
         self.fun = fun
 
@@ -250,7 +250,7 @@ def get_config(self):
         return conf
 
     @staticmethod
-    def to_distance(maybe_distance: Callable | Distance) -> Distance:
+    def to_distance(maybe_distance: Callable | Distance | None) -> Distance:
         """
         Parameters
         ----------

pyabc/distance/pnorm.py

@@ -597,7 +597,9 @@ def __init__(
 
         self.predictor = predictor
 
-        self.initial_info_weights: dict[str, float] = initial_info_weights
+        self.initial_info_weights: dict[str, float] | None = (
+            initial_info_weights
+        )
         self.info_weights: dict[int, np.ndarray] = {}
 
         if fit_info_ixs is None:

pyabc/inference/smc.py

@@ -4,6 +4,7 @@
 import logging
 from collections.abc import Callable
 from datetime import datetime, timedelta
+from time import perf_counter
 from typing import TypeVar
 
 import numpy as np
@@ -54,6 +55,23 @@ def identity(x):
     return x
 
 
+class _Timer:
+    """Context manager measuring wall-clock execution time in seconds.
+
+    The elapsed time is available via the ``elapsed`` attribute after the
+    ``with`` block has finished, and is used for execution time profiling.
+    """
+
+    def __enter__(self) -> '_Timer':
+        self.elapsed = 0.0
+        self._start = perf_counter()
+        return self
+
+    def __exit__(self, *exc_info) -> bool:
+        self.elapsed = perf_counter() - self._start
+        return False
+
+
 def run_cleanup(run):
     """Wrapper: Run and in any case clean up afterwards."""
 
@@ -172,7 +190,7 @@ class ABCSMC:
     def __init__(
         self,
         models: list[Model] | Model | Callable,
-        parameter_priors: list[Distribution] | Distribution | Callable,
+        parameter_priors: list[Distribution] | Distribution,
         distance_function: Distance | Callable | None = None,
         population_size: PopulationStrategy | int = 100,
         summary_statistics: Callable[[model_output], dict] = identity,
@@ -545,6 +563,9 @@ def _sample_from_prior(self, t: int) -> Population:
         Only sample from prior and return results without changing
         the history of the distance function or the epsilon.
         """
+        # record start time
+        calibration_start_time = datetime.now()
+
         # create simulate function
         simulate_one = self._create_simulate_from_prior_function()
 
@@ -567,8 +588,13 @@ def _sample_from_prior(self, t: int) -> Population:
         population = sample.get_accepted_population()
 
         # update information saved in history about calibration
+        calibration_end_time = datetime.now()
         self.history.update_after_calibration(
-            nr_samples=self.sampler.nr_evaluations_, end_time=datetime.now()
+            nr_samples=self.sampler.nr_evaluations_,
+            end_time=calibration_end_time,
+            wall_time=(
+                calibration_end_time - calibration_start_time
+            ).total_seconds(),
         )
 
         return population
@@ -792,6 +818,9 @@ def run_generation(
             generation terminated successfully,
             and potentially "acceptance_rate".
         """
+        # start execution time profiling for this generation
+        generation_perf_start = perf_counter()
+
         # get epsilon for generation t
         current_eps = self.eps(t)
         if current_eps is None or np.isnan(current_eps):
@@ -800,26 +829,29 @@ def run_generation(
             )
         logger.info(f't: {t}, eps: {current_eps:.8e}.')
 
-        # create simulate function
-        simulate_one = self._create_simulate_function(t)
-
-        # population size and maximum number of evaluations
-        pop_size = self.population_size(t)
-        max_eval = (
-            np.inf
-            if self.min_acceptance_rate == 0.0
-            else pop_size / self.min_acceptance_rate
-        )
+        # set up the simulation pipeline for this generation
+        with _Timer() as setup_timer:
+            # create simulate function
+            simulate_one = self._create_simulate_function(t)
+
+            # population size and maximum number of evaluations
+            pop_size = self.population_size(t)
+            max_eval = (
+                np.inf
+                if self.min_acceptance_rate == 0.0
+                else pop_size / self.min_acceptance_rate
+            )
 
         # perform the sampling
         logger.debug(f'Submitting population {t}.')
-        sample = self.sampler.sample_until_n_accepted(
-            n=pop_size,
-            simulate_one=simulate_one,
-            t=t,
-            max_eval=max_eval,
-            ana_vars=self._vars(t=t),
-        )
+        with _Timer() as simulation_timer:
+            sample = self.sampler.sample_until_n_accepted(
+                n=pop_size,
+                simulate_one=simulate_one,
+                t=t,
+                max_eval=max_eval,
+                ana_vars=self._vars(t=t),
+            )
 
         # check sample health
         if not sample.ok:
@@ -838,8 +870,9 @@ def run_generation(
         # save to database
         n_sim = self.sampler.nr_evaluations_
         model_names = [model.name for model in self.models]
+        wall_time = perf_counter() - generation_perf_start
         self.history.append_population(
-            t, current_eps, population, n_sim, model_names
+            t, current_eps, population, n_sim, model_names, wall_time=wall_time
         )
         logger.debug(
             f'Total samples up to t = {t}: '
@@ -856,16 +889,42 @@ def run_generation(
         )
 
         # prepare next iteration
-        self._prepare_next_iteration(
-            t=t + 1,
-            sample=sample,
-            population=population,
-            acceptance_rate=acceptance_rate,
+        with _Timer() as prepare_next_timer:
+            prepare_next_timings = self._prepare_next_iteration(
+                t=t + 1,
+                sample=sample,
+                population=population,
+                acceptance_rate=acceptance_rate,
+            )
+
+        # execution time profiling
+        total_time = perf_counter() - generation_perf_start
+        sim_fraction = (
+            100 * simulation_timer.elapsed / total_time
+            if total_time > 0
+            else 0.0
+        )
+        timings = {
+            'total': total_time,
+            'simulation': simulation_timer.elapsed,
+            'pipeline_setup': setup_timer.elapsed,
+            'prepare_next': prepare_next_timer.elapsed,
+            **prepare_next_timings,
+        }
+        logger.info(
+            f'Timing t={t} [s]: total={total_time:.3g}, '
+            f'simulation={simulation_timer.elapsed:.3g} '
+            f'({sim_fraction:.0f}%), '
+            f'pipeline-setup={setup_timer.elapsed:.3g}, '
+            f'prepare-next={prepare_next_timer.elapsed:.3g} '
+            f'(population-size={prepare_next_timings["population_size"]:.3g}, '
+            f'distance={prepare_next_timings["distance"]:.3g}).'
         )
 
         return {
             'successful': True,
             'acceptance_rate': acceptance_rate,
+            'timings': timings,
         }
 
     def check_terminate(
@@ -909,7 +968,7 @@ def _prepare_next_iteration(
         sample: Sample,
         population: Population,
         acceptance_rate: float,
-    ):
+    ) -> dict:
         """Update actors for the upcoming iteration.
 
         Be aware: The current (finished) iteration is t-1, the next t.
@@ -924,6 +983,12 @@ def _prepare_next_iteration(
             The current iteration's population object.
         acceptance_rate: float
             The current iteration's acceptance rate.
+
+        Returns
+        -------
+        timings:
+            Execution times in seconds of the profiled sub-steps, with keys
+            ``"population_size"`` and ``"distance"``.
         """
         # make a copy
         prev_transitions = copy.deepcopy(self.transitions)
@@ -932,17 +997,19 @@ def _prepare_next_iteration(
         self._fit_transitions(t)
 
         # update population size
-        self._adapt_population_size(t)
+        with _Timer() as population_size_timer:
+            self._adapt_population_size(t)
 
         def get_sample():
             return sample
 
         # update distance
-        df_updated = self.distance_function.update(
-            t=t,
-            get_sample=get_sample,
-            total_sims=self.history.total_nr_simulations,
-        )
+        with _Timer() as distance_timer:
+            df_updated = self.distance_function.update(
+                t=t,
+                get_sample=get_sample,
+                total_sims=self.history.total_nr_simulations,
+            )
 
         # compute distances with the new distance measure
         def get_weighted_distances():
@@ -999,6 +1066,11 @@ def get_all_records():
             acceptor_config=self.acceptor.get_epsilon_config(t),
         )
 
+        return {
+            'population_size': population_size_timer.elapsed,
+            'distance': distance_timer.elapsed,
+        }
+
     def _adapt_population_size(self, t):
         """
         Adapt population size based on the employed population strategy.
@@ -1016,11 +1088,16 @@ def _adapt_population_size(self, t):
             'p'
         ].values
 
+        # restrict to models still alive: dead models are never fitted
+        alive = self.history.alive_models(self.history.max_t)
+
         # make a copy in case the population strategy messes with
         # the transitions
         # WARNING: the deepcopy also copies the random states of scipy.stats
         # distributions
-        copied_transitions = copy.deepcopy(self.transitions)
+        copied_transitions = copy.deepcopy(
+            [self.transitions[m] for m in alive]
+        )
 
         # update the population size
         self.population_size.update(

pyabc/populationstrategy/populationstrategy.py

@@ -220,7 +220,7 @@ def update(
             )[0],
         )
 
-        if not np.isnan(cv_estimate.n_estimated):
+        if np.isfinite(cv_estimate.n_estimated):
             self.nr_particles = max(
                 min(int(cv_estimate.n_estimated), self.max_population_size),
                 self.min_population_size,

pyabc/storage/db_model.py

@@ -98,6 +98,7 @@ class Population(Base):
     abc_smc_id = Column(Integer, ForeignKey('abc_smc.id'))
     t = Column(Integer)
     population_end_time = Column(DateTime)
+    wall_time = Column(Float)
     nr_samples = Column(Integer)
     epsilon = Column(Float)
     models = relationship('Model')