From c28b446541798a8eaad54588a6da15a7fd7410a3 Mon Sep 17 00:00:00 2001 From: udo Date: Fri, 17 Jul 2026 19:11:05 +0000 Subject: [PATCH] Profile complete Wasm request timing --- site/doc/pages/request_perf.txt | 2 ++ src/fastcgi/src/fcgicc.cc | 15 +++++++++++++-- src/lib/types.h | 7 +++++++ src/linux_fastcgi.cpp | 3 +++ src/wasm/backend.cpp | 7 +++++++ src/wasm/worker.cpp | 15 +++++++++++++++ 6 files changed, 47 insertions(+), 2 deletions(-) diff --git a/site/doc/pages/request_perf.txt b/site/doc/pages/request_perf.txt index e3c4bc3..0baf240 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -21,6 +21,8 @@ Successful first loads within the request are counted by `unit_load_count` and d `unit_symbol_resolve_count` and `unit_symbol_resolve_us` isolate function and data symbol lookup within `unit_import_us`. The remainder of import time covers import-vector construction, Wasmtime Globals, GOT function table placement, and related bindings. +The request log's `wasm-ready`, `wasm`, `workspace`, `invoke`, `collect`, and `post` fields complete the timing boundary after this in-page snapshot: compiled-artifact readiness before backend entry, native backend wall time, complete workspace wall time, entry invocation, guest-output/meta collection, and native response assembly after the backend. They do not expose request data. This distinction is useful when a completed FastCGI request takes longer than the page's mid-render `request_perf()` snapshot. + Wasm FastCGI workers retain up to `MYSQL_PERSISTENT_POOL_SIZE` credential-keyed MySQL connections (default `8`; set `0` to disable). UCE calls the client library's connection-reset operation before another request receives a cached connection, clearing transactions, temporary tables, session variables, and selected databases while avoiding a new authentication handshake. Same-request leases continue to share state until request cleanup. :example diff --git a/src/fastcgi/src/fcgicc.cc b/src/fastcgi/src/fcgicc.cc index e21d449..dba0483 100644 --- a/src/fastcgi/src/fcgicc.cc +++ b/src/fastcgi/src/fcgicc.cc @@ -1331,15 +1331,26 @@ FastCGIServer::assemble_output_buffer(FastCGIRequest& request, Connection* conne request.flags.output_closed = true; request.stats.time_end = time_precise(); if(request.flags.log_request) - printf("(r) pid:%i\t%s\t%0.6fs\tfps:%0.0f\tout:%0.1fkB\tmem:%0.0f/%0.0fkB\n", + { + auto elapsed_us = [&](f64 from, f64 to) -> f64 { + return(from > 0 && to >= from ? (to - from) * 1000000.0 : 0.0); + }; + printf("(r) pid:%i\t%s\t%0.6fs\tfps:%0.0f\tout:%0.1fkB\tmem:%0.0f/%0.0fkB\twasm-ready:%0.3fms\twasm:%0.3fms\tworkspace:%0.3fms\tinvoke:%0.3fms\tcollect:%0.3fms\tpost:%0.3fms\n", my_pid, request.params["REQUEST_URI"].c_str(), request.stats.time_end - request.stats.time_start, 1.0 / (request.stats.time_end - request.stats.time_start), (f32)(request.out.length()/1024), (f32)(request.stats.mem_high/1024), - (f32)(request.stats.mem_alloc/1024) + (f32)(request.stats.mem_alloc/1024), + elapsed_us(request.stats.time_start, request.stats.wasm_handler_ready) / 1000.0, + elapsed_us(request.stats.wasm_backend_started, request.stats.wasm_backend_finished) / 1000.0, + (f64)request.stats.wasm_workspace_complete_us / 1000.0, + (f64)request.stats.wasm_entry_invoke_us / 1000.0, + (f64)request.stats.wasm_output_collect_us / 1000.0, + elapsed_us(request.stats.wasm_backend_finished, request.stats.time_end) / 1000.0 ); + } if(connection) { diff --git a/src/lib/types.h b/src/lib/types.h index 96746f9..c388b8a 100644 --- a/src/lib/types.h +++ b/src/lib/types.h @@ -309,6 +309,13 @@ struct Request { f64 time_input = 0; f64 time_start = 0; f64 time_end = 0; + f64 wasm_handler_ready = 0; + f64 wasm_backend_started = 0; + f64 wasm_backend_finished = 0; + u64 wasm_dispatch_us = 0; + u64 wasm_workspace_complete_us = 0; + u64 wasm_entry_invoke_us = 0; + u64 wasm_output_collect_us = 0; u64 mem_high = 0; u64 mem_alloc = 0; u32 invoke_count = 0; diff --git a/src/linux_fastcgi.cpp b/src/linux_fastcgi.cpp index 546d132..11ba149 100644 --- a/src/linux_fastcgi.cpp +++ b/src/linux_fastcgi.cpp @@ -547,9 +547,12 @@ int handle_complete(FastCGIRequest& request) { // guest traps, and the native handler would otherwise turn a clean // guest trap into a native fatal signal. Sets failure_* on error. auto serve_via_wasm = [&](const String& entry_unit, const String& handler) { + request.stats.wasm_handler_ready = time_precise(); request_fault_active = 0; restore_request_fault_handlers(); + request.stats.wasm_backend_started = time_precise(); String wasm_error = wasm_backend_serve(request, entry_unit, handler); + request.stats.wasm_backend_finished = time_precise(); install_request_fault_handlers(); request_fault_active = 1; if(wasm_error != "") diff --git a/src/wasm/backend.cpp b/src/wasm/backend.cpp index f32ad35..3ba239e 100644 --- a/src/wasm/backend.cpp +++ b/src/wasm/backend.cpp @@ -192,6 +192,10 @@ String wasm_backend_serve(Request& request, const String& entry_unit, const Stri } WasmResponse response = wasm_worker_serve(*g_wasm_worker, ctx, entry_unit, handler, &request); + request.stats.wasm_dispatch_us = response.dispatch_us; + request.stats.wasm_workspace_complete_us = response.workspace_complete_us; + request.stats.wasm_entry_invoke_us = response.entry_invoke_us; + request.stats.wasm_output_collect_us = response.output_collect_us; if(!response.ok) return(response.error == "" ? String("wasm workspace failed") : response.error); @@ -232,6 +236,9 @@ String wasm_backend_serve(Request& request, const String& entry_unit, const Stri { request.header["X-UCE-Backend"] = "wasm"; request.header["X-UCE-Wasm-Workspace-Birth-Us"] = std::to_string(response.workspace_birth_us); + request.header["X-UCE-Wasm-Workspace-Complete-Us"] = std::to_string(response.workspace_complete_us); + request.header["X-UCE-Wasm-Entry-Invoke-Us"] = std::to_string(response.entry_invoke_us); + request.header["X-UCE-Wasm-Output-Collect-Us"] = std::to_string(response.output_collect_us); request.header["X-UCE-Wasm-Component-Resolve-Count"] = std::to_string(response.component_resolve_count); request.header["X-UCE-Wasm-Component-Resolve-Total-Us"] = std::to_string(response.component_resolve_total_us); request.header["X-UCE-Wasm-Component-Resolve-Avg-Us"] = std::to_string( diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index ebfffce..b6d2e7c 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -174,6 +174,9 @@ struct WasmRequestProfile u64 workspace_birth_cpu_us = 0; u64 context_apply_us = 0; u64 context_apply_cpu_us = 0; + u64 entry_invoke_us = 0; + u64 output_collect_us = 0; + u64 workspace_complete_us = 0; u64 component_resolve_count = 0; u64 component_resolve_total_us = 0; u64 component_path_total_us = 0; @@ -3597,9 +3600,21 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_ (u64)((context_cpu_finished - context_cpu_start) * 1000000.0) : 0; } if(error == "") + { + auto invoke_start = std::chrono::steady_clock::now(); error = workspace.invoke_entry(entry_source_path, handler, &response.handler_present); + workspace.entry_invoke_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - invoke_start).count(); + } if(error == "") + { + auto collect_start = std::chrono::steady_clock::now(); error = workspace.collect(response); + workspace.output_collect_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - collect_start).count(); + } + workspace.workspace_complete_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - workspace_start).count(); static_cast(response) = workspace; if(error != "") {