diff --git a/crates/sds-bot/src/unit.rs b/crates/sds-bot/src/unit.rs index 6ae5f51..bfb28ab 100644 --- a/crates/sds-bot/src/unit.rs +++ b/crates/sds-bot/src/unit.rs @@ -548,7 +548,7 @@ pub fn propose_including( let us = |nanos: u64| nanos / 1_000; eprintln!( "[sds-bot] unit {} timing: paths {}us, envelopes {}us, \ - sweep {}us (volleys {}us), rank {}us, surface {}us", + sweep {}us (volleys ~{}us), rank {}us, surface {}us", me.id, us(cost.paths_nanos), us(cost.envelopes_nanos), @@ -585,10 +585,12 @@ pub fn propose_including( cost.volley_misses ); eprintln!( - "[sds-bot] unit {} volley split: gather {}us, memo lookup {}us", + "[sds-bot] unit {} volley split: gather ~{}us, memo lookup ~{}us \ + (sampled 1 call in {})", me.id, cost.gather_nanos / 1_000, - cost.lookup_nanos / 1_000 + cost.lookup_nanos / 1_000, + sds_core::volley::TIMING_STRIDE ); // The sweep is the menu. It replaces the hold rather than joining // it, so the force chooses among reachable states or nothing. diff --git a/crates/sds-core/src/stands.rs b/crates/sds-core/src/stands.rs index 56b554c..02adb8c 100644 --- a/crates/sds-core/src/stands.rs +++ b/crates/sds-core/src/stands.rs @@ -1202,7 +1202,12 @@ pub fn score_stands( // Outgoing. The key carries the arc the damage lands in, and // the error carries which prune stopped it. let their_state = foe.who.target(there); - let clock = std::time::Instant::now(); + // Sampled on the same fixed stride as the volley cache's own + // timings, and for the same reason: two clock reads an exchange + // over millions of exchanges is instrumentation you can see in + // the number it produces. See `volley::VolleyStats`. + let clock = + (stats.exchanges % volley::TIMING_STRIDE == 0).then(std::time::Instant::now); let (key, mine) = best_volley_keyed(cache, los, &our_firer, &their_state, &us.who.weapons); let deal = half(&key, &mine, || { @@ -1216,7 +1221,9 @@ pub fn score_stands( let their_firer = foe.who.firer(there); let (key, theirs) = best_volley_keyed(cache, los, &their_firer, &our_target, &foe.who.weapons); - stats.volley_nanos += clock.elapsed().as_nanos() as u64; + if let Some(clock) = clock { + stats.volley_nanos += clock.elapsed().as_nanos() as u64 * volley::TIMING_STRIDE; + } let take = half(&key, &theirs, || { any_bears(&their_firer, our_target.hex, &foe.who.weapons) }); diff --git a/crates/sds-core/src/volley.rs b/crates/sds-core/src/volley.rs index 7a06e51..ed94bba 100644 --- a/crates/sds-core/src/volley.rs +++ b/crates/sds-core/src/volley.rs @@ -610,10 +610,21 @@ pub struct VolleyStats { /// cache is consulted - it is what *builds* the key - so a hit pays for it /// in full. These two numbers are how you tell a memo that is not helping /// from a memo that is helping and being outweighed by the cost of asking. + /// + /// **Both are estimates, sampled one call in [`TIMING_STRIDE`].** Timing + /// every call meant four clock reads per `best_volley_keyed` and two calls + /// per exchange, against a measured 2.4 million exchanges in one unit's + /// decision - the instrumentation was a measurable share of what it was + /// measuring. The stride is fixed rather than random, so the same run + /// samples the same calls and nothing here can reach a result. pub gather_nanos: u64, pub lookup_nanos: u64, } +/// One call in this many is timed; the reading is scaled back up. See +/// [`VolleyStats::gather_nanos`]. +pub const TIMING_STRIDE: u64 = 64; + /// Memoised volley estimates, and the damage cache underneath them. /// /// `BTreeMap`, so nothing about iteration order can reach a result. Scope one to @@ -966,18 +977,24 @@ pub fn best_volley_keyed( weapons: &[MountedWeapon], ) -> (Result, VolleyOutcome) { cache.stats.asked += 1; - let gather_clock = std::time::Instant::now(); + // Sampled, and on a fixed stride: see `VolleyStats::gather_nanos`. + let timed = cache.stats.asked.is_multiple_of(TIMING_STRIDE); + let gather_clock = timed.then(std::time::Instant::now); let gathered = gather(los_cache, state, target, weapons); - cache.stats.gather_nanos += gather_clock.elapsed().as_nanos() as u64; + if let Some(clock) = gather_clock { + cache.stats.gather_nanos += clock.elapsed().as_nanos() as u64 * TIMING_STRIDE; + } match gathered { Ok(gathered) => { // The memo answers the damage half. Heat is attached after it, from // our own equipment list, for whichever twist `solve` named - so a // cache hit against a volley armed differently still reports our // heat and not theirs. - let lookup_clock = std::time::Instant::now(); + let lookup_clock = timed.then(std::time::Instant::now); let mut outcome = cache.outcome(&gathered.key); - cache.stats.lookup_nanos += lookup_clock.elapsed().as_nanos() as u64; + if let Some(clock) = lookup_clock { + cache.stats.lookup_nanos += clock.elapsed().as_nanos() as u64 * TIMING_STRIDE; + } outcome.heat = gathered.heat_at(outcome.twist); (Ok(gathered.key), outcome) }