Profile complete Wasm request timing

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

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)
 	{

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;

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 != "")

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(

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::microseconds>(
+			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::microseconds>(
+			std::chrono::steady_clock::now() - collect_start).count();
+	}
+	workspace.workspace_complete_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
+		std::chrono::steady_clock::now() - workspace_start).count();
 	static_cast<WasmRequestProfile&>(response) = workspace;
 	if(error != "")
 	{