OXYGENHUB

A job's finish report says where its time went: image, prepare, run, finish (refs #35) 1215f05ff8d0

Author
Andy McCall @andymccall <[email protected]>
via
agent agent:claude@andymccall <[email protected]> · keyless, under your grant for changes,refs,seal · key 004ce6189dae
When
· 2026-10-27 03:09 UTC
Signature
◈ sealed by agent:claude@andymccall
Hash
1215f05ff8d00714f50b88d5038397d318d459ae691ad0c95baa3297dc5e5b68
Depends on
069e16fba3bd 280ef951d193 28cc603f737d 3007d8f011fa 47c1d64dec8a 4be5e4cd0af6 4cf0c99a1486 8f211e20bea5 b14aeaae683a c3db750ed96e d60aac6c3f8a e0918b887850 ea56c56eaf90 ed4aef8b70ca
Depended on by
1a50d4dae89c 9296a15494d3
In bookmarks
main
In tags
v0.5.0 v0.5.1 v0.5.2 v0.5.3
Edits
22 atoms, 0 tree operations, 4 files

Browse the tree at this change

modified CHANGELOG.md +1 −0
…
3 unchanged lines
4 4
5 5
## Unreleased
6 6
7 +
- **A job's report says where its time went (#35).** The finish report carries `phases` in milliseconds: `image` (fetching its image, when the runner lacked it), `prepare` (its workspace and disks), `run` (the sandbox from start to stop) and `finish` (outputs, caches and receipt), so a slow job shows whether it waited on an image, a fetch or itself.
7 8
- **The swarm reads images in order (#97).** A fetcher took equally rare chunks at random, so a peer read its whole image in random order, a seek per chunk on a spinning disk: plex-1 got 2.3 GiB from earth-1 at about 2 MB/s. Neighbouring chunks now come in runs, shuffled so runners starting together still spread, and the picker no longer rescans what it has: picking a 142,244-chunk image went from 19 s to 0.35 s.
8 9
- **The swarm moves an image nobody pushed (#94).** A runner that serves its peers tells the hub, at start and every ten minutes, which images it holds, and sends the manifest of each the hub keeps none of: the manifest alone, not the image. With a hub that keeps such manifests (oxygenhub#342), runners in the same site fetch the image from it. A fetch told the hub holds no chunks asks peers alone, and fails plainly when none can serve it. Design: docs/jetstream.md §8.1.1.
9 10
- **A WASM job stopped while its module compiles stops (#93).** The time limit or a cancel moved the engine's epoch once; a store made after that set its deadline past it, so the job ran on forever (seen as a test spinning 35 minutes under load). Once stopped, the epoch now moves every tick until the job ends.
…
113 unchanged lines
modified crates/flow-core/src/api.rs +6 −0
…
459 unchanged lines
460 460
    pub peak_disk_mib: Option<u64>,
461 461
    #[serde(default, skip_serializing_if = "Option::is_none")]
462 462
    pub peak_memory_mib: Option<u64>,
463 +
    /// Where the job's time went, in milliseconds (oxygenflow#35): `image`
464 +
    /// (fetching its image, when the runner lacked it), `prepare` (its
465 +
    /// workspace and disks), `run` (the sandbox, from start to stop) and
466 +
    /// `finish` (its outputs, caches and receipt).
467 +
    #[serde(default, skip_serializing_if = "std::collections::BTreeMap::is_empty")]
468 +
    pub phases: std::collections::BTreeMap<String, u64>,
463 469
}
464 470
465 471
/// Longest text of one record the hub keeps; longer lines are cut.
…
3 unchanged lines
modified crates/flow-core/src/tests.rs +12 −0
…
756 unchanged lines
757 757
        "schema-version 1\nsandbox \"w\" {\n  runtime \"wasm\"\n  network \"loopback\"\n}\njob \"t\" { sandbox \"w\"; exec \"a.wasm\"; }\n";
758 758
    assert!(problems(networked).iter().any(|(_, m)| m.contains("has no network")));
759 759
}
760 +
761 +
#[test]
762 +
fn a_finish_says_where_its_time_went_and_an_older_one_still_reads() {
763 +
    let old = r#"{"exit_code":0,"duration_ms":5,"receipt":null,"error":null}"#;
764 +
    let mut f: crate::api::Finish = serde_json::from_str(old).unwrap();
765 +
    assert!(f.phases.is_empty());
766 +
    assert!(!serde_json::to_string(&f).unwrap().contains("phases"), "absent when there are none");
767 +
    f.phases.insert("prepare".into(), 1200);
768 +
    f.phases.insert("run".into(), 3400);
769 +
    let back: crate::api::Finish = serde_json::from_str(&serde_json::to_string(&f).unwrap()).unwrap();
770 +
    assert_eq!(back.phases["run"], 3400);
771 +
}
modified crates/flow/src/runner.rs +33 −8
…
46 unchanged lines
47 47
        error: Some(CANCELLED.into()),
48 48
        peak_disk_mib: None,
49 49
        peak_memory_mib: None,
50 +
        phases: Default::default(),
50 51
    }
