diff --git a/docs/wasm-runtime-architecture.md b/docs/wasm-runtime-architecture.md index bebc1bf..26f21cd 100644 --- a/docs/wasm-runtime-architecture.md +++ b/docs/wasm-runtime-architecture.md @@ -169,7 +169,11 @@ hostcalls without per-import timeout bookkeeping. `request_perf()` reports worker module-cache hits and misses and divides a miss into artifact lookup, wasm read, custom-section parse, serialized-module deserialization or wasm compilation, and immutable import classification. This -keeps cold-worker module latency distinguishable without exposing source paths. +includes a bounded per-request unit trace with site-relative unit names, cache +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. 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 diff --git a/site/tests/services.uce b/site/tests/services.uce index 3e732a0..c8a5ee0 100644 --- a/site/tests/services.uce +++ b/site/tests/services.uce @@ -147,11 +147,17 @@ RENDER(Request& context) } DValue mysql_perf = request_perf(); String mysql_operations = json_encode(mysql_perf["mysql_operations"]); + String unit_module_operations = json_encode(mysql_perf["unit_module_operations"]); mark( "request_perf() exposes bounded query-text-free MySQL operations", mysql_perf["mysql_operation_count"].to_u64() > 0 && mysql_operations.find("\"connect\"") != String::npos && mysql_operations.find("\"source\"") != String::npos && mysql_operations.find("\"us\"") != String::npos && mysql_operations.find("SHOW DATABASES") == String::npos && (mysql_error_text != "" || mysql_perf["mysql_connection_open_count"].to_u64() + mysql_perf["mysql_connection_reuse_count"].to_u64() > 0) && mysql_perf["mysql_operations_dropped"].to_u64() == 0 ? "pass" : "fail", mysql_operations ); + mark( + "request_perf() identifies bounded site-relative unit module work", + unit_module_operations != "[]" && unit_module_operations.find("services.uce") != String::npos && unit_module_operations.find("\"source\"") != String::npos && unit_module_operations.find("/Code/") == String::npos && mysql_perf["unit_module_operations_dropped"].to_u64() == 0 ? "pass" : "fail", + unit_module_operations + ); site_tests_summary(passed, failed, skipped, "Memcache or MySQL checks are allowed to skip cleanly when the corresponding service is not available on the development host."); site_tests_page_end(); diff --git a/src/wasm/worker.cpp b/src/wasm/worker.cpp index 2eba71a..e8c8346 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -139,6 +139,19 @@ struct WasmMySQLOperation u64 elapsed_us = 0; }; +struct WasmUnitModuleOperation +{ + String unit; + String source; + u64 total_us = 0; + u64 lookup_us = 0; + u64 read_us = 0; + u64 read_bytes = 0; + u64 parse_us = 0; + u64 build_us = 0; + u64 classify_us = 0; +}; + struct WasmRequestProfile { u64 dispatch_us = 0; @@ -163,6 +176,8 @@ struct WasmRequestProfile u64 unit_module_parse_total_us = 0; u64 unit_module_compile_total_us = 0; u64 unit_module_classify_total_us = 0; + u64 unit_module_operations_dropped = 0; + std::vector unit_module_operations; u64 unit_allocate_total_us = 0; u64 unit_import_total_us = 0; u64 unit_symbol_resolve_count = 0; @@ -1561,8 +1576,9 @@ private: auto module_start = std::chrono::steady_clock::now(); WasmUnitModuleLoadProfile module_profile; auto mod = worker.unit_module(source_path, error, module_profile); - unit_module_total_us += (u64)std::chrono::duration_cast( + u64 module_total_us = (u64)std::chrono::duration_cast( std::chrono::steady_clock::now() - module_start).count(); + unit_module_total_us += module_total_us; unit_module_cache_hit_count += module_profile.cache_hit ? 1 : 0; unit_module_cache_miss_count += module_profile.cache_hit ? 0 : 1; unit_module_serialized_cache_hit_count += module_profile.serialized_cache_hit ? 1 : 0; @@ -1573,6 +1589,30 @@ private: unit_module_parse_total_us += module_profile.parse_us; unit_module_compile_total_us += module_profile.compile_us; unit_module_classify_total_us += module_profile.classify_us; + if(unit_module_operations.size() < 32) + { + String unit_name = source_path; + String site_prefix = worker.cfg.site_root; + if(site_prefix != "" && site_prefix.back() != '/') + site_prefix += "/"; + if(site_prefix != "" && unit_name.rfind(site_prefix, 0) == 0) + unit_name = unit_name.substr(site_prefix.size()); + else if(unit_name.rfind('/') != String::npos) + unit_name = unit_name.substr(unit_name.rfind('/') + 1); + WasmUnitModuleOperation operation; + operation.unit = unit_name; + 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; + operation.read_us = module_profile.read_us; + operation.read_bytes = module_profile.read_bytes; + operation.parse_us = module_profile.parse_us; + operation.build_us = module_profile.compile_us; + operation.classify_us = module_profile.classify_us; + unit_module_operations.push_back(operation); + } + else + unit_module_operations_dropped++; if(!mod) return(error); // Compiling/deserializing a cold module is host work. Refresh the guest @@ -2230,6 +2270,22 @@ private: response["unit_module_parse_us"] = (f64)self->unit_module_parse_total_us; response["unit_module_compile_us"] = (f64)self->unit_module_compile_total_us; response["unit_module_classify_us"] = (f64)self->unit_module_classify_total_us; + response["unit_module_operations_dropped"] = (f64)self->unit_module_operations_dropped; + response["unit_module_operations"].set_array(); + for(auto& operation : self->unit_module_operations) + { + DValue item; + item["unit"] = operation.unit; + item["source"] = operation.source; + item["total_us"] = (f64)operation.total_us; + item["lookup_us"] = (f64)operation.lookup_us; + item["read_us"] = (f64)operation.read_us; + item["read_bytes"] = (f64)operation.read_bytes; + item["parse_us"] = (f64)operation.parse_us; + item["build_us"] = (f64)operation.build_us; + item["classify_us"] = (f64)operation.classify_us; + response["unit_module_operations"].push(item); + } 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;