runner: task: print detailed CPU usage for finished tasks

2 files changed, 26 insertions, 7 deletions

diff --git a/crates/runner/Cargo.toml b/crates/runner/Cargo.toml
index ed2716b..0108e4b 100644
--- a/crates/runner/Cargo.toml
+++ b/crates/runner/Cargo.toml
@@ -15,7 +15,7 @@ blake3 = { version = "1.3.0", features = ["traits-preview"] }
 capctl = "0.2.0"
 digest = "0.10.1"
 libc = "0.2.84"
-nix = { version = "0.28.0", features = ["user", "fs", "process", "mount", "sched", "poll", "signal", "hostname"] }
+nix = { version = "0.28.0", features = ["user", "fs", "process", "mount", "sched", "poll", "signal", "hostname", "resource"] }
 olpc-cjson = "0.1.0"
 serde = { version = "1", features = ["derive"] }
 serde_json = "1.0.62"
diff --git a/crates/runner/src/task.rs b/crates/runner/src/task.rs
index 7bf1fda..5c27e78 100644
--- a/crates/runner/src/task.rs
+++ b/crates/runner/src/task.rs
@@ -11,7 +11,7 @@ use capctl::prctl;
 use nix::{
 	mount::{self, MsFlags},
 	sched::{unshare, CloneFlags},
-	sys::wait,
+	sys::{resource, time::TimeVal, wait},
 	unistd::{self, Gid, Uid},
 };
 use serde::Serialize;
@@ -568,6 +568,26 @@ fn save_cached(input_hash: &InputHash, output: &TaskOutput) -> Result<()> {
 	Ok(())
 }
 
+trait AsSecsF32 {
+	fn as_secs_f32(&self) -> f32;
+}
+
+impl AsSecsF32 for TimeVal {
+	fn as_secs_f32(&self) -> f32 {
+		self.tv_sec() as f32 + 1e-6 * (self.tv_usec() as f32)
+	}
+}
+
+fn get_usage(total: f32) -> String {
+	let usage = resource::getrusage(resource::UsageWho::RUSAGE_CHILDREN).expect("getrusage()");
+
+	let user = usage.user_time().as_secs_f32();
+	let system = usage.system_time().as_secs_f32();
+	let cpu = (100.0 * (user + system) / total).round();
+
+	format!("{user:.2}s user {system:.2}s system {cpu:.0}% cpu")
+}
+
 pub fn handle(task: Task, jobserver: &mut Jobserver) -> Result<TaskOutput> {
 	let input_hash = input_hash(&task);
 
@@ -596,12 +616,11 @@ pub fn handle(task: Task, jobserver: &mut Jobserver) -> Result<TaskOutput> {
 
 	save_cached(&input_hash, &task_output)?;
 
-	let duration = Instant::now().duration_since(start_time);
+	let duration = Instant::now().duration_since(start_time).as_secs_f32();
+	let usage = get_usage(duration);
 	println!(
-		"Finished task {} ({}) in {}",
-		task.label,
-		input_hash,
-		duration.as_secs_f32()
+		"Finished task {} ({}) in {:.2}s ({})",
+		task.label, input_hash, duration, usage,
 	);
 
 	if let Ok(cached_output) = cached_output {