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

Profile logical MySQL operations

Browse Source
This commit is contained in:
udo 2026-07-16 16:31:13 +00:00
parent 9dc9c61af6
commit b04ce3d005
5 changed files with 45 additions and 3 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
site/demo/index.uce
View File

@ -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");

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

@ -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();

3
site/tests/io.uce
View File

@ -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));

7
site/tests/services.uce
View File

@ -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();

35
src/wasm/worker.cpp
View File

@ -99,6 +99,12 @@ struct WasmWorkerConfig
std::set<String> 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<WasmMySQLOperation> 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::microseconds>(
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);