Profile pre-dispatch WASM readiness

docs/wasm-runtime-architecture.md

@@ -205,6 +205,10 @@ source, bytes, and phase durations so a cold outlier identifies its exact unit
 and whether it used worker memory, serialized code, compilation, or failed.
 Absolute source paths and source contents are not exposed. This keeps cold-worker
 module latency distinguishable without exposing source paths.
+The same snapshot divides pre-dispatch WASM readiness into entry normalization,
+mutation freshness, artifact stat, complete dependency freshness, and worker
+availability. `ready_check_count` distinguishes the warm one-check path from an
+on-demand compile and recheck; repeated snapshot reads retain the initial values.
 When a current serialized module exists, the worker scans wasm section headers
 and reads only `dylink.0` and `uce.abi`; it does not fault the multi-megabyte code
 and data bodies into every new worker. A missing/stale/invalid serialized module

site/tests/io.uce

@@ -181,7 +181,13 @@ RENDER(Request& context)
 	u64 dropped_hostcall_operations = perf["hostcall_operations_dropped"].to_u64();
 	hostcall_operation_profile_valid = hostcall_operation_profile_valid && perf["hostcall_cpu_profiled"].type == 'B' && perf["hostcall_cpu_us"].to_u64() <= perf["hostcall_us"].to_u64() + 2 && operation_kinds > 0 && operation_kinds <= 32 && ((dropped_hostcall_operations == 0 && operation_hostcalls == perf["hostcall_count"].to_u64() && operation_hostcall_us == perf["hostcall_us"].to_u64() && operation_hostcall_cpu_us == perf["hostcall_cpu_us"].to_u64()) || (dropped_hostcall_operations > 0 && operation_kinds == 32 && operation_hostcalls < perf["hostcall_count"].to_u64() && operation_hostcall_us <= perf["hostcall_us"].to_u64() && operation_hostcall_cpu_us <= perf["hostcall_cpu_us"].to_u64()));
 	bool thread_runtime_profile_valid = perf["thread_runtime_profiled"].type == 'B' && (!perf["thread_runtime_profiled"].to_bool() || (perf["thread_cpu_start"].to_f64() >= 0 && perf["thread_cpu_end"].to_f64() >= 0 && perf["thread_cpu_migrated"].type == 'B' && perf["thread_user_cpu_us"].to_u64() + perf["thread_system_cpu_us"].to_u64() <= perf["workspace_wall_us"].to_u64() + 5 && perf["thread_voluntary_context_switches"].type != 'S' && perf["thread_involuntary_context_switches"].type != 'S' && perf["thread_minor_faults"].type != 'S' && perf["thread_major_faults"].type != 'S'));
