feat(agc): record a present window as a Chrome trace and a summary line
APS5_TRACE_FRAMES=<start>:<count> (or APS5_TRACE_SECONDS=<start>:<length>) records every PerformanceTimer scope and stage of the queue workers and the presenter inside the window as complete events, named after their frame timing keys, into a preallocated buffer per thread. Slices under 20 us are counted per thread instead of written; a full buffer stops that thread and sets trace_dropped. When the window closes, a ProfileOutput writer thread writes aps5-trace-<commit>-<pid>.json.gz and appends one line to aps5-summary.jsonl. Without either switch a PerformanceTimer costs one more predictable branch. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
AlxcBTW
Adrià Franch
parent
cf4557e5d8
commit
5668e0d0e7
|
|
@ -162,6 +162,7 @@ set(agcDriverSources
|
|||
${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/Driver/Synchronization/WaitMemory.cpp
|
||||
${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/Driver/Synchronization/WaitStatistics.cpp
|
||||
${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/WorkerSampler.cpp
|
||||
${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/PerformanceTrace.cpp
|
||||
${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/ThreadPriority.cpp
|
||||
${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/GuestMemory.cpp
|
||||
${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/ShaderMemory.cpp
|
||||
|
|
@ -219,9 +220,21 @@ set(agcDriverSources
|
|||
${CMAKE_CURRENT_SOURCE_DIR}/Submit/src/Dcb.cpp
|
||||
)
|
||||
|
||||
find_package(Git QUIET)
|
||||
set(agcTraceRevisionHeader ${agcTextureDetileGeneratedRoot}/prx/libSceAgcDriver/TraceRevision.hpp)
|
||||
add_custom_target(agc_trace_revision
|
||||
COMMAND ${CMAKE_COMMAND} -DGIT=${GIT_EXECUTABLE} -DSOURCE=${CMAKE_SOURCE_DIR} -DOUTPUT=${agcTraceRevisionHeader} -P ${CMAKE_CURRENT_SOURCE_DIR}/trace_revision.cmake
|
||||
BYPRODUCTS ${agcTraceRevisionHeader}
|
||||
VERBATIM
|
||||
)
|
||||
set_source_files_properties(${CMAKE_CURRENT_SOURCE_DIR}/Execution/src/PerformanceTrace.cpp PROPERTIES
|
||||
INCLUDE_DIRECTORIES ${CMAKE_SOURCE_DIR}/3rdparty/libjpeg-turbo/src/spng/zlib
|
||||
)
|
||||
|
||||
add_library(libSceAgcDriver SHARED EXCLUDE_FROM_ALL
|
||||
${agcDriverSources}
|
||||
)
|
||||
add_dependencies(libSceAgcDriver agc_trace_revision)
|
||||
|
||||
target_include_directories(libSceAgcDriver PRIVATE
|
||||
${LIBS_INCLUDE_DIR}
|
||||
|
|
@ -247,6 +260,7 @@ target_link_libraries(libSceAgcDriver PRIVATE
|
|||
SDL2-static
|
||||
libc
|
||||
libkernel
|
||||
jpeg_turbo
|
||||
${CMAKE_DL_LIBS}
|
||||
)
|
||||
|
||||
|
|
@ -285,6 +299,17 @@ if(BUILD_TESTING)
|
|||
set_tests_properties(agc_stack_walk PROPERTIES ENVIRONMENT_MODIFICATION
|
||||
"PATH=path_list_prepend:$<TARGET_FILE_DIR:libc>")
|
||||
endif()
|
||||
|
||||
add_test_executable(agc_performance_trace_tests tests/PerformanceTrace.cpp)
|
||||
target_include_directories(agc_performance_trace_tests PRIVATE ${LIBS_INCLUDE_DIR})
|
||||
target_link_libraries(agc_performance_trace_tests PRIVATE libc)
|
||||
configure_windows_unwind(agc_performance_trace_tests)
|
||||
add_test(NAME agc_performance_trace COMMAND agc_performance_trace_tests)
|
||||
set_tests_properties(agc_performance_trace PROPERTIES TIMEOUT 20)
|
||||
if(WIN32)
|
||||
set_tests_properties(agc_performance_trace PROPERTIES ENVIRONMENT_MODIFICATION
|
||||
"PATH=path_list_prepend:$<TARGET_FILE_DIR:libc>")
|
||||
endif()
|
||||
endif()
|
||||
|
||||
if(WIN32)
|
||||
|
|
@ -1014,7 +1039,8 @@ target_include_directories(agc_driver_mesh_tests PRIVATE
|
|||
${ANYPS5_VULKAN_HEADERS_INCLUDE_DIR}
|
||||
${ANYPS5_SPIRV_HEADERS_INCLUDE_DIR}
|
||||
)
|
||||
target_link_libraries(agc_driver_mesh_tests PRIVATE shader_recompiler_agc_driver SDL2-static libc libkernel ${CMAKE_DL_LIBS})
|
||||
target_link_libraries(agc_driver_mesh_tests PRIVATE shader_recompiler_agc_driver SDL2-static libc libkernel jpeg_turbo ${CMAKE_DL_LIBS})
|
||||
add_dependencies(agc_driver_mesh_tests agc_trace_revision)
|
||||
set_target_properties(agc_driver_mesh_tests PROPERTIES CXX_EXTENSIONS OFF)
|
||||
configure_windows_unwind(agc_driver_mesh_tests)
|
||||
|
||||
|
|
@ -1345,7 +1371,9 @@ if(AGC_BUILD_VISUAL_TEST)
|
|||
SDL2-static
|
||||
libc
|
||||
libkernel
|
||||
jpeg_turbo
|
||||
)
|
||||
add_dependencies(agc_driver_visual_test agc_trace_revision)
|
||||
|
||||
set_target_properties(agc_driver_visual_test PROPERTIES CXX_EXTENSIONS OFF)
|
||||
configure_windows_unwind(agc_driver_visual_test)
|
||||
|
|
|
|||
|
|
@ -1,6 +1,7 @@
|
|||
#ifndef CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETIMER_HPP
|
||||
#define CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETIMER_HPP
|
||||
|
||||
#include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp"
|
||||
#include <algorithm>
|
||||
#include <chrono>
|
||||
#include <cstddef>
|
||||
|
|
@ -258,11 +259,11 @@ private:
|
|||
|
||||
class PerformanceTimer {
|
||||
public:
|
||||
explicit PerformanceTimer(const char* scope) : frame(PerformanceContext::Current()), scope(scope) {
|
||||
explicit PerformanceTimer(const char* scope) : frame(PerformanceContext::Current()), trace(PerformanceTrace::Recording() ? PerformanceTrace::Thread() : nullptr), scope(scope) {
|
||||
if (frame != nullptr) {
|
||||
total = frame->Get(scope, "total");
|
||||
}
|
||||
if (frame != nullptr) start = Clock::now();
|
||||
if (frame != nullptr || trace != nullptr) start = Clock::now();
|
||||
previous = start;
|
||||
}
|
||||
|
||||
|
|
@ -274,8 +275,11 @@ public:
|
|||
}
|
||||
|
||||
void Finish() {
|
||||
if (frame == nullptr) return;
|
||||
if (frame == nullptr && trace == nullptr) return;
|
||||
const auto end = Clock::now();
|
||||
if (trace != nullptr) trace->Add(scope, nullptr, start, end);
|
||||
trace = nullptr;
|
||||
if (frame == nullptr) return;
|
||||
if (tail != nullptr) frame->Add(tail, end - previous);
|
||||
frame->Add(total, end - start);
|
||||
frame = nullptr;
|
||||
|
|
@ -287,10 +291,13 @@ public:
|
|||
}
|
||||
|
||||
void Mark(const char* stage, std::uint64_t bytes = 0) {
|
||||
if (frame == nullptr) return;
|
||||
if (frame == nullptr && trace == nullptr) return;
|
||||
const auto now = Clock::now();
|
||||
if (tail == nullptr) tail = frame->Get(scope, "tail");
|
||||
frame->Add(frame->Get(scope, stage), now - previous, bytes);
|
||||
if (trace != nullptr) trace->Add(scope, stage, previous, now);
|
||||
if (frame != nullptr) {
|
||||
if (tail == nullptr) tail = frame->Get(scope, "tail");
|
||||
frame->Add(frame->Get(scope, stage), now - previous, bytes);
|
||||
}
|
||||
previous = now;
|
||||
}
|
||||
|
||||
|
|
@ -298,6 +305,7 @@ private:
|
|||
using Clock = FrameTiming::Clock;
|
||||
|
||||
FrameTiming* frame;
|
||||
TraceThread* trace;
|
||||
const char* scope;
|
||||
FrameTiming::Metric* total = nullptr;
|
||||
FrameTiming::Metric* tail = nullptr;
|
||||
|
|
|
|||
|
|
@ -0,0 +1,396 @@
|
|||
#ifndef CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETRACE_HPP
|
||||
#define CORE_LIBS_PRX_LIBSCEAGCDRIVER_EXECUTION_INCLUDE_PERFORMANCETRACE_HPP
|
||||
|
||||
#include <algorithm>
|
||||
#include <array>
|
||||
#include <atomic>
|
||||
#include <charconv>
|
||||
#include <chrono>
|
||||
#include <cstddef>
|
||||
#include <cstdint>
|
||||
#include <cstdio>
|
||||
#include <cstdlib>
|
||||
#include <map>
|
||||
#include <memory>
|
||||
#include <optional>
|
||||
#include <span>
|
||||
#include <stdexcept>
|
||||
#include <string>
|
||||
#include <string_view>
|
||||
#include <utility>
|
||||
#include <vector>
|
||||
|
||||
namespace AgcDriver {
|
||||
|
||||
class VulkanDevice;
|
||||
|
||||
class TraceWindow {
|
||||
public:
|
||||
using Clock = std::chrono::steady_clock;
|
||||
enum class Edge { None, Open, Close };
|
||||
|
||||
static std::optional<TraceWindow> Parse(const char* frames, const char* seconds) {
|
||||
if (frames == nullptr && seconds == nullptr) return std::nullopt;
|
||||
if (frames != nullptr && seconds != nullptr) throw std::invalid_argument("APS5_TRACE_FRAMES and APS5_TRACE_SECONDS cannot be set together");
|
||||
const std::string_view name = frames != nullptr ? "APS5_TRACE_FRAMES" : "APS5_TRACE_SECONDS";
|
||||
const std::string_view text = frames != nullptr ? frames : seconds;
|
||||
const auto colon = text.find(':');
|
||||
std::uint64_t start = 0;
|
||||
std::uint64_t length = 0;
|
||||
if (colon == std::string_view::npos || !number(text.substr(0, colon), start) || !number(text.substr(colon + 1), length) || length == 0)
|
||||
throw std::invalid_argument(std::string(name) + "=" + std::string(text) + " is not <start>:<length> with a length above 0");
|
||||
return TraceWindow(frames != nullptr, start, length);
|
||||
}
|
||||
|
||||
Edge Present(std::uint64_t present, Clock::duration elapsed) {
|
||||
if (state == State::Closed) return Edge::None;
|
||||
if (state == State::Waiting) {
|
||||
if (frames ? present < start : wholeSeconds(elapsed) < start) return Edge::None;
|
||||
state = State::Open;
|
||||
openedPresent = present;
|
||||
openedAt = elapsed;
|
||||
return Edge::Open;
|
||||
}
|
||||
if (frames ? present - openedPresent < length : wholeSeconds(elapsed - openedAt) < length) return Edge::None;
|
||||
state = State::Closed;
|
||||
return Edge::Close;
|
||||
}
|
||||
|
||||
std::string Describe() const {
|
||||
return std::string(frames ? "frames " : "seconds ") + std::to_string(start) + ":" + std::to_string(length);
|
||||
}
|
||||
|
||||
private:
|
||||
enum class State { Waiting, Open, Closed };
|
||||
|
||||
TraceWindow(bool frames, std::uint64_t start, std::uint64_t length) : frames(frames), start(start), length(length) {}
|
||||
|
||||
static bool number(std::string_view text, std::uint64_t& value) {
|
||||
const auto end = text.data() + text.size();
|
||||
const auto [last, error] = std::from_chars(text.data(), end, value);
|
||||
return !text.empty() && error == std::errc{} && last == end;
|
||||
}
|
||||
|
||||
static std::uint64_t wholeSeconds(Clock::duration elapsed) {
|
||||
return static_cast<std::uint64_t>(std::chrono::duration_cast<std::chrono::seconds>(elapsed).count());
|
||||
}
|
||||
|
||||
bool frames;
|
||||
std::uint64_t start;
|
||||
std::uint64_t length;
|
||||
State state = State::Waiting;
|
||||
std::uint64_t openedPresent = 0;
|
||||
Clock::duration openedAt{};
|
||||
};
|
||||
|
||||
class TraceThread {
|
||||
public:
|
||||
using Clock = std::chrono::steady_clock;
|
||||
static constexpr std::size_t DefaultCapacity = 262144;
|
||||
static constexpr Clock::duration MinimumSlice = std::chrono::microseconds(20);
|
||||
|
||||
struct Slice {
|
||||
const char* scope;
|
||||
const char* stage;
|
||||
Clock::time_point begin;
|
||||
Clock::duration length;
|
||||
};
|
||||
|
||||
struct Total {
|
||||
const char* scope;
|
||||
const char* stage;
|
||||
Clock::duration length;
|
||||
std::uint64_t count;
|
||||
};
|
||||
|
||||
struct Snapshot {
|
||||
std::string name;
|
||||
std::span<const Slice> slices;
|
||||
std::vector<Total> totals;
|
||||
bool dropped = false;
|
||||
};
|
||||
|
||||
TraceThread(std::string name, const std::atomic<std::uint64_t>& presents, std::size_t capacity = DefaultCapacity)
|
||||
: name(std::move(name)), presents(presents), slices(std::make_unique<Slice[]>(capacity)), capacity(capacity) {}
|
||||
|
||||
TraceThread(const TraceThread&) = delete;
|
||||
TraceThread& operator=(const TraceThread&) = delete;
|
||||
|
||||
void Add(const char* scope, const char* stage, Clock::time_point begin, Clock::time_point end) {
|
||||
const auto length = end - begin;
|
||||
account(scope, stage, length);
|
||||
const auto present = presents.load(std::memory_order_relaxed);
|
||||
if (!sampled || present != sampledPresent) {
|
||||
if (sampled) append({nullptr, nullptr, sampleBegin, folded});
|
||||
sampled = true;
|
||||
sampledPresent = present;
|
||||
sampleBegin = begin;
|
||||
folded = {};
|
||||
}
|
||||
if (length < MinimumSlice) folded += length;
|
||||
else append({scope, stage, begin, length});
|
||||
}
|
||||
|
||||
Snapshot Collect() const {
|
||||
Snapshot snapshot{name, {slices.get(), used.load(std::memory_order_acquire)}, {}, false};
|
||||
for (const auto& entry : entries) {
|
||||
const auto* scope = entry.scope.load(std::memory_order_acquire);
|
||||
if (scope == nullptr) continue;
|
||||
snapshot.totals.push_back({scope, entry.stage.load(std::memory_order_relaxed), Clock::duration(entry.length.load(std::memory_order_relaxed)), entry.count.load(std::memory_order_relaxed)});
|
||||
}
|
||||
snapshot.dropped = dropped.load(std::memory_order_relaxed);
|
||||
return snapshot;
|
||||
}
|
||||
|
||||
private:
|
||||
struct Entry {
|
||||
std::atomic<const char*> scope{nullptr};
|
||||
std::atomic<const char*> stage{nullptr};
|
||||
std::atomic<Clock::rep> length{0};
|
||||
std::atomic<std::uint64_t> count{0};
|
||||
};
|
||||
|
||||
void append(const Slice& slice) {
|
||||
const auto index = used.load(std::memory_order_relaxed);
|
||||
if (index == capacity) {
|
||||
dropped.store(true, std::memory_order_relaxed);
|
||||
return;
|
||||
}
|
||||
slices[index] = slice;
|
||||
used.store(index + 1, std::memory_order_release);
|
||||
}
|
||||
|
||||
void account(const char* scope, const char* stage, Clock::duration length) {
|
||||
const auto key = reinterpret_cast<std::uintptr_t>(scope) ^ (reinterpret_cast<std::uintptr_t>(stage) >> 3);
|
||||
const auto hash = static_cast<std::size_t>((static_cast<std::uint64_t>(key) * 0x9e3779b97f4a7c15ull) >> 55);
|
||||
for (std::size_t probe = 0; probe < entries.size(); ++probe) {
|
||||
auto& entry = entries[(hash + probe) % entries.size()];
|
||||
const auto* current = entry.scope.load(std::memory_order_relaxed);
|
||||
if (current == nullptr) {
|
||||
entry.stage.store(stage, std::memory_order_relaxed);
|
||||
entry.scope.store(scope, std::memory_order_release);
|
||||
} else if (current != scope || entry.stage.load(std::memory_order_relaxed) != stage) {
|
||||
continue;
|
||||
}
|
||||
entry.length.store(entry.length.load(std::memory_order_relaxed) + length.count(), std::memory_order_relaxed);
|
||||
entry.count.store(entry.count.load(std::memory_order_relaxed) + 1, std::memory_order_relaxed);
|
||||
return;
|
||||
}
|
||||
dropped.store(true, std::memory_order_relaxed);
|
||||
}
|
||||
|
||||
const std::string name;
|
||||
const std::atomic<std::uint64_t>& presents;
|
||||
const std::unique_ptr<Slice[]> slices;
|
||||
const std::size_t capacity;
|
||||
std::atomic<std::size_t> used{0};
|
||||
std::atomic<bool> dropped{false};
|
||||
std::array<Entry, 512> entries;
|
||||
bool sampled = false;
|
||||
std::uint64_t sampledPresent = 0;
|
||||
Clock::time_point sampleBegin{};
|
||||
Clock::duration folded{};
|
||||
};
|
||||
|
||||
struct TraceSummary {
|
||||
std::string commit;
|
||||
std::optional<bool> dirty;
|
||||
std::vector<std::pair<std::string, std::string>> environment;
|
||||
std::string gpu;
|
||||
std::string driver;
|
||||
std::string os;
|
||||
std::uint32_t width = 0;
|
||||
std::uint32_t height = 0;
|
||||
std::string window;
|
||||
std::uint64_t firstPresent = 0;
|
||||
double gpuBusyMs = 0;
|
||||
std::string trace;
|
||||
};
|
||||
|
||||
class TraceFormat {
|
||||
public:
|
||||
using Clock = std::chrono::steady_clock;
|
||||
static constexpr std::array<std::string_view, 5> WorkerBusyScopes{"Driver.Packet", "Driver.Suspend", "Driver.EndSubmission", "Driver.Rewind", "Driver.Completion"};
|
||||
static constexpr std::string_view WorkerWaitScope = "Driver.WorkerWait";
|
||||
static constexpr std::string_view WorkerPrefix = "queue worker ";
|
||||
static constexpr std::size_t TopPhases = 8;
|
||||
|
||||
static void AppendString(std::string& output, std::string_view text) {
|
||||
output += '"';
|
||||
for (const char character : text) {
|
||||
const auto byte = static_cast<unsigned char>(character);
|
||||
if (character == '"' || character == '\\') {
|
||||
output += '\\';
|
||||
output += character;
|
||||
} else if (byte < 0x20 || byte >= 0x7f) {
|
||||
char escaped[8];
|
||||
std::snprintf(escaped, sizeof escaped, "\\u%04x", static_cast<unsigned>(byte));
|
||||
output += escaped;
|
||||
} else {
|
||||
output += character;
|
||||
}
|
||||
}
|
||||
output += '"';
|
||||
}
|
||||
|
||||
static std::string Name(const char* scope, const char* stage) {
|
||||
return stage == nullptr ? std::string(scope) : std::string(scope) + "." + stage;
|
||||
}
|
||||
|
||||
static std::string Events(std::uint64_t process, Clock::time_point origin, std::span<const TraceThread::Snapshot> threads, std::size_t presenter, std::span<const Clock::time_point> presents, std::uint64_t firstPresent) {
|
||||
std::string output = "{\"traceEvents\":[\n";
|
||||
bool first = true;
|
||||
const auto event = [&](std::string_view name, const char* phase, Clock::time_point at, std::size_t tid) {
|
||||
if (!first) output += ",\n";
|
||||
first = false;
|
||||
output += "{\"name\":";
|
||||
AppendString(output, name);
|
||||
char text[96];
|
||||
std::snprintf(text, sizeof text, ",\"ph\":\"%s\",\"ts\":%.3f,\"pid\":%llu,\"tid\":%llu", phase, microseconds(at - origin), static_cast<unsigned long long>(process), static_cast<unsigned long long>(tid));
|
||||
output += text;
|
||||
};
|
||||
event("process_name", "M", origin, 0);
|
||||
output += ",\"args\":{\"name\":\"AnyPS5\"}}";
|
||||
for (std::size_t index = 0; index < threads.size(); ++index) {
|
||||
const auto& thread = threads[index];
|
||||
const auto tid = index + 1;
|
||||
event("thread_name", "M", origin, tid);
|
||||
output += ",\"args\":{\"name\":";
|
||||
AppendString(output, thread.name);
|
||||
output += "}}";
|
||||
std::vector<TraceThread::Slice> slices(thread.slices.begin(), thread.slices.end());
|
||||
std::stable_sort(slices.begin(), slices.end(), [](const auto& a, const auto& b) { return a.begin != b.begin ? a.begin < b.begin : a.length > b.length; });
|
||||
const auto folded = thread.name + " folded";
|
||||
for (const auto& slice : slices) {
|
||||
char text[64];
|
||||
if (slice.scope == nullptr) {
|
||||
event(folded, "C", slice.begin, tid);
|
||||
std::snprintf(text, sizeof text, ",\"args\":{\"ms\":%.3f}}", milliseconds(slice.length));
|
||||
} else {
|
||||
event(Name(slice.scope, slice.stage), "X", slice.begin, tid);
|
||||
std::snprintf(text, sizeof text, ",\"dur\":%.3f}", microseconds(slice.length));
|
||||
}
|
||||
output += text;
|
||||
}
|
||||
}
|
||||
for (std::size_t index = 0; index + 1 < presents.size(); ++index) {
|
||||
event("present", "i", presents[index], presenter + 1);
|
||||
output += ",\"s\":\"g\",\"args\":{\"present\":" + std::to_string(firstPresent + index) + "}}";
|
||||
}
|
||||
output += "\n]}\n";
|
||||
return output;
|
||||
}
|
||||
|
||||
static std::string Summary(const TraceSummary& summary, std::span<const TraceThread::Snapshot> threads, std::span<const Clock::time_point> presents) {
|
||||
const auto count = presents.empty() ? std::size_t{0} : presents.size() - 1;
|
||||
const auto span = presents.empty() ? Clock::duration{} : presents.back() - presents.front();
|
||||
std::vector<double> frames;
|
||||
for (std::size_t index = 1; index < presents.size(); ++index) frames.push_back(milliseconds(presents[index] - presents[index - 1]));
|
||||
std::sort(frames.begin(), frames.end());
|
||||
const auto percentile = [&](double fraction) { return frames.empty() ? 0.0 : frames[std::min(frames.size() - 1, static_cast<std::size_t>(fraction * static_cast<double>(frames.size())))]; };
|
||||
const double perPresent = count != 0 ? 1.0 / static_cast<double>(count) : 0.0;
|
||||
|
||||
std::string output = "{\"commit\":";
|
||||
AppendString(output, summary.commit);
|
||||
output += ",\"dirty\":";
|
||||
output += summary.dirty.has_value() ? (*summary.dirty ? "true" : "false") : "null";
|
||||
output += ",\"env\":{";
|
||||
for (std::size_t index = 0; index < summary.environment.size(); ++index) {
|
||||
if (index != 0) output += ',';
|
||||
AppendString(output, summary.environment[index].first);
|
||||
output += ':';
|
||||
AppendString(output, summary.environment[index].second);
|
||||
}
|
||||
output += "},\"gpu\":";
|
||||
AppendString(output, summary.gpu);
|
||||
output += ",\"driver\":";
|
||||
AppendString(output, summary.driver);
|
||||
output += ",\"os\":";
|
||||
AppendString(output, summary.os);
|
||||
output += ",\"resolution\":";
|
||||
AppendString(output, std::to_string(summary.width) + "x" + std::to_string(summary.height));
|
||||
output += ",\"window\":{\"spec\":";
|
||||
AppendString(output, summary.window);
|
||||
output += ",\"first_present\":" + std::to_string(summary.firstPresent);
|
||||
output += ",\"ms\":" + number(milliseconds(span)) + "}";
|
||||
output += ",\"presents\":" + std::to_string(count);
|
||||
output += ",\"frame_ms\":{\"p50\":" + number(percentile(0.5)) + ",\"p90\":" + number(percentile(0.9)) + ",\"p99\":" + number(percentile(0.99)) + ",\"max\":" + number(frames.empty() ? 0.0 : frames.back()) + "}";
|
||||
output += ",\"gpu_busy_ms_per_present\":" + number(summary.gpuBusyMs * perPresent);
|
||||
|
||||
output += ",\"worker_busy_pct\":{";
|
||||
bool firstWorker = true;
|
||||
std::map<std::string, Clock::duration> phases;
|
||||
bool dropped = false;
|
||||
for (const auto& thread : threads) {
|
||||
dropped = dropped || thread.dropped;
|
||||
Clock::duration busy{};
|
||||
for (const auto& total : thread.totals) {
|
||||
const std::string_view scope = total.scope;
|
||||
if (total.stage == nullptr && std::find(WorkerBusyScopes.begin(), WorkerBusyScopes.end(), scope) != WorkerBusyScopes.end()) busy += total.length;
|
||||
if (scope != WorkerWaitScope) phases[Name(total.scope, total.stage)] += total.length;
|
||||
}
|
||||
if (!thread.name.starts_with(WorkerPrefix)) continue;
|
||||
if (!firstWorker) output += ',';
|
||||
firstWorker = false;
|
||||
AppendString(output, thread.name);
|
||||
output += ':' + number(span != Clock::duration{} ? 100.0 * static_cast<double>(busy.count()) / static_cast<double>(span.count()) : 0.0);
|
||||
}
|
||||
output += "},\"top_phases_ms_per_frame\":{";
|
||||
std::vector<std::pair<std::string, Clock::duration>> top(phases.begin(), phases.end());
|
||||
std::stable_sort(top.begin(), top.end(), [](const auto& a, const auto& b) { return a.second > b.second; });
|
||||
for (std::size_t index = 0; index < top.size() && index < TopPhases; ++index) {
|
||||
if (index != 0) output += ',';
|
||||
AppendString(output, top[index].first);
|
||||
output += ':' + number(milliseconds(top[index].second) * perPresent);
|
||||
}
|
||||
output += "},\"trace_dropped\":";
|
||||
output += dropped ? "true" : "false";
|
||||
output += ",\"trace\":";
|
||||
AppendString(output, summary.trace);
|
||||
output += "}\n";
|
||||
return output;
|
||||
}
|
||||
|
||||
private:
|
||||
static double microseconds(Clock::duration elapsed) {
|
||||
return std::chrono::duration<double, std::micro>(elapsed).count();
|
||||
}
|
||||
|
||||
static double milliseconds(Clock::duration elapsed) {
|
||||
return std::chrono::duration<double, std::milli>(elapsed).count();
|
||||
}
|
||||
|
||||
static std::string number(double value) {
|
||||
char text[32];
|
||||
std::snprintf(text, sizeof text, "%.3f", value);
|
||||
return text;
|
||||
}
|
||||
};
|
||||
|
||||
class PerformanceTrace {
|
||||
public:
|
||||
static bool Configured() {
|
||||
static const bool configured = std::getenv("APS5_TRACE_FRAMES") != nullptr || std::getenv("APS5_TRACE_SECONDS") != nullptr;
|
||||
return configured;
|
||||
}
|
||||
|
||||
static void BindThread(const char* name);
|
||||
static void Present(std::uint32_t width, std::uint32_t height, const VulkanDevice* device);
|
||||
|
||||
static bool Recording() {
|
||||
return recording.load(std::memory_order_relaxed);
|
||||
}
|
||||
|
||||
static TraceThread* Thread() {
|
||||
return local;
|
||||
}
|
||||
|
||||
private:
|
||||
inline static std::atomic<bool> recording{false};
|
||||
inline static std::atomic<std::uint64_t> presentCount{0};
|
||||
inline static thread_local TraceThread* local = nullptr;
|
||||
};
|
||||
|
||||
}
|
||||
|
||||
#endif
|
||||
|
|
@ -39,6 +39,7 @@ public:
|
|||
VulkanDevice(const VulkanDevice&) = delete;
|
||||
VulkanDevice& operator=(const VulkanDevice&) = delete;
|
||||
std::string DeviceName() const;
|
||||
std::string DriverInfo() const;
|
||||
ShaderRecompiler::SpirvTarget Target() const;
|
||||
std::optional<ShaderRecompiler::GeometryStageLimits> GeometryLimits() const;
|
||||
const std::uint32_t* WorkGroupCountLimit() const;
|
||||
|
|
|
|||
|
|
@ -37,7 +37,7 @@ void Driver::AttachWindow(const PresentationWindow& window) {
|
|||
}
|
||||
|
||||
void Driver::Present(const PresentationWindow& window, const DisplayBuffer* buffer, bool opaque, void (*gpuReady)(void*), void* context) {
|
||||
|
||||
if (PerformanceTrace::Configured()) PerformanceTrace::Present(window.width, window.height, device.Load().get());
|
||||
PerformanceContext timingContext(window.timing.get());
|
||||
PerformanceTimer timing("Driver.Present");
|
||||
static thread_local bool pinned = false;
|
||||
|
|
|
|||
|
|
@ -67,11 +67,9 @@ void Driver::reapCompletionLabels() {
|
|||
|
||||
void Driver::run(std::uint32_t id) noexcept {
|
||||
onWorkerThread() = true;
|
||||
{
|
||||
char role[32];
|
||||
std::snprintf(role, sizeof role, "queue worker 0x%x", id);
|
||||
PinWorkerThread(role);
|
||||
}
|
||||
char role[32];
|
||||
std::snprintf(role, sizeof role, "queue worker 0x%x", id);
|
||||
PinWorkerThread(role);
|
||||
|
||||
GuestMemory::TagGpuLockThread(id);
|
||||
if (id == 0) StartWorkerSampler();
|
||||
|
|
@ -79,6 +77,7 @@ void Driver::run(std::uint32_t id) noexcept {
|
|||
static const bool profile = std::getenv("APS5_PROFILE_DRAW") != nullptr;
|
||||
auto& costs = submissionCosts(id);
|
||||
try {
|
||||
if (PerformanceTrace::Configured()) PerformanceTrace::BindThread(role);
|
||||
for (;;) {
|
||||
submission = Submission{};
|
||||
struct Running {
|
||||
|
|
|
|||
|
|
@ -0,0 +1,205 @@
|
|||
#include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp"
|
||||
#include "prx/libSceAgcDriver/Execution/include/ProfileOutput.hpp"
|
||||
#include "prx/libSceAgcDriver/Execution/include/VulkanDevice.hpp"
|
||||
#include "prx/libSceAgcDriver/TraceRevision.hpp"
|
||||
#include "zlib.h"
|
||||
#include <cstdlib>
|
||||
#include <filesystem>
|
||||
#include <fstream>
|
||||
#include <limits>
|
||||
#include <mutex>
|
||||
#include <system_error>
|
||||
#ifdef _WIN32
|
||||
#include <windows.h>
|
||||
#else
|
||||
#include <cerrno>
|
||||
#include <sys/utsname.h>
|
||||
#include <unistd.h>
|
||||
#endif
|
||||
|
||||
#ifndef _WIN32
|
||||
extern char** environ;
|
||||
#endif
|
||||
|
||||
namespace AgcDriver {
|
||||
|
||||
namespace {
|
||||
|
||||
using Clock = std::chrono::steady_clock;
|
||||
|
||||
struct Session {
|
||||
std::mutex mutex;
|
||||
std::vector<std::unique_ptr<TraceThread>> threads;
|
||||
std::optional<TraceWindow> window;
|
||||
Clock::time_point first{};
|
||||
std::uint64_t present = 0;
|
||||
std::uint64_t firstPresent = 0;
|
||||
double gpuBusyAtOpen = 0;
|
||||
std::vector<Clock::time_point> presents;
|
||||
};
|
||||
|
||||
Session& session() {
|
||||
static auto& state = *new Session();
|
||||
return state;
|
||||
}
|
||||
|
||||
std::unique_ptr<ProfileOutput>& writer() {
|
||||
static std::unique_ptr<ProfileOutput> output;
|
||||
return output;
|
||||
}
|
||||
|
||||
std::uint64_t processId() {
|
||||
#ifdef _WIN32
|
||||
return GetCurrentProcessId();
|
||||
#else
|
||||
return static_cast<std::uint64_t>(::getpid());
|
||||
#endif
|
||||
}
|
||||
|
||||
std::string operatingSystem() {
|
||||
#ifdef _WIN32
|
||||
using QueryVersion = LONG(WINAPI*)(PRTL_OSVERSIONINFOW);
|
||||
static const auto query = reinterpret_cast<QueryVersion>(reinterpret_cast<void*>(::GetProcAddress(::GetModuleHandleW(L"ntdll.dll"), "RtlGetVersion")));
|
||||
RTL_OSVERSIONINFOW version{};
|
||||
version.dwOSVersionInfoSize = sizeof(version);
|
||||
if (query == nullptr || query(&version) != 0) throw std::runtime_error("RtlGetVersion failed");
|
||||
return "Windows " + std::to_string(version.dwMajorVersion) + "." + std::to_string(version.dwMinorVersion) + "." + std::to_string(version.dwBuildNumber);
|
||||
#else
|
||||
utsname name{};
|
||||
if (::uname(&name) != 0) throw std::system_error(errno, std::generic_category(), "uname");
|
||||
return std::string(name.sysname) + " " + name.release;
|
||||
#endif
|
||||
}
|
||||
|
||||
std::vector<std::pair<std::string, std::string>> environment() {
|
||||
#ifdef _WIN32
|
||||
char** entries = _environ;
|
||||
#else
|
||||
char** entries = environ;
|
||||
#endif
|
||||
std::vector<std::pair<std::string, std::string>> result;
|
||||
for (; entries != nullptr && *entries != nullptr; ++entries) {
|
||||
const std::string_view entry = *entries;
|
||||
const auto equals = entry.find('=');
|
||||
if (!entry.starts_with("APS5_") || equals == std::string_view::npos) continue;
|
||||
std::string value(entry.substr(equals + 1));
|
||||
if (value.find_first_of("/\\") != std::string::npos) value = "<path>";
|
||||
result.emplace_back(std::string(entry.substr(0, equals)), std::move(value));
|
||||
}
|
||||
std::sort(result.begin(), result.end());
|
||||
return result;
|
||||
}
|
||||
|
||||
void writeGzip(const std::filesystem::path& path, std::string_view text) {
|
||||
z_stream stream{};
|
||||
if (deflateInit2(&stream, Z_DEFAULT_COMPRESSION, Z_DEFLATED, 15 + 16, 8, Z_DEFAULT_STRATEGY) != Z_OK) throw std::runtime_error("deflateInit2 failed");
|
||||
struct End {
|
||||
z_stream& stream;
|
||||
~End() { deflateEnd(&stream); }
|
||||
} end{stream};
|
||||
std::ofstream output;
|
||||
output.exceptions(std::ios::badbit | std::ios::failbit);
|
||||
output.open(path, std::ios::binary | std::ios::trunc);
|
||||
std::vector<unsigned char> chunk(1 << 16);
|
||||
std::size_t offset = 0;
|
||||
int status = Z_OK;
|
||||
while (status != Z_STREAM_END) {
|
||||
if (stream.avail_in == 0 && offset < text.size()) {
|
||||
const auto piece = std::min<std::size_t>(text.size() - offset, std::numeric_limits<uInt>::max());
|
||||
stream.next_in = reinterpret_cast<Bytef*>(const_cast<char*>(text.data() + offset));
|
||||
stream.avail_in = static_cast<uInt>(piece);
|
||||
offset += piece;
|
||||
}
|
||||
stream.next_out = chunk.data();
|
||||
stream.avail_out = static_cast<uInt>(chunk.size());
|
||||
status = deflate(&stream, offset == text.size() ? Z_FINISH : Z_NO_FLUSH);
|
||||
if (status != Z_OK && status != Z_STREAM_END) throw std::runtime_error("deflate failed with " + std::to_string(status));
|
||||
output.write(reinterpret_cast<const char*>(chunk.data()), static_cast<std::streamsize>(chunk.size() - stream.avail_out));
|
||||
}
|
||||
output.close();
|
||||
}
|
||||
|
||||
void appendLine(const std::filesystem::path& path, std::string_view line) {
|
||||
std::ofstream output;
|
||||
output.exceptions(std::ios::badbit | std::ios::failbit);
|
||||
output.open(path, std::ios::binary | std::ios::app);
|
||||
output.write(line.data(), static_cast<std::streamsize>(line.size()));
|
||||
output.close();
|
||||
}
|
||||
|
||||
}
|
||||
|
||||
void PerformanceTrace::BindThread(const char* name) {
|
||||
if (!Configured() || local != nullptr) return;
|
||||
auto bound = std::make_unique<TraceThread>(name, presentCount);
|
||||
auto& state = session();
|
||||
std::lock_guard lock(state.mutex);
|
||||
local = bound.get();
|
||||
state.threads.push_back(std::move(bound));
|
||||
}
|
||||
|
||||
void PerformanceTrace::Present(std::uint32_t width, std::uint32_t height, const VulkanDevice* device) {
|
||||
const auto now = Clock::now();
|
||||
BindThread("presenter");
|
||||
auto& state = session();
|
||||
std::lock_guard lock(state.mutex);
|
||||
if (!state.window) {
|
||||
state.window.emplace(TraceWindow::Parse(std::getenv("APS5_TRACE_FRAMES"), std::getenv("APS5_TRACE_SECONDS")).value());
|
||||
state.first = now;
|
||||
}
|
||||
const auto present = state.present++;
|
||||
const auto edge = state.window->Present(present, now - state.first);
|
||||
if (edge == TraceWindow::Edge::Open) {
|
||||
state.firstPresent = present;
|
||||
state.gpuBusyAtOpen = VulkanDevice::PresentCounts().gpuBusyMs;
|
||||
state.presents.push_back(now);
|
||||
presentCount.fetch_add(1, std::memory_order_relaxed);
|
||||
recording.store(true, std::memory_order_relaxed);
|
||||
ProfilePrint_nid_no_patch("[trace] recording %s from present %llu\n", state.window->Describe().c_str(), static_cast<unsigned long long>(present));
|
||||
return;
|
||||
}
|
||||
if (!recording.load(std::memory_order_relaxed)) return;
|
||||
state.presents.push_back(now);
|
||||
presentCount.fetch_add(1, std::memory_order_relaxed);
|
||||
if (edge != TraceWindow::Edge::Close) return;
|
||||
recording.store(false, std::memory_order_relaxed);
|
||||
|
||||
std::vector<TraceThread::Snapshot> snapshots;
|
||||
std::size_t presenter = 0;
|
||||
for (std::size_t index = 0; index < state.threads.size(); ++index) {
|
||||
if (state.threads[index].get() == local) presenter = index;
|
||||
snapshots.push_back(state.threads[index]->Collect());
|
||||
}
|
||||
const auto process = processId();
|
||||
TraceSummary summary;
|
||||
summary.commit = APS5_TRACE_COMMIT;
|
||||
if (APS5_TRACE_DIRTY >= 0) summary.dirty = APS5_TRACE_DIRTY != 0;
|
||||
summary.environment = environment();
|
||||
summary.gpu = device != nullptr ? device->DeviceName() : std::string();
|
||||
summary.driver = device != nullptr ? device->DriverInfo() : std::string();
|
||||
summary.os = operatingSystem();
|
||||
summary.width = width;
|
||||
summary.height = height;
|
||||
summary.window = state.window->Describe();
|
||||
summary.firstPresent = state.firstPresent;
|
||||
summary.gpuBusyMs = VulkanDevice::PresentCounts().gpuBusyMs - state.gpuBusyAtOpen;
|
||||
summary.trace = "aps5-trace-" + summary.commit + "-" + std::to_string(process) + ".json.gz";
|
||||
auto events = TraceFormat::Events(process, state.presents.front(), snapshots, presenter, state.presents, state.firstPresent);
|
||||
const char* traceDirectory = std::getenv("APS5_TRACE_DIR");
|
||||
auto& output = writer();
|
||||
output = std::make_unique<ProfileOutput>([directory = std::filesystem::path(traceDirectory != nullptr ? traceDirectory : "."), name = summary.trace, line = TraceFormat::Summary(summary, snapshots, state.presents)](std::string_view text) {
|
||||
try {
|
||||
std::filesystem::create_directories(directory);
|
||||
writeGzip(directory / name, text);
|
||||
appendLine(directory / "aps5-summary.jsonl", line);
|
||||
std::fprintf(stderr, "[trace] wrote %s and its line in aps5-summary.jsonl\n", name.c_str());
|
||||
} catch (const std::exception& error) {
|
||||
std::fprintf(stderr, "[trace] writing %s failed: %s\n", name.c_str(), error.what());
|
||||
throw;
|
||||
}
|
||||
}, std::numeric_limits<std::size_t>::max());
|
||||
ProfilePrint_nid_no_patch("[trace] closed at present %llu, writing %s (%zu bytes of JSON)\n", static_cast<unsigned long long>(present), summary.trace.c_str(), events.size());
|
||||
output->Write(std::move(events));
|
||||
}
|
||||
|
||||
}
|
||||
|
|
@ -255,6 +255,7 @@ struct VulkanDevice::State {
|
|||
void* uploadMapping = nullptr;
|
||||
VkDeviceSize uploadSize = 0;
|
||||
VkPhysicalDeviceProperties properties{};
|
||||
std::string driverInfo;
|
||||
VkPhysicalDeviceSubgroupProperties subgroup{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_SUBGROUP_PROPERTIES};
|
||||
std::vector<std::uint32_t> capabilities{1};
|
||||
std::vector<std::string_view> spirvExtensions;
|
||||
|
|
@ -1039,7 +1040,13 @@ VulkanDevice::VulkanDevice(const PresentationWindow* window, bool compileOnly) :
|
|||
std::vector<VkExtensionProperties> availableExtensions(extensionCount);
|
||||
check(enumerateDeviceExtensions(selected, nullptr, &extensionCount, availableExtensions.data()), "vkEnumerateDeviceExtensionProperties");
|
||||
const auto hasExtension = [&](const char* name) { return std::any_of(availableExtensions.begin(), availableExtensions.end(), [&](const auto& item) { return std::strcmp(item.extensionName, name) == 0; }); };
|
||||
auto byteFeatures = QueryBdaByteFeatures(selected, state->InstanceFunction<PFN_vkGetPhysicalDeviceFeatures2>("vkGetPhysicalDeviceFeatures2"), availableExtensions);
|
||||
if (hasExtension(VK_KHR_DRIVER_PROPERTIES_EXTENSION_NAME)) {
|
||||
VkPhysicalDeviceDriverProperties driver{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_DRIVER_PROPERTIES};
|
||||
VkPhysicalDeviceProperties2 driverProperties{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_PROPERTIES_2, &driver};
|
||||
state->InstanceFunction<PFN_vkGetPhysicalDeviceProperties2>("vkGetPhysicalDeviceProperties2")(selected, &driverProperties);
|
||||
state->driverInfo = std::string(driver.driverName) + " " + driver.driverInfo;
|
||||
}
|
||||
auto byteFeatures =QueryBdaByteFeatures(selected, state->InstanceFunction<PFN_vkGetPhysicalDeviceFeatures2>("vkGetPhysicalDeviceFeatures2"), availableExtensions);
|
||||
auto bdaFeatures = QueryBdaFeatures(selected, state->InstanceFunction<PFN_vkGetPhysicalDeviceFeatures2>("vkGetPhysicalDeviceFeatures2"), availableExtensions);
|
||||
require(hasExtension(VK_KHR_SHADER_FLOAT_CONTROLS_EXTENSION_NAME), "VK_KHR_shader_float_controls is unavailable");
|
||||
VkPhysicalDeviceFloatControlsProperties floatControls{VK_STRUCTURE_TYPE_PHYSICAL_DEVICE_FLOAT_CONTROLS_PROPERTIES};
|
||||
|
|
@ -2942,6 +2949,10 @@ std::string VulkanDevice::DeviceName() const {
|
|||
return state->properties.deviceName;
|
||||
}
|
||||
|
||||
std::string VulkanDevice::DriverInfo() const {
|
||||
return state->driverInfo.empty() ? std::to_string(state->properties.driverVersion) : state->driverInfo;
|
||||
}
|
||||
|
||||
const std::uint32_t* VulkanDevice::WorkGroupCountLimit() const {
|
||||
return state->properties.limits.maxComputeWorkGroupCount;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -1811,7 +1811,7 @@ bool Recorder::GpuTimingEnabled() {
|
|||
}
|
||||
|
||||
bool Recorder::BatchStampsEnabled() {
|
||||
return GpuTimingEnabled() || DrawProfiled();
|
||||
return GpuTimingEnabled() || DrawProfiled() || PerformanceTrace::Configured();
|
||||
}
|
||||
|
||||
void Recorder::CountBarriers(CommandClass which, std::uint32_t count) {
|
||||
|
|
@ -1903,7 +1903,7 @@ std::uint32_t Recorder::BeginGpuTiming(std::uint64_t key) {
|
|||
|
||||
std::uint32_t Recorder::beginTiming(std::uint64_t key) {
|
||||
const bool full = GpuTimingEnabled();
|
||||
if (!full && !(key == BatchTimingKey && DrawProfiled())) return NoTiming;
|
||||
if (!full && !(key == BatchTimingKey && BatchStampsEnabled())) return NoTiming;
|
||||
const auto commands = open->commands;
|
||||
const std::uint32_t queryCount = full ? MaxTimedRanges * 2 : 2;
|
||||
if (open->queries == VK_NULL_HANDLE) {
|
||||
|
|
|
|||
|
|
@ -0,0 +1,157 @@
|
|||
#include "prx/libSceAgcDriver/Execution/include/PerformanceTrace.hpp"
|
||||
#include <iostream>
|
||||
|
||||
namespace {
|
||||
|
||||
using AgcDriver::TraceFormat;
|
||||
using AgcDriver::TraceThread;
|
||||
using AgcDriver::TraceWindow;
|
||||
using Clock = std::chrono::steady_clock;
|
||||
using Edge = TraceWindow::Edge;
|
||||
using std::chrono::microseconds;
|
||||
using std::chrono::milliseconds;
|
||||
|
||||
void Check(bool condition, const char* message) {
|
||||
if (!condition) throw std::runtime_error(message);
|
||||
}
|
||||
|
||||
void WindowByFrames() {
|
||||
auto window = TraceWindow::Parse("3:2", nullptr).value();
|
||||
std::vector<Edge> edges;
|
||||
for (std::uint64_t present = 0; present < 8; ++present) edges.push_back(window.Present(present, std::chrono::seconds(present)));
|
||||
Check(edges == std::vector<Edge>{Edge::None, Edge::None, Edge::None, Edge::Open, Edge::None, Edge::Close, Edge::None, Edge::None}, "frame window opened or closed at the wrong present");
|
||||
Check(window.Describe() == "frames 3:2", "frame window description changed");
|
||||
}
|
||||
|
||||
void WindowBySeconds() {
|
||||
auto window = TraceWindow::Parse(nullptr, "2:1").value();
|
||||
std::vector<Edge> edges;
|
||||
for (const auto elapsed : {milliseconds(0), milliseconds(1999), milliseconds(2000), milliseconds(2999), milliseconds(3000), milliseconds(5000)})
|
||||
edges.push_back(window.Present(0, elapsed));
|
||||
Check(edges == std::vector<Edge>{Edge::None, Edge::None, Edge::Open, Edge::None, Edge::Close, Edge::None}, "seconds window opened or closed at the wrong present");
|
||||
Check(window.Describe() == "seconds 2:1", "seconds window description changed");
|
||||
}
|
||||
|
||||
void WindowRejects() {
|
||||
Check(!TraceWindow::Parse(nullptr, nullptr).has_value(), "a window was made without a switch");
|
||||
for (const auto* text : {"5", "a:1", "1:0", "1:", ":1", "1:2:3", "-1:2"}) {
|
||||
bool rejected = false;
|
||||
try { TraceWindow::Parse(text, nullptr); }
|
||||
catch (const std::invalid_argument&) { rejected = true; }
|
||||
Check(rejected, "a malformed window was accepted");
|
||||
}
|
||||
bool rejected = false;
|
||||
try { TraceWindow::Parse("1:1", "1:1"); }
|
||||
catch (const std::invalid_argument&) { rejected = true; }
|
||||
Check(rejected, "frames and seconds were accepted together");
|
||||
}
|
||||
|
||||
void BufferCap() {
|
||||
std::atomic<std::uint64_t> presents{1};
|
||||
TraceThread thread("queue worker 0x0", presents, 2);
|
||||
const auto origin = Clock::now();
|
||||
for (int index = 0; index < 3; ++index) thread.Add("Driver.Packet", nullptr, origin + milliseconds(index), origin + milliseconds(index) + microseconds(30));
|
||||
const auto snapshot = thread.Collect();
|
||||
Check(snapshot.slices.size() == 2 && snapshot.dropped, "a full buffer did not stop and set the dropped flag");
|
||||
Check(snapshot.totals.size() == 1 && snapshot.totals[0].count == 3 && snapshot.totals[0].length == microseconds(90), "totals missed a slice past the cap");
|
||||
}
|
||||
|
||||
void FoldShortSlices() {
|
||||
std::atomic<std::uint64_t> presents{1};
|
||||
TraceThread thread("queue worker 0x0", presents, 16);
|
||||
const auto origin = Clock::now();
|
||||
thread.Add("Driver.Packet", nullptr, origin, origin + microseconds(5));
|
||||
thread.Add("Driver.Packet", "draw", origin + microseconds(5), origin + microseconds(10));
|
||||
thread.Add("Driver.Draw", nullptr, origin + microseconds(10), origin + microseconds(40));
|
||||
presents.store(2);
|
||||
thread.Add("Driver.Completion", nullptr, origin + microseconds(50), origin + microseconds(90));
|
||||
const auto snapshot = thread.Collect();
|
||||
Check(snapshot.slices.size() == 3 && !snapshot.dropped, "short slices were written or long ones lost");
|
||||
Check(std::string_view(snapshot.slices[0].scope) == "Driver.Draw", "the first long slice is missing");
|
||||
Check(snapshot.slices[1].scope == nullptr && snapshot.slices[1].begin == origin && snapshot.slices[1].length == microseconds(10), "the folded sample of the previous present is wrong");
|
||||
Check(std::string_view(snapshot.slices[2].scope) == "Driver.Completion", "the slice after the present is missing");
|
||||
Check(snapshot.totals.size() == 4, "totals did not keep scope and stage apart");
|
||||
for (const auto& total : snapshot.totals) Check(total.count == 1, "a total counted a slice twice");
|
||||
}
|
||||
|
||||
void EscapeStrings() {
|
||||
std::string output;
|
||||
TraceFormat::AppendString(output, "a\"b\\c\n\xe9");
|
||||
Check(output == "\"a\\\"b\\\\c\\u000a\\u00e9\"", "string escaping is not valid JSON");
|
||||
}
|
||||
|
||||
void EventsShape() {
|
||||
const auto origin = Clock::now();
|
||||
const std::vector<TraceThread::Slice> slices{
|
||||
{"Driver.Packet", nullptr, origin + microseconds(10), microseconds(30)},
|
||||
{"Driver.Packet", "draw", origin + microseconds(12), microseconds(25)},
|
||||
{nullptr, nullptr, origin, milliseconds(2)},
|
||||
};
|
||||
const std::vector<TraceThread::Snapshot> threads{{"queue worker 0x0", slices, {}, false}};
|
||||
const std::vector<Clock::time_point> presents{origin, origin + milliseconds(16)};
|
||||
const auto json = TraceFormat::Events(7, origin, threads, 0, presents, 5);
|
||||
const std::string expected =
|
||||
"{\"traceEvents\":[\n"
|
||||
"{\"name\":\"process_name\",\"ph\":\"M\",\"ts\":0.000,\"pid\":7,\"tid\":0,\"args\":{\"name\":\"AnyPS5\"}},\n"
|
||||
"{\"name\":\"thread_name\",\"ph\":\"M\",\"ts\":0.000,\"pid\":7,\"tid\":1,\"args\":{\"name\":\"queue worker 0x0\"}},\n"
|
||||
"{\"name\":\"queue worker 0x0 folded\",\"ph\":\"C\",\"ts\":0.000,\"pid\":7,\"tid\":1,\"args\":{\"ms\":2.000}},\n"
|
||||
"{\"name\":\"Driver.Packet\",\"ph\":\"X\",\"ts\":10.000,\"pid\":7,\"tid\":1,\"dur\":30.000},\n"
|
||||
"{\"name\":\"Driver.Packet.draw\",\"ph\":\"X\",\"ts\":12.000,\"pid\":7,\"tid\":1,\"dur\":25.000},\n"
|
||||
"{\"name\":\"present\",\"ph\":\"i\",\"ts\":0.000,\"pid\":7,\"tid\":1,\"s\":\"g\",\"args\":{\"present\":5}}\n"
|
||||
"]}\n";
|
||||
Check(json == expected, "trace events changed shape");
|
||||
}
|
||||
|
||||
void SummaryFields() {
|
||||
const auto origin = Clock::now();
|
||||
AgcDriver::TraceSummary summary;
|
||||
summary.commit = "abc";
|
||||
summary.dirty = false;
|
||||
summary.environment = {{"APS5_TRACE_FRAMES", "3:2"}};
|
||||
summary.gpu = "GPU";
|
||||
summary.driver = "Driver 1";
|
||||
summary.os = "OS 1";
|
||||
summary.width = 1920;
|
||||
summary.height = 1080;
|
||||
summary.window = "frames 3:2";
|
||||
summary.firstPresent = 3;
|
||||
summary.gpuBusyMs = 20;
|
||||
summary.trace = "aps5-trace-abc-7.json.gz";
|
||||
const std::vector<TraceThread::Snapshot> threads{
|
||||
{"queue worker 0x0", {}, {{"Driver.Packet", nullptr, milliseconds(12), 4}, {"Driver.WorkerWait", nullptr, milliseconds(8), 4}, {"Driver.Completion", nullptr, milliseconds(2), 4}, {"Driver.Packet", "draw", milliseconds(10), 2}}, false},
|
||||
{"presenter", {}, {{"Driver.Present", nullptr, milliseconds(6), 2}, {"Driver.Present", "inflight_wait", milliseconds(4), 2}}, false},
|
||||
};
|
||||
const std::vector<Clock::time_point> presents{origin, origin + milliseconds(16), origin + milliseconds(40)};
|
||||
const auto line = TraceFormat::Summary(summary, threads, presents);
|
||||
const std::string expected =
|
||||
"{\"commit\":\"abc\",\"dirty\":false,\"env\":{\"APS5_TRACE_FRAMES\":\"3:2\"},\"gpu\":\"GPU\",\"driver\":\"Driver 1\",\"os\":\"OS 1\","
|
||||
"\"resolution\":\"1920x1080\",\"window\":{\"spec\":\"frames 3:2\",\"first_present\":3,\"ms\":40.000},\"presents\":2,"
|
||||
"\"frame_ms\":{\"p50\":24.000,\"p90\":24.000,\"p99\":24.000,\"max\":24.000},\"gpu_busy_ms_per_present\":10.000,"
|
||||
"\"worker_busy_pct\":{\"queue worker 0x0\":35.000},"
|
||||
"\"top_phases_ms_per_frame\":{\"Driver.Packet\":6.000,\"Driver.Packet.draw\":5.000,\"Driver.Present\":3.000,\"Driver.Present.inflight_wait\":2.000,\"Driver.Completion\":1.000},"
|
||||
"\"trace_dropped\":false,\"trace\":\"aps5-trace-abc-7.json.gz\"}\n";
|
||||
Check(line == expected, "summary line changed");
|
||||
auto dropped = threads;
|
||||
dropped[1].dropped = true;
|
||||
Check(TraceFormat::Summary(summary, dropped, presents).find("\"trace_dropped\":true") != std::string::npos, "a dropped thread did not mark the summary");
|
||||
}
|
||||
|
||||
}
|
||||
|
||||
int main() {
|
||||
try {
|
||||
WindowByFrames();
|
||||
WindowBySeconds();
|
||||
WindowRejects();
|
||||
BufferCap();
|
||||
FoldShortSlices();
|
||||
EscapeStrings();
|
||||
EventsShape();
|
||||
SummaryFields();
|
||||
std::cout << "performance trace tests passed\n";
|
||||
return 0;
|
||||
} catch (const std::exception& error) {
|
||||
std::cerr << error.what() << '\n';
|
||||
return 1;
|
||||
}
|
||||
}
|
||||
|
|
@ -0,0 +1,19 @@
|
|||
set(commit unknown)
|
||||
set(dirty -1)
|
||||
if(GIT)
|
||||
execute_process(COMMAND "${GIT}" -C "${SOURCE}" rev-parse --short=12 HEAD
|
||||
OUTPUT_VARIABLE head RESULT_VARIABLE failed OUTPUT_STRIP_TRAILING_WHITESPACE ERROR_QUIET)
|
||||
if(failed EQUAL 0 AND NOT head STREQUAL "")
|
||||
set(commit ${head})
|
||||
execute_process(COMMAND "${GIT}" -C "${SOURCE}" status --porcelain --untracked-files=no
|
||||
OUTPUT_VARIABLE changes RESULT_VARIABLE failed ERROR_QUIET)
|
||||
if(failed EQUAL 0 AND changes STREQUAL "")
|
||||
set(dirty 0)
|
||||
elseif(failed EQUAL 0)
|
||||
set(dirty 1)
|
||||
endif()
|
||||
endif()
|
||||
endif()
|
||||
file(WRITE "${OUTPUT}.new" "#pragma once\n#define APS5_TRACE_COMMIT \"${commit}\"\n#define APS5_TRACE_DIRTY ${dirty}\n")
|
||||
execute_process(COMMAND ${CMAKE_COMMAND} -E copy_if_different "${OUTPUT}.new" "${OUTPUT}")
|
||||
file(REMOVE "${OUTPUT}.new")
|
||||
|
|
@ -120,6 +120,16 @@ Set `APS5_SAMPLE_WORKER=<file>` to sample queue worker 0 every millisecond (in p
|
|||
|
||||
`APS5_SAMPLE_THREADS=<file>` samples every thread of the process every 2 ms and writes the 40 hottest addresses of each busy thread to `<file>`, 12 frames deep and through `.pdata` only. Both samplers exist only on Windows; the addresses are symbolized offline, for example with `nm` on the `.prx`.
|
||||
|
||||
## Performance trace
|
||||
|
||||
Set `APS5_TRACE_FRAMES=<start>:<count>` to record `<count>` presents from present `<start>` (counted from 0), or `APS5_TRACE_SECONDS=<start>:<length>` to record from the first present at least `<start>` seconds after the first present until the first present `<length>` seconds later. Both values are whole numbers and the length is above 0; a malformed value, or both switches together, fails the first present. The window opens and closes at presents.
|
||||
|
||||
Inside the window the queue workers and the presenter record every `PerformanceTimer` scope and stage as a complete event named after its frame timing key: `Driver.WorkerWait`, `Driver.Packet`, `Driver.Packet.draw`, `Graphics.Draw`, `Driver.Present`, `Driver.Present.inflight_wait`, `Vulkan.Retire` and so on. A slice shorter than 20 us is only counted: its time is in the thread's counter `<thread> folded` (milliseconds per present) and in the summary. Each thread allocates a buffer for 262,144 events when it starts; a full buffer stops that thread's recording and sets `trace_dropped`. When the window closes, the presenter formats the trace once and a `ProfileOutput` writer thread writes `aps5-trace-<commit>-<pid>.json.gz` (Chrome trace-event JSON, opened by ui.perfetto.dev or chrome://tracing) and appends one line to `aps5-summary.jsonl`, both in `APS5_TRACE_DIR` or the working directory. A window that is still open when the title exits writes nothing.
|
||||
|
||||
The summary line has `commit` and `dirty` of the build, `env` (every `APS5_*` variable; a value containing `/` or `\` is written as `<path>`), `gpu`, `driver`, `os`, `resolution` (the video output's), `window`, `presents`, `frame_ms` (p50, p90, p99 and max of the intervals between presents), `gpu_busy_ms_per_present` (the batch timestamps behind `[present]`), `worker_busy_pct` (share of the window each queue worker spends in `Driver.Packet`, `Driver.Suspend`, `Driver.EndSubmission`, `Driver.Rewind` and `Driver.Completion`), `top_phases_ms_per_frame` (the eight largest scopes and stages, without `Driver.WorkerWait`), `trace_dropped` and `trace`. A trace holds timings, scope names, counts and thread names; no guest memory, paths or strings of the title.
|
||||
|
||||
With either switch set, the recorder writes a timestamp pair per batch for the whole run, as with `APS5_PROFILE_DRAW`. Without them, a `PerformanceTimer` costs one more predictable branch.
|
||||
|
||||
## Driver thread priority
|
||||
|
||||
Set `APS5_THREAD_PRIORITY=high` to raise the AGC driver's queue workers and the video output presenter above the title's threads. On Linux the threads get nice `APS5_THREAD_NICE` (default -10) through rtkit; on Windows they get `THREAD_PRIORITY_HIGHEST`. `APS5_THREAD_PRIORITY=rt` asks rtkit for real-time priority `APS5_THREAD_RT` (default 10, at most rtkit's `MaxRealtimePriority`) under rtkit's policy, `SCHED_RR` by default; on Windows it sets `THREAD_PRIORITY_TIME_CRITICAL`. rtkit only grants it when the process's hard `RLIMIT_RTTIME` is at most its `RTTimeUSecMax` (200000 us by default), so a hard limit above `APS5_THREAD_RTTIME_US` (default 200000, capped at `RTTimeUSecMax`) is lowered to it and the soft limit to at most half of it. The hard limit cannot be raised again and stays lowered for the whole process even if rtkit then refuses; see [technical debt](TechnicalDebt.md#functional). There is no fallback between the modes: when rtkit or `SetThreadPriority` refuses, a queue worker reports the refusal as a driver failure, which the next submission, wait or shutdown rethrows, and the presenter's start throws it. Each raised thread logs its priority once as `[thread-priority]`. The setting is `off` by default; a value other than `off`, `high` or `rt` is reported the same way as a refusal.
|
||||
|
|
|
|||
Loading…
Reference in New Issue