diff --git a/CHANGELOG.md b/CHANGELOG.md index de4bb39..2a4b0bb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,11 @@ GitHub are taken from the matching section here. large and small icons and their hover text. Text and image fields accept `{place_name}` and `{place_icon}`. Set `text.state: ""` to hide the "Playing Roblox" line. +- `--profile ` writes a Chrome-format trace of the Vulkan adapter's + work: presents, GPU waits, submits, ETC2 texture decode, and pipeline and + shader creation. Open it in ui.perfetto.dev. `docs/BENCHMARKING.md` + describes the benchmark runs, and `scripts/summarize_profile_trace.py` + turns traces into a before and after table. ### Fixed diff --git a/docs/BENCHMARKING.md b/docs/BENCHMARKING.md new file mode 100644 index 0000000..f708b0e --- /dev/null +++ b/docs/BENCHMARKING.md @@ -0,0 +1,97 @@ +# Benchmarking + +A pull request that claims a speedup shows before and after numbers taken +the way this guide describes. Numbers from different machines are not +compared with each other. Each run is compared with a run on the same +machine. + +## Two layers, two tools + +Roblox measures its own work. Nightcap measures the layer between Roblox and +your driver. + +| Layer | What it covers | Tool | +| --- | --- | --- | +| Roblox | Scripts, physics, rendering jobs, network | Roblox's stats overlays, Shift+F4 and Shift+F5 in game | +| Nightcap | Vulkan adapter: present, swapchain and GPU waits, submits, ETC2 texture decode, pipeline and shader creation | `--profile` | + +A Nightcap change should move the `--profile` numbers. If it only moves the +Roblox overlay numbers, say so in the pull request, since the cause is then +less direct. + +## Recording a trace + +```sh +mocktail --profile ~/nightcap-before.json +``` + +The Vulkan adapter writes a Chrome-format trace to that file, a few times a +second. The file is valid JSON after every write, so a session that crashes +or is killed still leaves a readable trace. Exit from the Roblox menu when you are done. Open the file +in [ui.perfetto.dev](https://ui.perfetto.dev) or `chrome://tracing`. + +Expect about 130 bytes per event, around 15 MB per minute at 240 FPS. +Profiling is off unless `--profile` is given, and `MOCKTAIL_PROFILE_TRACE` +does the same thing as the flag. + +### What the trace contains + +Each slice is named after the call it times, on the thread that made it. + +| Category | Slices | Arguments | +| --- | --- | --- | +| `present` | `vkQueuePresentKHR`: the whole adapter present, including the text overlay | `result` | +| `present` | `host present`: the host driver's present, nested inside the slice above | | +| `wait` | `vkAcquireNextImageKHR`, `vkAcquireNextImage2KHR`, `vkWaitForFences`, `vkWaitSemaphores`, `vkWaitSemaphoresKHR`, `vkQueueWaitIdle`, `vkDeviceWaitIdle` | | +| `submit` | `vkQueueSubmit`, `vkQueueSubmit2`, `vkQueueSubmit2KHR` | `submits` | +| `texture` | `etc2 decode`: CPU decode of ETC2 textures before a submit | `uploads`, `compressed_bytes`, `decoded_bytes` | +| `pipeline` | `vkCreateGraphicsPipelines`, `vkCreateComputePipelines` | `count`, `cache` (1 when a pipeline cache was passed), `result` | +| `pipeline` | `vkCreateShaderModule` | `bytes`, `result` | +| `pipeline` | `vkCreatePipelineCache` | `initial_bytes`, `result` | + +The `frame interval (ms)` counter is the time between successive adapter +presents. `vkQueuePresentKHR` time minus `host present` time is the adapter's +own cost per frame. + +## The benchmark runs + +Run every scenario before and after the change, on the same build type +(`make build`), with the same `config.yaml`. Close other GPU-heavy apps. +Record `graphics.frame_rate_limit` and `graphics.vsync` in the pull request, +because a frame cap hides frame time gains. + +| Scenario | How to start | What to do | What it shows | +| --- | --- | --- | --- | +| Home screen, cold | `mocktail --profile home-cold.json` with an empty shader cache (below) | Wait 30 s on the home screen, exit | First-load stutter: `pipeline` and `texture` slices | +| Tower of Hell | `mocktail --profile toh.json --launch-uri "roblox://experiences/start?placeId=1962086868"` | Stand still at spawn for 60 s, exit | Steady-state frame time on a light scene | +| Murder Mystery 2 | `mocktail --profile mm2.json --launch-uri "roblox://experiences/start?placeId=142823291"` | Stay in the lobby for 60 s, exit | Frame time with many players and a busier scene | + +For the cold run, point the driver's shader cache at an empty directory, so +your normal cache is left alone: + +```sh +cache=$(mktemp -d) +MESA_SHADER_CACHE_DIR="$cache" __GL_SHADER_DISK_CACHE_PATH="$cache" \ + mocktail --profile home-cold.json +``` + +`MESA_SHADER_CACHE_DIR` applies to Mesa drivers (AMD, Intel) and +`__GL_SHADER_DISK_CACHE_PATH` to the NVIDIA driver. + +Run each scenario three times and keep the median run, since one run can +catch a background stall. + +## Comparing runs + +```sh +scripts/summarize_profile_trace.py toh-before.json toh-after.json +``` + +This prints a Markdown table with one column per trace: frame count, frame +interval mean, p50, p95, p99 and max, then count, total, mean, p99 and max +for every slice name, largest total first. Paste the table into the pull +request and attach both traces. + +For frame time, compare p95 and p99 as well as the mean. Stutter shows up in +the tail first. For first-load work, compare the `total (ms)` rows of the +`pipeline` and `texture` slices from the cold run. diff --git a/docs/ROADMAP.md b/docs/ROADMAP.md index 5b5b5dc..164e991 100644 --- a/docs/ROADMAP.md +++ b/docs/ROADMAP.md @@ -51,14 +51,16 @@ you can switch it all off in one click. Every performance change should come with numbers. Today they come with a feeling. -- A frame time overlay, toggled by a key and a config flag, showing CPU time, - GPU time, and present latency. -- Shader compile and pipeline cache tracing, so first-load stutter can be - measured and cut. -- A `--profile` flag that writes a Chrome-format trace file, readable in - `ui.perfetto.dev` and `chrome://tracing`. -- A short benchmark guide in `docs/` with a fixed set of experiences, so - before and after numbers can be compared across machines. +Roblox's own stats overlays (Shift+F4, Shift+F5) already cover the game's +frame time, so this item measures only the layer Roblox cannot see. + +- A `--profile` flag that writes a Chrome-format trace of the Vulkan + adapter's work, readable in `ui.perfetto.dev` and `chrome://tracing`. +- Shader compile and pipeline cache tracing in that trace, so first-load + stutter can be measured and cut. +- A short benchmark guide, [BENCHMARKING.md](BENCHMARKING.md), with a fixed + set of experiences, so before and after numbers can be compared on one + machine. Done when a pull request that claims a speedup can show the trace that proves it. diff --git a/include/mocktail/graphics/chrome_trace_writer.h b/include/mocktail/graphics/chrome_trace_writer.h new file mode 100644 index 0000000..eae2d16 --- /dev/null +++ b/include/mocktail/graphics/chrome_trace_writer.h @@ -0,0 +1,121 @@ +#ifndef MOCKTAIL_GRAPHICS_CHROME_TRACE_WRITER_H_ +#define MOCKTAIL_GRAPHICS_CHROME_TRACE_WRITER_H_ + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace mocktail { +namespace graphics { + +// Environment variable naming the trace file the Vulkan adapter writes. +inline constexpr char kProfileTraceEnvironment[] = "MOCKTAIL_PROFILE_TRACE"; + +struct TraceArg { + const char* key; + std::int64_t value; +}; + +// CLOCK_MONOTONIC in nanoseconds. +std::uint64_t TraceClockNanos(); + +// Writes the Trace Event Format JSON array read by chrome://tracing and +// ui.perfetto.dev. Recording threads only format into a shared buffer; a +// background thread owns file writes, so disk stalls do not land inside the +// measured calls. Events are written in arrival order. Each write ends the +// file with the closing bracket, so a killed session leaves a loadable trace +// holding everything written before it died. +// Names, categories, and keys must outlive the call. +class ChromeTraceWriter final { + public: + static std::unique_ptr Open( + const std::filesystem::path& path, std::string* error); + + ~ChromeTraceWriter(); + ChromeTraceWriter(const ChromeTraceWriter&) = delete; + ChromeTraceWriter& operator=(const ChromeTraceWriter&) = delete; + + // A complete ("X") slice on the calling thread. Slices on one thread must + // nest, which scoped timing gives. + void Slice(const char* name, const char* category, std::uint64_t start_ns, + std::uint64_t end_ns, std::initializer_list args = {}); + void Slice(const char* name, const char* category, std::uint64_t start_ns, + std::uint64_t end_ns, const TraceArg* args, + std::size_t arg_count); + // A counter ("C") sample; each name becomes one counter track. + void Counter(const char* name, std::uint64_t timestamp_ns, double value); + + // Returns once every event recorded before the call is on disk. + void Flush(); + // Flushes, closes the file, and drops later events. Idempotent. + void Close(); + + private: + explicit ChromeTraceWriter(std::FILE* file); + void Append(const char* event, std::size_t size); + void WriterLoop(); + void WritePending(); + + std::FILE* file_; + const int owner_pid_; + std::mutex file_mutex_; // Guards file_ and spare_. + std::string spare_; + std::mutex mutex_; + std::condition_variable wake_; + std::string pending_; + bool first_event_ = true; + bool closed_ = false; + bool stopping_ = false; + std::thread writer_; +}; + +// The process trace named by MOCKTAIL_PROFILE_TRACE, opened on first use. +// Null when profiling is off or the file could not be opened. The writer is +// never destroyed; it is closed when the process exits normally. +ChromeTraceWriter* ActiveProfileTrace(); + +// Times its own lifetime as one slice. A null writer records nothing. +class TraceScope final { + public: + TraceScope(ChromeTraceWriter* writer, const char* name, + const char* category) + : writer_(writer), + name_(name), + category_(category), + start_ns_(writer != nullptr ? TraceClockNanos() : 0) {} + ~TraceScope() { + if (writer_ != nullptr) { + writer_->Slice(name_, category_, start_ns_, TraceClockNanos(), args_, + arg_count_); + } + } + TraceScope(const TraceScope&) = delete; + TraceScope& operator=(const TraceScope&) = delete; + + // Keeps the first kMaxArgs arguments. + void Arg(const char* key, std::int64_t value) { + if (writer_ != nullptr && arg_count_ < kMaxArgs) { + args_[arg_count_++] = {key, value}; + } + } + + private: + static constexpr std::size_t kMaxArgs = 4; + ChromeTraceWriter* writer_; + const char* name_; + const char* category_; + std::uint64_t start_ns_; + TraceArg args_[kMaxArgs]{}; + std::size_t arg_count_ = 0; +}; + +} // namespace graphics +} // namespace mocktail + +#endif // MOCKTAIL_GRAPHICS_CHROME_TRACE_WRITER_H_ diff --git a/include/runtime/command_line.h b/include/runtime/command_line.h index 8a491a9..f0d1c7f 100644 --- a/include/runtime/command_line.h +++ b/include/runtime/command_line.h @@ -33,6 +33,8 @@ struct CommandLineOptions { // Requests one explicit launch of the provider latest without promoting it // into the managed payload state. bool force_run_latest = false; + // Chrome trace file the Vulkan adapter writes; empty when not profiling. + std::string profile_trace_path; }; struct CommandLineParseResult { diff --git a/scripts/summarize_profile_trace.py b/scripts/summarize_profile_trace.py new file mode 100755 index 0000000..64a2c64 --- /dev/null +++ b/scripts/summarize_profile_trace.py @@ -0,0 +1,126 @@ +#!/usr/bin/env python3 +# Copyright 2026 Mocktail Project Authors +# Licensed under the Apache License, Version 2.0. +"""Summarizes `--profile` traces as a Markdown table for pull requests. + +Usage: summarize_profile_trace.py TRACE [TRACE ...] + +Each trace gets its own column, so `before.json after.json` compares them. +Frame times come from the "frame interval (ms)" counter; every other row is +a slice name recorded by the Vulkan adapter. +""" + +from __future__ import annotations + +from dataclasses import dataclass +import json +import math +from pathlib import Path +import sys +from typing import Iterable + +FRAME_COUNTER = "frame interval (ms)" + + +@dataclass(frozen=True) +class Distribution: + count: int + total: float + mean: float + p50: float + p95: float + p99: float + max: float + + +@dataclass(frozen=True) +class Summary: + frames: Distribution | None + slices: dict[str, Distribution] + + +def _nearest_rank(ordered: list[float], percent: float) -> float: + rank = max(1, math.ceil(percent / 100 * len(ordered))) + return ordered[rank - 1] + + +def _distribution(values: list[float]) -> Distribution: + ordered = sorted(values) + total = sum(ordered) + return Distribution(count=len(ordered), total=total, + mean=total / len(ordered), + p50=_nearest_rank(ordered, 50), + p95=_nearest_rank(ordered, 95), + p99=_nearest_rank(ordered, 99), max=ordered[-1]) + + +def summarize(events: Iterable[dict]) -> Summary: + frames: list[float] = [] + slices: dict[str, list[float]] = {} + for event in events: + phase = event.get("ph") + if phase == "C" and event.get("name") == FRAME_COUNTER: + frames.append(float(event["args"]["value"])) + elif phase == "X": + slices.setdefault(event["name"], []).append(event["dur"] / 1000) + return Summary( + frames=_distribution(frames) if frames else None, + slices={name: _distribution(values) + for name, values in slices.items()}) + + +def _row(label: str, cells: list[str]) -> str: + return "| " + " | ".join([label, *cells]) + " |" + + +def _cell(distribution: Distribution | None, field: str) -> str: + if distribution is None: + return "-" + if field == "count": + return str(distribution.count) + return f"{getattr(distribution, field):.2f}" + + +def _metric_row(label: str, distributions: list[Distribution | None], + field: str) -> str: + return _row(label, [_cell(item, field) for item in distributions]) + + +def to_markdown(traces: list[tuple[str, Summary]]) -> str: + summaries = [summary for _, summary in traces] + lines = [_row("metric", [name for name, _ in traces]), + _row("---", ["---:"] * len(traces))] + + frames = [summary.frames for summary in summaries] + lines.append(_metric_row("frames", frames, "count")) + if any(frames): + lines += [_metric_row(f"frame interval {field} (ms)", frames, field) + for field in ("mean", "p50", "p95", "p99", "max")] + + # Largest total time first, taken from whichever trace spent the most. + totals: dict[str, float] = {} + for summary in summaries: + for name, distribution in summary.slices.items(): + totals[name] = max(totals.get(name, 0.0), distribution.total) + for name in sorted(totals, key=lambda name: -totals[name]): + column = [summary.slices.get(name) for summary in summaries] + lines.append(_metric_row(f"{name} count", column, "count")) + lines += [_metric_row(f"{name} {field} (ms)", column, field) + for field in ("total", "mean", "p99", "max")] + return "\n".join(lines) + + +def main(arguments: list[str]) -> int: + if not arguments: + print(__doc__.strip(), file=sys.stderr) + return 2 + traces = [] + for argument in arguments: + path = Path(argument) + traces.append((path.name, summarize(json.loads(path.read_text())))) + print(to_markdown(traces)) + return 0 + + +if __name__ == "__main__": + sys.exit(main(sys.argv[1:])) diff --git a/src/graphics/bionic_vulkan_loader_adapter.cc b/src/graphics/bionic_vulkan_loader_adapter.cc index fb30b5f..bc32c9f 100644 --- a/src/graphics/bionic_vulkan_loader_adapter.cc +++ b/src/graphics/bionic_vulkan_loader_adapter.cc @@ -17,6 +17,7 @@ #include #include "mocktail/graphics/android_vulkan_wsi_adapter.h" +#include "mocktail/graphics/chrome_trace_writer.h" #include "mocktail/graphics/present_mode_policy.h" #include "mocktail/graphics/vulkan_etc2_emulation.h" #include "mocktail/graphics/vulkan_text_overlay_compositor.h" @@ -1011,7 +1012,8 @@ VkResult WaitForSemaphoresObserved(const char* call_name, } return VK_ERROR_INITIALIZATION_FAILED; } - static_cast(call_name); + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + call_name, "wait"); const VkResult result = host_wait(device, wait_info, timeout); if (observation != nullptr) { observation->SetResult(result); @@ -1130,7 +1132,12 @@ ObservedHostQueuePresent(VkQueue queue, const VkPresentInfoKHR* present_info) { } const bool fps_trace = FpsTraceEnabled(); const std::uint64_t present_start_ns = fps_trace ? MonotonicNanos() : 0; - const VkResult result = host_present(queue, present_info); + VkResult result = VK_SUCCESS; + { + mocktail::graphics::TraceScope scope( + mocktail::graphics::ActiveProfileTrace(), "host present", "present"); + result = host_present(queue, present_info); + } if (fps_trace) { PresentWaitTrace().Record(present_start_ns); } @@ -1142,6 +1149,119 @@ ObservedHostQueuePresent(VkQueue queue, const VkPresentInfoKHR* present_info) { return result; } +// Samples the time between successive adapter present calls. +void RecordProfiledFrame(mocktail::graphics::ChromeTraceWriter* trace, + std::uint64_t present_start_ns) { + static std::atomic previous_start_ns{0}; + const std::uint64_t previous = + previous_start_ns.exchange(present_start_ns, std::memory_order_relaxed); + if (previous != 0 && present_start_ns > previous) { + trace->Counter("frame interval (ms)", present_start_ns, + static_cast(present_start_ns - previous) / 1e6); + } +} + +// Pipeline and shader creation is wrapped only while profiling, so a normal +// session calls the host driver directly. +VkResult VKAPI_CALL ProfiledCreateGraphicsPipelines( + VkDevice device, VkPipelineCache cache, std::uint32_t count, + const VkGraphicsPipelineCreateInfo* infos, + const VkAllocationCallbacks* allocator, VkPipeline* pipelines) { + const auto host = reinterpret_cast( + HostDeviceProc(device, "vkCreateGraphicsPipelines")); + if (host == nullptr) { + return VK_ERROR_INITIALIZATION_FAILED; + } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkCreateGraphicsPipelines", + "pipeline"); + const VkResult result = + host(device, cache, count, infos, allocator, pipelines); + scope.Arg("count", count); + scope.Arg("cache", cache != VK_NULL_HANDLE); + scope.Arg("result", result); + return result; +} + +VkResult VKAPI_CALL ProfiledCreateComputePipelines( + VkDevice device, VkPipelineCache cache, std::uint32_t count, + const VkComputePipelineCreateInfo* infos, + const VkAllocationCallbacks* allocator, VkPipeline* pipelines) { + const auto host = reinterpret_cast( + HostDeviceProc(device, "vkCreateComputePipelines")); + if (host == nullptr) { + return VK_ERROR_INITIALIZATION_FAILED; + } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkCreateComputePipelines", + "pipeline"); + const VkResult result = + host(device, cache, count, infos, allocator, pipelines); + scope.Arg("count", count); + scope.Arg("cache", cache != VK_NULL_HANDLE); + scope.Arg("result", result); + return result; +} + +VkResult VKAPI_CALL ProfiledCreateShaderModule( + VkDevice device, const VkShaderModuleCreateInfo* create_info, + const VkAllocationCallbacks* allocator, VkShaderModule* shader_module) { + const auto host = reinterpret_cast( + HostDeviceProc(device, "vkCreateShaderModule")); + if (host == nullptr) { + return VK_ERROR_INITIALIZATION_FAILED; + } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkCreateShaderModule", "pipeline"); + const VkResult result = host(device, create_info, allocator, shader_module); + scope.Arg("bytes", create_info != nullptr + ? static_cast(create_info->codeSize) + : 0); + scope.Arg("result", result); + return result; +} + +VkResult VKAPI_CALL ProfiledCreatePipelineCache( + VkDevice device, const VkPipelineCacheCreateInfo* create_info, + const VkAllocationCallbacks* allocator, VkPipelineCache* cache) { + const auto host = reinterpret_cast( + HostDeviceProc(device, "vkCreatePipelineCache")); + if (host == nullptr) { + return VK_ERROR_INITIALIZATION_FAILED; + } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkCreatePipelineCache", "pipeline"); + const VkResult result = host(device, create_info, allocator, cache); + scope.Arg("initial_bytes", + create_info != nullptr + ? static_cast(create_info->initialDataSize) + : 0); + scope.Arg("result", result); + return result; +} + +// Null unless profiling is on and `name` is a profiled device command. +PFN_vkVoidFunction ProfileAdapterProc(const char* name) { + if (name == nullptr || mocktail::graphics::ActiveProfileTrace() == nullptr) { + return nullptr; + } + if (std::strcmp(name, "vkCreateGraphicsPipelines") == 0) { + return reinterpret_cast( + ProfiledCreateGraphicsPipelines); + } + if (std::strcmp(name, "vkCreateComputePipelines") == 0) { + return reinterpret_cast( + ProfiledCreateComputePipelines); + } + if (std::strcmp(name, "vkCreateShaderModule") == 0) { + return reinterpret_cast(ProfiledCreateShaderModule); + } + if (std::strcmp(name, "vkCreatePipelineCache") == 0) { + return reinterpret_cast(ProfiledCreatePipelineCache); + } + return nullptr; +} + template Function HostPhysicalDeviceProc(const char* name, const char* alias) { VkInstance instance = VK_NULL_HANDLE; @@ -1397,6 +1517,10 @@ vkGetInstanceProcAddr(VkInstance instance, const char* name) { vkGetPhysicalDeviceSurfacePresentModesKHR) : nullptr; } + if (const PFN_vkVoidFunction profiled = ProfileAdapterProc(name); + profiled != nullptr) { + return HostInstanceProc(instance, name) != nullptr ? profiled : nullptr; + } if (const PFN_vkVoidFunction adapter = AdapterProc(name); adapter != nullptr) { if ((IsDeviceAdapterProc(name) || IsEtc2PhysicalDeviceProc(name)) && @@ -1418,6 +1542,10 @@ VKAPI_ATTR PFN_vkVoidFunction VKAPI_CALL vkGetDeviceProcAddr(VkDevice device, const PFN_vkVoidFunction host = host_get_device_proc_addr != nullptr ? host_get_device_proc_addr(device, name) : nullptr; + if (const PFN_vkVoidFunction profiled = ProfileAdapterProc(name); + profiled != nullptr) { + return host != nullptr ? profiled : nullptr; + } if (!IsDeviceAdapterProc(name)) { return host; } @@ -1599,6 +1727,10 @@ vkDestroyDevice(VkDevice device, const VkAllocationCallbacks* allocator) { host_destroy(device, allocator); } RemoveHostDeviceDispatch(device); + if (auto* trace = mocktail::graphics::ActiveProfileTrace(); + trace != nullptr) { + trace->Flush(); + } } VKAPI_ATTR void VKAPI_CALL vkGetDeviceQueue(VkDevice device, @@ -1754,6 +1886,8 @@ VKAPI_ATTR VkResult VKAPI_CALL vkAcquireNextImageKHR( observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkAcquireNextImageKHR", "wait"); const bool fps_trace = FpsTraceEnabled(); const std::uint64_t acquire_start_ns = fps_trace ? MonotonicNanos() : 0; const VkResult host_result = host_acquire( @@ -1783,6 +1917,8 @@ VKAPI_ATTR VkResult VKAPI_CALL vkAcquireNextImage2KHR( observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkAcquireNextImage2KHR", "wait"); const VkResult host_result = host_acquire(device, acquire_info, image_index); const VkResult result = NormalizeSwapchainResult(host_result); @@ -1807,6 +1943,8 @@ VKAPI_ATTR VkResult VKAPI_CALL vkWaitForFences( observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkWaitForFences", "wait"); const bool fps_trace = FpsTraceEnabled(); const std::uint64_t fence_start_ns = fps_trace ? MonotonicNanos() : 0; const VkResult result = @@ -2002,6 +2140,9 @@ VKAPI_ATTR VkResult VKAPI_CALL vkQueueSubmit( observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkQueueSubmit", "submit"); + scope.Arg("submits", submit_count); if (submits != nullptr) { for (std::uint32_t index = 0; index < submit_count; ++index) { State().etc2.PrepareSubmit(submits[index].pCommandBuffers, @@ -2024,6 +2165,9 @@ VKAPI_ATTR VkResult VKAPI_CALL vkQueueSubmit2( observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkQueueSubmit2", "submit"); + scope.Arg("submits", submit_count); PrepareEtc2Submit2(submit_count, submits); const VkResult result = State().text_overlay.QueueSubmit2( queue, submit_count, submits, fence, host_submit); @@ -2041,6 +2185,9 @@ VKAPI_ATTR VkResult VKAPI_CALL vkQueueSubmit2KHR( observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkQueueSubmit2KHR", "submit"); + scope.Arg("submits", submit_count); PrepareEtc2Submit2(submit_count, submits); const VkResult result = State().text_overlay.QueueSubmit2( queue, submit_count, submits, fence, @@ -2073,6 +2220,8 @@ VKAPI_ATTR VkResult VKAPI_CALL vkQueueWaitIdle(VkQueue queue) { observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkQueueWaitIdle", "wait"); const bool fps_trace = FpsTraceEnabled(); const std::uint64_t idle_start_ns = fps_trace ? MonotonicNanos() : 0; const VkResult result = @@ -2092,6 +2241,8 @@ VKAPI_ATTR VkResult VKAPI_CALL vkDeviceWaitIdle(VkDevice device) { observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::TraceScope scope(mocktail::graphics::ActiveProfileTrace(), + "vkDeviceWaitIdle", "wait"); const VkResult result = State().text_overlay.DeviceWaitIdle(device, host_wait); observation.SetResult(result); @@ -2210,8 +2361,15 @@ vkQueuePresentKHR(VkQueue queue, const VkPresentInfoKHR* present_info) { observation.SetResult(VK_ERROR_INITIALIZATION_FAILED); return VK_ERROR_INITIALIZATION_FAILED; } + mocktail::graphics::ChromeTraceWriter* const trace = + mocktail::graphics::ActiveProfileTrace(); + mocktail::graphics::TraceScope scope(trace, "vkQueuePresentKHR", "present"); + if (trace != nullptr) { + RecordProfiledFrame(trace, mocktail::graphics::TraceClockNanos()); + } const VkResult result = state.text_overlay.QueuePresent( queue, present_info, ObservedHostQueuePresent); + scope.Arg("result", result); const VkResult normalized_result = NormalizeSwapchainResult(result); if (normalized_result == VK_ERROR_OUT_OF_DATE_KHR) { const NoteSurfaceOutOfDateFn note_surface_out_of_date = diff --git a/src/graphics/chrome_trace_writer.cc b/src/graphics/chrome_trace_writer.cc new file mode 100644 index 0000000..e9ed7f2 --- /dev/null +++ b/src/graphics/chrome_trace_writer.cc @@ -0,0 +1,276 @@ +#include "mocktail/graphics/chrome_trace_writer.h" + +#include +#include +#include + +#include +#include +#include +#include +#include + +namespace mocktail { +namespace graphics { +namespace { + +// Buffered bytes that wake the writer before its periodic tick. +constexpr std::size_t kWakeBytes = 256 * 1024; +constexpr std::chrono::milliseconds kWriteInterval{250}; +// Every write ends the file with this, and the next write starts over it. +constexpr char kArrayEnd[] = "\n]\n"; +constexpr long kArrayEndBytes = sizeof(kArrayEnd) - 1; + +void AppendInteger(std::string* out, std::int64_t value) { + char digits[24]; + const auto [end, error] = + std::to_chars(digits, digits + sizeof(digits), value); + out->append(digits, error == std::errc() ? end : digits); +} + +void AppendDouble(std::string* out, double value) { + char digits[32]; + const auto [end, error] = + std::to_chars(digits, digits + sizeof(digits), value); + if (error == std::errc()) { + out->append(digits, end); + } else { + out->push_back('0'); + } +} + +void AppendString(std::string* out, const char* value) { + out->push_back('"'); + for (const char* cursor = value != nullptr ? value : ""; *cursor != '\0'; + ++cursor) { + const unsigned char byte = static_cast(*cursor); + if (byte == '"' || byte == '\\') { + out->push_back('\\'); + out->push_back(static_cast(byte)); + } else if (byte < 0x20) { + static constexpr char kHex[] = "0123456789abcdef"; + out->append("\\u00"); + out->push_back(kHex[byte >> 4]); + out->push_back(kHex[byte & 0xf]); + } else { + out->push_back(static_cast(byte)); + } + } + out->push_back('"'); +} + +void AppendHeader(std::string* out, const char* name, const char* category, + char phase, std::uint64_t timestamp_ns) { + static const std::int64_t pid = getpid(); + thread_local const std::int64_t tid = gettid(); + out->append("{\"name\":"); + AppendString(out, name); + if (category != nullptr) { + out->append(",\"cat\":"); + AppendString(out, category); + } + out->append(",\"ph\":\""); + out->push_back(phase); + out->append("\",\"ts\":"); + AppendInteger(out, static_cast(timestamp_ns / 1000)); + out->append(",\"pid\":"); + AppendInteger(out, pid); + out->append(",\"tid\":"); + AppendInteger(out, tid); +} + +std::string& ThreadScratch() { + thread_local std::string scratch; + scratch.clear(); + return scratch; +} + +} // namespace + +std::uint64_t TraceClockNanos() { + timespec now{}; + clock_gettime(CLOCK_MONOTONIC, &now); + return static_cast(now.tv_sec) * 1'000'000'000ULL + + static_cast(now.tv_nsec); +} + +std::unique_ptr ChromeTraceWriter::Open( + const std::filesystem::path& path, std::string* error) { + std::FILE* file = std::fopen(path.c_str(), "wb"); + if (file == nullptr || std::fputs("[", file) == EOF || + std::fputs(kArrayEnd, file) == EOF || std::fflush(file) != 0) { + const int saved = errno; + if (file != nullptr) { + std::fclose(file); + } + if (error != nullptr) { + *error = "could not open profile trace " + path.string() + ": " + + std::strerror(saved); + } + return nullptr; + } + return std::unique_ptr(new ChromeTraceWriter(file)); +} + +ChromeTraceWriter::ChromeTraceWriter(std::FILE* file) + : file_(file), owner_pid_(getpid()) { + writer_ = std::thread([this] { WriterLoop(); }); +} + +ChromeTraceWriter::~ChromeTraceWriter() { Close(); } + +void ChromeTraceWriter::Slice(const char* name, const char* category, + std::uint64_t start_ns, std::uint64_t end_ns, + std::initializer_list args) { + Slice(name, category, start_ns, end_ns, args.begin(), args.size()); +} + +void ChromeTraceWriter::Slice(const char* name, const char* category, + std::uint64_t start_ns, std::uint64_t end_ns, + const TraceArg* args, std::size_t arg_count) { + std::string& event = ThreadScratch(); + AppendHeader(&event, name, category, 'X', start_ns); + event.append(",\"dur\":"); + const std::uint64_t start_us = start_ns / 1000; + const std::uint64_t end_us = end_ns / 1000; + AppendInteger(&event, static_cast( + end_us > start_us ? end_us - start_us : 0)); + if (args != nullptr && arg_count != 0) { + event.append(",\"args\":{"); + for (std::size_t index = 0; index < arg_count; ++index) { + if (index != 0) { + event.push_back(','); + } + AppendString(&event, args[index].key); + event.push_back(':'); + AppendInteger(&event, args[index].value); + } + event.push_back('}'); + } + event.push_back('}'); + Append(event.data(), event.size()); +} + +void ChromeTraceWriter::Counter(const char* name, std::uint64_t timestamp_ns, + double value) { + std::string& event = ThreadScratch(); + AppendHeader(&event, name, nullptr, 'C', timestamp_ns); + event.append(",\"args\":{\"value\":"); + AppendDouble(&event, value); + event.append("}}"); + Append(event.data(), event.size()); +} + +void ChromeTraceWriter::Append(const char* event, std::size_t size) { + bool wake = false; + { + std::lock_guard lock(mutex_); + if (closed_) { + return; + } + pending_.append(first_event_ ? "\n" : ",\n"); + first_event_ = false; + pending_.append(event, size); + wake = pending_.size() >= kWakeBytes; + } + if (wake) { + wake_.notify_one(); + } +} + +void ChromeTraceWriter::WriterLoop() { + std::unique_lock lock(mutex_); + while (!stopping_) { + wake_.wait_for(lock, kWriteInterval, [this] { + return stopping_ || pending_.size() >= kWakeBytes; + }); + if (stopping_) { + break; + } + lock.unlock(); + WritePending(); + lock.lock(); + } +} + +// The file lock is taken before the buffer lock, so chunks reach the file in +// the order they were buffered. +void ChromeTraceWriter::WritePending() { + std::lock_guard file_lock(file_mutex_); + spare_.clear(); + { + std::lock_guard lock(mutex_); + pending_.swap(spare_); + } + if (file_ == nullptr || spare_.empty()) { + return; + } + if (std::fseek(file_, -kArrayEndBytes, SEEK_END) != 0 || + std::fwrite(spare_.data(), 1, spare_.size(), file_) != spare_.size() || + std::fputs(kArrayEnd, file_) == EOF || std::fflush(file_) != 0) { + std::fprintf(stderr, " [profile] trace write failed: %s\n", + std::strerror(errno)); + std::fclose(file_); + file_ = nullptr; + std::lock_guard lock(mutex_); + closed_ = true; + } +} + +void ChromeTraceWriter::Flush() { WritePending(); } + +void ChromeTraceWriter::Close() { + // A forked child shares the file but not the writer thread. + if (getpid() != owner_pid_) { + return; + } + { + std::lock_guard lock(mutex_); + if (stopping_) { + return; + } + stopping_ = true; + } + wake_.notify_all(); + if (writer_.joinable() && writer_.get_id() != std::this_thread::get_id()) { + writer_.join(); + } + WritePending(); + std::lock_guard file_lock(file_mutex_); + { + std::lock_guard lock(mutex_); + closed_ = true; + } + if (file_ != nullptr) { + std::fclose(file_); + file_ = nullptr; + } +} + +ChromeTraceWriter* ActiveProfileTrace() { + static ChromeTraceWriter* const trace = []() -> ChromeTraceWriter* { + const char* path = std::getenv(kProfileTraceEnvironment); + if (path == nullptr || path[0] == '\0') { + return nullptr; + } + std::string error; + std::unique_ptr writer = + ChromeTraceWriter::Open(path, &error); + if (writer == nullptr) { + std::fprintf(stderr, " [profile] %s\n", error.c_str()); + return nullptr; + } + std::fprintf(stderr, " [profile] writing Chrome trace to %s\n", path); + // Leaked so threads still recording during exit never touch a destroyed + // writer; they find it closed instead. + static struct CloseAtExit { + ChromeTraceWriter* writer; + ~CloseAtExit() { writer->Close(); } + } close_at_exit{writer.get()}; + return writer.release(); + }(); + return trace; +} + +} // namespace graphics +} // namespace mocktail diff --git a/src/graphics/vulkan_etc2_emulation.cc b/src/graphics/vulkan_etc2_emulation.cc index b36b892..aa30ff8 100644 --- a/src/graphics/vulkan_etc2_emulation.cc +++ b/src/graphics/vulkan_etc2_emulation.cc @@ -1,5 +1,6 @@ #include "mocktail/graphics/vulkan_etc2_emulation.h" +#include "mocktail/graphics/chrome_trace_writer.h" #include "mocktail/graphics/texture_override.h" #include @@ -1242,6 +1243,8 @@ void VulkanEtc2Emulation::PrepareSubmit(const VkCommandBuffer* command_buffers, EtcDecodeJob job; job.format = upload.format; job.source = source + layer * compressed_layer; + TraceScope trace_scope(work.empty() ? nullptr : ActiveProfileTrace(), + "etc2 decode", "texture"); job.source_bytes = compressed_layer; job.width = upload.width; job.height = upload.height; @@ -1289,6 +1292,10 @@ void VulkanEtc2Emulation::ReleaseCommandBuffer(VkCommandBuffer command_buffer) { if (record == state_->commands.end()) { return; } + trace_scope.Arg("uploads", static_cast(copies.size())); + trace_scope.Arg("compressed_bytes", + static_cast(compressed_total)); + trace_scope.Arg("decoded_bytes", static_cast(decoded_total)); doomed = std::move(record->second.staging); state_->commands.erase(record); state_->has_commands.store(!state_->commands.empty(), diff --git a/src/runtime/command_line.cc b/src/runtime/command_line.cc index 99f8670..a72ff93 100644 --- a/src/runtime/command_line.cc +++ b/src/runtime/command_line.cc @@ -1,6 +1,7 @@ #include "runtime/command_line.h" #include +#include #include #include #include @@ -78,6 +79,12 @@ CommandLineParseResult ParseCommandLine(int argc, const char* const argv[]) { result.options.allow_unverified_build = true; } else if (argument == "--force-run-latest") { result.options.force_run_latest = true; + } else if (argument == "--profile") { + if (!ReadOptionValue(argc, argv, &index, argument, + &result.options.profile_trace_path, + &result.error)) { + return result; + } } else if (argument == "--launch-uri") { if (!result.options.launch_request_json.empty()) { result.error = "duplicate option: --launch-uri"; @@ -227,6 +234,20 @@ bool ApplyCommandLineEnvironment(const CommandLineOptions& options, error)) { return false; } + if (!options.profile_trace_path.empty()) { + // Absolute, so a later working-directory change cannot move the trace. + std::error_code absolute_error; + const std::filesystem::path trace_path = + std::filesystem::absolute(options.profile_trace_path, absolute_error); + if (absolute_error || + !SetEnvironment("MOCKTAIL_PROFILE_TRACE", trace_path.string(), + error)) { + if (error != nullptr && absolute_error) { + *error = "could not resolve --profile path"; + } + return false; + } + } if (options.window_mode == WindowMode::kHeadless) { return SetEnvironment("MOCKTAIL_HEADLESS", "1", error); } @@ -256,6 +277,8 @@ std::string CommandLineUsage(const std::string& program_name) { "without approval; it is not activated\n" << " --launch-uri Join from a roblox: or roblox-player: " "website link\n" + << " --profile Write a Chrome trace of Vulkan adapter " + "work for ui.perfetto.dev\n" << " --help, -h Show this help\n\n" << "Auth:\n" << " When no saved Roblox session is found, Roblox's welcome screen " diff --git a/stubs/CMakeLists.txt b/stubs/CMakeLists.txt index 6d0a1f9..1a8ff71 100644 --- a/stubs/CMakeLists.txt +++ b/stubs/CMakeLists.txt @@ -106,6 +106,7 @@ target_link_libraries(stub_glesv2 PRIVATE dl) # The host Vulkan loader owns device commands; this target adapts Android WSI. add_library(stub_vulkan SHARED ${CMAKE_SOURCE_DIR}/src/graphics/bionic_vulkan_loader_adapter.cc + ${CMAKE_SOURCE_DIR}/src/graphics/chrome_trace_writer.cc ${CMAKE_SOURCE_DIR}/src/graphics/vulkan_text_overlay_compositor.cc ${CMAKE_SOURCE_DIR}/src/graphics/vulkan_etc2_emulation.cc ${CMAKE_SOURCE_DIR}/src/graphics/etc2_decoder.cc diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 4a1bc70..ab459d5 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -513,9 +513,21 @@ target_link_libraries(texture_override_test PRIVATE GTest::gtest_main PkgConfig::LIBPNG) mocktail_apply_compile_options(texture_override_test) +add_executable(chrome_trace_writer_test + chrome_trace_writer_test.cc + ${PROJECT_SOURCE_DIR}/src/graphics/chrome_trace_writer.cc +) +target_include_directories(chrome_trace_writer_test PRIVATE + ${PROJECT_SOURCE_DIR}/include +) +target_link_libraries(chrome_trace_writer_test PRIVATE GTest::gtest_main + Threads::Threads nlohmann_json::nlohmann_json) +mocktail_apply_compile_options(chrome_trace_writer_test) + add_executable(vulkan_etc2_emulation_test vulkan_etc2_emulation_test.cc ${PROJECT_SOURCE_DIR}/src/graphics/vulkan_etc2_emulation.cc + ${PROJECT_SOURCE_DIR}/src/graphics/chrome_trace_writer.cc ${PROJECT_SOURCE_DIR}/src/graphics/etc2_decoder.cc ${PROJECT_SOURCE_DIR}/src/graphics/texture_override.cc ) @@ -989,6 +1001,7 @@ gtest_discover_tests(vulkan_surface_recovery_gate_test) gtest_discover_tests(vulkan_present_progress_gate_test) gtest_discover_tests(vulkan_text_overlay_compositor_test) gtest_discover_tests(etc2_decoder_test) +gtest_discover_tests(chrome_trace_writer_test) gtest_discover_tests(vulkan_etc2_emulation_test) gtest_discover_tests(video_driver_policy_test) gtest_discover_tests(window_surface_lifecycle_test) diff --git a/tests/chrome_trace_writer_test.cc b/tests/chrome_trace_writer_test.cc new file mode 100644 index 0000000..9fd01ac --- /dev/null +++ b/tests/chrome_trace_writer_test.cc @@ -0,0 +1,273 @@ +#include "mocktail/graphics/chrome_trace_writer.h" + +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace mocktail { +namespace graphics { +namespace { + +class TemporaryDirectory final { + public: + TemporaryDirectory() { + char pattern[] = "/tmp/mocktail_chrome_trace_XXXXXX"; + const char* created = mkdtemp(pattern); + if (created != nullptr) root_ = created; + } + + ~TemporaryDirectory() { + std::error_code error; + std::filesystem::remove_all(root_, error); + } + + const std::filesystem::path& root() const { return root_; } + + private: + std::filesystem::path root_; +}; + +std::string ReadFile(const std::filesystem::path& path) { + std::ifstream input(path, std::ios::binary); + std::ostringstream content; + content << input.rdbuf(); + return content.str(); +} + +nlohmann::json ParseTrace(const std::filesystem::path& path) { + return nlohmann::json::parse(ReadFile(path)); +} + +std::unique_ptr OpenOrFail( + const std::filesystem::path& path) { + std::string error; + auto writer = ChromeTraceWriter::Open(path, &error); + EXPECT_NE(writer, nullptr) << error; + return writer; +} + +TEST(ChromeTraceWriterTest, WritesSliceAsCompleteEventInMicroseconds) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + writer->Slice("vkQueuePresentKHR", "present", 5'000'123'456ULL, + 5'002'623'456ULL, {{"frame", 7}, {"result", -4}}); + writer->Close(); + + const nlohmann::json trace = ParseTrace(path); + ASSERT_TRUE(trace.is_array()); + ASSERT_EQ(trace.size(), 1u); + const nlohmann::json& event = trace[0]; + EXPECT_EQ(event["name"], "vkQueuePresentKHR"); + EXPECT_EQ(event["cat"], "present"); + EXPECT_EQ(event["ph"], "X"); + EXPECT_EQ(event["ts"], 5'000'123); + EXPECT_EQ(event["dur"], 2'500); + EXPECT_EQ(event["pid"], static_cast(getpid())); + EXPECT_EQ(event["tid"], static_cast(gettid())); + EXPECT_EQ(event["args"]["frame"], 7); + EXPECT_EQ(event["args"]["result"], -4); +} + +TEST(ChromeTraceWriterTest, WritesCounterSample) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + writer->Counter("frame interval (ms)", 9'000'000ULL, 16.5); + writer->Close(); + + const nlohmann::json trace = ParseTrace(path); + ASSERT_EQ(trace.size(), 1u); + EXPECT_EQ(trace[0]["name"], "frame interval (ms)"); + EXPECT_EQ(trace[0]["ph"], "C"); + EXPECT_EQ(trace[0]["ts"], 9'000); + EXPECT_DOUBLE_EQ(trace[0]["args"]["value"].get(), 16.5); +} + +TEST(ChromeTraceWriterTest, EmptyTraceIsAnEmptyArray) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + writer->Close(); + + EXPECT_EQ(ParseTrace(path), nlohmann::json::array()); +} + +TEST(ChromeTraceWriterTest, EscapesNames) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + writer->Slice("say \"hi\"\\now", "c\ta", 0, 1000); + writer->Close(); + + const nlohmann::json trace = ParseTrace(path); + ASSERT_EQ(trace.size(), 1u); + EXPECT_EQ(trace[0]["name"], "say \"hi\"\\now"); + EXPECT_EQ(trace[0]["cat"], "c\ta"); +} + +TEST(ChromeTraceWriterTest, FileIsValidJsonBetweenWrites) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + // A session killed at any of these points leaves a loadable trace. + EXPECT_EQ(ParseTrace(path), nlohmann::json::array()); + writer->Slice("first", "test", 1000, 2000); + writer->Flush(); + EXPECT_EQ(ParseTrace(path).size(), 1u); + writer->Slice("second", "test", 3000, 4000); + writer->Flush(); + + const nlohmann::json trace = ParseTrace(path); + ASSERT_EQ(trace.size(), 2u); + EXPECT_EQ(trace[0]["name"], "first"); + EXPECT_EQ(trace[1]["name"], "second"); + writer->Close(); + EXPECT_EQ(ParseTrace(path), trace); +} + +TEST(ChromeTraceWriterTest, DropsEventsAfterClose) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + writer->Slice("kept", "test", 0, 1); + writer->Close(); + writer->Slice("dropped", "test", 2, 3); + writer->Counter("dropped", 4, 1.0); + writer->Flush(); + writer->Close(); + + const nlohmann::json trace = ParseTrace(path); + ASSERT_EQ(trace.size(), 1u); + EXPECT_EQ(trace[0]["name"], "kept"); +} + +TEST(ChromeTraceWriterTest, KeepsEveryEventFromConcurrentThreads) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + constexpr int kThreads = 8; + constexpr int kEventsPerThread = 20'000; + std::vector threads; + for (int thread = 0; thread < kThreads; ++thread) { + threads.emplace_back([&writer, thread] { + for (int event = 0; event < kEventsPerThread; ++event) { + writer->Slice("work", "test", 1000, 2000, + {{"thread", thread}, {"event", event}}); + } + }); + } + for (std::thread& thread : threads) { + thread.join(); + } + writer->Close(); + + const nlohmann::json trace = ParseTrace(path); + ASSERT_EQ(trace.size(), static_cast(kThreads) * + kEventsPerThread); + std::set> seen; + std::set tids; + for (const nlohmann::json& event : trace) { + seen.emplace(event["args"]["thread"].get(), + event["args"]["event"].get()); + tids.insert(event["tid"].get()); + } + EXPECT_EQ(seen.size(), trace.size()); + EXPECT_EQ(tids.size(), static_cast(kThreads)); +} + +TEST(ChromeTraceWriterTest, DestructorClosesTheArray) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + { + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + writer->Slice("only", "test", 0, 1000); + } + EXPECT_EQ(ParseTrace(path).size(), 1u); +} + +TEST(ChromeTraceWriterTest, OpenReportsUnwritablePath) { + TemporaryDirectory directory; + std::string error; + + const auto writer = ChromeTraceWriter::Open( + directory.root() / "missing" / "trace.json", &error); + + EXPECT_EQ(writer, nullptr); + EXPECT_NE(error.find("missing"), std::string::npos) << error; +} + +TEST(ChromeTraceWriterTest, OpenCreatesOrTruncatesTheFile) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + std::ofstream(path) << "stale content that is not json"; + + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + writer->Close(); + + EXPECT_EQ(ParseTrace(path), nlohmann::json::array()); +} + +TEST(ChromeTraceWriterTest, ScopeRecordsItsLifetimeAndArgs) { + TemporaryDirectory directory; + const auto path = directory.root() / "trace.json"; + auto writer = OpenOrFail(path); + ASSERT_NE(writer, nullptr); + + const std::uint64_t before = TraceClockNanos(); + { + TraceScope scope(writer.get(), "scoped", "test"); + scope.Arg("count", 3); + std::this_thread::sleep_for(std::chrono::milliseconds(2)); + } + const std::uint64_t after = TraceClockNanos(); + writer->Close(); + + const nlohmann::json trace = ParseTrace(path); + ASSERT_EQ(trace.size(), 1u); + const auto ts = trace[0]["ts"].get(); + const auto dur = trace[0]["dur"].get(); + EXPECT_GE(ts, before / 1000); + EXPECT_GE(dur, 2'000u); + EXPECT_LE(ts + dur, after / 1000 + 1); + EXPECT_EQ(trace[0]["args"]["count"], 3); +} + +TEST(ChromeTraceWriterTest, ScopeWithoutWriterRecordsNothing) { + TraceScope scope(nullptr, "unused", "test"); + scope.Arg("ignored", 1); +} + +TEST(ChromeTraceWriterTest, ActiveProfileTraceIsOffWithoutEnvironment) { + ASSERT_EQ(std::getenv(kProfileTraceEnvironment), nullptr); + EXPECT_EQ(ActiveProfileTrace(), nullptr); +} + +} // namespace +} // namespace graphics +} // namespace mocktail diff --git a/tests/command_line_test.cc b/tests/command_line_test.cc index 75fdfe9..a23e106 100644 --- a/tests/command_line_test.cc +++ b/tests/command_line_test.cc @@ -4,6 +4,8 @@ #include #include +#include +#include #include #include @@ -160,6 +162,42 @@ TEST(CommandLineTest, ScrubsInternalLaunchDocumentFromOwnedAndProcessArgv) { [](char byte) { return byte == '\0'; })); } +TEST(CommandLineTest, ParsesProfileTracePath) { + const std::array arguments = {"mocktail", "--profile", + "/traces/session.json"}; + + const CommandLineParseResult result = + ParseCommandLine(arguments.size(), arguments.data()); + + ASSERT_TRUE(result) << result.error; + EXPECT_EQ(result.options.profile_trace_path, "/traces/session.json"); +} + +TEST(CommandLineTest, AppliesProfileTraceAsAbsolutePath) { + unsetenv("MOCKTAIL_PROFILE_TRACE"); + CommandLineOptions options; + options.profile_trace_path = "session.json"; + std::string error; + + ASSERT_TRUE(ApplyCommandLineEnvironment(options, &error)) << error; + + const char* applied = std::getenv("MOCKTAIL_PROFILE_TRACE"); + ASSERT_NE(applied, nullptr); + EXPECT_EQ(std::string(applied), + (std::filesystem::current_path() / "session.json").string()); + unsetenv("MOCKTAIL_PROFILE_TRACE"); +} + +TEST(CommandLineTest, LeavesProfileTraceUnsetWithoutOption) { + unsetenv("MOCKTAIL_PROFILE_TRACE"); + std::string error; + + ASSERT_TRUE(ApplyCommandLineEnvironment(CommandLineOptions{}, &error)) + << error; + + EXPECT_EQ(std::getenv("MOCKTAIL_PROFILE_TRACE"), nullptr); +} + TEST(CommandLineTest, RejectsUnsupportedPositionalArgument) { const std::array arguments = {"mocktail", "/tmp/payload"}; @@ -182,7 +220,7 @@ TEST(CommandLineTest, RejectsUnknownOptionBeforeRuntimeWork) { TEST(CommandLineTest, RejectsEveryMissingValue) { for (const char* option : - {"--roblox-lib", "--graphics", "--launch-uri"}) { + {"--roblox-lib", "--graphics", "--launch-uri", "--profile"}) { const std::array arguments = {"mocktail", option}; const CommandLineParseResult result = ParseCommandLine(arguments.size(), arguments.data()); @@ -268,7 +306,7 @@ TEST(CommandLineTest, UsageContainsEverySupportedOption) { for (const char* option : {"--roblox-lib", "--headless", "--windowed", "--graphics", "--allow-unverified-build", "--force-run-latest", "--launch-uri", - "--help"}) { + "--profile", "--help"}) { EXPECT_NE(usage.find(option), std::string::npos) << option; } EXPECT_EQ(usage.find("--login"), std::string::npos); diff --git a/tests/summarize_profile_trace_test.py b/tests/summarize_profile_trace_test.py new file mode 100644 index 0000000..b15d777 --- /dev/null +++ b/tests/summarize_profile_trace_test.py @@ -0,0 +1,117 @@ +#!/usr/bin/env python3 +# Copyright 2026 Mocktail Project Authors +# Licensed under the Apache License, Version 2.0. + +from __future__ import annotations + +import contextlib +import importlib.util +import io +import json +from pathlib import Path +import sys +import tempfile +import unittest + + +SCRIPT = Path(__file__).parents[1] / "scripts/summarize_profile_trace.py" +SPEC = importlib.util.spec_from_file_location("summarize_profile_trace", + SCRIPT) +assert SPEC is not None and SPEC.loader is not None +summary = importlib.util.module_from_spec(SPEC) +# Dataclasses resolve their module through sys.modules. +sys.modules[SPEC.name] = summary +SPEC.loader.exec_module(summary) + + +def frame(ts_us: int, interval_ms: float) -> dict: + return {"name": "frame interval (ms)", "ph": "C", "ts": ts_us, + "pid": 1, "tid": 1, "args": {"value": interval_ms}} + + +def slice_event(name: str, dur_us: int, ts_us: int = 0) -> dict: + return {"name": name, "cat": "test", "ph": "X", "ts": ts_us, + "dur": dur_us, "pid": 1, "tid": 1} + + +class SummarizeTest(unittest.TestCase): + + def test_frame_interval_percentiles_use_nearest_rank(self) -> None: + events = [frame(index, float(index)) for index in range(1, 101)] + + result = summary.summarize(events) + + frames = result.frames + self.assertEqual(frames.count, 100) + self.assertAlmostEqual(frames.mean, 50.5) + self.assertEqual(frames.p50, 50.0) + self.assertEqual(frames.p95, 95.0) + self.assertEqual(frames.p99, 99.0) + self.assertEqual(frames.max, 100.0) + + def test_slices_are_grouped_by_name_in_milliseconds(self) -> None: + events = [ + slice_event("vkQueuePresentKHR", 2_000), + slice_event("vkQueuePresentKHR", 4_000), + slice_event("vkCreateGraphicsPipelines", 30_000), + ] + + result = summary.summarize(events) + + present = result.slices["vkQueuePresentKHR"] + self.assertEqual(present.count, 2) + self.assertAlmostEqual(present.total, 6.0) + self.assertAlmostEqual(present.mean, 3.0) + self.assertAlmostEqual(present.max, 4.0) + self.assertEqual(result.slices["vkCreateGraphicsPipelines"].count, 1) + + def test_other_events_are_ignored(self) -> None: + events = [ + {"name": "thread", "ph": "M", "ts": 0, "pid": 1, "tid": 1}, + {"name": "other counter", "ph": "C", "ts": 0, "pid": 1, "tid": 1, + "args": {"value": 5.0}}, + ] + + result = summary.summarize(events) + + self.assertIsNone(result.frames) + self.assertEqual(result.slices, {}) + + def test_markdown_puts_each_trace_in_its_own_column(self) -> None: + before = summary.summarize([frame(1, 20.0), slice_event("a", 1_000)]) + after = summary.summarize([frame(1, 10.0), slice_event("a", 500)]) + + table = summary.to_markdown([("before.json", before), + ("after.json", after)]) + + lines = table.splitlines() + self.assertEqual(lines[0], "| metric | before.json | after.json |") + self.assertIn("| frame interval p50 (ms) | 20.00 | 10.00 |", lines) + self.assertIn("| a mean (ms) | 1.00 | 0.50 |", lines) + + def test_markdown_marks_missing_values(self) -> None: + with_slice = summary.summarize([slice_event("a", 1_000)]) + without = summary.summarize([]) + + table = summary.to_markdown([("one", with_slice), ("two", without)]) + + self.assertIn("| a count | 1 | - |", table.splitlines()) + self.assertIn("| frames | - | - |", table.splitlines()) + + def test_main_reads_trace_files(self) -> None: + with tempfile.TemporaryDirectory() as directory: + path = Path(directory) / "trace.json" + path.write_text(json.dumps([frame(1, 16.0), + slice_event("b", 2_000)])) + output = io.StringIO() + + with contextlib.redirect_stdout(output): + code = summary.main([str(path)]) + + self.assertEqual(code, 0) + self.assertIn("| frame interval p99 (ms) | 16.00 |", + output.getvalue()) + + +if __name__ == "__main__": + unittest.main()