Proposal: an opt-in trace of every system library call a title makes (APS5_TRACE_CALLS)

Proposal: an opt-in trace of every system library call a title makes

When a title stops early, finding which call went wrong is mostly manual work.

In #3308, for example, finding the Cyberpunk 2077 stop took locating a call site by hand: "call site at address 0x1d762d2 in the converted app.elf, PLT slot of NID wzvqT4UqKX8". The ~25 APS5_TRACE_* switches each cover one subsystem (GPU, draws, AJM, timers, waits, …). None of them shows the boundary between the title and the libraries: which import was called, from which thread, with which arguments, and what AnyPS5 returned.

I'd like to add one switch for that, off by default:

APS5_TRACE_CALLS=libkernel,libSceSaveData   (or "all")

When the switch is set, each call through a traced import would write a record:

a sequence number;
the thread;
the import index;
the six integer argument registers;
the return value;
for a short list of functions that take a path (sceKernelOpen, sceKernelStat, …), the path string as well.

The import index maps to NID and library through the --registry output that already exists. Names come from tools/nid_names.py's database when given, so nothing new is shipped. A small tool would print the records as text, and could diff two runs. Diffing would show where a run changed after a PR, or between Windows and Linux, or NVIDIA and Intel. A trace from real hardware could be compared the same way, if one ever exists.

Example output after formatting:

#48210  thread 7  libkernel  sceKernelOpen       (0x7f12…"/app0/…", 0x0, 0x0) -> 0x1d
#48213  thread 7  libkernel  sceKernelRead       (0x1d, 0x7f12…, 0x10000)     -> 0x10000

Where to hook (this is my question)

Windows. The relinker's entry stub already resolves every import itself (WindowsEntryStubBuilder, GetProcAddress, then WriteImport). With tracing on, it could write the address of a per-import trampoline instead of the function's address.

Linux. ld.so binds the imports (DF_BIND_NOW), so there are two options:

(a) Relinker-generated trampolines behind a relinker option. This is one design for Linux, Windows and macOS, it has no cost unless the title is relinked with the option, and it adds codegen on three platforms.
(b) Runtime patching. An AnyPS5 library rewrites the bound import slots at startup when the variable is set. No relink is needed, but discovering the slots is per platform: the Windows entry stub versus the ELF DT_JMPREL/GLOB_DAT slots.

Which of the two would you take, or is there a better place?

Details I'd plan for

Return values without breaking stack arguments. The trampoline would swap the return address in place against a per-thread side stack, instead of calling the real function from a new frame. That way functions with more than six arguments, or with varargs, see their stack unchanged. Functions that don't return (exit, longjmp, thread exit, …) are logged at entry only.
Cost. The libc string and memory functions are called millions of times per second, so the default would trace only the libraries that are named. Records would go to per-thread binary buffers, not formatted text. I'd measure the overhead on a homebrew title before proposing "all".
Tests. I'd write a guest test that calls traced imports with known arguments, including a stack-argument case, a varargs case and a non-returning case. It would check the records on Windows and Linux.

Is this something you'd want in the tree? I'd rather hear "no" or "do it differently" before writing it.

Written with AI assistance.

A partial implementation is up for review in #4546 (runtime) and #4547 (relinker option --trace-imports). It is your option (a), reduced: Windows only, the entry of each call (import, library, thread, caller address) and per-import counts, shown by the crash and abort reports. Arguments, return values, path strings, a full on-disk trace, diffing and Linux are not done, so most of this proposal is still open.

AI-assisted (Claude Code).

We have local env-controlled traces from title bring-up that sit next to what #4546/#4547 add, and I would like to know which of them are wanted before opening anything. I am not proposing another call trace: #4546/#4547 cover the import calls, and #4526 the present-window summary, so those stay out.

What I would send as one pull request, if it is wanted:

an opt-in timestamp prefix for WriteLogLine (off by default, one environment switch, so existing logs keep their format);
host thread names on Windows for the video-out present thread and the AGC queue workers (SetThreadDescription), so a thread dump or a profiler names them;
a docs/dev/TRACING.md that lists every APS5_TRACE_* switch found in the code with what it prints; none of the roughly 40 files that read one is documented under docs/ today.

Questions: is a single pull request fine for these three, and should the switch be called APS5_LOG_TIMESTAMPS (the existing switches are APS5_TRACE_<AREA>)?

AI-assisted (Claude Code).

#4546 and #4547 cover the import trace on Windows. For the rest, one PR per topic: the timestamp prefix, the thread names and the list of trace switches are three.

The timestamp-prefix topic is now in #5860. APS5_LOG_TIMESTAMPS is off by default; enabled lines get a monotonic elapsed-time prefix emitted in the same write as the message. The default and timestamped short/long/no-argument log cases pass in the focused Linux test. The trace-switch reference is separate in #5854; thread names remain their own topic.

The host thread-name topic is now in #5862. It uses the existing presenter/queue-worker role labels and resolves SetThreadDescription dynamically; a Windows test reads the assigned name back when supported. The timestamp topic is #5860 and the trace-switch reference is #5854.

This proposal looks fully implemented now: the call trace landed for Windows in #4546/#4547 and for Linux in #7411/#7417, and the side topics in #5854 (the tracing switch reference), #5860 (log timestamps) and #5862 (thread names). It's documented in docs/dev/TRACING.md and docs/user/USAGE.md.

A quick check that it works as described on current main 9656d366be (Windows 11 10.0.26300, WinLibs GCC 15.2.0 r7, Release): Yamagi Quake II (PPSA99007) relinked with --registry --trace-imports, run 25 s with APS5_TRACE_CALLS=libkernel and APS5_TRACE_CALLS_FILE=<path>. The file listed 44 libkernel imports with their call counts, most called first, e.g.:

278195 libkernel.prx 0-KXaS70xy4
177505 libkernel.prx lLMT9vJAck0
102658 libkernel.prx 1jfXLRVzisc

The entries are NIDs; tools/nid_names.py --nid resolves them (pthread_getspecific, clock_gettime, sceKernelUsleep here). The limits that remain (entry only, no arguments or results; one 65536-call ring) are recorded in the "Call tracing" entry of docs/dev/debt/libc.md. So unless something from the original list is still wanted, this can be closed.

AI-assisted: yes (Claude Code)

The call trace is on main for Windows (#4546, #4547) and Linux (#7411, #7417), with the side topics in #5854, #5860 and #5862. LeandroLP23 checked it end to end on current main on 10-26. The limits that remain (entry only, no arguments or results, one 65536-call ring) are recorded in the "Call tracing" entry of docs/dev/debt/libc.md. Closing as completed; open a new issue for anything still wanted.

Navigation Menu

Repository navigation

Proposal: an opt-in trace of every system library call a title makes (APS5_TRACE_CALLS) #3815