51 52
}
52 53
…
502 unchanged lines
555 556
/// Fetch `claim`'s image from the hub when this home lacks it
556 557
/// (oxygenflow#39), saying so in the job's log. A hub that does not hold it
557 558
/// leaves it missing, and the preflight declines the job as before.
558 -
fn fetch_image(home: &Home, hub: &Hub, cfg: &RunnerConfig, swarm: Option<&crate::swarm::Swarm>, claim: &Claim) {
559 +
fn fetch_image(home: &Home, hub: &Hub, cfg: &RunnerConfig, swarm: Option<&crate::swarm::Swarm>, claim: &Claim) -> Option<u64> {
559 560
    let hash = &claim.sandbox.rootfs;
560 561
    if hash.is_empty() || home.rootfs(hash).is_file() || !jet::images::is_hash(hash) {
561 -
        return;
562 +
        return None;
562 563
    }
563 564
    let note = |text: String| {
564 565
        eprintln!("job {}: {text}", claim.job_id);
…
3 unchanged lines
568 569
    static FETCHING: std::sync::Mutex<()> = std::sync::Mutex::new(());
569 570
    let _one = FETCHING.lock().unwrap_or_else(|p| p.into_inner());
570 571
    if home.rootfs(hash).is_file() {
571 -
        return;
572 +
        return None;
572 573
    }
573 574
    let client = match crate::images::Client::new(&cfg.hub, &cfg.token, cfg.ca.as_deref()) {
574 575
        Ok(c) => c,
575 -
        Err(e) => return note(format!("image {}: cannot reach the hub: {e:#}", &hash[..12])),
576 +
        Err(e) => {
577 +
            note(format!("image {}: cannot reach the hub: {e:#}", &hash[..12]));
578 +
            return None;
579 +
        }
576 580
    };
581 +
    let fetching = Instant::now();
577 582
    let fetched = match swarm {
578 583
        Some(sw) => {
579 584
            note(format!("image {} is not on this runner: fetching it from its peers and the hub", &hash[..12]));
…
4 unchanged lines
584 589
            client.fetch(home, hash)
585 590
        }
586 591
    };
592 +
    let took = fetching.elapsed().as_millis() as u64;
587 593
    match fetched {
588 594
        Ok(Some(m)) => note(format!(
589 595
            "image {}: fetched {} chunks, {}{} in {:.1} s",
…
6 unchanged lines
596 602
        Ok(None) => note(format!("image {}: the hub does not hold it either", &hash[..12])),
597 603
        Err(e) => note(format!("image {}: fetch failed: {e:#}", &hash[..12])),
598 604
    }
605 +
    Some(took)
599 606
}
600 607
601 608
/// Why this runner cannot run `claim` now (spec §11.5), checked before
…
340 unchanged lines
942 949
                    let (home, hub, cfg, used, key, held, swarm) = (home, &hub, &cfg, &used, &key, &held, swarm.as_ref());
943 950
                    scope.spawn(move || {
944 951
                        let id = claim.job_id;
945 -
                        fetch_image(home, hub, cfg, swarm, &claim);
952 +
                        let image_ms = fetch_image(home, hub, cfg, swarm, &claim);
946 953
                        if let Some(why) = preflight(home, &claim) {
947 954
                            eprintln!("job {id}: declined: {why}");
948 955
                            crate::metrics::DECLINED.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
…
14 unchanged lines
963 970
                            claim.heads.first().map(|h| &h[..12]).unwrap_or("-")
964 971
                        );
965 972
                        crate::metrics::RUNNING.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
966 -
                        let finish = run_claim(home, hub, cfg, key, &claim).unwrap_or_else(|e| Finish {
973 +
                        let finish = run_claim(home, hub, cfg, key, &claim, image_ms).unwrap_or_else(|e| Finish {
967 974
                            exit_code: None,
968 975
                            duration_ms: 0,
969 976
                            receipt: None,
…
1 unchanged lines
971 978
                            error: Some(format!("{e:#}")),
972 979
                            peak_disk_mib: None,
973 980
                            peak_memory_mib: None,
981 +
                            phases: Default::default(),
974 982
                        });
975 983
                        eprintln!(
976 984
                            "job {id}: exit {:?}{}",
…
280 unchanged lines
1257 1265
    format!("{:.1} s", d.as_secs_f64())
1258 1266
}
1259 1267
1260 -
fn run_claim(home: &Home, hub: &Hub, cfg: &RunnerConfig, key: &RunnerKey, claim: &Claim) -> Result<Finish> {
1268 +
/// `image_ms`: how long fetching its image took, when the runner lacked it.
1269 +
fn run_claim(home: &Home, hub: &Hub, cfg: &RunnerConfig, key: &RunnerKey, claim: &Claim, image_ms: Option<u64>) -> Result<Finish> {
1261 1270
    let started = Instant::now();
1262 1271
    let mut sink = LogSink {
1263 1272
        hub,
…
173 unchanged lines
1437 1446
            );
1438 1447
        }
1439 1448
        let timeout = Duration::from_secs(claim.timeout_s);
1449 +
        // Where the time goes (oxygenflow#35): what came before the
1450 +
        // sandbox, the sandbox, and what comes after.
1451 +
        let prepare_ms = started.elapsed().as_millis() as u64;
1452 +
        let sandbox_started = Instant::now();
1440 1453
        let mut outcome = if wasm_tier {
1441 1454
            crate::wasm::run(&claim.sandbox, &job, &scratch.join("tree"), &scratch, timeout, &mut sink)?
1442 1455
        } else if syscall_tier {
…
2 unchanged lines
1445 1458
        } else {
1446 1459
            microvm::run(home, &claim.sandbox, &job, &claim.secrets, &scratch.join("workspace.ext4"), &scratch, timeout, &mut sink)?
1447 1460
        };
1461 +
        let run_ms = sandbox_started.elapsed().as_millis() as u64;
1448 1462
        if outcome.cancelled {
1449 1463
            // Handed back as the runner leaves: its checkpoints first, for
1450 1464
            // the next attempt (oxygenflow#77).
…
117 unchanged lines
1568 1582
                Ok(None) => {}
1569 1583
                Err(e) => note(&mut sink, format!("cache: not {}: {e:#}", if kept { "kept" } else { "discarded" })),
1570 1584
            }
1585 +
        }
1586 +
        let total_ms = started.elapsed().as_millis() as u64;
1587 +
        let mut phases: std::collections::BTreeMap<String, u64> =
1588 +
            [("prepare", prepare_ms), ("run", run_ms), ("finish", total_ms.saturating_sub(prepare_ms + run_ms))]
1589 +
                .into_iter()
1590 +
                .map(|(k, v)| (k.to_string(), v))
1591 +
                .collect();
1592 +
        if let Some(ms) = image_ms {
1593 +
            phases.insert("image".into(), ms);
1571 1594
        }
1572 1595
        Ok(Finish {
1596 +
            phases,
1573 1597
            exit_code: outcome.exit_code,
1574 -
            duration_ms: started.elapsed().as_millis() as u64,
1598 +
            duration_ms: total_ms,
1575 1599
            receipt,
1576 1600
            signed_receipt,
1577 1601
            error: output_error.or_else(|| outcome.timed_out.then(|| "stopped at the time limit".to_string())),
…
482 unchanged lines
2060 2084
            error: None,
2061 2085
            peak_disk_mib: None,
2062 2086
            peak_memory_mib: None,
2087 +
            phases: Default::default(),
2063 2088
        };
2064 2089
        let quick = Duration::from_millis(10);
2065 2090
        let (base, seen) = fake_hub(vec![502, 503, 500, 500, 204]);
…
236 unchanged lines