PerfTimers.hpp

Go to the documentation of this file.

 
#pragma once
// -----------------------------------------------------------------------------
// PerfTimers — lightweight, env-gated wall-clock accumulators used to attribute
// run time between the 2D surface solve, the 1D routing step, and the 2D-window
// (rainfall + coupling) overhead. Header-only (C++17 inline variables) so no
// CMake/link changes are needed; the ScopedTimer only touches a steady_clock at
// coarse call sites (per macro-window / per routing step), never a hot inner
// loop. The split is printed once from SWMMEngine::end() when OPENSWMM_PERF is
// set. Zero cost when the env var is unset except the clock reads themselves.
// -----------------------------------------------------------------------------
#include <array>
#include <mutex>
#include <chrono>
#include <cstdio>
#include <cstdlib>
 
namespace openswmm::perf {
 
inline double sec_2d_window = 0.0;  // full 2D advance window (rainfall+coupling+solve)
inline double sec_2d_advance = 0.0; // pure 2D solve (solver_->advance)
inline double sec_1d_step = 0.0;    // 1D routing (router_.step)
 
// ---------------------------------------------------------------------------
// Load-phase accumulators — the open() / initialize() / start() window, which
// is what the user sees between clicking Run and the first routing step. Same
// env gate and same ScopedTimer as above; reset by open() so a process that
// runs several models reports each one separately.
// ---------------------------------------------------------------------------
 
inline double sec_open_prescan2d = 0.0; // twoD::prescan2DUnitsHeader (whole-file pass)
inline double sec_open_read = 0.0;      // input_plugin->read (tokenize + handlers)
// open.read split: the line scan (getline, trim, section_lines assembly) is
// everything in read() that is not a section handler. Dispatch is measured and
// scan is derived as the remainder, so the two always sum to open.read.
inline double sec_read_dispatch = 0.0; // SectionRegistry handler execution
inline double sec_open_resolve = 0.0;  // input::resolve_cross_references
inline double sec_open_validate = 0.0; // validate_project
 
// resolve_cross_references sub-phases (sum <= sec_open_resolve; the remainder
// is everything not individually bracketed).
inline double sec_res_extfiles = 0.0;  // FILE-backed timeseries/curve loads
inline double sec_res_tables = 0.0;    // gage/inflow/table name bindings
inline double sec_res_transects = 0.0; // transect + street/inlet resolution
inline double sec_res_xsect = 0.0;     // per-link cross-section parameter loop
inline double sec_res_shrink = 0.0;    // shrink_all_to_fit
 
inline double sec_init_state = 0.0;      // initialize() body before init_modules()
inline double sec_init_hydraulics = 0.0; // initHydraulics (router_.init, FV mesh build)
inline double sec_init_hydrology = 0.0;  // initHydrology
inline double sec_init_quality = 0.0;    // initQuality
inline double sec_init_geometry = 0.0;   // initGeometry
 
inline double sec_start_iface = 0.0;   // [FILES] interface-file open block
inline double sec_start_plugins = 0.0; // plugins_.prepare_all (report preamble + .out header)
 
// ---------------------------------------------------------------------------
// FV 1D solver phase breakdown. `sec_1d_step` brackets the whole router step,
// which is enough to say the FV solver is slow and nothing about WHY. These
// split it by phase so a plan can be ranked against a profile instead of a
// recollection.
//
// Granularity is per-substep-phase, never per-cell or per-face: at hundreds of
// substeps a steady_clock read per phase is noise, at millions of faces it
// would BE the profile. The counters are therefore incremented by loop extents
// (`+= n`) at loop boundaries rather than by ++ inside the loop, which also
// keeps them correct without atomics when the flux loop goes parallel.
//
// Parallel closure and node-solve counters are accumulated privately and
// merged after each worksharing phase. Counts are exact at every team size.
// ---------------------------------------------------------------------------
 
inline double sec_fv_census = 0.0;      // censusDt (Courant min-reduction)
inline double sec_fv_flux = 0.0;        // computeFluxes (active-face sweep)
inline double sec_fv_nodesolve = 0.0;   // relaxNodeFluxes + solveAlgebraicNode
inline double sec_fv_positivity = 0.0;  // limitPositivity
inline double sec_fv_cellupdate = 0.0;  // updateCells (incl. depth inversion)
inline double sec_fv_nodeupdate = 0.0;  // updateNodes
inline double sec_fv_refreshdep = 0.0;  // refreshDepths (full-mesh inversion)
inline double sec_fv_savestate = 0.0;   // saveState (11-vector snapshot)
inline double sec_fv_restore = 0.0;     // restoreState (snapshot + refreshDepths)
inline double sec_fv_structref = 0.0;   // refreshStructFlows (solver side)
inline double sec_fv_bndcallback = 0.0; // Router::refreshFvBoundaryFlows (engine side)
inline double sec_fv_rebuild = 0.0;     // rebuildActiveLists (halo growth)
inline double sec_fv_reconstruct = 0.0; // reconstructState (MUSCL slopes)
inline double sec_fv_ltsfire = 0.0;     // fireFaces (LTS face pass)
inline double sec_fv_settle = 0.0;      // settleAccumulators
inline double sec_fv_tier = 0.0;        // assignTiers
 
// Each worker accumulates into a private CounterBatch. Only the completed
// batch is merged, once per worker/phase; no atomics on individual operations.
enum FvCounter : std::size_t {
    n_fv_substep,
    n_fv_census,
    n_fv_census_face,
    n_fv_invert,
    n_fv_savestate,
    n_fv_restore,
    n_fv_structref,
    n_fv_alg_visit,
    n_fv_alg_passthru,
    n_fv_alg_solve,
    n_fv_alg_resid,
    n_fv_alg_flux,
    n_fv_geom_area,
    n_fv_geom_width,
    n_fv_geom_i1,
    n_fv_geom_hydrad,
    n_fv_macro_cycles,
    n_fv_macro_rejected,
    n_fv_counter_count
};
using FvCounts = std::array<long, n_fv_counter_count>;
inline FvCounts fv_counts{};
inline thread_local FvCounts* local_fv_counts = nullptr;
inline std::mutex fv_counts_mutex;
 
// Read/reset only between worksharing regions. Like the existing phase
// timers, totals describe one profiled simulation at a time.
inline long value(FvCounter counter) noexcept {
    return fv_counts[counter];
}

inline void reset_fv() noexcept {
    sec_fv_census = sec_fv_flux = sec_fv_nodesolve = sec_fv_positivity = 0.0;
    sec_fv_cellupdate = sec_fv_nodeupdate = sec_fv_refreshdep = 0.0;
    sec_fv_savestate = sec_fv_restore = 0.0;
    sec_fv_structref = sec_fv_bndcallback = 0.0;
    sec_fv_rebuild = sec_fv_reconstruct = sec_fv_ltsfire = 0.0;
    sec_fv_settle = sec_fv_tier = 0.0;
    fv_counts.fill(0);
}

inline void dump_fv() noexcept {
    const double total = sec_fv_census + sec_fv_flux + sec_fv_nodesolve + sec_fv_positivity +
                         sec_fv_cellupdate + sec_fv_nodeupdate + sec_fv_refreshdep +
                         sec_fv_savestate + sec_fv_restore + sec_fv_structref + sec_fv_bndcallback +
                         sec_fv_rebuild + sec_fv_reconstruct + sec_fv_ltsfire + sec_fv_settle +
                         sec_fv_tier;
    std::fprintf(
        stderr,
        "[PERF-FV] step=%.4f total=%.4f "
        "census=%.4f flux=%.4f nodesolve=%.4f positivity=%.4f "
        "cellupdate=%.4f nodeupdate=%.4f refreshdepths=%.4f "
        "savestate=%.4f restore=%.4f structrefresh=%.4f bndcallback=%.4f "
        "rebuild=%.4f reconstruct=%.4f ltsfire=%.4f settle=%.4f tier=%.4f "
        "n.substep=%ld n.census=%ld n.censusface=%ld n.invert=%ld "
        "n.savestate=%ld n.rollback=%ld n.structrefresh=%ld "
        "n.algvisit=%ld n.algpassthru=%ld n.algsolve=%ld "
        "n.algresidual=%ld n.algfaceflux=%ld "
        "n.area=%ld n.width=%ld n.i1=%ld n.hydrad=%ld "
        "n.macro=%ld n.macrorej=%ld "
        "passthru_frac=%.4f rollback_frac=%.4f "
        "algresid_per_solve=%.2f algflux_per_solve=%.2f\n",
        sec_1d_step, total, sec_fv_census, sec_fv_flux, sec_fv_nodesolve, sec_fv_positivity,
        sec_fv_cellupdate, sec_fv_nodeupdate, sec_fv_refreshdep, sec_fv_savestate, sec_fv_restore,
        sec_fv_structref, sec_fv_bndcallback, sec_fv_rebuild, sec_fv_reconstruct, sec_fv_ltsfire,
        sec_fv_settle, sec_fv_tier, value(n_fv_substep), value(n_fv_census),
        value(n_fv_census_face), value(n_fv_invert), value(n_fv_savestate), value(n_fv_restore),
        value(n_fv_structref), value(n_fv_alg_visit), value(n_fv_alg_passthru),
        value(n_fv_alg_solve), value(n_fv_alg_resid), value(n_fv_alg_flux), value(n_fv_geom_area),
        value(n_fv_geom_width), value(n_fv_geom_i1), value(n_fv_geom_hydrad),
        value(n_fv_macro_cycles), value(n_fv_macro_rejected),
        (value(n_fv_alg_visit) > 0) ? static_cast<double>(value(n_fv_alg_passthru)) /
                                          static_cast<double>(value(n_fv_alg_visit))
                                    : 0.0,
        (value(n_fv_savestate) > 0)
            ? static_cast<double>(value(n_fv_restore)) / static_cast<double>(value(n_fv_savestate))
            : 0.0,
        (value(n_fv_alg_solve) > 0) ? static_cast<double>(value(n_fv_alg_resid)) /
                                          static_cast<double>(value(n_fv_alg_solve))
                                    : 0.0,
        (value(n_fv_alg_solve) > 0)
            ? static_cast<double>(value(n_fv_alg_flux)) / static_cast<double>(value(n_fv_alg_solve))
            : 0.0);
}

inline std::chrono::steady_clock::time_point now() noexcept {
    return std::chrono::steady_clock::now();
}

inline double since(std::chrono::steady_clock::time_point t0) noexcept {
    return std::chrono::duration<double>(now() - t0).count();
}

inline bool enabled() noexcept {
    static const bool on = (std::getenv("OPENSWMM_PERF") != nullptr);
    return on;
}

inline void reset_load() noexcept {
    sec_open_prescan2d = sec_open_read = sec_open_resolve = sec_open_validate = 0.0;
    sec_read_dispatch = 0.0;
    sec_res_extfiles = sec_res_tables = sec_res_transects = 0.0;
    sec_res_xsect = sec_res_shrink = 0.0;
    sec_init_state = sec_init_hydraulics = sec_init_hydrology = 0.0;
    sec_init_quality = sec_init_geometry = 0.0;
    sec_start_iface = sec_start_plugins = 0.0;
}

inline void dump_load() noexcept {
    const double open_total =
        sec_open_prescan2d + sec_open_read + sec_open_resolve + sec_open_validate;
    const double init_total = sec_init_state + sec_init_hydraulics + sec_init_hydrology +
                              sec_init_quality + sec_init_geometry;
    const double start_total = sec_start_iface + sec_start_plugins;
    std::fprintf(stderr,
                 "[PERF-LOAD] open=%.4f open.prescan2d=%.4f open.read=%.4f "
                 "read.scan=%.4f read.dispatch=%.4f "
                 "open.resolve=%.4f open.validate=%.4f "
                 "res.extfiles=%.4f res.tables=%.4f res.transects=%.4f res.xsect=%.4f "
                 "res.shrink=%.4f "
                 "init=%.4f init.state=%.4f init.hydraulics=%.4f init.hydrology=%.4f "
                 "init.quality=%.4f init.geometry=%.4f "
                 "start=%.4f start.iface=%.4f start.plugins=%.4f\n",
                 open_total, sec_open_prescan2d, sec_open_read, sec_open_read - sec_read_dispatch,
                 sec_read_dispatch, sec_open_resolve, sec_open_validate, sec_res_extfiles,
                 sec_res_tables, sec_res_transects, sec_res_xsect, sec_res_shrink, init_total,
                 sec_init_state, sec_init_hydraulics, sec_init_hydrology, sec_init_quality,
                 sec_init_geometry, start_total, sec_start_iface, sec_start_plugins);
}
 
// Adds the elapsed wall time between construction and destruction to `acc`.
struct ScopedTimer {
    double* acc;
    std::chrono::steady_clock::time_point t0;
    explicit ScopedTimer(double& a) noexcept : acc(&a), t0(std::chrono::steady_clock::now()) {}
    ~ScopedTimer() noexcept {
        *acc += std::chrono::duration<double>(std::chrono::steady_clock::now() - t0).count();
    }

