udo/uce
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Profile FastCGI transport phases

Browse Source
This commit is contained in:
udo 2026-07-16 20:49:13 +00:00
parent bbfbd63b53
commit 83c05111a9
5 changed files with 23 additions and 4 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
site/doc/pages/request_perf.txt
View File

@ -9,7 +9,9 @@ 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, 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. `mysql_operations` is an ordered, query-text-free list of up to 64 logical MySQL operations and their microsecond durations. A connect operation also identifies its source as `new`, cross-request `worker`, or same-request `request`; the corresponding `mysql_connection_open_count`, `mysql_connection_reuse_count`, and `mysql_request_pool_hit_count` fields provide totals. `mysql_operations_dropped` reports any overflow. The profiling hostcall itself is excluded from those totals so repeated snapshots remain comparable.
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. `accept_us` is divided into `transport_params_us` (FastCGI begin through the end of parameters), `transport_input_us` (parameters through the end of input), and `handler_queue_us` (input close through handler entry). This distinguishes upstream request delivery from work inside the UCE handler.
Hostcall totals include component resolution; MySQL, memcache, and component resolution also expose their own count and microsecond fields. `mysql_operations` is an ordered, query-text-free list of up to 64 logical MySQL operations and their microsecond durations. A connect operation also identifies its source as `new`, cross-request `worker`, or same-request `request`; the corresponding `mysql_connection_open_count`, `mysql_connection_reuse_count`, and `mysql_request_pool_hit_count` fields provide totals. `mysql_operations_dropped` reports any overflow. The profiling hostcall itself is excluded from those totals so repeated snapshots remain comparable.
Component resolution is divided into `component_path_us`, `component_artifact_us`, `component_load_us`, and `component_link_us`. These aggregate path resolution, artifact readiness/freshness, Wasmtime side-module loading, and exported-handler lookup/table placement without exposing source paths.

3
site/tests/io.uce
View File

@ -156,7 +156,8 @@ RENDER(Request& context)
u64 module_read_bytes = perf["unit_module_read_bytes"].to_u64();
bool serialized_reads_bounded = module_misses == 0 || serialized_hits != module_misses || (module_read_bytes > 0 && module_read_bytes < module_misses * 1024 * 1024);
bool unit_module_profile_valid = serialized_reads_bounded && perf["unit_module_cache_hit_count"].to_u64() + module_misses == perf["unit_load_count"].to_u64() && serialized_hits + perf["unit_module_compile_count"].to_u64() == module_misses && perf["unit_module_lookup_us"].type != 'S' && perf["unit_module_read_us"].type != 'S' && perf["unit_module_read_bytes"].type != 'S' && perf["unit_module_parse_us"].type != 'S' && perf["unit_module_compile_us"].type != 'S' && perf["unit_module_classify_us"].type != 'S';
bool perf_stable = unit_module_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_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 transport_profile_valid = perf["transport_params_us"].type != 'S' && perf["transport_input_us"].type != 'S' && perf["handler_queue_us"].type != 'S' && perf["accept_us"].to_f64() + 2 >= perf["transport_params_us"].to_f64() + perf["transport_input_us"].to_f64() + perf["handler_queue_us"].to_f64();
bool perf_stable = transport_profile_valid && unit_module_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_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_hostcalls = perf["hostcall_count"].to_u64();
f64 profiled_hostcall_us = perf["hostcall_us"].to_f64();
u64 profiled_components = perf["component_resolve_count"].to_u64();

2
src/fastcgi/src/fcgicc.cc
View File

@ -1224,6 +1224,7 @@ FastCGIServer::read_fgci(Connection& connection)
request.resources.params_buffer.size());
request.resources.params_buffer.clear();
request.flags.params_closed = true;
request.stats.time_params = time_precise();
//std::cout << "Params " << var_dump(request.params) << "\n";
request.flags.status = on_request(request);
if (request.flags.status == 0 && !request.in.empty())
@ -1261,6 +1262,7 @@ FastCGIServer::read_fgci(Connection& connection)
}
} else {
request.flags.input_closed = true;
request.stats.time_input = time_precise();
if (request.flags.params_closed && request.flags.status == 0) {
request.flags.status = on_complete(request);
request_write_fgci(connection, request_id, request);

2
src/lib/types.h
View File

@ -305,6 +305,8 @@ struct Request {
struct Stats {
u32 bytes_written = 0;
f64 time_init = 0;
f64 time_params = 0;
f64 time_input = 0;
f64 time_start = 0;
f64 time_end = 0;
u64 mem_high = 0;

16
src/wasm/worker.cpp
View File

@ -1145,6 +1145,8 @@ public:
u64 parent_pid = 0;
u64 request_count = 0;
f64 time_init = 0;
f64 time_params = 0;
f64 time_input = 0;
f64 time_start = 0;
bool active = false;
} request_perf;
@ -1153,12 +1155,15 @@ public:
{
}
void set_perf_snapshot(u64 worker_pid, u64 parent_pid, u64 request_count, f64 time_init, f64 time_start)
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)
{
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_params = time_params;
request_perf.time_input = time_input;
request_perf.time_start = time_start;
request_perf.active = true;
}
@ -2165,6 +2170,12 @@ private:
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_params > 0 && self->request_perf.time_init > 0)
response["transport_params_us"] = (f64)((self->request_perf.time_params - self->request_perf.time_init) * 1000000.0);
if(self->request_perf.time_input > 0 && self->request_perf.time_params > 0)
response["transport_input_us"] = (f64)((self->request_perf.time_input - self->request_perf.time_params) * 1000000.0);
if(self->request_perf.time_start > 0 && self->request_perf.time_input > 0)
response["handler_queue_us"] = (f64)((self->request_perf.time_start - self->request_perf.time_input) * 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)
@ -3298,7 +3309,8 @@ inline WasmResponse wasm_worker_serve(WasmWorker& worker, const DValue& context_
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);
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);
if(request->stats.time_start > 0 && serve_started > request->stats.time_start)
workspace.dispatch_us = (u64)((serve_started - request->stats.time_start) * 1000000.0);
}