feat: request_perf() worker-side timing hostcall; restore demo System Info

Units run in the wasm sandbox, so my_pid/parent_pid/context.server->request_count
read as sandbox stubs — the demo System Info counters were broken, and there was
no authoritative server-side request timing available to unit code (client-side
measurement cannot see queue/dispatch latency).

Add a request_perf() unit API backed by a new uce_host_request_perf hostcall.
The native worker answers it live, returning a DValue:
  worker_pid, parent_pid, request_count,
  accept_us  = (time_start - time_init)*1e6   (entry -> dispatch wait),
  running_us = (now - time_start)*1e6         (since dispatch, live),
  total_us   = (now - time_init)*1e6          (since the request entered UCE),
  workspace_birth_us.
time_init is captured at request entry (handle_request, with a handle_complete
fallback); a RequestPerfSnapshot {pids, request_count, time_init, time_start} is
threaded from wasm_backend_serve through wasm_worker_serve onto the workspace,
and the hostcall computes the live deltas at call time. Wired like uce_host_units
(sized DValue hostcall): core_hostcalls.syms + sys.cpp/sys.h request_perf().

site/demo/index.uce System Info now uses request_perf() and shows the real worker
PID, an incrementing per-worker request count, and the timing counters.

Implemented via the pi agent (gpt-5.3-codex-spark); a review of the live numbers
caught accept_us mistakenly computed as (now - time_init) (== total_us), fixed to
the dispatch wait (time_start - time_init). Independently verified on the host:
System Info shows non-zero PIDs, incrementing count, accept_us ~50us << total_us
~2.4ms with accept+running==total; run_cli_tests --include-wasm-kill => 87 passed,
0 failed, 0 skipped.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This commit is contained in:
root 2026-06-15 08:18:04 +00:00
parent 83ab9e10f7
commit 4f84ac544d
7 changed files with 94 additions and 15 deletions

View File

@ -84,10 +84,16 @@ RENDER(Request& context)
<div class="system-info">
<h3>System Info</h3>
<pre><?
print("Worker PID: ", my_pid, "\n");
print("Parent PID: ", parent_pid, "\n");
DValue perf = request_perf();
print("Worker PID: ", (u64)perf["worker_pid"].to_u64(), "\n");
print("Parent PID: ", (u64)perf["parent_pid"].to_u64(), "\n");
print("Request #: ", (u64)perf["request_count"].to_u64(), "\n");
print("Accept us: ", (f64)perf["accept_us"].to_f64(), "\n");
print("Running us: ", (f64)perf["running_us"].to_f64(), "\n");
print("Total us: ", (f64)perf["total_us"].to_f64(), "\n");
if(perf["workspace_birth_us"].type != 'S')
print("Workspace birth us: ", (u64)perf["workspace_birth_us"].to_u64(), "\n");
print("Output buffer size: ", context.ob->str().length(), "\n");
print("Request #", context.server->request_count, "\n");
?></pre>
</div>
<? } ?>

View File