    ScopedTimer(const ScopedTimer&) = delete;
    ScopedTimer& operator=(const ScopedTimer&) = delete;
};

inline thread_local double nested_wall = 0.0;
 
struct GatedTimer {
    double* acc = nullptr;
    double outer = 0.0; 
    std::chrono::steady_clock::time_point t0;
    explicit GatedTimer(double& a) noexcept {
        if (enabled()) {
            acc = &a;
            outer = nested_wall; // stash whatever our parent has collected
            nested_wall = 0.0;   // ...and start a fresh tally for our own
            t0 = std::chrono::steady_clock::now();
        }
    }

    ~GatedTimer() noexcept {
        if (!acc)
            return;
        const double wall =
            std::chrono::duration<double>(std::chrono::steady_clock::now() - t0).count();
        // Ours is what the clock says minus what our children already claimed.
        *acc += wall - nested_wall;
        // Our FULL wall time is our parent's child time — the parent must not
        // be charged for us twice, once through its own clock and once here.
        nested_wall = outer + wall;
    }

    GatedTimer(const GatedTimer&) = delete;
    GatedTimer& operator=(const GatedTimer&) = delete;
};

class CounterBatch {
    FvCounts local_;
    FvCounts* previous_ = nullptr;
    bool active_;
 
public:
    CounterBatch() noexcept : active_(enabled()) {
        if (!active_)
            return;
        local_.fill(0);
        previous_ = local_fv_counts;
        local_fv_counts = &local_;
    }

    ~CounterBatch() noexcept {
        if (!active_)
            return;
        local_fv_counts = previous_;
        if (previous_) {
            for (std::size_t i = 0; i < local_.size(); ++i)
                (*previous_)[i] += local_[i];
        } else {
            const std::lock_guard<std::mutex> lock(fv_counts_mutex);
            for (std::size_t i = 0; i < local_.size(); ++i)
                fv_counts[i] += local_[i];
        }
    }

    CounterBatch(const CounterBatch&) = delete;
    CounterBatch& operator=(const CounterBatch&) = delete;
};

inline void count(FvCounter counter, long n = 1) noexcept {
    if (!enabled())
        return;
    if (local_fv_counts)
        (*local_fv_counts)[counter] += n;
    else
        fv_counts[counter] += n;
}
 
} // namespace openswmm::perf