-	bool perf_stable = transport_profile_valid && workspace_cpu_profile_valid && unit_module_profile_valid && hostcall_operation_profile_valid && thread_runtime_profile_valid && 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' && perf["component_loaded_reuse_count"].type != 'S' && perf["component_path_us"].type != 'S' && perf["component_artifact_us"].type != 'S' && perf["component_load_us"].type != 'S' && perf["component_link_us"].type != 'S' && perf["unit_load_count"].to_u64() > 0 && perf["unit_module_us"].type != 'S' && perf["unit_allocate_us"].type != 'S' && perf["unit_import_us"].type != 'S' && perf["unit_symbol_resolve_count"].type != 'S' && perf["unit_symbol_resolve_us"].type != 'S' && perf["unit_instantiate_us"].type != 'S' && perf["unit_initialize_us"].type != 'S';
+	bool perf_stable = transport_profile_valid && workspace_cpu_profile_valid && unit_module_profile_valid && hostcall_operation_profile_valid && thread_runtime_profile_valid && perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["ready_normalize_us"].type != 'S' && perf["ready_mutation_check_us"].type != 'S' && perf["ready_artifact_stat_us"].type != 'S' && perf["ready_freshness_us"].type != 'S' && perf["ready_worker_us"].type != 'S' && perf["ready_check_count"].to_u64() > 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' && perf["component_loaded_reuse_count"].type != 'S' && perf["component_path_us"].type != 'S' && perf["component_artifact_us"].type != 'S' && perf["component_load_us"].type != 'S' && perf["component_link_us"].type != 'S' && perf["unit_load_count"].to_u64() > 0 && perf["unit_module_us"].type != 'S' && perf["unit_allocate_us"].type != 'S' && perf["unit_import_us"].type != 'S' && perf["unit_symbol_resolve_count"].type != 'S' && perf["unit_symbol_resolve_us"].type != 'S' && perf["unit_instantiate_us"].type != 'S' && perf["unit_initialize_us"].type != 'S';
+	u64 profiled_ready_normalize = perf["ready_normalize_us"].to_u64();
+	u64 profiled_ready_mutation_check = perf["ready_mutation_check_us"].to_u64();
+	u64 profiled_ready_artifact_stat = perf["ready_artifact_stat_us"].to_u64();
+	u64 profiled_ready_freshness = perf["ready_freshness_us"].to_u64();
+	u64 profiled_ready_worker = perf["ready_worker_us"].to_u64();
+	u64 profiled_ready_checks = perf["ready_check_count"].to_u64();
 	u64 profiled_hostcalls = perf["hostcall_count"].to_u64();
 	f64 profiled_hostcall_us = perf["hostcall_us"].to_f64();
 	u64 profiled_hostcall_cpu_us = perf["hostcall_cpu_us"].to_u64();
