Profile request execution phases

site/demo/index.uce

@@ -91,8 +91,15 @@ RENDER(Request& context)
 				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("Dispatch us: ", (u64)perf["dispatch_us"].to_u64(), "\n");
-					print("Workspace birth us: ", (u64)perf["workspace_birth_us"].to_u64(), "\n");
+				print("Workspace setup us: ", (u64)perf["workspace_setup_us"].to_u64(), "\n");
+				print("Workspace birth us: ", (u64)perf["workspace_birth_us"].to_u64(), "\n");
+				print("Context apply us: ", (u64)perf["context_apply_us"].to_u64(), "\n");
+				print("Guest us: ", (f64)perf["guest_us"].to_f64(), "\n");
+				print("Hostcalls: ", (u64)perf["hostcall_count"].to_u64(), " / ", (u64)perf["hostcall_us"].to_u64(), " us\n");
+				print("MySQL hostcalls: ", (u64)perf["mysql_hostcall_count"].to_u64(), " / ", (u64)perf["mysql_hostcall_us"].to_u64(), " us\n");
+				print("Memcache hostcalls: ", (u64)perf["memcache_hostcall_count"].to_u64(), " / ", (u64)perf["memcache_hostcall_us"].to_u64(), " us\n");
+				print("Component resolves: ", (u64)perf["component_resolve_count"].to_u64(), " / ", (u64)perf["component_resolve_us"].to_u64(), " us\n");
 				print("Output buffer size: ", context.ob->str().length(), "\n");
 			?></pre>
 		</div>

site/doc/pages/request_perf.txt

@@ -9,7 +9,7 @@ return value : performance snapshot for the active request/workspace
 >time_precise
 
 :content
-Returns a DValue with timing and process metadata such as worker pid, parent pid, request count, request start times, and workspace birth timing when available.
+Returns a DValue with timing and process metadata such as worker pid, parent pid, request count, request start times, native dispatch, workspace setup and birth, context application, guest execution, and hostcall timing. Hostcall totals include component resolution; MySQL, memcache, and component resolution also expose their own count and microsecond fields. The profiling hostcall itself is excluded from those totals so repeated snapshots remain comparable.
 
 :example
 DValue perf = request_perf();

site/tests/io.uce

@@ -151,11 +151,14 @@ RENDER(Request& context)
 	check("to_u64() / to_s64() / to_f64() / to_bool()", to_u64(cfg["u64"], 7) == 42 && to_u64(cfg["bad"], 7) == 7 && to_s64(cfg["s64"], 5) == -12 && to_s64(cfg["bad"], 5) == 5 && to_f64(cfg["f64"], 1.0) > 3.49 && to_f64(cfg["bad"], 1.25) == 1.25 && to_bool(cfg["yes"], false) && !to_bool(cfg["no"], true) && !to_bool("unknown", false), var_dump(cfg));
 
 	DValue perf = request_perf();
-	bool perf_stable = perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0;
+	bool perf_stable = perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["dispatch_us"].type != 'S' && perf["workspace_setup_us"].type != 'S' && perf["workspace_birth_us"].type != 'S' && perf["context_apply_us"].type != 'S' && perf["hostcall_count"].to_u64() > 0 && perf["hostcall_us"].type != 'S' && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].type != 'S';
+	u64 profiled_hostcalls = perf["hostcall_count"].to_u64();
+	f64 profiled_hostcall_us = perf["hostcall_us"].to_f64();
+	u64 profiled_components = perf["component_resolve_count"].to_u64();
 	for(u64 i = 0; i < 512 && perf_stable; i++)
 	{
 		perf = request_perf();
-		perf_stable = perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0;
+		perf_stable = perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["dispatch_us"].type != 'S' && perf["workspace_setup_us"].type != 'S' && perf["workspace_birth_us"].type != 'S' && perf["context_apply_us"].type != 'S' && perf["hostcall_count"].to_u64() == profiled_hostcalls && perf["hostcall_us"].to_f64() == profiled_hostcall_us && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components;
 	}
 	check("request_perf() stages stable repeated snapshots", perf_stable, json_encode(perf));
 

src/wasm/worker.cpp

@@ -99,16 +99,29 @@ struct WasmWorkerConfig
 	std::set<String> hostcall_blocklist;
 };
 
-struct WasmResponse
+struct WasmRequestProfile
+{
+	u64 dispatch_us = 0;
+	u64 workspace_setup_us = 0;
+	u64 workspace_birth_us = 0;
+	u64 context_apply_us = 0;
+	u64 component_resolve_count = 0;
+	u64 component_resolve_total_us = 0;
+	u64 hostcall_count = 0;
+	u64 hostcall_total_us = 0;
+	u64 mysql_hostcall_count = 0;
+	u64 mysql_hostcall_total_us = 0;
+	u64 memcache_hostcall_count = 0;
+	u64 memcache_hostcall_total_us = 0;
+};
+
+struct WasmResponse : WasmRequestProfile
 {
 	bool ok = false;
 	bool handler_present = true;  // false → unit has no handler for the requested kind (404)
 	String body;
 	DValue meta;          // status / headers / cookies / session
 	String error;         // collapsed trace or loader error when !ok
-	u64 workspace_birth_us = 0;
-	u64 component_resolve_count = 0;
-	u64 component_resolve_total_us = 0;
 };
 
 static u64 wasm_file_lock_timeout_ms()
