diff --git a/site/doc/pages/mysql_connected.txt b/site/doc/pages/mysql_connected.txt index fe36669..956a0aa 100644 --- a/site/doc/pages/mysql_connected.txt +++ b/site/doc/pages/mysql_connected.txt @@ -17,4 +17,5 @@ if(!mysql_connected(db)) { print("database unavailable: ", mysql_error(db), "\n"); } +else print("database connected\n"); if(db != 0) mysql_disconnect(db); diff --git a/site/doc/pages/request_perf.txt b/site/doc/pages/request_perf.txt index 3fef0b5..e3c4bc3 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -15,7 +15,7 @@ Hostcall totals include component resolution. When `WASM_PROFILE_HOSTCALL_CPU=1` 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. -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. +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. `entry_unit_load_count` and `entry_unit_materialize_us` isolate the initial page/CLI unit; `dynamic_include_load_count` and `dynamic_include_materialize_us` isolate side units first requested through `component()`. The per-unit bounded list adds `kind` (`entry` or `component`) and `materialize_us`, the inclusive host-side time from module acquisition through request binding. Repeated handlers from an already loaded unit are excluded. `unit_module_cache_hit_count` and `unit_module_cache_miss_count` divide module loads by the worker's compiled-module cache. A miss is further identified by `unit_module_serialized_cache_hit_count` when Wasmtime deserializes the current `.cwasm`; `unit_module_compile_count` means it fell back to compiling the `.wasm`. `unit_module_lookup_us`, `unit_module_read_us`, `unit_module_read_bytes`, `unit_module_parse_us`, `unit_module_compile_us`, and `unit_module_classify_us` divide `unit_module_us` into artifact stat/cache lookup, wasm metadata/full-artifact read volume, custom-section parse, deserialize-or-compile, and immutable import classification. A current serialized-module hit scans only section headers and the `dylink.0`/`uce.abi` payloads; compilation fallback reads the complete wasm. The phase sum can be below the total because allocation and cache publication overhead remain in the aggregate. diff --git a/site/tests/components.uce b/site/tests/components.uce index 090f0c4..a651958 100644 --- a/site/tests/components.uce +++ b/site/tests/components.uce @@ -55,6 +55,13 @@ RENDER(Request& context) check("component_render() named handler", footer_markup.find("Named footer render") != String::npos, footer_markup); check("component(\"unit:NAME\") named handler", header_markup.find("Component Output") != String::npos && header_markup.find("This body comes from component()") == String::npos, header_markup); check("ob_start() / ob_get_close()", buffer_markup == "buffered-text", buffer_markup); + DValue perf = request_perf(); + String unit_operations = json_encode(perf["unit_module_operations"]); + check( + "request_perf() separates entry code from dynamic component materialization", + perf["entry_unit_load_count"].to_u64() == 1 && perf["entry_unit_materialize_us"].to_u64() > 0 && perf["dynamic_include_load_count"].to_u64() > 0 && perf["dynamic_include_materialize_us"].to_u64() > 0 && unit_operations.find("\"kind\": \"entry\"") != String::npos && unit_operations.find("\"kind\": \"component\"") != String::npos && unit_operations.find("\"materialize_us\"") != String::npos, + unit_operations + ); ?>

Rendered Component

diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 6a6d535..ebfffce 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -146,8 +146,10 @@ struct WasmMySQLOperation struct WasmUnitModuleOperation { String unit; + String kind; String source; u64 total_us = 0; + u64 materialize_us = 0; u64 lookup_us = 0; u64 read_us = 0; u64 read_bytes = 0; @@ -179,6 +181,10 @@ struct WasmRequestProfile u64 component_load_total_us = 0; u64 component_link_total_us = 0; u64 unit_load_count = 0; + u64 entry_unit_load_count = 0; + u64 entry_unit_materialize_total_us = 0; + u64 dynamic_include_load_count = 0; + u64 dynamic_include_materialize_total_us = 0; u64 unit_module_total_us = 0; u64 unit_module_cache_hit_count = 0; u64 unit_module_cache_miss_count = 0; @@ -1417,7 +1423,7 @@ public: { entry_dir = dir_of(entry_source_path); size_t unit_index = 0; - String error = load_unit(entry_source_path, unit_index); + String error = load_unit(entry_source_path, "entry", unit_index); if(error != "") return(error); bool present = (bool)unit_func(unit_index, handler_export_symbol(handler)); @@ -1630,7 +1636,7 @@ private: // ---- unit loading (the ยง6 sequence) ------------------------------------ - String load_unit(const String& source_path, size_t& unit_index_out) + String load_unit(const String& source_path, String kind, size_t& unit_index_out) { auto known = units_by_source.find(source_path); if(known != units_by_source.end()) @@ -1640,6 +1646,7 @@ private: } unit_load_count++; + auto materialize_start = std::chrono::steady_clock::now(); String error; auto module_start = std::chrono::steady_clock::now(); WasmUnitModuleLoadProfile module_profile; @@ -1670,6 +1677,7 @@ private: unit_name = unit_name.substr(unit_name.rfind('/') + 1); WasmUnitModuleOperation operation; operation.unit = unit_name; + operation.kind = kind; operation.source = !mod ? "error" : module_profile.cache_hit ? "worker" : module_profile.serialized_cache_hit ? "serialized" : "compiled"; operation.total_us = module_total_us; operation.lookup_us = module_profile.lookup_us; @@ -1888,6 +1896,20 @@ private: unit_initialize_total_us += initialize_us; if(module_operation_index < unit_module_operations.size()) unit_module_operations[module_operation_index].initialize_us = initialize_us; + u64 materialize_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - materialize_start).count(); + if(kind == "entry") + { + entry_unit_load_count++; + entry_unit_materialize_total_us += materialize_us; + } + else if(kind == "component") + { + dynamic_include_load_count++; + dynamic_include_materialize_total_us += materialize_us; + } + if(module_operation_index < unit_module_operations.size()) + unit_module_operations[module_operation_index].materialize_us = materialize_us; // Exclude the rest of host-side loading as well. A genuine runaway loop // makes no loads, so it still trips the deadline. ctx().set_epoch_deadline(worker.cfg.epoch_deadline_ticks); @@ -2166,7 +2188,7 @@ private: auto load_start = std::chrono::steady_clock::now(); size_t unit_index = 0; - String error = load_unit(resolved, unit_index); + String error = load_unit(resolved, "component", unit_index); component_load_total_us += (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - load_start).count(); if(error != "") @@ -2424,6 +2446,10 @@ private: response["component_load_us"] = (f64)self->component_load_total_us; response["component_link_us"] = (f64)self->component_link_total_us; response["unit_load_count"] = (f64)self->unit_load_count; + response["entry_unit_load_count"] = (f64)self->entry_unit_load_count; + response["entry_unit_materialize_us"] = (f64)self->entry_unit_materialize_total_us; + response["dynamic_include_load_count"] = (f64)self->dynamic_include_load_count; + response["dynamic_include_materialize_us"] = (f64)self->dynamic_include_materialize_total_us; response["unit_module_us"] = (f64)self->unit_module_total_us; response["unit_module_cache_hit_count"] = (f64)self->unit_module_cache_hit_count; response["unit_module_cache_miss_count"] = (f64)self->unit_module_cache_miss_count; @@ -2441,8 +2467,10 @@ private: { DValue item; item["unit"] = operation.unit; + item["kind"] = operation.kind; item["source"] = operation.source; item["total_us"] = (f64)operation.total_us; + item["materialize_us"] = (f64)operation.materialize_us; item["lookup_us"] = (f64)operation.lookup_us; item["read_us"] = (f64)operation.read_us; item["read_bytes"] = (f64)operation.read_bytes;