@@ -204,7 +210,7 @@ RENDER(Request& context)
 	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["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["hostcall_cpu_us"].to_u64() == profiled_hostcall_cpu_us && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components && perf["component_loaded_reuse_count"].to_u64() == profiled_component_loaded_reuses && perf["component_path_us"].to_u64() == profiled_component_path && perf["component_artifact_us"].to_u64() == profiled_component_artifact && perf["component_load_us"].to_u64() == profiled_component_load && perf["component_link_us"].to_u64() == profiled_component_link && perf["unit_load_count"].to_u64() == profiled_unit_loads && perf["unit_module_us"].to_u64() == profiled_unit_module && perf["unit_allocate_us"].to_u64() == profiled_unit_allocate && perf["unit_import_us"].to_u64() == profiled_unit_import && perf["unit_symbol_resolve_count"].to_u64() == profiled_unit_symbol_resolve_count && perf["unit_symbol_resolve_us"].to_u64() == profiled_unit_symbol_resolve && perf["unit_instantiate_us"].to_u64() == profiled_unit_instantiate && perf["unit_initialize_us"].to_u64() == profiled_unit_initialize && json_encode(perf["mysql_operations"]) == profiled_mysql_operations && json_encode(perf["hostcall_operations"]) == profiled_hostcall_operations;
+		perf_stable = perf["worker_pid"].to_u64() > 0 && perf["running_us"].to_f64() > 0 && perf["ready_normalize_us"].to_u64() == profiled_ready_normalize && perf["ready_mutation_check_us"].to_u64() == profiled_ready_mutation_check && perf["ready_artifact_stat_us"].to_u64() == profiled_ready_artifact_stat && perf["ready_freshness_us"].to_u64() == profiled_ready_freshness && perf["ready_worker_us"].to_u64() == profiled_ready_worker && perf["ready_check_count"].to_u64() == profiled_ready_checks && 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["hostcall_cpu_us"].to_u64() == profiled_hostcall_cpu_us && perf["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components && perf["component_loaded_reuse_count"].to_u64() == profiled_component_loaded_reuses && perf["component_path_us"].to_u64() == profiled_component_path && perf["component_artifact_us"].to_u64() == profiled_component_artifact && perf["component_load_us"].to_u64() == profiled_component_load && perf["component_link_us"].to_u64() == profiled_component_link && perf["unit_load_count"].to_u64() == profiled_unit_loads && perf["unit_module_us"].to_u64() == profiled_unit_module && perf["unit_allocate_us"].to_u64() == profiled_unit_allocate && perf["unit_import_us"].to_u64() == profiled_unit_import && perf["unit_symbol_resolve_count"].to_u64() == profiled_unit_symbol_resolve_count && perf["unit_symbol_resolve_us"].to_u64() == profiled_unit_symbol_resolve && perf["unit_instantiate_us"].to_u64() == profiled_unit_instantiate && perf["unit_initialize_us"].to_u64() == profiled_unit_initialize && json_encode(perf["mysql_operations"]) == profiled_mysql_operations && json_encode(perf["hostcall_operations"]) == profiled_hostcall_operations;
 	}
 	check("request_perf() stages stable repeated snapshots", perf_stable, json_encode(perf));
 

src/lib/types.h

@@ -316,6 +316,12 @@ struct Request {
 		u64 wasm_workspace_complete_us = 0;
 		u64 wasm_entry_invoke_us = 0;
 		u64 wasm_output_collect_us = 0;
+		u64 wasm_ready_normalize_us = 0;
+		u64 wasm_ready_mutation_check_us = 0;
+		u64 wasm_ready_artifact_stat_us = 0;
+		u64 wasm_ready_freshness_us = 0;
+		u64 wasm_ready_worker_us = 0;
+		u32 wasm_ready_check_count = 0;
 		u64 mem_high = 0;
 		u64 mem_alloc = 0;
 		u32 invoke_count = 0;

src/linux_fastcgi.cpp

@@ -581,10 +581,14 @@ int handle_complete(FastCGIRequest& request) {
 				}
 			};
 
+			f64 ready_phase_started = time_precise();
 			String entry_unit = compiler_normalize_unit_path(&request, request.params["SCRIPT_FILENAME"]);
+			request.stats.wasm_ready_normalize_us += (u64)((time_precise() - ready_phase_started) * 1000000.0);
 			String request_method = to_upper(trim(request.params["REQUEST_METHOD"]));
 			bool read_request = request_method == "GET" || request_method == "HEAD" || request_method == "OPTIONS";
+			ready_phase_started = time_precise();
 			bool stale_mutation = !request.resources.is_cli && !read_request && compiler_unit_needs_recompile(&request, entry_unit);
+			request.stats.wasm_ready_mutation_check_us += (u64)((time_precise() - ready_phase_started) * 1000000.0);
 			if(stale_mutation)
 			{
 				compiler_prioritize_unit(&request, entry_unit);

src/wasm/backend.cpp

@@ -116,17 +116,26 @@ static bool wasm_artifact_exists(Request* context, const String& entry_unit)
 		return(false);
 	String wasm_path = context->server->config["BIN_DIRECTORY"] + entry_unit + ".wasm";
 	struct stat wasm_st;
+	f64 phase_started = time_precise();
+	context->stats.wasm_ready_check_count++;
 	if(stat(wasm_path.c_str(), &wasm_st) != 0 || !S_ISREG(wasm_st.st_mode))
+	{
+		context->stats.wasm_ready_artifact_stat_us += (u64)((time_precise() - phase_started) * 1000000.0);
 		return(false);
+	}
+	context->stats.wasm_ready_artifact_stat_us += (u64)((time_precise() - phase_started) * 1000000.0);
 	// Require the artifact to satisfy the full compiler freshness check. Source
 	// mtime alone misses runtime/unit ABI changes, setup-template changes, and
 	// metadata mismatches, which can leave stale wasm with old imports.
 	bool source_missing = false;
+	phase_started = time_precise();
 	if(compiler_unit_needs_recompile(context, entry_unit, &source_missing))
 	{
+		context->stats.wasm_ready_freshness_us += (u64)((time_precise() - phase_started) * 1000000.0);
 		compiler_prioritize_unit(context, entry_unit);
 		return(compiler_request_can_serve_stale_artifact(context));
 	}
+	context->stats.wasm_ready_freshness_us += (u64)((time_precise() - phase_started) * 1000000.0);
 	if(source_missing)
 		return(false);
 	return(true);
@@ -141,7 +150,10 @@ bool wasm_backend_should_handle(Request& request, const String& entry_unit)
 		return(false);
 	if(!wasm_artifact_exists(&request, entry_unit))
 		return(false);
-	if(wasm_backend_ensure_started(&request) != "")
+	f64 phase_started = time_precise();
+	String start_error = wasm_backend_ensure_started(&request);
+	request.stats.wasm_ready_worker_us += (u64)((time_precise() - phase_started) * 1000000.0);
+	if(start_error != "")
 		return(false);
 	return(true);
 }

src/wasm/worker.cpp

@@ -1343,6 +1343,12 @@ public:
 		f64 time_params = 0;
 		f64 time_input = 0;
 		f64 time_start = 0;
+		u64 ready_normalize_us = 0;
+		u64 ready_mutation_check_us = 0;
+		u64 ready_artifact_stat_us = 0;
+		u64 ready_freshness_us = 0;
+		u64 ready_worker_us = 0;
+		u32 ready_check_count = 0;
 		f64 workspace_wall_start = 0;
 		f64 workspace_cpu_start = 0;
 		struct rusage thread_runtime_start = {};
@@ -1358,6 +1364,8 @@ public:
 
 	void set_perf_snapshot(u64 worker_pid, u64 parent_pid, u64 request_count,
 		f64 time_init, f64 time_params, f64 time_input, f64 time_start,
+		u64 ready_normalize_us, u64 ready_mutation_check_us, u64 ready_artifact_stat_us,
+		u64 ready_freshness_us, u64 ready_worker_us, u32 ready_check_count,
 		f64 workspace_wall_start, f64 workspace_cpu_start)
 	{
 		request_perf.worker_pid = worker_pid;
@@ -1367,6 +1375,12 @@ public:
 		request_perf.time_params = time_params;
 		request_perf.time_input = time_input;
 		request_perf.time_start = time_start;
+		request_perf.ready_normalize_us = ready_normalize_us;
+		request_perf.ready_mutation_check_us = ready_mutation_check_us;
+		request_perf.ready_artifact_stat_us = ready_artifact_stat_us;
+		request_perf.ready_freshness_us = ready_freshness_us;
+		request_perf.ready_worker_us = ready_worker_us;
+		request_perf.ready_check_count = ready_check_count;
 		request_perf.workspace_wall_start = workspace_wall_start;
 		request_perf.workspace_cpu_start = workspace_cpu_start;
 		request_perf.active = true;
@@ -2645,6 +2659,12 @@ private:
 						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;
+						response["ready_normalize_us"] = (f64)self->request_perf.ready_normalize_us;
+						response["ready_mutation_check_us"] = (f64)self->request_perf.ready_mutation_check_us;
+						response["ready_artifact_stat_us"] = (f64)self->request_perf.ready_artifact_stat_us;
+						response["ready_freshness_us"] = (f64)self->request_perf.ready_freshness_us;
+						response["ready_worker_us"] = (f64)self->request_perf.ready_worker_us;
+						response["ready_check_count"] = (f64)self->request_perf.ready_check_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_params > 0 && self->request_perf.time_init > 0)
@@ -3883,6 +3903,9 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const Request& request
 		(u64)((setup_cpu_finished - cpu_started) * 1000000.0) : 0;
 	workspace.set_perf_snapshot(my_pid, (u64)parent_pid, request.server ? request.server->request_count : 0,
 		request.stats.time_init, request.stats.time_params, request.stats.time_input, request.stats.time_start,
+		request.stats.wasm_ready_normalize_us, request.stats.wasm_ready_mutation_check_us,
+		request.stats.wasm_ready_artifact_stat_us, request.stats.wasm_ready_freshness_us,
+		request.stats.wasm_ready_worker_us, request.stats.wasm_ready_check_count,
 		serve_started, cpu_started);
 	workspace.request_perf.thread_runtime_start = thread_runtime_start;
 	workspace.request_perf.thread_cpu_start = thread_cpu_start;