From 4f84ac544d9c91a66d068d372055eec8e1723def Mon Sep 17 00:00:00 2001 From: root Date: Mon, 15 Jun 2026 08:18:04 +0000 Subject: [PATCH] feat: request_perf() worker-side timing hostcall; restore demo System Info MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- site/demo/index.uce | 12 ++++++-- src/lib/sys.cpp | 17 ++++++++++++ src/lib/sys.h | 5 ++++ src/linux_fastcgi.cpp | 18 +++++++----- src/wasm/backend.cpp | 2 +- src/wasm/core_hostcalls.syms | 1 + src/wasm/worker.cpp | 54 +++++++++++++++++++++++++++++++++--- 7 files changed, 94 insertions(+), 15 deletions(-) diff --git a/site/demo/index.uce b/site/demo/index.uce index 3a9fa4c..9b68240 100644 --- a/site/demo/index.uce +++ b/site/demo/index.uce @@ -84,10 +84,16 @@ RENDER(Request& context)

System Info

str().length(), "\n");
-				print("Request #", context.server->request_count, "\n");
 			?>
diff --git a/src/lib/sys.cpp b/src/lib/sys.cpp index 8ac6e3e..dbf6da8 100644 --- a/src/lib/sys.cpp +++ b/src/lib/sys.cpp @@ -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 diff --git a/src/lib/sys.h b/src/lib/sys.h index e9863b8..9ba2268 100644 --- a/src/lib/sys.h +++ b/src/lib/sys.h @@ -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); diff --git a/src/linux_fastcgi.cpp b/src/linux_fastcgi.cpp index a5309d6..6f58cbb 100644 --- a/src/linux_fastcgi.cpp +++ b/src/linux_fastcgi.cpp @@ -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; diff --git a/src/wasm/backend.cpp b/src/wasm/backend.cpp index f9729a8..78c3548 100644 --- a/src/wasm/backend.cpp +++ b/src/wasm/backend.cpp @@ -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); diff --git a/src/wasm/core_hostcalls.syms b/src/wasm/core_hostcalls.syms index ae9c68b..86d0ed6 100644 --- a/src/wasm/core_hostcalls.syms +++ b/src/wasm/core_hostcalls.syms @@ -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 diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 0478472..f4ebc91 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -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, Span results) -> Result { - 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 args, Span results) -> Result { + 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(