diff --git a/CMakeLists.txt b/CMakeLists.txt index 11039135be..5f2aac80f8 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -252,6 +252,8 @@ if(BUILD_TESTING) endforeach() add_test(NAME trace_digest COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tools/tests/test_trace_digest.py) + add_test(NAME symbolize_samples COMMAND ${Python3_EXECUTABLE} + ${CMAKE_CURRENT_SOURCE_DIR}/tools/tests/test_symbolize_samples.py) add_test(NAME conventions_bom_shebang COMMAND ${Python3_EXECUTABLE} ${CMAKE_CURRENT_SOURCE_DIR}/tools/tests/test_check_conventions_bom_shebang.py) set_tests_properties(conventions_bom_shebang PROPERTIES TIMEOUT 20) diff --git a/core/libs/prx/libSceAgcDriver/Execution/src/WorkerSampler.cpp b/core/libs/prx/libSceAgcDriver/Execution/src/WorkerSampler.cpp index f95ac3a62f..3bdac581be 100644 --- a/core/libs/prx/libSceAgcDriver/Execution/src/WorkerSampler.cpp +++ b/core/libs/prx/libSceAgcDriver/Execution/src/WorkerSampler.cpp @@ -163,18 +163,29 @@ struct Sampler { return frame; } + static void writeModules(std::FILE* file, const std::map& loaded) { + for (const auto& [base, name] : loaded) { + const auto* dos = reinterpret_cast(base); + const auto* nt = reinterpret_cast(base + dos->e_lfanew); + std::fprintf(file, "# module %s 0x%lx 0x%lx\n", name.c_str(), static_cast(nt->OptionalHeader.SizeOfImage), static_cast(nt->FileHeader.TimeDateStamp)); + } + } + void write() { std::lock_guard lock(mutex); std::FILE* file = std::fopen(path.c_str(), "w"); if (file == nullptr) return; std::fprintf(file, "# %llu samples\n", static_cast(samples)); + std::map loaded; for (const auto& [address, count] : counts) { HMODULE module = nullptr; char name[MAX_PATH] = "?"; if (GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS | GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT, reinterpret_cast(address), &module)) GetModuleFileNameA(module, name, sizeof(name)); const char* base = std::strrchr(name, '\\'); + if (module != nullptr) loaded.emplace(reinterpret_cast(module), base ? base + 1 : name); std::fprintf(file, "%s 0x%llx %llu %llu\n", base ? base + 1 : name, static_cast(address - reinterpret_cast(module)), static_cast(count.first), static_cast(count.second)); } + writeModules(file, loaded); std::fclose(file); if (keepStacks) writeStacks(); } @@ -195,11 +206,7 @@ struct Sampler { const double tickUs = 1e6 / static_cast(frequency.QuadPart); std::fprintf(file, "# samples=%llu depth=%d truncated=%llu suspended_us_mean=%.1f suspended_us_max=%.1f\n", static_cast(samples), depth, static_cast(stacks.Truncated()), samples != 0 ? static_cast(suspendedTicks) * tickUs / static_cast(samples) : 0.0, static_cast(longestSuspendedTicks) * tickUs); - for (const auto& [base, name] : loaded) { - const auto* dos = reinterpret_cast(base); - const auto* nt = reinterpret_cast(base + dos->e_lfanew); - std::fprintf(file, "# module %s 0x%lx 0x%lx\n", name.c_str(), static_cast(nt->OptionalHeader.SizeOfImage), static_cast(nt->FileHeader.TimeDateStamp)); - } + writeModules(file, loaded); const auto text = stacks.Format([&](std::uint64_t address) { return names.at(address); }); const bool written = std::fwrite(text.data(), 1, text.size(), file) == text.size(); if (std::fclose(file) != 0 || !written) return; @@ -246,6 +253,7 @@ struct ProcessSampler { std::FILE* file = std::fopen(path.c_str(), "w"); if (file == nullptr) return; std::fprintf(file, "# %llu rounds\n", static_cast(rounds)); + std::map loaded; for (auto& [id, thread] : threads) { std::lock_guard lock(thread.mutex); std::vector>> hot(thread.counts.begin(), thread.counts.end()); @@ -260,9 +268,11 @@ struct ProcessSampler { char name[MAX_PATH] = "?"; if (GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS | GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT, reinterpret_cast(address), &module)) GetModuleFileNameA(module, name, sizeof(name)); const char* base = std::strrchr(name, '\\'); + if (module != nullptr) loaded.emplace(reinterpret_cast(module), base ? base + 1 : name); std::fprintf(file, " %s 0x%llx %llu %llu\n", base ? base + 1 : name, static_cast(address - reinterpret_cast(module)), static_cast(hot[i].second.first), static_cast(hot[i].second.second)); } } + Sampler::writeModules(file, loaded); std::fclose(file); } }; diff --git a/docs/dev/BUILD.md b/docs/dev/BUILD.md index 6646a5c33c..dfef62f9b1 100644 --- a/docs/dev/BUILD.md +++ b/docs/dev/BUILD.md @@ -216,11 +216,11 @@ On a device that supports `VK_EXT_device_fault`, the first `VK_ERROR_DEVICE_LOST ## Worker sampler -Set `APS5_SAMPLE_WORKER=` to sample queue worker 0 every millisecond (in practice every timer tick). Every 20 s and at exit it writes ``, one `module offset self inclusive` line per sampled address, and `.collapsed.txt`, the worker's whole stacks in the collapsed format that speedscope.app and flamegraph.pl read: one `frame;...;frame count` line per distinct stack, root first, each frame as `module+0xRVA`. A walk that ends before the thread's root starts with `[truncated]`. The `#` lines give the samples, the walk depth (64 frames), the truncated walks, the mean and longest time the worker was suspended, and the size and PE timestamp of each module, to check the binary a file is symbolized against. A frame with `.pdata` is stepped by `RtlVirtualUnwind`; any other frame by its DWARF record in `.ehfram`, the unwind data the libraries are built with. Those steps read only inside the worker's stack, and a module is indexed after the worker resumes, the first time a walk meets it. +Set `APS5_SAMPLE_WORKER=` to sample queue worker 0 every millisecond (in practice every timer tick). Every 20 s and at exit it writes ``, one `module offset self inclusive` line per sampled address, and `.collapsed.txt`, the worker's whole stacks in the collapsed format that speedscope.app and flamegraph.pl read: one `frame;...;frame count` line per distinct stack, root first, each frame as `module+0xRVA`. A walk that ends before the thread's root starts with `[truncated]`. The `#` lines give the samples, the walk depth (64 frames), the truncated walks, the mean and longest time the worker was suspended, and the size and PE timestamp of each module, to check the binary a file is symbolized against. A frame with `.pdata` is stepped by `RtlVirtualUnwind`; any other frame by its DWARF record in `.ehfram`, the unwind data the libraries are built with. Those steps read only inside the worker's stack, and a module is indexed after the worker resumes, the first time a walk meets it. `python tools/symbolize_samples.py .collapsed.txt --libs ` names each frame from the COFF symbols of the module that ran, or from its export table when it has none, and leaves a module unsymbolized when its size or timestamp differs from its `# module` line or when it has none (`--unverified` symbolizes it anyway); `--since ` keeps only the samples taken after that copy, `--out` writes the named stacks and `--demangle` uses `c++filt`. Given ``, it lists functions by self and by inclusive samples, where a function's inclusive count is the sum of its addresses' and overcounts a function that is on one stack more than once. `APS5_SAMPLE_COMMITTER=` samples queue 0's draw committer the same way and writes the same two files. The committer records the draws the worker hands over (`APS5_PIPELINED_DRAWS`), so when the worker's stacks wait in `DrawPipeline::Enqueue`, its stacks show what bounds the frame. It starts with the first pipelined draw; with `APS5_PIPELINED_DRAWS=0` nothing is sampled. -`APS5_SAMPLE_THREADS=` samples every thread of the process every 2 ms and writes the 40 hottest addresses of each busy thread to ``, 12 frames deep and through `.pdata` only. The samplers exist only on Windows; the addresses are symbolized offline, for example with `nm` on the `.prx`. +`APS5_SAMPLE_THREADS=` samples every thread of the process every 2 ms and writes the 40 hottest addresses of each busy thread to ``, 12 frames deep and through `.pdata` only, under a `thread samples ` line per thread and with the same `# module` lines. The samplers exist only on Windows; the addresses are symbolized offline with `tools/symbolize_samples.py`, which adds up all threads or, with `--thread `, keeps one. ## Performance trace diff --git a/tools/symbolize_samples.py b/tools/symbolize_samples.py new file mode 100644 index 0000000000..f61b586e53 --- /dev/null +++ b/tools/symbolize_samples.py @@ -0,0 +1,300 @@ +import argparse +import bisect +import collections +import shutil +import struct +import subprocess +import sys +from pathlib import Path + +DESCRIPTION = """Symbolize the output of the Windows samplers (APS5_SAMPLE_WORKER, APS5_SAMPLE_COMMITTER and +APS5_SAMPLE_THREADS) against the modules that ran. Each sampled frame is written as module+0xRVA; this reads the +COFF symbol table of each module found in --libs (the MinGW-built .prx and .dll files keep one), or its export +table when it has none, and names every frame module!function. + +The '# module name size timestamp' header lines the samplers write are compared with the SizeOfImage and +TimeDateStamp of the file that is found; a module whose file does not match is left unsymbolized, since its +addresses would name the wrong functions. + +The sampler rewrites its files every 20 s with totals since start-up. --since takes an earlier copy of the same +file and subtracts it, which keeps only the samples taken between the two copies (a steady-state window). + +A module with no such record is also left unsymbolized, since nothing shows which build it was; --unverified +symbolizes it anyway against the file found. + +Input: a collapsed-stack file (.collapsed.txt, 'frame;...;frame count' lines) or an address file +('module offset self inclusive' lines, under 'thread samples ' headings for APS5_SAMPLE_THREADS; --thread +keeps one thread). Output: the hottest functions by self and by inclusive samples, and with --out a symbolized +collapsed-stack file for speedscope.app or flamegraph.pl. For an address file, a function's inclusive count is the +sum of its addresses' counts, which overcounts the samples in which it is on the stack more than once.""" + +IMAGE_SCN_CNT_CODE = 0x20 +IMAGE_SYM_CLASS_EXTERNAL = 2 +IMAGE_SYM_CLASS_STATIC = 3 + + +class PeModule: + def __init__(self, path): + data = Path(path).read_bytes() + if data[:2] != b"MZ": + raise ValueError(f"{path}: not a PE file") + pe = struct.unpack_from("> 4) != 2 and value == 0: + continue + if name[:4] == b"\0\0\0\0": + at = strings + struct.unpack_from(" samples '") + samples.stacks[frames] += int(count) + return samples + + +def subtract(later, earlier): + result = collections.Counter(later) + result.subtract(earlier) + return collections.Counter({key: count for key, count in result.items() if count > 0}) + + +def window(later, earlier): + result = Samples() + result.headers = {**earlier.headers, **later.headers} + for name in ("stacks", "self_counts", "inclusive", "total"): + setattr(result, name, subtract(getattr(later, name), getattr(earlier, name))) + return result + + +def summarize(symbolizer, samples, top): + self_counts = collections.Counter() + inclusive = collections.Counter() + total = 0 + if samples.stacks: + for frames, count in samples.stacks.items(): + names = [symbolizer.frame(frame) for frame in frames.split(";")] + total += count + self_counts[names[-1]] += count + for name in set(names): + inclusive[name] += count + else: + for (module, offset), count in samples.self_counts.items(): + self_counts[symbolizer.frame(f"{module}+{offset}")] += count + for (module, offset), count in samples.inclusive.items(): + inclusive[symbolizer.frame(f"{module}+{offset}")] += count + total = samples.total["threads"] or samples.total["samples"] or sum(samples.self_counts.values()) + lines = [f"{total} samples"] + for title, counter in (("self", self_counts), ("inclusive", inclusive)): + if not counter: + continue + lines.append(f"hottest by {title}:") + for name, count in counter.most_common(top): + lines.append(f" {count:8d} {100.0 * count / total if total else 0.0:5.1f}% {name}") + return lines + + +def main(argv=None): + parser = argparse.ArgumentParser(description=DESCRIPTION, formatter_class=argparse.RawDescriptionHelpFormatter) + parser.add_argument("samples", help="collapsed-stack file or address file written by a Windows sampler") + parser.add_argument("--libs", action="append", required=True, help="directory holding the modules that ran (repeatable)") + parser.add_argument("--since", help="an earlier copy of the same file, subtracted to keep the samples taken after it") + parser.add_argument("--out", help="write the symbolized collapsed stacks to this file") + parser.add_argument("--top", type=int, default=30, help="functions listed per table (default 30)") + parser.add_argument("--demangle", action="store_true", help="demangle C++ names with c++filt when it is on PATH") + parser.add_argument("--thread", help="keep only this thread of an APS5_SAMPLE_THREADS file") + parser.add_argument("--unverified", action="store_true", help="also symbolize modules the samples have no '# module' record for") + args = parser.parse_args(argv) + samples = load(args.samples, args.thread) + if args.since: + samples = window(samples, load(args.since, args.thread)) + symbolizer = Symbolizer(args.libs, samples.headers, args.demangle, warn=lambda text: print("warning: " + text, file=sys.stderr), unverified=args.unverified) + for line in summarize(symbolizer, samples, args.top): + print(line) + if args.out: + if not samples.stacks: + parser.error("--out needs a collapsed-stack file") + with open(args.out, "w", encoding="utf-8") as output: + for frames, count in samples.stacks.items(): + output.write(";".join(symbolizer.frame(frame) for frame in frames.split(";")) + f" {count}\n") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tools/tests/test_symbolize_samples.py b/tools/tests/test_symbolize_samples.py new file mode 100644 index 0000000000..5e000527dc --- /dev/null +++ b/tools/tests/test_symbolize_samples.py @@ -0,0 +1,202 @@ +import contextlib +import io +import struct +import sys +import tempfile +import unittest +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parents[1])) +import symbolize_samples + +TIMESTAMP = 0x6AD92AC4 +SIZE_OF_IMAGE = 0x3000 + + +def symbol(name, value, section, kind, storage, aux=0): + return struct.pack("<8sIhHBB", name, value, section, kind, storage, aux) + + +def build_pe(path, with_symbols=True, with_exports=False, second_code=False): + image = bytearray(0xC00) + image[0:2] = b"MZ" + struct.pack_into("