@@ -764,14 +777,11 @@ private:
 
 // ---- workspace (per request) ----------------------------------------------
 
-class WasmWorkspace
+class WasmWorkspace : public WasmRequestProfile
 {
 public:
 	WasmWorker& worker;
 	wasmtime::Store store;
-	u64 workspace_birth_us = 0;
-	u64 component_resolve_count = 0;
-	u64 component_resolve_total_us = 0;
 
 	struct FileHandle
 	{
@@ -1675,7 +1685,29 @@ private:
 		WasmWorkspace* self = this;
 
 		auto add = [&](auto&& callback) -> Extern {
-			Func func(cx, func_type, callback);
+			String profile_name = name;
+			auto profiled = [self, callback, profile_name](Caller caller, Span<const Val> args, Span<Val> results) mutable -> Result<std::monostate, Trap> {
+				auto started = std::chrono::steady_clock::now();
+				auto result = callback(caller, args, results);
+				if(profile_name != "uce_host_request_perf")
+				{
+					u64 elapsed = (u64)std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - started).count();
+					self->hostcall_count++;
+					self->hostcall_total_us += elapsed;
+					if(profile_name == "uce_host_mysql")
+					{
+						self->mysql_hostcall_count++;
+						self->mysql_hostcall_total_us += elapsed;
+					}
+					else if(profile_name == "uce_host_memcache_command")
+					{
+						self->memcache_hostcall_count++;
+						self->memcache_hostcall_total_us += elapsed;
+					}
+				}
+				return(result);
+			};
+			Func func(cx, func_type, profiled);
 			host_funcs.push_back(func);
 			return(host_funcs.back());
 		};
@@ -1727,8 +1759,21 @@ private:
 							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["dispatch_us"] = (f64)self->dispatch_us;
-							response["workspace_birth_us"] = (f64)self->workspace_birth_us;
+						response["workspace_setup_us"] = (f64)self->workspace_setup_us;
+						response["workspace_birth_us"] = (f64)self->workspace_birth_us;
+						response["context_apply_us"] = (f64)self->context_apply_us;
+						response["hostcall_count"] = (f64)self->hostcall_count;
+						response["hostcall_us"] = (f64)self->hostcall_total_us;
+						response["mysql_hostcall_count"] = (f64)self->mysql_hostcall_count;
+						response["mysql_hostcall_us"] = (f64)self->mysql_hostcall_total_us;
+						response["memcache_hostcall_count"] = (f64)self->memcache_hostcall_count;
+						response["memcache_hostcall_us"] = (f64)self->memcache_hostcall_total_us;
+						response["component_resolve_count"] = (f64)self->component_resolve_count;
+						response["component_resolve_us"] = (f64)self->component_resolve_total_us;
+						f64 running_us = response["running_us"].to_f64();
+						f64 accounted_us = (f64)(self->dispatch_us + self->workspace_setup_us + self->workspace_birth_us + self->context_apply_us + self->hostcall_total_us);
+						response["guest_us"] = running_us > accounted_us ? running_us - accounted_us : 0.0;
 					}
 					encoded = ucb_encode(response);
 					if(args[2].i32() == 0)
@@ -2776,22 +2821,33 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
 	const String& handler = "render", const Request* request = 0)
 {
 	WasmResponse response;
+	f64 serve_started = time_precise();
+	auto workspace_start = std::chrono::steady_clock::now();
 	WasmWorkspace workspace(worker);
+	workspace.workspace_setup_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
+		std::chrono::steady_clock::now() - workspace_start).count();
 	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);
+		if(request->stats.time_start > 0 && serve_started > request->stats.time_start)
+			workspace.dispatch_us = (u64)((serve_started - request->stats.time_start) * 1000000.0);
+	}
 	auto birth_start = std::chrono::steady_clock::now();
 	String error = workspace.birth();
 	workspace.workspace_birth_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
 		std::chrono::steady_clock::now() - birth_start).count();
 	if(error == "")
+	{
+		auto context_start = std::chrono::steady_clock::now();
 		error = workspace.apply_context(context_tree);
+		workspace.context_apply_us = (u64)std::chrono::duration_cast<std::chrono::microseconds>(
+			std::chrono::steady_clock::now() - context_start).count();
+	}
 	if(error == "")
 		error = workspace.invoke_entry(entry_source_path, handler, &response.handler_present);
 	if(error == "")
 		error = workspace.collect(response);
-	response.workspace_birth_us = workspace.workspace_birth_us;
+	static_cast<WasmRequestProfile&>(response) = workspace;
-	response.component_resolve_count = workspace.component_resolve_count;
-	response.component_resolve_total_us = workspace.component_resolve_total_us;
 	if(error != "")
 	{
 		response.ok = false;