diff --git a/core/libs/prx/libc/CMakeLists.txt b/core/libs/prx/libc/CMakeLists.txt index ed2da1c7a5..5ea3fa5136 100644 --- a/core/libs/prx/libc/CMakeLists.txt +++ b/core/libs/prx/libc/CMakeLists.txt @@ -642,7 +642,7 @@ if(BUILD_TESTING) "PATH=path_list_prepend:$") endif() set_tests_properties(guest_call_trace_abort PROPERTIES TIMEOUT 20 PASS_REGULAR_EXPRESSION - "last traced system library calls[^~]*#1 thread [0-9]+ libTraced.prx Integers from [^~]*guest_call_trace_tests${CMAKE_EXECUTABLE_SUFFIX}[^~]*#2 thread [0-9]+ libOther.prx Blocks from[^~]*most called traced imports \\(2 calls in total\\):[^~]* 1 libTraced.prx Integers[^~]* 1 libOther.prx Blocks") + "last traced system library calls[^~]*#1 thread [0-9]+ libTraced.prx Integers from [^~]*guest_call_trace_tests${CMAKE_EXECUTABLE_SUFFIX}[^~]*#2 thread [0-9]+ libOther.prx Blocks from[^~]*last traced calls of thread [0-9]+:[^~]*#1 libTraced.prx Integers from[^~]*#2 libOther.prx Blocks from[^~]*most called traced imports \\(2 calls in total\\):[^~]* 1 libTraced.prx Integers[^~]* 1 libOther.prx Blocks") if(NOT WIN32) add_test(NAME guest_call_trace_abort_race COMMAND guest_call_trace_tests abort-race) set_tests_properties(guest_call_trace_abort_race PROPERTIES TIMEOUT 20 PASS_REGULAR_EXPRESSION diff --git a/core/libs/prx/libc/include/CallTrace.hpp b/core/libs/prx/libc/include/CallTrace.hpp index 2c1f46c600..b53c1ba96e 100644 --- a/core/libs/prx/libc/include/CallTrace.hpp +++ b/core/libs/prx/libc/include/CallTrace.hpp @@ -21,6 +21,7 @@ struct CallTraceCount { extern "C" { void* TraceImport_nid_no_patch(void* target, const char* name, const char* library); std::size_t CopyCallTrace_nid_no_patch(CallTraceEntry* entries, std::size_t capacity); +std::size_t CopyThreadCallTrace_nid_no_patch(std::uint64_t thread, CallTraceEntry* entries, std::size_t capacity); std::size_t CopyCallCounts_nid_no_patch(CallTraceCount* entries, std::size_t capacity, std::uint64_t* total); } diff --git a/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp b/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp index bb46adda9a..7b4cc729ed 100644 --- a/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp +++ b/core/libs/prx/libc/src/specifics/windows/CrashReport.cpp @@ -481,6 +481,16 @@ void ReportCallTrace() { Report(" #%llu thread %llu %s %s from %s\n", static_cast(entries[index].sequence), static_cast(entries[index].thread), entries[index].library, entries[index].name, line); } + static CallTraceEntry own[32]; + const std::uint64_t thread = GetCurrentThreadId(); + const std::size_t owned = CopyThreadCallTrace_nid_no_patch(thread, own, std::size(own)); + if (owned != 0) { + Report(" last traced calls of thread %llu:\n", static_cast(thread)); + for (std::size_t index = 0; index < owned; ++index) { + DescribeAddress(own[index].returnAddress, line, sizeof(line)); + Report(" #%llu %s %s from %s\n", static_cast(own[index].sequence), own[index].library, own[index].name, line); + } + } static CallTraceCount counts[32]; std::uint64_t total = 0; const std::size_t counted = CopyCallCounts_nid_no_patch(counts, std::size(counts), &total); diff --git a/core/libs/prx/libc/src/specifics/x86_64/CallTrace.cpp b/core/libs/prx/libc/src/specifics/x86_64/CallTrace.cpp index f5e0920719..96d6c872a9 100644 --- a/core/libs/prx/libc/src/specifics/x86_64/CallTrace.cpp +++ b/core/libs/prx/libc/src/specifics/x86_64/CallTrace.cpp @@ -225,6 +225,17 @@ void ReportCallTrace() { DescribeAddress(line, entries[index].returnAddress); line.Write(); } + static CallTraceEntry own[32]; + const std::uint64_t thread = CurrentThread(); + const std::size_t owned = CopyThreadCallTrace_nid_no_patch(thread, own, std::size(own)); + if (owned != 0) { + line.Text(" last traced calls of thread ").Decimal(thread).Text(":").Write(); + for (std::size_t index = 0; index < owned; ++index) { + line.Text(" #").Decimal(own[index].sequence).Text(" ").Text(own[index].library).Text(" ").Text(own[index].name).Text(" from "); + DescribeAddress(line, own[index].returnAddress); + line.Write(); + } + } std::uint64_t total = 0; const std::size_t counted = CopyCallCounts_nid_no_patch(counts, std::size(counts), &total); if (counted == 0) return; @@ -351,6 +362,24 @@ std::size_t CopyCallTrace_nid_no_patch(CallTraceEntry* entries, std::size_t capa return count; } +std::size_t CopyThreadCallTrace_nid_no_patch(std::uint64_t thread, CallTraceEntry* entries, std::size_t capacity) { + const RingSlot* ring = g_ring.load(std::memory_order_acquire); + if (entries == nullptr || capacity == 0 || ring == nullptr) return 0; + const std::uint64_t last = g_sequence.load(std::memory_order_acquire); + const std::uint64_t span = std::min(last, RingCapacity); + std::size_t count = 0; + for (std::uint64_t sequence = last; sequence > last - span && count < capacity; --sequence) { + const RingSlot& slot = ring[sequence % RingCapacity]; + if (slot.sequence.load(std::memory_order_acquire) != sequence || slot.thread.load(std::memory_order_relaxed) != thread) continue; + const auto* record = slot.record.load(std::memory_order_relaxed); + const CallTraceEntry entry{sequence, thread, slot.returnAddress.load(std::memory_order_relaxed), record->name.c_str(), record->library.c_str()}; + if (slot.sequence.load(std::memory_order_acquire) != sequence) continue; + entries[count++] = entry; + } + std::reverse(entries, entries + count); + return count; +} + std::size_t CopyCallCounts_nid_no_patch(CallTraceCount* entries, std::size_t capacity, std::uint64_t* total) { if (total != nullptr) *total = g_sequence.load(std::memory_order_acquire); if (entries == nullptr || capacity == 0) return 0; diff --git a/core/libs/tests/GuestCallTrace.cpp b/core/libs/tests/GuestCallTrace.cpp index 11d3999982..4b7e2091e9 100644 --- a/core/libs/tests/GuestCallTrace.cpp +++ b/core/libs/tests/GuestCallTrace.cpp @@ -161,12 +161,20 @@ int main(int argc, char** argv) { Require(CopyCallCounts_nid_no_patch(counts, 2, nullptr) == 2); Require(counts[0].calls == 3 && std::strcmp(counts[0].name, "Blocks") == 0 && counts[1].calls == 2 && std::strcmp(counts[1].name, "Doubles") == 0); Require(CopyCallCounts_nid_no_patch(nullptr, 8, &total) == 0 && total == 8); + Require(CopyThreadCallTrace_nid_no_patch(CurrentThread(), entries, 16) == 8); + for (std::uint64_t index = 0; index < 8; ++index) Require(entries[index].sequence == index + 1 && entries[index].thread == CurrentThread()); + Require(CopyThreadCallTrace_nid_no_patch(CurrentThread(), entries, 2) == 2 && entries[0].sequence == 7 && entries[1].sequence == 8); + Require(std::strcmp(entries[1].name, "Blocks") == 0); + Require(CopyThreadCallTrace_nid_no_patch(CurrentThread() + 1, entries, 16) == 0); + Require(CopyThreadCallTrace_nid_no_patch(CurrentThread(), nullptr, 16) == 0 && CopyThreadCallTrace_nid_no_patch(CurrentThread(), entries, 0) == 0); constexpr std::uint64_t Workers = 4; constexpr std::uint64_t Calls = 20000; std::vector workers; + std::uint64_t workerThreads[Workers]{}; for (std::uint64_t worker = 0; worker < Workers; ++worker) { - workers.emplace_back([integers, worker] { + workers.emplace_back([integers, worker, &workerThreads] { + workerThreads[worker] = CurrentThread(); for (std::uint64_t call = 0; call < Calls; ++call) Require(integers(worker, call, 1, 2, 3, 4, 5, 6) == Integers(worker, call, 1, 2, 3, 4, 5, 6)); }); } @@ -176,6 +184,19 @@ int main(int argc, char** argv) { Require(CopyCallTrace_nid_no_patch(recent.get(), Window) == Window); Require(recent[Window - 1].sequence == 8 + Workers * Calls && recent[0].sequence == 8 + Workers * Calls - Window + 1); for (std::size_t index = 0; index < Window; ++index) Require(std::strcmp(recent[index].name, "Integers") == 0); + Require(CopyThreadCallTrace_nid_no_patch(CurrentThread(), entries, 16) == 0); + const auto own = std::make_unique(Window); + std::size_t owned = 0; + for (const std::uint64_t thread : workerThreads) { + std::size_t expected = 0; + for (std::size_t index = 0; index < Window; ++index) expected += recent[index].thread == thread; + const std::size_t count = CopyThreadCallTrace_nid_no_patch(thread, own.get(), Window); + Require(count == expected); + for (std::size_t index = 0; index < count; ++index) Require(own[index].thread == thread && (index == 0 || own[index - 1].sequence < own[index].sequence)); + if (count != 0) Require(CopyThreadCallTrace_nid_no_patch(thread, entries, 1) == 1 && entries[0].sequence == own[count - 1].sequence); + owned += count; + } + Require(owned == Window); Require(CopyCallCounts_nid_no_patch(counts, 1, &total) == 1 && total == 8 + Workers * Calls); Require(counts[0].calls == 1 + Workers * Calls && std::strcmp(counts[0].name, "Integers") == 0); } diff --git a/docs/dev/debt/libc.md b/docs/dev/debt/libc.md index 5329443dc7..770a0e9e25 100644 --- a/docs/dev/debt/libc.md +++ b/docs/dev/debt/libc.md @@ -125,7 +125,7 @@ - [_WStoul](../../../core/libs/prx/libc/src/Strings.cpp), [_Iswctype](../../../core/libs/prx/libc/src/RuneLocale.cpp), [swscanf_s and swscanf](../../../core/libs/prx/libc/src/ScanningWide.cpp) (libc) - `_WStoul` is `wcstoul` and throws for a base other than 0 or 2 to 36. `_Iswctype` takes the class numbers of Dinkumware's [xwcc.h](https://github.com/superna9999/ti-cgt6x/blob/cgt6x_7_3_4/include/xwcc.h) (1 `alnum` to 11 `xdigit`, 12 `blank`) and throws for any other value, including the FreeBSD masks `wctype` returns; the numbering is not confirmed on the console's `libc.prx`. `swscanf_s` follows C11 7.29.2.2 and K.3.9.1.5, but reads the size argument as `unsigned int` like `sscanf_s` where K.3.9.1.5 specifies `rsize_t`; the console's width is unverified. A runtime-constraint violation (null buffer, format or receiving pointer) only returns `EOF`, and a too small array gets a null first element as in `sscanf_s`. A literal mismatch is a matching failure and a field that is only a prefix, such as `0x` or `1e`, does not convert, as C11 requires; FreeBSD's `vfwscanf` reports an input failure for the first and converts the second. Integers out of range are truncated from `strtoll`/`strtoull`. `%p` follows FreeBSD 11's [vfwscanf.c](https://github.com/freebsd/freebsd-src/blob/4ab2e064d7950be84256d671a7ae93f87cc6aa36/lib/libc/stdio/vfwscanf.c#L610-L615): a hexadecimal integer with an optional `0x`, converted as unsigned and stored as a pointer; a length modifier on it throws, where FreeBSD ignores it. It throws for `%S`, `%C`, unknown length modifiers, scanset ranges, `%n` with suppression or width, and narrow `%s`, `%c` or `%[` input that the C-locale `wcrtomb` cannot convert. `swscanf` runs the same scanner without the size arguments of `%s`, `%c` and `%[`, as FreeBSD's [swscanf.c](https://github.com/freebsd/freebsd-src/blob/d106002967eff712894ab8b5337bbbff106ce5e0/lib/libc/stdio/swscanf.c) passes its arguments to `vswscanf`, so everything above except the sizes applies to it; it also keeps the null buffer, format and receiving pointer checks returning `EOF`, where C leaves those undefined. Neither variant is confirmed on a PS5 title - [flock](../../../core/libs/prx/libc/src/FileLock.cpp) (libkernel) on Windows shares one lock state between duplicated descriptors, following FreeBSD 11.4's [flock(2)](https://github.com/freebsd/freebsd-src/blob/releng/11.4/lib/libc/sys/flock.2). Independent opens have separate states; closing a descriptor or reopening a stream drops only its reference. Lock transitions on one open file description are serialized. The lock is a host [LockFileEx](https://learn.microsoft.com/en-us/windows/win32/api/fileapi/nf-fileapi-lockfileex) lock on one byte at offset 2^63 - 2, which no file reaches, so it excludes other `flock` calls and leaves reads, writes and mapped views alone, like FreeBSD's advisory locks. Console behavior, signal interruption and concurrent closure of a descriptor while its lock call is pending are unverified. - [std::_Throw_Cpp_error](../../../core/libs/prx/libc/src/exception/StandardExceptions.cpp) (libc) follows Dinkumware `thread0.cpp` ([VC12](https://github.com/ganboing/crt.vc12/blob/f1d47126/src/thread0.cpp), [STL](https://github.com/microsoft/STL/blob/da52dc0f/stl/src/thread0.cpp)), without console verification. Codes outside 0..6 throw `std::out_of_range`, the deleting destructor throws, and STREAMS errnos absent from FreeBSD 11.4 [`errno.h`](https://github.com/freebsd/freebsd-src/blob/releng/11.4/sys/sys/errno.h) (`ENODATA`, `ENOSR`, `ENOSTR`, `ETIME`) are omitted. Codes 0..6 throw a 32-byte [VC12 `system_error`](https://github.com/ganboing/crt.vc12/blob/f1d47126/src/system_error) with FreeBSD errnos (16, 22, 3, 12, 1, 11, 35), a static `generic_category` (not `_Generic_object`), and unverified 40-byte [GuestLocale::String](../../../core/libs/prx/libc/include/GuestLocale.hpp) messages from [`syserror.cpp`](https://github.com/ganboing/crt.vc12/blob/f1d47126/src/syserror.cpp) -- [Call tracing](../../../core/libs/prx/libc/src/specifics/x86_64/CallTrace.cpp) (`--trace-imports`, `APS5_TRACE_CALLS`) is missing on macOS and records only the entry of a call, not its arguments or result. One process-wide ring keeps the last 65536 calls, so a busy thread pushes the others out. Calls are counted per traced target; an import bound to a target already traced under another name is counted under the first name. The thunk saves the integer argument registers and `xmm0` to `xmm7`; wider vector arguments survive only while the recording code avoids AVX, which is untested. Linux has no crash report, so it prints the trace only on `SIGABRT` (guest or host `abort()`), not on `SIGSEGV`; a caller in a module loaded after the last traced import prints without a module name, and a thread aborting while another writes the report waits for it at most 2 seconds +- [Call tracing](../../../core/libs/prx/libc/src/specifics/x86_64/CallTrace.cpp) (`--trace-imports`, `APS5_TRACE_CALLS`) is missing on macOS and records only the entry of a call, not its arguments or result. One process-wide ring keeps the last 65536 calls, so a busy thread pushes the others out; the reporting thread's own calls are listed only while they are still in that ring. Calls are counted per traced target; an import bound to a target already traced under another name is counted under the first name. The thunk saves the integer argument registers and `xmm0` to `xmm7`; wider vector arguments survive only while the recording code avoids AVX, which is untested. Linux has no crash report, so it prints the trace only on `SIGABRT` (guest or host `abort()`), not on `SIGSEGV`; a caller in a module loaded after the last traced import prints without a module name, and a thread aborting while another writes the report waits for it at most 2 seconds - [_Dtest](../../../core/libs/prx/libc/src/Math.cpp) (libc) follows Dinkumware double classification matching _FDtest: finite values return -1, subnormals -2, zeros 0, infinities 1, and NaNs 2. - [app0.zar](../../../core/libs/prx/libc/src/AppArchive.cpp) (libc) - a [ZArchive](https://github.com/Exzap/ZArchive) beside `app0/` is a read-only layer under it: a path missing from `app0/` is looked up in the archive, case-insensitively. It is not a console format; titles ship their files in a PFS image instead. Resolving an archive-only path through any call other than the archive-aware libkernel ones throws, so `fopen`, `stat`, `access`, `opendir` and the rest do not read the archive yet, and `opendir` of a directory that exists in both places, `app0/` itself included, and `fdopen` of an archived descriptor throw instead of missing its entries or reading the null device. A damaged compressed block throws instead of returning `EIO` - [fopen_s](../../../core/libs/prx/libc/src/FileAndHeap.cpp) (libc) - returns the errno of the failed open, as C11 K.3.5.2.1 leaves the nonzero value open and Microsoft's CRT returns errno; the console's Dinkumware `fopen_s` is not verified diff --git a/docs/user/USAGE.md b/docs/user/USAGE.md index 1ea392b91f..42270f520c 100644 --- a/docs/user/USAGE.md +++ b/docs/user/USAGE.md @@ -308,11 +308,13 @@ To measure how a title runs on a machine, start it with `APS5_TRACE_SUMMARY_EVER ### Tracing system library calls -Windows and Linux. An executable converted with `--trace-imports` records the calls it makes to the libraries named in `APS5_TRACE_CALLS`, a comma-separated list such as `libkernel,libSceSaveData`, or `all`. Without the variable nothing is recorded. The crash and abort reports then end with the last 64 calls (on Linux, which has no crash report, only an abort prints them): sequence number, thread, library, import name as the executable imports it (a NID) and the caller's address. They are followed by the 32 most called imports since start-up, with their number of calls. +Windows and Linux. An executable converted with `--trace-imports` records the calls it makes to the libraries named in `APS5_TRACE_CALLS`, a comma-separated list such as `libkernel,libSceSaveData`, or `all`. Without the variable nothing is recorded. The crash and abort reports then end with the last 64 calls (on Linux, which has no crash report, only an abort prints them): sequence number, thread, library, import name as the executable imports it (a NID) and the caller's address. The last 32 of these calls made by the reporting thread follow, taken from the 65536 most recent calls, so a thread whose calls were pushed out of the last 64 by a busier one still shows them. Then come the 32 most called imports since start-up, with their number of calls. ``` last traced system library calls (APS5_TRACE_CALLS): #1 thread 9384 libkernel.prx k+AXqu2-eBc from 0x0000000140010006 app.exe+0x10006 +last traced calls of thread 9384: + #1 libkernel.prx k+AXqu2-eBc from 0x0000000140010006 app.exe+0x10006 most called traced imports (1 calls in total): 1 libkernel.prx k+AXqu2-eBc ```