diff --git a/runtime/vk.h b/runtime/vk.h index d13fe759..3efa1048 100644 --- a/runtime/vk.h +++ b/runtime/vk.h @@ -129,6 +129,14 @@ static inline int vk_device_is_lost(void) { return __atomic_load_n(&vk_lost, __A // signals), and ends the run through vk_device_lost_check when it is. The completion thread calls it before it runs // callbacks: a lost device may report the submissions' timeline as reached (vk_sync.c completion_main). void vk_device_lost_poll(void); +// vk_sync.c "a lost device in the timelines' values": a host signal of VkCtx.timeline notes its value first; a read of +// the timeline above every value its signals carry ends the run as a lost device (vk_sync_check_timeline, any thread, +// `where` for the fatal line). vk_sync_state_text: the submissions' values and the two timelines' readings, one line +// without a lock; vk_sync_lost_report logs it (vk_device.c device_fault_report). +void vk_sync_signal_note(uint64_t value); +void vk_sync_check_timeline(const char *where); +void vk_sync_state_text(char *o, size_t n); +void vk_sync_lost_report(void); // ---- GPU breadcrumbs (vk_crumbs.c): with VK_AMD_buffer_marker, each crumb has the GPU write its code into host memory // twice, when the command processor reaches it and when all work before it has finished. After a lost device the two diff --git a/runtime/vk_device.c b/runtime/vk_device.c index 0a1c55db..e614ea9b 100644 --- a/runtime/vk_device.c +++ b/runtime/vk_device.c @@ -797,6 +797,7 @@ static const char *fault_address_type(VkDeviceFaultAddressTypeEXT t) { // The report of a lost device: the breadcrumbs, the pass marks, the video memory and the driver's fault information. // Once per process, on the thread that saw the loss first (vk_device_lost_check). static void device_fault_report(void) { + vk_sync_lost_report(); vk_crumbs_report(); vk_pass_marks_report(); vk_mem_lost_report(); @@ -894,6 +895,7 @@ int vk_selftest(void) { vmaDestroyBuffer(c->vma, buf, alloc); VkSemaphoreSignalInfo sig = {.sType = VK_STRUCTURE_TYPE_SEMAPHORE_SIGNAL_INFO, .semaphore = c->timeline, .value = 1}; + vk_sync_signal_note(1); // a host signal of the timeline is noted first (vk_sync.c timeline_beyond) if ((r = vkSignalSemaphore(c->device, &sig)) != VK_SUCCESS) { rt_log("vk selftest: vkSignalSemaphore failed (%d)", (int)r); return 3; } uint64_t value = 1; VkSemaphoreWaitInfo wi = {.sType = VK_STRUCTURE_TYPE_SEMAPHORE_WAIT_INFO, .semaphoreCount = 1, .pSemaphores = &c->timeline, diff --git a/runtime/vk_exec_xfer.c b/runtime/vk_exec_xfer.c index 1dc37041..8fe418cd 100644 --- a/runtime/vk_exec_xfer.c +++ b/runtime/vk_exec_xfer.c @@ -390,7 +390,7 @@ static uint32_t oq_nseg, oq_capseg; static int oq_lost; // replay: the segment missed a draw (ring full) static uint64_t oq_count; // completion thread: samples since the last reset -typedef struct { uint64_t addr, seq; int reset; volatile int32_t lost; uint32_t n, cap; uint32_t *q; } OqSegment; +typedef struct { uint64_t addr, seq, fence; int reset; volatile int32_t lost; uint32_t n, cap; uint32_t *q; } OqSegment; // The replay workers (vk_exec.c "parallel groups") record the draws of one group at once. The front pass replays a // group's samples-passed resets and reports in the order of the stream before the workers record (vk_exec_xfer_front): @@ -682,8 +682,24 @@ static void oq_cb(void *arg) { if (avail) sum += v; else { sum += 1; - vk_device_lost_poll(); // a query its submission never wrote: on a lost device the run ends here - LOG_ONCE("vk: occlusion query slot %u not available after its fence, counted as visible", s->q[i]); + // A query its submission never wrote. Every RX 6000 report of a lost device (0.8.0 to 0.9.2) had this line + // first, its callback run for work the GPU had not finished. A timeline read above every value its signals + // carry, then the device itself, end the run here when it is lost (vk_sync.c "a lost device in the + // timelines' values", vk_device.c vk_device_lost_poll). Otherwise the slot counts as visible and the game + // goes on, as a ring that came round too early would leave it. The first such slot is logged with the + // submissions' state and the GPU's breadcrumbs: whether the GPU had finished this submission, and whether + // the timeline read above what was signalled. + vk_sync_check_timeline("an occlusion query its finished submission never wrote (a timeline value no " + "submission signals)"); + vk_device_lost_poll(); + static volatile char logged; + if (!__atomic_exchange_n(&logged, 1, __ATOMIC_RELAXED)) { + char st[512]; + vk_sync_state_text(st, sizeof st); + rt_log("vk: occlusion query slot %u of submission %llu not available after its fence, counted as visible; " + "%s", s->q[i], (unsigned long long)s->fence, st); + vk_crumbs_report(); + } } } if (s->n && ++OQB.segs >= 12000) { @@ -711,7 +727,7 @@ static void oq_segment(VkExec *ex, uint64_t addr, int reset) { OqSegment *s = calloc(1, sizeof *s); if (!s || (oq_nseg && !(s->q = malloc(sizeof *s->q * oq_nseg)))) rt_fatal("vk: out of memory"); s->cap = oq_nseg; - s->addr = addr, s->seq = report_seq, s->reset = reset, s->lost = oq_lost, s->n = oq_nseg; + s->addr = addr, s->seq = report_seq, s->fence = ex->fence, s->reset = reset, s->lost = oq_lost, s->n = oq_nseg; if (addr) vk_exec_note_results(VK_RES_OQ); if (oq_nseg) memcpy(s->q, oq_seg, sizeof *s->q * oq_nseg); if (gs_on >= 0) { // the front pass: the workers add the queries of the group's ops before it diff --git a/runtime/vk_sync.c b/runtime/vk_sync.c index d864e659..586eff9c 100644 --- a/runtime/vk_sync.c +++ b/runtime/vk_sync.c @@ -19,6 +19,7 @@ #include "prof.h" #include "vk.h" #include "vk_lowlat.h" +#include "vk_sync_hw.h" #include "platform/platform.h" #define WEAK __attribute__((weak)) @@ -190,6 +191,14 @@ static int hold_max = -1; // NX2NAVI_WB_SPLIT=2 keeps the split with shadow storage too, to measure that fault. static VkSemaphore exec_tl; static uint64_t exec_sig; // sub_lock: the newest value a submitted part signals on exec_tl + +// ---- a lost device in the timelines' values (vk_sync_hw.h) +// The newest value any signal of the timeline (tl_hw) and of exec_tl (ex_hw) carries, noted before the signal can +// happen: by hold_flush_locked before vkQueueSubmit2, by the host's own signals before vkSignalSemaphore. A value read +// above the note ends the run as a lost device (timeline_beyond). Reaching those values is no proof the device lives: +// a driver that reports every pending signal as done after a reset reads at or below the note, and the line an +// occlusion query left unwritten logs (vk_exec_xfer.c oq_cb, vk_sync_state_text) shows which of the two a report had. +static volatile uint64_t tl_hw, ex_hw; static int wb_split = -1; static int wb_results; // the wait on exec_tl also runs the results the game reads (not with 3) @@ -275,6 +284,14 @@ static void hold_flush_locked(VkCtx *c) { __atomic_store_n(&held_n, 0, __ATOMIC_RELEASE); return; } + // every value this hand-over signals is noted before the queue can reach it ("a lost device in the timelines' + // values") + for (int i = 0; i < H.n; i++) + for (uint32_t k = 0; k < H.si[i].signalSemaphoreInfoCount; k++) { + const VkSemaphoreSubmitInfo *s = &H.si[i].pSignalSemaphoreInfos[k]; + if (s->semaphore == c->timeline) sync_hw_raise(&tl_hw, s->value); + else if (s->semaphore == exec_tl) sync_hw_raise(&ex_hw, s->value); + } VkResult r = lost_at_due() ? VK_ERROR_DEVICE_LOST : vkQueueSubmit2(c->gfx_queue, (uint32_t)H.n, H.si, VK_NULL_HANDLE); if (r != VK_SUCCESS) { vk_mem_oom_report("replay submit", r); @@ -850,6 +867,56 @@ WEAK int vk_exec_record(VkCommandBuffer cb, const uint64_t *handles, int n, uint return 0; } +// Without vk_exec.c (the probes): no submission is held back for an event. +WEAK int vk_exec_held(void) { return 0; } + +// raw, read from the timeline whose signals hw notes: above every one of them the device is lost, and the run ends +// here (vk_device_lost_check) after a line with the two values. +static void timeline_beyond(const char *name, uint64_t raw, volatile uint64_t *hw, const char *where) { + uint64_t h = __atomic_load_n(hw, __ATOMIC_ACQUIRE); + if (!sync_hw_beyond(raw, h)) return; + rt_log("vk: the %s reads %llu, above every value its signals carry (%llu): the device is lost", name, + (unsigned long long)raw, (unsigned long long)h); + vk_device_lost_check(VK_ERROR_DEVICE_LOST, where); +} + +void vk_sync_signal_note(uint64_t value) { sync_hw_raise(&tl_hw, value); } + +void vk_sync_check_timeline(const char *where) { + VkCtx *c = vk_ctx(); + if (!c || !c->timeline || vk_device_is_lost()) return; + uint64_t raw = 0; + VkResult r = vkGetSemaphoreCounterValue(c->device, c->timeline, &raw); + vk_device_lost_check(r, where); + if (r == VK_SUCCESS) timeline_beyond("submissions' timeline", raw, &tl_hw, where); +} + +// No lock: the thread that reports a lost device may hold any (vk_device.c device_fault_report). +void vk_sync_state_text(char *o, size_t n) { + VkCtx *c = vk_ctx(); + uint64_t tl = 0, ex = 0; + char a[32] = "nothing (unreadable)", b[32] = "nothing (unreadable)"; + if (c && c->timeline && vkGetSemaphoreCounterValue(c->device, c->timeline, &tl) == VK_SUCCESS) + snprintf(a, sizeof a, "%llu", (unsigned long long)tl); + if (c && exec_tl && vkGetSemaphoreCounterValue(c->device, exec_tl, &ex) == VK_SUCCESS) + snprintf(b, sizeof b, "%llu", (unsigned long long)ex); + snprintf(o, n, + "submissions issued up to %llu, their side effects run up to %llu, handed to the queue up to %llu with %d " + "held back; the submissions' timeline reads %s of %llu signalled at most, the executed timeline %s of %llu; " + "%d submission(s) held for an event", + (unsigned long long)__atomic_load_n(&issued, __ATOMIC_ACQUIRE), + (unsigned long long)__atomic_load_n(&done, __ATOMIC_ACQUIRE), + (unsigned long long)__atomic_load_n(&queued_v, __ATOMIC_ACQUIRE), (int)__atomic_load_n(&held_n, __ATOMIC_ACQUIRE), + a, (unsigned long long)__atomic_load_n(&tl_hw, __ATOMIC_ACQUIRE), b, + (unsigned long long)__atomic_load_n(&ex_hw, __ATOMIC_ACQUIRE), vk_exec_held()); +} + +void vk_sync_lost_report(void) { + char t[512]; + vk_sync_state_text(t, sizeof t); + rt_log("vk: when the device was lost: %s", t); +} + static void completion_main(void *arg) { VkCtx *c = arg; __atomic_store_n(&cb_tid, plat_thread_id(), __ATOMIC_RELEASE); @@ -882,9 +949,13 @@ static void completion_main(void *arg) { vk_device_lost_check(r, "the completion thread's read of the submissions' timeline"); rt_fatal("vk: the submissions' timeline could not be read (%d; device lost?)", (int)r); } - // Both calls may succeed on a lost device and give a value its submissions never reached. So before a - // new value counts, the device is asked once more with a call of its own (vk_device.c - // vk_device_lost_poll, which ends the run when it is lost). + // Both calls may succeed on a lost device and give a value its submissions never reached. A value above + // every one the timeline's signals carry ends the run ("a lost device in the timelines' values"); then, + // before a new value counts, the device is asked once more with a call of its own (vk_device.c + // vk_device_lost_poll, which ends the run when it is lost). That poll alone did not see the losses of the + // RX 6000 reports of 0.9.1 and 0.9.2: their callbacks ran for work the GPU never finished. + timeline_beyond("submissions' timeline", reached, &tl_hw, "the completion thread's read of the submissions' " + "timeline (a value no submission signals)"); if (reached > __atomic_load_n(&done, __ATOMIC_ACQUIRE)) vk_device_lost_poll(); plat_mutex_lock(&st_lock); if (reached > issued) reached = issued; @@ -963,6 +1034,8 @@ void vk_sync_start(void) { perf_gpu_stats = gpu_stats; uint64_t now = 0; vkGetSemaphoreCounterValue(c->device, c->timeline, &now); + sync_hw_raise(&tl_hw, now > issued ? now : issued); // before the restart's signal below + sync_hw_raise(&ex_hw, now > issued ? now : issued); // the executed timeline below starts there if (issued > now) { // a new device after vk_shutdown: values keep increasing for the front end VkSemaphoreSignalInfo si = {.sType = VK_STRUCTURE_TYPE_SEMAPHORE_SIGNAL_INFO, .semaphore = c->timeline, .value = issued}; @@ -1623,6 +1696,14 @@ int vk_sync_exec_wait(uint64_t value, uint64_t timeout_ns) { vk_device_lost_check(r, "the wait for a submission's commands"); rt_fatal("vk: the wait for a submission's commands failed (%d; device lost?)", (int)r); } + if (r == VK_SUCCESS) { // a lost device may end the wait too: the results below would be read from work never run + uint64_t raw = 0; + VkResult q = vkGetSemaphoreCounterValue(c->device, exec_tl, &raw); + vk_device_lost_check(q, "the read of the executed timeline"); + if (q == VK_SUCCESS) + timeline_beyond("executed timeline", raw, &ex_hw, "the wait for a submission's commands (a value no part " + "signals)"); + } // The results the game reads, of this submission and of those before it, which the GPU ran first: here, not when // the completion thread gets to them behind the other side effects of the last frame's submissions. if (r == VK_SUCCESS && wb_results) results_run(value); @@ -1734,6 +1815,7 @@ static uint64_t probe_lost_advance(VkCtx *c, volatile int32_t *ran) { uint64_t v = issued + 1; plat_mutex_unlock(&st_lock); vk_completion_add(v, probe_lost_cb, (void *)ran); + sync_hw_raise(&tl_hw, v); // a host signal: noted before it ("a lost device in the timelines' values") VkSemaphoreSignalInfo si = {.sType = VK_STRUCTURE_TYPE_SEMAPHORE_SIGNAL_INFO, .semaphore = c->timeline, .value = v}; if (vkSignalSemaphore(c->device, &si) != VK_SUCCESS) return 0; plat_mutex_lock(&st_lock); diff --git a/runtime/vk_sync_hw.h b/runtime/vk_sync_hw.h new file mode 100644 index 00000000..9d9dc56b --- /dev/null +++ b/runtime/vk_sync_hw.h @@ -0,0 +1,23 @@ +// The newest value each of the replay's timelines may reach, and the test a value read from one of them must pass +// (vk_sync.c "a lost device in the timelines' values"). Header only, so that tests/sync_hw_check.c checks it without a +// device. +// +// A timeline semaphore changes only through signal operations, and each of them carries a value the program chose: +// for the replay's two timelines, the queue hand-overs of its submissions (vk_sync.c hold_flush_locked) and the host's +// own signals (vk_sync.c vk_sync_start's restart, the lost-device probe, vk_device.c vk_selftest). A live device never +// reports a value above the newest of them. Each such value is noted here before its signal can happen, so a value read +// above the note comes from a device that answers for work it never ran: after a timeout reset, Windows releases every +// waiter of a timeline, and the reports of AMD's RX 6000 cards (0.9.1, 0.9.2) ran the completion callbacks of +// submissions the GPU had not finished ("occlusion query slot ... not available after its fence") before any call +// returned VK_ERROR_DEVICE_LOST. +#pragma once +#include + +// Raises the note *hw to v; never lowers it. Any thread. +static inline void sync_hw_raise(volatile uint64_t *hw, uint64_t v) { + uint64_t o = __atomic_load_n(hw, __ATOMIC_RELAXED); + while (v > o && !__atomic_compare_exchange_n(hw, &o, v, 1, __ATOMIC_RELEASE, __ATOMIC_RELAXED)) {} +} + +// 1 when raw, read from a timeline whose signals were all noted in hw (read after raw), is above every one of them. +static inline int sync_hw_beyond(uint64_t raw, uint64_t hw) { return raw > hw; } diff --git a/tests/sync_hw_check.c b/tests/sync_hw_check.c new file mode 100644 index 00000000..2fd3a41e --- /dev/null +++ b/tests/sync_hw_check.c @@ -0,0 +1,78 @@ +// runtime/vk_sync_hw.h: the newest value each of the replay's timelines may reach, and the test that takes a value read +// above it as a lost device (vk_sync.c "a lost device in the timelines' values"). Built and run by +// tests/sync_hw_check.py; prints each failed check and exits 1 on any. +#include +#include + +#include "vk_sync_hw.h" + +#ifdef _WIN32 +#include +#else +#include +#endif + +static int fails; +#define CHECK(c, ...) do { if (!(c)) { fails++; printf("FAIL line %d: ", __LINE__); printf(__VA_ARGS__); printf("\n"); } } while (0) + +// Four threads raise one note with interleaved values, as the submitting thread, the present and the probes may. +enum { THREADS = 4, PER = 200000 }; +static volatile uint64_t shared_hw; + +#ifdef _WIN32 +static DWORD WINAPI raiser(LPVOID arg) { +#else +static void *raiser(void *arg) { +#endif + uint64_t k = (uint64_t)(uintptr_t)arg; + for (uint64_t i = 0; i < PER; i++) sync_hw_raise(&shared_hw, i * THREADS + k); + return 0; +} + +int main(void) { + // ---- a note only rises + volatile uint64_t hw = 0; + sync_hw_raise(&hw, 10); + CHECK(hw == 10, "a first value of 10 left %llu", (unsigned long long)hw); + sync_hw_raise(&hw, 7); + CHECK(hw == 10, "an older value (7) lowered the note to %llu", (unsigned long long)hw); + sync_hw_raise(&hw, 11); + CHECK(hw == 11, "a newer value (11) left %llu", (unsigned long long)hw); + + // ---- what a live device can read, and what it cannot + // submissions 1..11 noted: the timeline at any of them, or not yet at the first, is a live reading + for (uint64_t raw = 0; raw <= 11; raw++) CHECK(!sync_hw_beyond(raw, hw), "a reading of %llu with 11 noted counted as lost", (unsigned long long)raw); + CHECK(sync_hw_beyond(12, hw), "a reading one past the newest noted value did not count as lost"); + // after a timeout reset Windows releases the waiters of a timeline with the largest value + CHECK(sync_hw_beyond(UINT64_MAX, hw), "the reading a reset leaves (UINT64_MAX) did not count as lost"); + // a note at the largest value (nothing above it can be read) never counts a reading as lost + volatile uint64_t top = 0; + sync_hw_raise(&top, UINT64_MAX); + CHECK(!sync_hw_beyond(UINT64_MAX, top), "a reading equal to a note of UINT64_MAX counted as lost"); + + // ---- the restart of vk_sync_start: the note is raised to the value signalled before the signal, so the + // completion thread's first reading after it is a live one + volatile uint64_t restart = 0; + uint64_t issued = 500, now = 3; // a new device: its timeline at 3, the front end's values at 500 + sync_hw_raise(&restart, now > issued ? now : issued); + CHECK(!sync_hw_beyond(issued, restart), "the restart's own value (500) counted as lost"); + CHECK(sync_hw_beyond(issued + 1, restart), "a reading past the restart's value did not count as lost"); + + // ---- concurrent raises end at the largest value any thread gave +#ifdef _WIN32 + HANDLE t[THREADS]; + for (int k = 0; k < THREADS; k++) t[k] = CreateThread(NULL, 0, raiser, (LPVOID)(uintptr_t)k, 0, NULL); + WaitForMultipleObjects(THREADS, t, TRUE, INFINITE); + for (int k = 0; k < THREADS; k++) CloseHandle(t[k]); +#else + pthread_t t[THREADS]; + for (int k = 0; k < THREADS; k++) pthread_create(&t[k], NULL, raiser, (void *)(uintptr_t)k); + for (int k = 0; k < THREADS; k++) pthread_join(t[k], NULL); +#endif + uint64_t want = (uint64_t)(PER - 1) * THREADS + (THREADS - 1); + CHECK(shared_hw == want, "four threads' raises ended at %llu, not the largest value %llu", + (unsigned long long)shared_hw, (unsigned long long)want); + + printf("sync_hw_check: %s\n", fails ? "FAILED" : "passed"); + return fails ? 1 : 0; +} diff --git a/tests/sync_hw_check.py b/tests/sync_hw_check.py new file mode 100644 index 00000000..c3dc1b97 --- /dev/null +++ b/tests/sync_hw_check.py @@ -0,0 +1,42 @@ +"""Build and run tests/sync_hw_check.c: runtime/vk_sync_hw.h, the newest value each of the replay's timelines may +reach and the test that takes a value read above it as a lost device (vk_sync.c "a lost device in the timelines' +values"). + +No GPU, no game files, any Python. + +Usage: sync_hw_check.py +""" +import os +import shutil +import subprocess +import sys +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[1] +MSYS_BIN = Path(r'C:\msys64\ucrt64\bin') + + +def compiler(): + """$CC, else MSYS2 UCRT64's clang, else clang on PATH (as tests/diff/common.py picks it, without its Unicorn).""" + if os.environ.get('CC'): + return os.environ['CC'] + if os.name == 'nt' and (MSYS_BIN / 'clang.exe').exists(): + return str(MSYS_BIN / 'clang.exe') + return shutil.which('clang') or 'clang' + + +def main(): + work = ROOT / 'build' / 'test' / 'sync_hw' + work.mkdir(parents=True, exist_ok=True) + exe = work / ('sync_hw_check.exe' if os.name == 'nt' else 'sync_hw_check') + env = dict(os.environ) + if os.name == 'nt' and MSYS_BIN.exists(): + env['PATH'] = str(MSYS_BIN) + os.pathsep + env.get('PATH', '') + extra = [] if os.name == 'nt' else ['-pthread'] + subprocess.check_call([compiler(), '-std=gnu11', '-O1', '-Wall', '-Werror', '-I', str(ROOT / 'runtime'), + str(ROOT / 'tests' / 'sync_hw_check.c'), '-o', str(exe), *extra], env=env) + return subprocess.run([str(exe)], env=env).returncode + + +if __name__ == '__main__': + sys.exit(main())