Log every second a reducer takes to run

[coolreader18]

Description of Changes

• Change ReducerBudget::DEFAULT_BUDGET to 1.3 trillion
• Log a warning for every minute a reducer runs

Expected complexity level and risk

1

Testing

• Need to write a test for this, somehow.

[coolreader18]

Manual test results (with a reducer with an infinite loop{})

2025-05-29T18:05:14.582796Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 996.146446ms reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:05:15.582383Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 1.995762256s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:05:16.582689Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 2.996070384s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:05:17.583015Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 3.996397277s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:05:18.582840Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 4.996214695s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:05:19.583166Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 5.996547219s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
<!-- snip snip snip snip snip snip snip snip snip -->
2025-05-29T18:06:13.582806Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 59.996185127s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:14.582634Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 60.996015179s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:15.582967Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 61.99635198s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:16.582883Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 62.996251973s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:17.583026Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 63.996398338s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:18.583069Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 64.996447931s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:19.582833Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 65.996192172s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:20.582719Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 66.996096583s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:21.582440Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 67.995824233s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:22.582588Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 68.995968243s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:23.582394Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 69.995783267s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:24.583094Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 70.99649416s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:25.583337Z  WARN crates/core/src/host/wasmtime/wasmtime_module.rs:107: Wasm has been running for 71.996716928s reducer="add" database=Identity(c20030d374920af4c93f472d3d43477f77223b8ff9539390ec2b3fae7048ccc2)
2025-05-29T18:06:25.751589Z DEBUG crates/core/src/host/wasm_common/module_host_actor.rs:428: Long running reducer finished executing reducer_name="add" timings.total_duration=72.164940413s
2025-05-29T18:06:25.751676Z  INFO crates/core/src/host/wasmtime/wasmtime_module.rs:14: reducer "add" runtime error: error while executing at wasm backtrace:
    0:  0xd84 - spacetime_module.wasm!spacetime_module::add::invoke::hfdeb4eea9c7aa3fd
    1: 0x7dc1 - spacetime_module.wasm!__call_reducer__    
2025-05-29T18:06:25.751842Z  INFO crates/core/src/host/wasmtime/wasmtime_module.rs:18:   Frame #2: spacetime_module::add::invoke::hfdeb4eea9c7aa3fd    
2025-05-29T18:06:25.751854Z  INFO crates/core/src/host/wasmtime/wasmtime_module.rs:18:   Frame #1: __call_reducer__    
2025-05-29T18:06:25.756010Z  WARN crates/client-api/src/routes/database.rs:167: Node's energy budget exceeded for identity: c2002b069d4e0851195ad298c8a707b6b397d2c9369441d3437c7ca62db64381 while executing add    

[coolreader18]

Thinking about it, it's possible this could affect performance, given that we're introducing additional instrumentation to the code. It's probably very minimal especially compared to fuel metering, but something to keep in mind if wasm execution performance ever becomes an optimization target.