diff --git a/site/demo/index.uce b/site/demo/index.uce index 3036114..6378716 100644 --- a/site/demo/index.uce +++ b/site/demo/index.uce @@ -98,6 +98,7 @@ RENDER(Request& context) print("Guest us: ", (f64)perf["guest_us"].to_f64(), "\n"); print("Hostcalls: ", (u64)perf["hostcall_count"].to_u64(), " / ", (u64)perf["hostcall_us"].to_u64(), " us\n"); print("MySQL hostcalls: ", (u64)perf["mysql_hostcall_count"].to_u64(), " / ", (u64)perf["mysql_hostcall_us"].to_u64(), " us\n"); + print("MySQL operations: ", json_encode(perf["mysql_operations"]), " / dropped ", (u64)perf["mysql_operations_dropped"].to_u64(), "\n"); print("Memcache hostcalls: ", (u64)perf["memcache_hostcall_count"].to_u64(), " / ", (u64)perf["memcache_hostcall_us"].to_u64(), " us\n"); print("Component resolves: ", (u64)perf["component_resolve_count"].to_u64(), " / ", (u64)perf["component_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 9813f22..9b2594a 100644 --- a/site/doc/pages/request_perf.txt +++ b/site/doc/pages/request_perf.txt @@ -9,7 +9,7 @@ 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. 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. 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; `mysql_operations_dropped` reports any overflow. The profiling hostcall itself is excluded from those totals so repeated snapshots remain comparable. :example DValue perf = request_perf(); diff --git a/site/tests/io.uce b/site/tests/io.uce index eea9342..18ee439 100644 --- a/site/tests/io.uce +++ b/site/tests/io.uce @@ -155,10 +155,11 @@ RENDER(Request& context) 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(); + 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_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 && json_encode(perf["mysql_operations"]) == profiled_mysql_operations; } check("request_perf() stages stable repeated snapshots", perf_stable, json_encode(perf)); diff --git a/site/tests/services.uce b/site/tests/services.uce index a3332db..823aac3 100644 --- a/site/tests/services.uce +++ b/site/tests/services.uce @@ -145,6 +145,13 @@ RENDER(Request& context) "inserted=" + std::to_string((u64)inserted) + " updated=" + std::to_string((u64)updated) + " selected=" + std::to_string((u64)selected) ); } + DValue mysql_perf = request_perf(); + String mysql_operations = json_encode(mysql_perf["mysql_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("\"us\"") != String::npos && mysql_operations.find("SHOW DATABASES") == String::npos && mysql_perf["mysql_operations_dropped"].to_u64() == 0 ? "pass" : "fail", + mysql_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 c3e086a..a06cee4 100644 --- a/src/wasm/worker.cpp +++ b/src/wasm/worker.cpp @@ -99,6 +99,12 @@ struct WasmWorkerConfig std::set hostcall_blocklist; }; +struct WasmMySQLOperation +{ + String op; + u64 elapsed_us = 0; +}; + struct WasmRequestProfile { u64 dispatch_us = 0; @@ -111,6 +117,9 @@ struct WasmRequestProfile u64 hostcall_total_us = 0; u64 mysql_hostcall_count = 0; u64 mysql_hostcall_total_us = 0; + u64 mysql_operation_count = 0; + u64 mysql_operations_dropped = 0; + std::vector mysql_operations; u64 memcache_hostcall_count = 0; u64 memcache_hostcall_total_us = 0; }; @@ -1769,6 +1778,16 @@ private: response["hostcall_us"] = (f64)self->hostcall_total_us; response["mysql_hostcall_count"] = (f64)self->mysql_hostcall_count; response["mysql_hostcall_us"] = (f64)self->mysql_hostcall_total_us; + response["mysql_operation_count"] = (f64)self->mysql_operation_count; + response["mysql_operations_dropped"] = (f64)self->mysql_operations_dropped; + response["mysql_operations"].set_array(); + for(auto& operation : self->mysql_operations) + { + DValue item; + item["op"] = operation.op; + item["us"] = (f64)operation.elapsed_us; + response["mysql_operations"].push(item); + } response["memcache_hostcall_count"] = (f64)self->memcache_hostcall_count; response["memcache_hostcall_us"] = (f64)self->memcache_hostcall_total_us; response["component_resolve_count"] = (f64)self->component_resolve_count; @@ -2480,9 +2499,11 @@ private: { DValue request, response; String decode_error; + String op; + auto operation_started = std::chrono::steady_clock::now(); if(ucb_decode(encoded, request, &decode_error)) { - String op = request["op"].to_string(); + op = request["op"].to_string(); if(op == "connect") { String host = request["host"].to_string(); @@ -2546,6 +2567,18 @@ private: } } } + if(op != "") + { + WasmMySQLOperation operation; + operation.op = op; + operation.elapsed_us = (u64)std::chrono::duration_cast( + std::chrono::steady_clock::now() - operation_started).count(); + self->mysql_operation_count++; + if(self->mysql_operations.size() < 64) + self->mysql_operations.push_back(operation); + else + self->mysql_operations_dropped++; + } out = ucb_encode(response); if(buf == 0) self->hostcall_stage(stage_key, out);