diff --git a/site/demo/index.uce b/site/demo/index.uce index 7ff2163..dfe81e7 100644 --- a/site/demo/index.uce +++ b/site/demo/index.uce @@ -104,6 +104,7 @@ RENDER(Request& context) print("Component resolves: ", (u64)perf["component_resolve_count"].to_u64(), " / ", (u64)perf["component_resolve_us"].to_u64(), " us\n"); print("Component phases: path ", (u64)perf["component_path_us"].to_u64(), " / artifact ", (u64)perf["component_artifact_us"].to_u64(), " / load ", (u64)perf["component_load_us"].to_u64(), " / link ", (u64)perf["component_link_us"].to_u64(), " us\n"); print("Unit loads: ", (u64)perf["unit_load_count"].to_u64(), " / module ", (u64)perf["unit_module_us"].to_u64(), " / allocate ", (u64)perf["unit_allocate_us"].to_u64(), " / imports ", (u64)perf["unit_import_us"].to_u64(), " / instantiate ", (u64)perf["unit_instantiate_us"].to_u64(), " / initialize ", (u64)perf["unit_initialize_us"].to_u64(), " us\n"); + print("Unit symbol resolves: ", (u64)perf["unit_symbol_resolve_count"].to_u64(), " / ", (u64)perf["unit_symbol_resolve_us"].to_u64(), " us\n"); print("Output buffer size: ", context.ob->str().length(), "\n"); ?> diff --git a/site/doc/pages/request_perf.txt b/site/doc/pages/request_perf.txt index dcf7cf6..892c66e 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -15,6 +15,8 @@ Component resolution is divided into `component_path_us`, `component_artifact_us Successful first loads within the request are counted by `unit_load_count` and divided into `unit_module_us`, `unit_allocate_us`, `unit_import_us`, `unit_instantiate_us`, and `unit_initialize_us`. These cover compiled-module lookup, guest memory/table allocation, import construction, Wasmtime instantiation, and relocations/constructors/request binding. Repeated handlers from an already loaded unit are excluded. +`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. + 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/site/tests/io.uce b/site/tests/io.uce index 861ad89..091009c 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -151,7 +151,7 @@ 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 && 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_instantiate_us"].type != 'S' && perf["unit_initialize_us"].type != 'S'; + 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' && 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(); @@ -163,13 +163,15 @@ RENDER(Request& context) u64 profiled_unit_module = perf["unit_module_us"].to_u64(); u64 profiled_unit_allocate = perf["unit_allocate_us"].to_u64(); u64 profiled_unit_import = perf["unit_import_us"].to_u64(); + u64 profiled_unit_symbol_resolve_count = perf["unit_symbol_resolve_count"].to_u64(); + u64 profiled_unit_symbol_resolve = perf["unit_symbol_resolve_us"].to_u64(); u64 profiled_unit_instantiate = perf["unit_instantiate_us"].to_u64(); u64 profiled_unit_initialize = perf["unit_initialize_us"].to_u64(); String profiled_mysql_operations = json_encode(perf["mysql_operations"]); 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["guest_us"].to_f64() > 0 && perf["component_resolve_count"].to_u64() == profiled_components && 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_instantiate_us"].to_u64() == profiled_unit_instantiate && perf["unit_initialize_us"].to_u64() == profiled_unit_initialize && json_encode(perf["mysql_operations"]) == profiled_mysql_operations; + 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 && 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; } check("request_perf() stages stable repeated snapshots", perf_stable, json_encode(perf)); diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index aa38e96..cc9a3b2 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -123,6 +123,8 @@ struct WasmRequestProfile u64 unit_module_total_us = 0; u64 unit_allocate_total_us = 0; u64 unit_import_total_us = 0; + u64 unit_symbol_resolve_count = 0; + u64 unit_symbol_resolve_total_us = 0; u64 unit_instantiate_total_us = 0; u64 unit_initialize_total_us = 0; u64 hostcall_count = 0; @@ -1357,7 +1359,11 @@ private: } if(mod_name == "env" && is_func_import) { + auto resolve_start = std::chrono::steady_clock::now(); auto func = resolve_func(name); + unit_symbol_resolve_count++; + unit_symbol_resolve_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - resolve_start).count(); if(!func) return(source_path + ": unresolved import env." + wasm_trace_demangle(name)); imports.push_back(*func); @@ -1367,7 +1373,12 @@ private: { wasmtime::GlobalType global_type(wasmtime::ValType::i32(), true); u32 address = 0; - if(resolve_data(name, address)) + auto resolve_start = std::chrono::steady_clock::now(); + bool resolved = resolve_data(name, address); + unit_symbol_resolve_count++; + unit_symbol_resolve_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - resolve_start).count(); + if(resolved) { auto global = wasmtime::Global::create(cx, global_type, wasmtime::Val((int32_t)address)); if(!global) @@ -1388,7 +1399,11 @@ private: } if(mod_name == "GOT.func") { + auto resolve_start = std::chrono::steady_clock::now(); auto func = resolve_func(name); + unit_symbol_resolve_count++; + unit_symbol_resolve_total_us += (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - resolve_start).count(); if(!func) return(source_path + ": unresolved GOT.func." + wasm_trace_demangle(name)); u32 slot = 0; @@ -1915,6 +1930,8 @@ private: response["unit_module_us"] = (f64)self->unit_module_total_us; response["unit_allocate_us"] = (f64)self->unit_allocate_total_us; response["unit_import_us"] = (f64)self->unit_import_total_us; + response["unit_symbol_resolve_count"] = (f64)self->unit_symbol_resolve_count; + response["unit_symbol_resolve_us"] = (f64)self->unit_symbol_resolve_total_us; response["unit_instantiate_us"] = (f64)self->unit_instantiate_total_us; response["unit_initialize_us"] = (f64)self->unit_initialize_total_us; f64 running_us = response["running_us"].to_f64();