@ -33,6 +33,7 @@ int uce_host_server_start_http(const char* key, size_t key_len, const char* bind
int uce_host_server_stop(const char* key, size_t key_len);
size_t uce_host_memcache_command(uint64_t sockfd, const char* command, size_t command_len, char* buf, size_t cap);
size_t uce_host_mysql(const char* in, size_t in_len, char* out, size_t cap);
size_t uce_host_request_perf(const char* in, size_t in_len, char* out, size_t cap);
}
static String wasm_current_unit_file()
@ -117,6 +118,22 @@ bool config_map_bool(StringMap& cfg, String key, bool fallback) { return(config_
u64 config_u64(String key, u64 fallback) { return(context ? config_map_u64(context->server->config, key, fallback) : fallback); }
f64 config_f64(String key, f64 fallback) { return(context ? config_map_f64(context->server->config, key, fallback) : fallback); }
bool config_bool(String key, bool fallback) { return(context ? config_map_bool(context->server->config, key, fallback) : fallback); }
DValue request_perf()
{
size_t required = uce_host_request_perf("", 0, 0, 0);
if(required == 0)
return(DValue());
String encoded_response(required, 0);
size_t got = uce_host_request_perf("", 0, &encoded_response[0], required);
if(got == 0 || got > required)
return(DValue());
DValue response;
String decode_error;
if(ucb_decode(encoded_response, response, &decode_error))
return(response);
return(DValue());
}
f64 time_precise() { return(uce_host_time_precise()); }
u64 time() { return(uce_host_time()); }
// The native build shells out to `date`; the wasm core has no shell, so it

View File

@ -67,6 +67,11 @@ bool config_bool(String key, bool fallback = true);
f64 time_precise();
u64 time();
String time_format_local(String format = "", u64 timestamp = 0);
// Runtime timing/profiling snapshot for the active wasm request/workspace.
struct DValue;
DValue request_perf();
String time_format_utc(String format = "", u64 timestamp = 0);
String time_format_relative(u64 timestamp, String format_very_recent = "", u64 medium_recency_seconds = 0, String format_medium_recent = "", u64 not_recent_seconds = 0, String format_not_recent = "");
u64 time_parse(String time_String);

View File

@ -459,13 +459,15 @@ int handle_cli_complete(FastCGIRequest& request)
}
int handle_request(FastCGIRequest& request) {
// This is always the first event to occur. It occurs when the
// server receives all parameters. There may be more data coming on the
// standard input stream.
if (request.params.count("REQUEST_URI"))
return 0; // OK, continue processing
else
return 1; // stop processing and return error code
// This is always the first event to occur. It occurs when the
// server receives all parameters. There may be more data coming on the
// standard input stream.
if(request.stats.time_init == 0)
request.stats.time_init = time_precise();
if(request.params.count("REQUEST_URI"))
return(0); // OK, continue processing
else
return(1); // stop processing and return error code
}
int handle_data(FastCGIRequest& request) {
@ -478,6 +480,8 @@ int handle_complete(FastCGIRequest& request) {
Request* previous_context = set_active_request(request);
server_state.request_count += 1;
request.server = &server_state;
if(request.stats.time_init == 0)
request.stats.time_init = time_precise();
request.stats.time_start = time_precise();
//request.stats.mem_alloc = 0;
//request.stats.mem_high = 0;

View File

@ -147,7 +147,7 @@ String wasm_backend_serve(Request& request, const String& entry_unit, const Stri
ctx["ws"]["connection_state"] = request.connection;
}
WasmResponse response = wasm_worker_serve(*g_wasm_worker, ctx, entry_unit, handler);
WasmResponse response = wasm_worker_serve(*g_wasm_worker, ctx, entry_unit, handler, &request);
if(!response.ok)
return(response.error == "" ? String("wasm workspace failed") : response.error);

View File

@ -18,6 +18,7 @@ uce_host_mysql
uce_host_zip
uce_host_units
uce_host_component_resolve
uce_host_request_perf
uce_host_file_exists
uce_host_file_read
uce_host_file_write

View File

@ -404,10 +404,30 @@ public:
u64 component_resolve_count = 0;
u64 component_resolve_total_us = 0;
struct RequestPerfSnapshot
{
u64 worker_pid = 0;
u64 parent_pid = 0;
u64 request_count = 0;
f64 time_init = 0;
f64 time_start = 0;
bool active = false;
} request_perf;
explicit WasmWorkspace(WasmWorker& w) : worker(w), store(w.engine)
{
}
void set_perf_snapshot(u64 worker_pid, u64 parent_pid, u64 request_count, f64 time_init, f64 time_start)
{
request_perf.worker_pid = worker_pid;
request_perf.parent_pid = parent_pid;
request_perf.request_count = request_count;
request_perf.time_init = time_init;
request_perf.time_start = time_start;
request_perf.active = true;
}
#ifdef UCE_WASM_HOST_CONNECTORS
// Host-owned resource handle table (§3.1): connections opened by the guest
// live here and are closed when the workspace drops at request end.
@ -1221,9 +1241,33 @@ private:
}));
if(mod == "env" && name == "uce_host_time_precise")
return(add([](Caller, Span<const Val>, Span<Val> results) -> Result<std::monostate, Trap> {
struct timeval tv;
gettimeofday(&tv, 0);
results[0] = Val((double)tv.tv_sec + (double)tv.tv_usec / 1e6);
results[0] = Val(time_precise());
return(std::monostate());
}));
if(mod == "env" && name == "uce_host_request_perf")
return(add([self](Caller, Span<const Val> args, Span<Val> results) -> Result<std::monostate, Trap> {
DValue response;
if(self->request_perf.active)
{
f64 now = time_precise();
response["worker_pid"] = (f64)self->request_perf.worker_pid;
response["parent_pid"] = (f64)self->request_perf.parent_pid;
response["request_count"] = (f64)self->request_perf.request_count;
if(self->request_perf.time_start > 0 && self->request_perf.time_init > 0)
response["accept_us"] = (f64)((self->request_perf.time_start - self->request_perf.time_init) * 1000000.0);
if(self->request_perf.time_start > 0)
response["running_us"] = (f64)((now - self->request_perf.time_start) * 1000000.0);
if(self->request_perf.time_init > 0)
response["total_us"] = (f64)((now - self->request_perf.time_init) * 1000000.0);
if(self->workspace_birth_us > 0)
response["workspace_birth_us"] = (f64)self->workspace_birth_us;
}
String encoded = ucb_encode(response);
u32 cap = (u32)args[3].i32();
int32_t buf = args[2].i32();
if(buf != 0 && cap >= encoded.size())
self->hostcall_write(buf, encoded);
results[0] = Val((int32_t)encoded.size());
return(std::monostate());
}));
if(mod == "env" && name == "uce_host_env")
@ -1898,10 +1942,12 @@ private:
// ---- public entry: one request through one workspace -----------------------
inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_tree, const String& entry_source_path,
const String& handler = "render")
const String& handler = "render", const Request* request = 0)
{
WasmResponse response;
WasmWorkspace workspace(worker);
if(request)
workspace.set_perf_snapshot(my_pid, (u64)parent_pid, request->server ? request->server->request_count : 0, request->stats.time_init, request->stats.time_start);
auto birth_start = std::chrono::steady_clock::now();
String error = workspace.birth();
workspace.workspace_birth_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(