diff --git a/app/src/main/cpp/waylandcomp/src/compositor.c b/app/src/main/cpp/waylandcomp/src/compositor.c index 2b3b66d09..101e91051 100644 --- a/app/src/main/cpp/waylandcomp/src/compositor.c +++ b/app/src/main/cpp/waylandcomp/src/compositor.c @@ -298,6 +298,7 @@ static struct { int64_t release_ns, release_max_ns; } g_perf; + static void schedule_render(void); static int64_t now_ns(void) { @@ -350,6 +351,12 @@ static int on_release_timer(int fd, uint32_t mask, void *data) { uint64_t expirations; int64_t now = now_ns() + 300000; if (read(fd, &expirations, sizeof(expirations)) < 0 && errno != EAGAIN) return 0; + if (vkp_present_pending()) { + struct itimerspec its = {0}; + its.it_value.tv_nsec = 1000000; + timerfd_settime(fd, 0, &its, NULL); + return 0; + } wl_list_for_each_safe(pr, tmp, &g_pending_releases, link) { if (pr->at_ns <= now) { wl_buffer_send_release(pr->buffer); @@ -365,7 +372,7 @@ static int on_release_timer(int fd, uint32_t mask, void *data) { static void release_buffer(struct surface *s, struct wl_resource *buffer, int64_t since_ns) { const int limit = g_fps_limit; const int64_t interval = limit > 0 ? 1000000000LL / limit : g_refresh_ns; - if (interval <= 0 || g_release_timer_fd < 0) { wl_buffer_send_release(buffer); perf_note_release(since_ns); return; } + if (interval <= 0 || g_release_timer_fd < 0) { vkp_present_wait_idle(); wl_buffer_send_release(buffer); perf_note_release(since_ns); return; } int64_t now = now_ns(); int64_t at = s->next_release_ns + interval; int64_t latest = now + interval * (int64_t)(s->releases_pending + 1); @@ -583,7 +590,7 @@ static void drop_dmabuf(struct surface *s, int paced) { wl_list_remove(&s->dmabuf_destroy.link); if (!ahb_swapchain_defer_release(s->dmabuf_buf, s->dmabuf, s, paced)) { if (paced) release_buffer(s, s->dmabuf, now_ns()); - else wl_buffer_send_release(s->dmabuf); + else { vkp_present_wait_idle(); wl_buffer_send_release(s->dmabuf); } } s->dmabuf = NULL; } @@ -752,7 +759,7 @@ void droiddeck_dmabuf_ref(struct dmabuf_buffer *b) { b->refs++; } void droiddeck_dmabuf_unref(struct dmabuf_buffer *b) { dmabuf_buffer_unref(b); } void droiddeck_release_buffer(struct surface *s, struct wl_resource *buffer, int paced, int64_t since_ns) { if (paced && s) release_buffer(s, buffer, since_ns); - else { wl_buffer_send_release(buffer); perf_note_release(since_ns); } + else { vkp_present_wait_idle(); wl_buffer_send_release(buffer); perf_note_release(since_ns); } } void droiddeck_surface_describe(const struct surface *s, char *out, size_t size) { describe(s, out, size); } const struct droiddeck_color *droiddeck_surface_color(const struct surface *s) { @@ -1809,6 +1816,22 @@ static void hdr_count_copied(const struct draw_list *dl, const char *reason) { } } +extern void (*vkp_scene_ready_hook)(void); +static int64_t g_scene_presented_ns; +static int g_scene_signalled; + +static void signal_scene_drawn(void) { + struct surface *s; + if (g_scene_signalled) return; + g_scene_signalled = 1; + wl_list_for_each(s, &g_surfaces, link) { + if (s->drawn) feedback_present_all(&s->feedback, g_scene_presented_ns); + else feedback_discard_all(&s->feedback); + } + fire_all_frames(); + wl_display_flush_clients(g_display); +} + static void render_scene(void) { struct draw_list dl = {0}; struct surface *s; @@ -1819,6 +1842,9 @@ static void render_scene(void) { g_dirty = 0; g_hud_fresh = 0; g_hdr_unimported = NULL; + g_scene_signalled = 0; + g_scene_presented_ns = presented_ns(t_scene); + vkp_scene_ready_hook = signal_scene_drawn; wl_list_for_each(s, &g_surfaces, link) s->drawn = 0; scene_size(&w, &h); if (w != g_scene_w || h != g_scene_h) { @@ -1947,14 +1973,10 @@ static void render_scene(void) { } free(hs.is_hdr); if (hdr_copy && rendered && droiddeck_color_hdr_open()) hdr_count_copied(&dl, hdr_copy); + vkp_scene_ready_hook = NULL; if (rendered) { - int64_t t = presented_ns(t_scene); g_stat_frames++; - wl_list_for_each(s, &g_surfaces, link) { - if (s->drawn) feedback_present_all(&s->feedback, t); - else feedback_discard_all(&s->feedback); - } - fire_all_frames(); + signal_scene_drawn(); } else { pace_without_output(); if (!g_frame_timer) @@ -1994,6 +2016,25 @@ static int scene_waits_for_game(int64_t now) { return g_hud_surface && !g_hud_fresh && now - g_hud_last_ns < 100000000LL && vkp_framegen_active(); } +/* gamescope submits a frame meant for a vsync only its 1.65 ms redzone ahead of it, and the + * commit then takes up to a few ms more to reach us. Latching right on the tick showed those + * frames a refresh late; the scene is composed a little after the vsync instead. */ +static int g_latch_timer_fd = -1; +static struct wl_event_source *g_latch_source; + +static int64_t latch_delay_ns(void) { + int64_t d = g_refresh_ns * 35 / 100; + if (d > 6000000LL) d = 6000000LL; + return d; +} + +static int on_latch_timer(int fd, uint32_t mask, void *data) { + uint64_t expirations; + if (read(fd, &expirations, sizeof(expirations)) < 0 && errno != EAGAIN) return 0; + if (g_dirty && !scene_waits_for_game(now_ns())) render_scene(); + return 0; +} + static void on_vsync(int64_t frame_time_ns) { int64_t now = now_ns(); g_perf.ticks++; @@ -2006,6 +2047,14 @@ static void on_vsync(int64_t frame_time_ns) { if (vkp_apply_window_request()) g_dirty = 1; if (vkp_effects_sync()) g_dirty = 1; if (vkp_cardboard_pose_changed()) g_dirty = 1; + const int64_t latch = frame_time_ns + latch_delay_ns(); + if (g_latch_timer_fd >= 0 && latch > now + 500000LL) { + struct itimerspec its = {0}; + its.it_value.tv_sec = latch / 1000000000LL; + its.it_value.tv_nsec = latch % 1000000000LL; + timerfd_settime(g_latch_timer_fd, TFD_TIMER_ABSTIME, &its, NULL); + return; + } if (g_dirty && !scene_waits_for_game(now)) render_scene(); } @@ -3211,6 +3260,10 @@ int droiddeck_wayland_run(void) { if (g_release_timer_fd >= 0) g_release_source = wl_event_loop_add_fd(wl_display_get_event_loop(display), g_release_timer_fd, WL_EVENT_READABLE, on_release_timer, NULL); + g_latch_timer_fd = timerfd_create(CLOCK_MONOTONIC, TFD_NONBLOCK | TFD_CLOEXEC); + if (g_latch_timer_fd >= 0) + g_latch_source = wl_event_loop_add_fd(wl_display_get_event_loop(display), g_latch_timer_fd, + WL_EVENT_READABLE, on_latch_timer, NULL); g_display = display; if (pipe2(g_input_pipe, O_CLOEXEC | O_NONBLOCK) == 0) { diff --git a/app/src/main/cpp/waylandcomp/src/vk_present.c b/app/src/main/cpp/waylandcomp/src/vk_present.c index 9405f00ed..462f1b576 100644 --- a/app/src/main/cpp/waylandcomp/src/vk_present.c +++ b/app/src/main/cpp/waylandcomp/src/vk_present.c @@ -104,6 +104,9 @@ static void perf_add(int64_t *sum, int64_t *max, unsigned *count, int64_t d) { if (d > *max) *max = d; (*count)++; } +void (*vkp_scene_ready_hook)(void); +static void present_drain(void); + static VkResult timed_wait(VkFence fence, uint64_t timeout) { int64_t t0 = perf_now(); VkResult r = g_vk.WaitForFences(g_dev, 1, &fence, VK_TRUE, timeout); @@ -199,6 +202,7 @@ static void reset_sync(void) { static void destroy_swapchain(void) { g_base_black = 0; if (g_dev_state != 1) return; + present_drain(); g_vk.DeviceWaitIdle(g_dev); reset_sync(); for (uint32_t i = 0; i < g_nimg; i++) blendp_forget_image(g_images[i]); @@ -727,6 +731,7 @@ static int memory_type(uint32_t bits, VkMemoryPropertyFlags want) { } static void init_black_image(void) { + present_drain(); g_black_state = -1; VkImageCreateInfo ici = { .sType = VK_STRUCTURE_TYPE_IMAGE_CREATE_INFO, .imageType = VK_IMAGE_TYPE_2D, @@ -1010,6 +1015,7 @@ struct vkp_image *vkp_image_create_shm(int w, int h) { } void vkp_image_upload_shm(struct vkp_image *img, const void *data, int stride) { + present_drain(); if (!img || !img->map || !data) return; size_t rowbytes = (size_t)img->w * 4; if ((size_t)stride < rowbytes) rowbytes = (size_t)stride; @@ -1306,6 +1312,7 @@ static void record_screen_blit(VkCommandBuffer cmd, VkImage src, int src_w, int } static int acquire_image(int k, int first, uint32_t *img, VkResult *ar_out) { + present_drain(); for (int attempt = 0; ; attempt++) { if (!g_swapchain && (!first || swap_init() != 0)) return -1; const int64_t t_acq = perf_now(); @@ -1430,6 +1437,96 @@ static void send_hdr_metadata(const struct droiddeck_color *c) { c->identity, c->text); } +/* vkQueuePresentKHR on this driver waits on the CPU for the frame's GPU work, which queues behind + * the game's. Done on the compositor thread, that wait held back vsync ticks and gamescope's + * commits by up to a frame and a half, so a game frame that arrived in time showed a refresh late. + * A single-present frame is handed to this thread instead; anything else that touches the queue, + * the fence or the swapchain drains it first. */ +static pthread_mutex_t g_pw_lock = PTHREAD_MUTEX_INITIALIZER; +static pthread_cond_t g_pw_cond = PTHREAD_COND_INITIALIZER; +static int g_pw_started, g_pw_job, g_pw_done; +static uint32_t g_pw_img; +static VkResult g_pw_pr, g_pw_fr; +static int64_t g_pw_present_ns, g_pw_wait_ns; + +static void *present_worker(void *arg) { + (void)arg; + pthread_mutex_lock(&g_pw_lock); + for (;;) { + while (!g_pw_job) pthread_cond_wait(&g_pw_cond, &g_pw_lock); + pthread_mutex_unlock(&g_pw_lock); + VkPresentInfoKHR pi = {.sType = VK_STRUCTURE_TYPE_PRESENT_INFO_KHR, .waitSemaphoreCount = 1, + .pWaitSemaphores = &g_rnds[0], .swapchainCount = 1, + .pSwapchains = &g_swapchain, .pImageIndices = &g_pw_img}; + const int64_t t0 = perf_now(); + VkResult pr = g_vk.QueuePresentKHR(g_queue, &pi); + const int64_t t1 = perf_now(); + VkResult fr = g_vk.WaitForFences(g_dev, 1, &g_fence, VK_TRUE, UINT64_MAX); + const int64_t t2 = perf_now(); + pthread_mutex_lock(&g_pw_lock); + g_pw_pr = pr; + g_pw_fr = fr; + g_pw_present_ns = t1 - t0; + g_pw_wait_ns = t2 - t1; + g_pw_job = 0; + g_pw_done = 1; + pthread_cond_broadcast(&g_pw_cond); + } + return NULL; +} + +static int present_async(uint32_t img) { + if (!g_pw_started) { + pthread_t t; + if (pthread_create(&t, NULL, present_worker, NULL) != 0) return -1; + pthread_setname_np(t, "dd-present"); + pthread_detach(t); + g_pw_started = 1; + } + pthread_mutex_lock(&g_pw_lock); + g_pw_img = img; + g_pw_job = 1; + pthread_cond_broadcast(&g_pw_cond); + pthread_mutex_unlock(&g_pw_lock); + return 0; +} + +int vkp_present_pending(void) { + pthread_mutex_lock(&g_pw_lock); + const int busy = g_pw_job; + pthread_mutex_unlock(&g_pw_lock); + return busy; +} + +void vkp_present_wait_idle(void) { + if (!g_pw_started) return; + pthread_mutex_lock(&g_pw_lock); + while (g_pw_job) pthread_cond_wait(&g_pw_cond, &g_pw_lock); + pthread_mutex_unlock(&g_pw_lock); +} + +static void present_drain(void) { + if (!g_pw_started) return; + pthread_mutex_lock(&g_pw_lock); + while (g_pw_job) pthread_cond_wait(&g_pw_cond, &g_pw_lock); + const int done = g_pw_done; + const VkResult pr = g_pw_pr, fr = g_pw_fr; + const int64_t present_ns = g_pw_present_ns, wait_ns = g_pw_wait_ns; + g_pw_done = 0; + pthread_mutex_unlock(&g_pw_lock); + if (!done) return; + perf_add(&g_perf.present_ns, &g_perf.present_max_ns, &g_perf.presents, present_ns); + perf_add(&g_perf.wait_ns, &g_perf.wait_max_ns, &g_perf.waits, wait_ns); + if (fr == VK_ERROR_DEVICE_LOST || pr == VK_ERROR_DEVICE_LOST) { device_lost("present"); return; } + if (pr == VK_ERROR_OUT_OF_DATE_KHR || pr == VK_ERROR_SURFACE_LOST_KHR) { + droiddeck_log("gpu", "screen surface %s on present: rebuilding the swapchain", vk_result_name(pr)); + destroy_swapchain(); + } else if (pr != VK_SUCCESS && pr != VK_SUBOPTIMAL_KHR) { + droiddeck_log("error", "present: vkQueuePresentKHR failed (%s %d)", vk_result_name(pr), (int)pr); + destroy_swapchain(); + } +} + static int render_impl(int scene_w, int scene_h, const struct vkp_draw *draws, int n, const struct vkp_hdr_frame *hf, int *how) { if (how) *how = 0; @@ -1455,6 +1552,7 @@ static int render_impl(int scene_w, int scene_h, const struct vkp_draw *draws, i uint32_t img = 0; VkResult ar; + if (vkp_scene_ready_hook) vkp_scene_ready_hook(); if (acquire_image(0, 1, &img, &ar) != 0) return -1; update_map(scene_w, scene_h); if (g_swap_is_hdr && hf && hf->color && hf->color->identity != g_swap_md_identity) { @@ -1621,7 +1719,7 @@ static int render_impl(int scene_w, int scene_h, const struct vkp_draw *draws, i g_vk.EndCommandBuffer(cmd); const int presents = 1 + ngen; - int fence_submitted = 0, presented_gen = 0; + int fence_submitted = 0, presented_gen = 0, async = 0; VkResult pr = VK_SUCCESS; g_vk.ResetFences(g_dev, 1, &g_fence); for (int k = 0; k < presents; k++) { @@ -1652,6 +1750,7 @@ static int render_impl(int scene_w, int scene_h, const struct vkp_draw *draws, i return -1; } fence_submitted = last; + if (presents == 1 && present_async(img) == 0) { async = 1; break; } VkPresentInfoKHR pi = {.sType = VK_STRUCTURE_TYPE_PRESENT_INFO_KHR, .waitSemaphoreCount = 1, .pWaitSemaphores = &g_rnds[k], .swapchainCount = 1, .pSwapchains = &g_swapchain, .pImageIndices = &img}; @@ -1665,7 +1764,7 @@ static int render_impl(int scene_w, int scene_h, const struct vkp_draw *draws, i VkSubmitInfo si = {.sType = VK_STRUCTURE_TYPE_SUBMIT_INFO}; g_vk.QueueSubmit(g_queue, 1, &si, g_fence); } - VkResult fr = timed_wait(g_fence, UINT64_MAX); + VkResult fr = async ? VK_SUCCESS : timed_wait(g_fence, UINT64_MAX); if (fg) vkp_framegen_presented(presented_gen); if (fr == VK_ERROR_DEVICE_LOST || pr == VK_ERROR_DEVICE_LOST) { device_lost("present"); return -1; } if (pr == VK_ERROR_OUT_OF_DATE_KHR || pr == VK_ERROR_SURFACE_LOST_KHR) { @@ -1777,6 +1876,7 @@ int vkp_map_draw(const struct vkp_draw *d, int out[8]) { } int vkp_blit_image(struct vkp_image *src, struct vkp_image *dst, int wait_fd) { + present_drain(); if (!src || !dst || !dst->blit_dst || g_dev_state == -2 || dev_init() != 0) { if (wait_fd >= 0) close(wait_fd); return -1; @@ -1850,6 +1950,7 @@ int vkp_blit_image(struct vkp_image *src, struct vkp_image *dst, int wait_fd) { static struct vkp_image *g_rb; int vkp_image_readback(struct vkp_image *src, uint32_t *out, int max_px) { + present_drain(); if (!src || !out || src->w <= 0 || src->h <= 0 || src->w * src->h > max_px || g_dev_state == -2 || dev_init() != 0) return -1; @@ -2049,6 +2150,7 @@ static int pass_begin_impl(int scene_w, int scene_h, const struct vkp_draw *draw } int vkp_pass_copy_to(struct vkp_image *dst, int wait_fd) { + present_drain(); if (!g_pass.active) { if (wait_fd >= 0) close(wait_fd); return -1; } g_pass.active = 0; VkCommandBuffer cmd = g_cmds[0]; diff --git a/app/src/main/cpp/waylandcomp/src/vk_present.h b/app/src/main/cpp/waylandcomp/src/vk_present.h index a965807e7..03da6e14e 100644 --- a/app/src/main/cpp/waylandcomp/src/vk_present.h +++ b/app/src/main/cpp/waylandcomp/src/vk_present.h @@ -53,6 +53,8 @@ int vkp_ready(void); int vkp_has_window(void); int vkp_device_lost(void); +int vkp_present_pending(void); +void vkp_present_wait_idle(void); int vkp_render(int scene_w, int scene_h, const struct vkp_draw *draws, int n); int vkp_render_plain(int scene_w, int scene_h); int vkp_base_black(int scene_w, int scene_h); diff --git a/app/src/main/cpp/waylandcomp/src/waylandcomp_jni.c b/app/src/main/cpp/waylandcomp/src/waylandcomp_jni.c index 207c52cd5..81c58932d 100644 --- a/app/src/main/cpp/waylandcomp/src/waylandcomp_jni.c +++ b/app/src/main/cpp/waylandcomp/src/waylandcomp_jni.c @@ -9,6 +9,10 @@ #include #include #include +#include +#include +#include +#include #include "vk_present.h" #include "droiddeck_ext.h" #include "ahb_swapchain.h" @@ -285,6 +289,61 @@ Java_com_droiddeck_launcher_wayland_WaylandCompositor_nativeVsync(JNIEnv *env, j droiddeck_wayland_vsync((int64_t)frameTimeNanos); } +/* The main thread's Choreographer runs behind UI work, which delivered ticks up to a frame late + * and made a gamescope frame that arrived on time miss its vsync. These ticks come from a + * Choreographer on a thread of their own. */ +typedef void (*vsync_cb64_fn)(int64_t, void *); +typedef void (*post_cb64_fn)(AChoreographer *, vsync_cb64_fn, void *); +static post_cb64_fn g_post_cb64; +static ALooper *g_vsync_looper; +static _Atomic int g_vsync_want, g_vsync_posted; +static pthread_once_t g_vsync_once = PTHREAD_ONCE_INIT; + +static void vsync_tick64(int64_t frame_time_ns, void *data); +static void vsync_tick(long frame_time_ns, void *data) { vsync_tick64((int64_t)frame_time_ns, data); } + +static void vsync_post(AChoreographer *c) { + if (g_post_cb64) g_post_cb64(c, vsync_tick64, c); + else AChoreographer_postFrameCallback(c, vsync_tick, c); +} + +static void vsync_tick64(int64_t frame_time_ns, void *data) { + if (!atomic_load(&g_vsync_want)) { atomic_store(&g_vsync_posted, 0); return; } + droiddeck_wayland_vsync(frame_time_ns); + vsync_post((AChoreographer *)data); +} + +static void *vsync_thread(void *arg) { + (void)arg; + if (setpriority(PRIO_PROCESS, 0, -10) != 0) setpriority(PRIO_PROCESS, 0, -8); + ALooper *looper = ALooper_prepare(0); + ALooper_acquire(looper); + AChoreographer *c = AChoreographer_getInstance(); + g_post_cb64 = (post_cb64_fn)dlsym(RTLD_DEFAULT, "AChoreographer_postFrameCallback64"); + __atomic_store_n(&g_vsync_looper, looper, __ATOMIC_RELEASE); + for (;;) { + if (atomic_load(&g_vsync_want) && !atomic_exchange(&g_vsync_posted, 1)) vsync_post(c); + ALooper_pollOnce(-1, NULL, NULL, NULL); + } + return NULL; +} + +static void vsync_thread_start(void) { + pthread_t t; + if (pthread_create(&t, NULL, vsync_thread, NULL) == 0) { + pthread_setname_np(t, "dd-vsync"); + pthread_detach(t); + } +} + +JNIEXPORT void JNICALL +Java_com_droiddeck_launcher_wayland_WaylandCompositor_nativeSetVsyncRunning(JNIEnv *env, jclass clazz, jboolean on) { + pthread_once(&g_vsync_once, vsync_thread_start); + atomic_store(&g_vsync_want, on ? 1 : 0); + ALooper *looper = __atomic_load_n(&g_vsync_looper, __ATOMIC_ACQUIRE); + if (looper) ALooper_wake(looper); +} + JNIEXPORT void JNICALL Java_com_droiddeck_launcher_wayland_WaylandCompositor_nativeSetHideShell(JNIEnv *env, jclass clazz, jboolean hide) { g_hide_shell = hide ? 1 : 0; diff --git a/app/src/main/java/com/droiddeck/launcher/wayland/CompositorHost.kt b/app/src/main/java/com/droiddeck/launcher/wayland/CompositorHost.kt index 9df4d4dfd..b8ab28ffb 100644 --- a/app/src/main/java/com/droiddeck/launcher/wayland/CompositorHost.kt +++ b/app/src/main/java/com/droiddeck/launcher/wayland/CompositorHost.kt @@ -1,6 +1,5 @@ package com.droiddeck.launcher.wayland -import android.view.Choreographer import android.view.Surface import com.droiddeck.launcher.session.SessionState @@ -9,13 +8,6 @@ object CompositorHost { private var started = false private var vsyncRunning = false - private val vsync = object : Choreographer.FrameCallback { - override fun doFrame(frameTimeNanos: Long) { - WaylandCompositor.nativeVsync(frameTimeNanos) - if (vsyncRunning) Choreographer.getInstance().postFrameCallback(this) - } - } - @Synchronized fun startOrAttach( surface: Surface, @@ -83,11 +75,12 @@ object CompositorHost { private fun resumeVsync() { if (vsyncRunning) return vsyncRunning = true - Choreographer.getInstance().postFrameCallback(vsync) + WaylandCompositor.nativeSetVsyncRunning(true) } private fun pauseVsync() { vsyncRunning = false + WaylandCompositor.nativeSetVsyncRunning(false) } fun newSession() { diff --git a/app/src/main/java/com/droiddeck/launcher/wayland/WaylandCompositor.java b/app/src/main/java/com/droiddeck/launcher/wayland/WaylandCompositor.java index 85f9464c1..4ab75ca4a 100644 --- a/app/src/main/java/com/droiddeck/launcher/wayland/WaylandCompositor.java +++ b/app/src/main/java/com/droiddeck/launcher/wayland/WaylandCompositor.java @@ -162,6 +162,7 @@ public final class WaylandCompositor { public static native void nativeSendKey(int evdev, int state); public static native void nativeVsync(long frameTimeNanos); + public static native void nativeSetVsyncRunning(boolean running); public static native int nativeCompositorTid(); diff --git a/docs/investigations/qam-frame-limit/README.md b/docs/investigations/qam-frame-limit/README.md new file mode 100644 index 000000000..cbdba571b --- /dev/null +++ b/docs/investigations/qam-frame-limit/README.md @@ -0,0 +1,156 @@ +# Steam QAM frame limit vs an in-game cap: pacing investigation (2026-10-15) + +Status: **unfinished**. The cause on the reporter's device is narrowed down but not fixed. This branch +holds compositor changes that are *plausible but unproven*, plus the tracing and repro tooling, so the +next person doesn't start from zero. + +## The report + +Discord, bug-reports forum, thread "Unstable frame limit". The main reporter, siigonis_ru, is on a +Retroid Pocket G2 (Adreno 732 class GPU, 60 Hz panel, 1280x720 session shown at 1920x1080 with FSR 1). + +- With Steam's QAM Frame Limit at 30, motion is choppy: "small stops and ladders" during camera pans. + It is worst with LSFG 2x on top, which also feels laggy. +- The same game capped by its own 30 FPS lock is smooth. In the Serious Sam 2 clip that is perfect even + with LSFG 2x ("the generated 60 feels like real 60"). +- The DroidDeck cap (session settings, 30) was "sometimes as good as the in-game lock, sometimes worse + than ever". +- Earlier PRs from the same thread: #731 (re-attached buffers counted as new frames), #753 (gamescope + patch 0115, per-window time-paced limiter), #717 (presentation timestamps on the vsync tick). + +## Timeline and findings + +### 1. The reporter's own data (logs + clips from 2026-10-13..15) + +Measured from his screen recordings (`tools/vdiff.py` + `tools/ana.py`, Serious Sam 2, LSFG 2x): + +| | Content changes/s | Spacing σ | Holds | +|---|---|---|---| +| In-game 30 cap + LSFG 2x | 60 | 0 ms | none | +| QAM 30 + LSFG 2x | 40-57 | 15-50 ms | 3- and 4-refresh holds | + +His compositor log (`DroidDeckWayland [perf]`) under QAM 30 with frame generation off shows `present` at +10-13 ms average (25 ms max) and `render_scene` around 16 ms. Uncapped, `present` is 0.3 ms. On the G2 +the compositor spends most of a refresh blocked in `vkQueuePresentKHR`. + +### 2. LSFG Adaptive runaway in the DroidDeck-cap log → fixed in #927 + +The "worse than ever" stretches of the DD-cap clip were LSFG Adaptive 60 locking itself at 2-3 +generations with the game shown at 16-20 fps. The pacer measured the source rate from compositor +passes, not game frames, so a slowed loop justified more generations. #927 feeds it the real game +frame count; validated on the Thor (recovers in 3-5 s after a load spike instead of 25-40 s). + +### 3. How gamescope's QAM limiter works here (code reading) + +- Steam sets the cap through `gamescope_control` / `GAMESCOPE_LIMITER_FILE` + (`STEAM_GAMESCOPE_DYNAMIC_FPSLIMITER=1`). The `GAMESCOPE_FPS_LIMIT` root atom is overwritten and is + useless for testing. The debug patch below adds `dd_force_fps_limit` for that. +- With the limiter on, the WSI layer forces FIFO. FIFO commits from a limited window only become + displayable on an allowed vblank (`handle_done_commits_xwayland`), and `frame_done` only goes out + then. DXVK paces on present completion, so the game runs one frame at a time against that grid. +- The Wayland backend's vblank grid comes from our `wp_presentation` timestamps. gamescope wakes + `redzone (1.65 ms) + draw time` before each target vblank. The redzone is hard-coded + (`kDefaultVBlankRedZone`) and tuned for DRM scanout, not for a nested host compositor. +- `GetValidDynamicRefreshRates()` is empty in the Wayland backend. Even exposing rates would not move a + 30 cap off 60 Hz: Steam picks the highest rate that divides by the cap. + +### 4. Reproducing on the AYN Thor (Saints Row IV, 60 Hz, Steam offline) + +Unloaded, QAM 30 is clean on screen on the Thor (`tools/shift.py` motion CV 0.05-0.08, one held frame +in 10 s). The gamescope trace shows a perfect 2-refresh cadence (865/865 frames). + +With 3 guest busy loops, QAM 30 + LSFG shows 50 ms holds like the reporter's. But `tools/slip.py` shows +**no game commit was waiting** at every skipped vblank: under that load Saints Row IV simply misses 33 ms. +Any limiter shows that, so this is not the reporter's case. + +Saints Row IV is a poor stand-in for his games anyway. Its vsync is off by default, so a DXVK +`maxFrameRate` cap presents non-FIFO and was *less* even than QAM (motion CV ~0.4). His games' 30 FPS +locks are most likely vsync interval 2, which FIFO-queues each frame for exactly two refreshes. + +### 5. The compositor side (compositor trace patch) + +With `patches/compositor-frame-trace.patch` (vsync ticks, every new client buffer, every render): + +- Our event loop blocks 8-25 ms per frame inside `vkQueuePresentKHR`. On Android, Turnip waits on the + CPU for the frame's GPU work, which queues behind the game's. 96% of late vsync ticks happened while + we were blocked there. +- gamescope paces its next composite on our presentation feedback. Feedback was sent only after the + blocked present, so gamescope's commit often landed right *after* the following tick. +- gamescope commits arrive only ~2.3 ms (median, min 0.05 ms) before our tick. With the composite or + transport a bit slower, they arrive after it and the frame shows one refresh late (3/1 "ladders"). +- Caveat found late: gamescope also pushes a new game-plane buffer whenever it re-composites (MangoHud + overlay update), so "new game-plane buffer" is **not** "new game frame". The compositor-side cadence + numbers overstate the problem; judge everything by the screen recording. + +### 6. Emulating the G2 on the Thor (the useful repro) + +`dd_force_fps_limit 30` plus `dd_paint_delay_us 8000` (each gamescope composite delayed by a random +0-8 ms) produces the reporter's symptom on the Thor's screen with the **stock** compositor: + +| stock compositor, QAM-style 30, FG off | off-cadence changes | motion CV | +|---|---|---| +| no delay | ~1% | 0.05-0.08 | +| 0-4 ms delay | 4 of ~150 | 0.09-0.14 | +| 0-8 ms delay | 16 of ~197 (8%) | 0.26-0.74 | + +**This A/B was not finished**: the same 0-8 ms run on this branch's compositor still has to be done. + +### 7. Side findings + +- Requesting a HIGH global-priority queue for the compositor (Turnip on KGSL) did not help. + `CP: AHB bus error` GPU faults then appeared and the Thor eventually froze and needed a reboot. The + faults later showed up on stock builds too (~120/min while gaming), so the link is unproven, but the + priority request was dropped. +- Wireless ADB changes port after a reboot (`adb mdns services`). Steam comes back online after every + session restart; `SteamClient.User.GoOffline()` over CDP avoids "account playing elsewhere" kicks. + +## What is on this branch + +Compositor changes, **unvalidated on screen**: + +1. **Present worker thread** (`vk_present.c`). A single-present frame (frame generation off) is handed to + `dd-present` for `vkQueuePresentKHR` and the fence wait. Everything that touches the queue, fence or + swapchain calls `present_drain()` first. Client buffer releases wait for an in-flight present. + Measured: `render_scene` from ~12 ms to under 1 ms; late vsync ticks p95 from 9 ms to 1.5 ms. +2. **Early feedback** (`compositor.c`). Presentation feedback and frame callbacks are sent when the scene + is ready (`vkp_scene_ready_hook`, before acquire/present) rather than after the present returns. +3. **Dedicated vsync thread** (`waylandcomp_jni.c`, `CompositorHost.kt`). Ticks come from an + `AChoreographer` on its own looper thread (`dd-vsync`), not the main thread's Choreographer. +4. **Post-vsync latch** (`compositor.c`). The scene is composed `min(35% of a refresh, 6 ms)` after the + vsync instead of on the tick, so a gamescope commit aimed at that vsync still makes it. Composing + takes under 1 ms now, so it should still hit the same SurfaceFlinger vsync and add no display + latency. That is **not yet measured**: check with SurfaceFlinger timestats + (`tools/droiddeckctl pacing`) before shipping. + +`patches/` (not built): + +- `gamescope-limiter-debug.patch`, on top of `tools/gamescope/patches` (after 0115). Adds the + `DD_FRAMETRACE=` env trace (`V` vblank wake, `C` client commit, `D` commit displayable, + `F` frame_done, `P` base-plane paint) and two convars for `gamescopectl`: + `dd_force_fps_limit ` and `dd_paint_delay_us `. +- `compositor-frame-trace.patch`, on top of this branch. Writes `T`/`S`/`R` lines to + `files/comptrace.log` when `files/comptrace.on` exists (create it as root, then chown/chcon it to + the app). + +`tools/`: capture and analysis scripts used above (headers say what each does). + +## How to pick this up + +1. Build gamescope with `patches/gamescope-limiter-debug.patch` (`tools/gamescope/build-in-arch.sh`, or + a persistent `menci/archlinuxarm:base-devel` container and `ninja src/gamescope` in + `pkg/arch/src/build` for 20 s rebuilds). Install it with `tools/droiddeckctl override gamescope` and + `droiddeckctl env set DD_FRAMETRACE=/tmp/ddtrace.log`, then restart the session. +2. In game: Steam QAM "Disable Frame Limit" on, then + `gamescopectl dd_force_fps_limit 30; gamescopectl dd_paint_delay_us 8000`. +3. `tools/capture-case.sh `, then `tools/vdiff.py` + `tools/ana.py` and `tools/shift.py` on the + clip. Compare this branch against main **on screen**, FG off and LSFG 2x. +4. If the branch wins and SurfaceFlinger timestats show no added latency, split it into PRs: the + present worker + early feedback, the vsync thread, the latch delay. Then ask the reporter to try a + `publish-test` build with Serious Sam 2 at QAM 30 + LSFG 2x. +5. If the latch doesn't help, the gamescope-side alternative is a larger redzone for the nested Wayland + backend (`kDefaultVBlankRedZone`). That has the same latency cost and needs a gamescope component + release. +6. Also worth testing on a weaker GPU: the reporter's DroidDeck-cap log (gamescope `-r 30` plus + compositor release pacing) was perfectly steady once #927's runaway is out of the way. Mapping the + QAM cap onto that path (nested refresh = cap when it divides the panel rate) is a candidate fix if + the compositor changes fall short. diff --git a/docs/investigations/qam-frame-limit/patches/compositor-frame-trace.patch b/docs/investigations/qam-frame-limit/patches/compositor-frame-trace.patch new file mode 100644 index 000000000..b004d962e --- /dev/null +++ b/docs/investigations/qam-frame-limit/patches/compositor-frame-trace.patch @@ -0,0 +1,52 @@ +--- a/app/src/main/cpp/waylandcomp/src/compositor.c ++++ b/app/src/main/cpp/waylandcomp/src/compositor.c +@@ -299,6 +299,25 @@ + } g_perf; + + ++static FILE *dd_ctrace_file(void) { ++ static int tried; static FILE *f; ++ if (!tried) { ++ tried = 1; ++ if (access("/data/user/0/com.droiddeck.launcher/files/comptrace.on", F_OK) == 0) ++ f = fopen("/data/user/0/com.droiddeck.launcher/files/comptrace.log", "w"); ++ } ++ return f; ++} ++static void dd_ctrace(const char *fmt, ...) __attribute__((format(printf, 1, 2))); ++static void dd_ctrace(const char *fmt, ...) { ++ FILE *f = dd_ctrace_file(); ++ if (!f) return; ++ struct timespec ts; clock_gettime(CLOCK_MONOTONIC, &ts); ++ fprintf(f, "%lld ", (long long)ts.tv_sec * 1000000000LL + ts.tv_nsec); ++ va_list ap; va_start(ap, fmt); vfprintf(f, fmt, ap); va_end(ap); ++ fputc('\n', f); ++ static unsigned n; if ((++n % 64) == 0) fflush(f); ++} + static void schedule_render(void); + + static int64_t now_ns(void) { +@@ -701,6 +720,7 @@ + s->buf_alpha = (b->format & 0xff) == 'A'; + s->has_content = b->img != NULL; + if (!repeat) g_stat_dmabuf++; ++ if (!repeat) dd_ctrace("S %d %dx%d", s == g_hud_surface, b->width, b->height); + const int announced_now = !s->announced_vulkan; + if (!s->announced_vulkan) { + char name[160]; +@@ -1989,6 +2009,7 @@ + if (rendered && copy) g_perf.copy_scenes++; + g_perf.scenes++; + const int64_t scene_ns = now_ns() - t_scene; ++ dd_ctrace("R %lld %d", (long long)t_scene, rendered); + g_perf.scene_ns += scene_ns; + if (scene_ns > g_perf.scene_max_ns) g_perf.scene_max_ns = scene_ns; + } +@@ -2037,6 +2058,7 @@ + + static void on_vsync(int64_t frame_time_ns) { + int64_t now = now_ns(); ++ dd_ctrace("T %lld %d", (long long)frame_time_ns, g_dirty); + g_perf.ticks++; + if (g_last_vsync_ns) { + int64_t d = now - g_last_vsync_ns; diff --git a/docs/investigations/qam-frame-limit/patches/gamescope-limiter-debug.patch b/docs/investigations/qam-frame-limit/patches/gamescope-limiter-debug.patch new file mode 100644 index 000000000..3938e6ea7 --- /dev/null +++ b/docs/investigations/qam-frame-limit/patches/gamescope-limiter-debug.patch @@ -0,0 +1,130 @@ +--- a/src/steamcompmgr.cpp ++++ b/src/steamcompmgr.cpp +@@ -1209,12 +1209,38 @@ + std::mutex g_SteamCompMgrXWaylandServerMutex; + + gamescope::VBlankTime g_SteamCompMgrVBlankTime = {}; ++#include ++static FILE *dd_trace_file() ++{ ++ static FILE *f = []() -> FILE * { ++ const char *path = getenv( "DD_FRAMETRACE" ); ++ return path && *path ? fopen( path, "w" ) : nullptr; ++ }(); ++ return f; ++} ++static void dd_trace( const char *fmt, ... ) ++{ ++ FILE *f = dd_trace_file(); ++ if ( !f ) return; ++ va_list ap; ++ va_start( ap, fmt ); ++ fprintf( f, "%lu ", (unsigned long) get_time_in_nanos() ); ++ vfprintf( f, fmt, ap ); ++ fputc( '\n', f ); ++ va_end( ap ); ++ static unsigned n; ++ if ( ( ++n % 64 ) == 0 ) fflush( f ); ++} + ++ + uint64_t g_uCurrentBasePlaneCommitID = 0; + uint32_t g_uCurrentBasePlaneAppID = 0; + bool g_bCurrentBasePlaneIsFifo = false; + + static int g_nSteamCompMgrTargetFPS = 0; ++gamescope::ConVar cv_dd_force_fps_limit{ "dd_force_fps_limit", 0, "Debug: force the frame limiter to this FPS (0 = leave it to Steam)" }; ++static int s_nDDForcedFPS = 0; ++ + static uint64_t g_uDynamicRefreshEqualityTime = 0; + static int g_nDynamicRefreshRate[gamescope::GAMESCOPE_SCREEN_TYPE_COUNT] = { 0, 0 }; + // Delay to stop modes flickering back and forth. +@@ -1266,6 +1292,8 @@ + { + int nPrevFPSLimit = g_nSteamCompMgrTargetFPS; + _update_app_target_refresh_cycle(); ++ if ( cv_dd_force_fps_limit ) ++ g_nSteamCompMgrTargetFPS = cv_dd_force_fps_limit; + if ( !!g_nSteamCompMgrTargetFPS != !!nPrevFPSLimit ) + update_runtime_info(); + } +@@ -2825,6 +2853,7 @@ + pFocus->CachedPlanes[ HELD_COMMIT_FADE ] = basePlane; + + pFocus->ulBasePlaneCommitID = lastCommit->commitID; ++ dd_trace( "P %u %lu", lastCommit->appID, (unsigned long) lastCommit->commitID ); + pFocus->uBasePlaneAppID = lastCommit->appID; + pFocus->bBasePlaneIsFifo = lastCommit->IsPerfOverlayFIFO(); + } +@@ -3104,9 +3133,16 @@ + gamescope::ConVar cv_paint_cursor_plane{ "paint_cursor_plane", true }; + gamescope::ConVar cv_paint_mura_plane{ "paint_mura_plane", true }; + ++gamescope::ConVar cv_dd_paint_delay_us{ "dd_paint_delay_us", 0, "Debug: delay each composite by a random 0..N us (emulates a slower device)" }; + static void + paint_all( global_focus_t *pFocus, bool async ) + { ++ if ( cv_dd_paint_delay_us > 0 ) ++ { ++ static uint32_t s_seed = 12345; ++ s_seed = s_seed * 1103515245u + 12345u; ++ usleep( ( s_seed >> 8 ) % (uint32_t) cv_dd_paint_delay_us ); ++ } + if ( !pFocus ) + return; + +@@ -6813,6 +6849,7 @@ + w->receivedDoneCommit = false; + + w->last_commit_first_latch_time = timespec_to_nanos(now); ++ dd_trace( "F %u", w->appID ); + + // Acknowledge commit once. + wlserver_lock(); +@@ -7307,6 +7344,8 @@ + if ( ev->atom == ctx->atoms.gamescopeFPSLimit ) + { + g_nSteamCompMgrTargetFPS = get_prop( ctx, ctx->root, ctx->atoms.gamescopeFPSLimit, 0 ); ++ if ( cv_dd_force_fps_limit ) ++ g_nSteamCompMgrTargetFPS = cv_dd_force_fps_limit; + update_runtime_info(); + } + for (int i = 0; i < gamescope::GAMESCOPE_SCREEN_TYPE_COUNT; i++) +@@ -7977,6 +8016,7 @@ + { + gpuvis_trace_printf( "commit %lu done", w->commit_queue[ j ]->commitID ); + w->commit_queue[ j ]->done = true; ++ dd_trace( "D %u %lu", w->appID, (unsigned long) commitID ); + w->commit_queue[ j ]->earliest_present_time = earliestPresentTime; + w->commit_queue[ j ]->present_margin = earliestPresentTime - earliestLatchTime; + bFoundWindow = true; +@@ -8448,6 +8488,7 @@ + // Import failed to import, early exit. + return; + } ++ dd_trace( "C %u %lu %d", w->appID, (unsigned long) newCommit->commitID, (int) reslistentry.fifo ); + + int fence = -1; + global_focus_t *pCurrentFocus = GetCurrentFocus(); +@@ -10086,6 +10127,7 @@ + { + g_SteamCompMgrVBlankTime = *pendingVBlank; + vblank = true; ++ dd_trace( "V %lu %lu", (unsigned long) pendingVBlank->schedule.ulTargetVBlank, (unsigned long) pendingVBlank->schedule.ulScheduledWakeupPoint ); + } + + if ( g_bRun == false ) +@@ -10391,7 +10433,13 @@ + static uint64_t vblank_idx = 0; + if ( vblank ) + { ++ if ( cv_dd_force_fps_limit != s_nDDForcedFPS || ( cv_dd_force_fps_limit && g_nSteamCompMgrTargetFPS != cv_dd_force_fps_limit ) ) + { ++ s_nDDForcedFPS = cv_dd_force_fps_limit; ++ g_nSteamCompMgrTargetFPS = s_nDDForcedFPS; ++ update_runtime_info(); ++ } ++ { + uint64_t now = get_time_in_nanos(); + + steamcompmgr_update_vr_session_state(); diff --git a/docs/investigations/qam-frame-limit/tools/ana.py b/docs/investigations/qam-frame-limit/tools/ana.py new file mode 100644 index 000000000..b54bfb2de --- /dev/null +++ b/docs/investigations/qam-frame-limit/tools/ana.py @@ -0,0 +1,18 @@ +# ana.py [base-hh:mm:ss] [threshold] [window-s]: per window, how often the picture changed and the spacing of changes in 60 Hz slots. +import json,sys,collections,statistics as S +d=json.load(open(sys.argv[1])); base=sys.argv[2] if len(sys.argv)>2 else None +th=float(sys.argv[3]) if len(sys.argv)>3 else 0.6 +win=float(sys.argv[4]) if len(sys.argv)>4 else 2.0 +def clk(t): + if not base: return f"{t:6.1f}" + h,m,s=map(int,base.split(":")); x=h*3600+m*60+s+t + return "%02d:%02d:%02d"%(x//3600,x//60%60,x%60) +ch=[(t,v) for t,v in d[1:] if v>th] +buckets=collections.defaultdict(list) +for i in range(1,len(ch)): + buckets[int(ch[i][0]//win)].append((ch[i][0]-ch[i-1][0])*1000) +allf=collections.Counter(int(t//win) for t,_ in d) +for b in sorted(buckets): + iv=buckets[b]; hist=collections.Counter(min(5,round(x/16.67)) for x in iv) + mags=[v for t,v in d if int(t//win)==b and v>th] + print(f"{clk(b*win)} frames={allf[b]:3d} changes={len(iv):3d} ({len(iv)/win:4.1f}/s) iv(ms) mean={S.mean(iv):5.1f} sd={S.pstdev(iv):5.1f} slots 1:{hist[1]:3d} 2:{hist[2]:3d} 3:{hist[3]:3d} 4+:{hist[4]+hist[5]:3d} motionCV={S.pstdev(mags)/max(1e-9,S.mean(mags)):.2f}") diff --git a/docs/investigations/qam-frame-limit/tools/cana.py b/docs/investigations/qam-frame-limit/tools/cana.py new file mode 100644 index 000000000..8fb6d459e --- /dev/null +++ b/docs/investigations/qam-frame-limit/tools/cana.py @@ -0,0 +1,24 @@ +# cana.py : from the compositor trace, ticks between new game-plane buffers and how close gamescope commits land to our vsync tick. +import sys,collections,statistics as st +ev=[l.split() for l in open(sys.argv[1])] +ticks=[]; pending=None; shown=[]; margins=[]; lat=[]; cb=[] +for e in ev: + t=int(e[0])/1e6 + if e[1]=='T': + ft=int(e[2])/1e6; ticks.append((ft,t)); cb.append(t-ft) + elif e[1]=='S' and e[2]=='1': + pending=t + elif e[1]=='R' and pending is not None: + rs=int(e[2])/1e6 + if rs>=pending: + ft=ticks[-1][0] if ticks else rs + shown.append(ft); lat.append(rs-pending) + # margin: tick callback time minus commit arrival + margins.append(ticks[-1][1]-pending if ticks else 0) + pending=None +iv=[b-a for a,b in zip(shown,shown[1:])] +slots=collections.Counter(round(x/16.667) for x in iv) +print("game frames shown",len(shown),"tick slots",dict(sorted(slots.items()))) +q=sorted(margins); print(f"commit->tick callback margin ms: min {q[0]:.2f} p5 {q[len(q)//20]:.2f} median {st.median(q):.2f}") +q=sorted(cb); print(f"choreographer callback delay after frame time: median {st.median(q):.2f} p95 {q[int(len(q)*.95)]:.2f} max {q[-1]:.2f}") +q=sorted(lat); print(f"commit->render start ms: median {st.median(q):.2f} p95 {q[int(len(q)*.95)]:.2f} max {q[-1]:.2f}") diff --git a/docs/investigations/qam-frame-limit/tools/capture-case.sh b/docs/investigations/qam-frame-limit/tools/capture-case.sh new file mode 100755 index 000000000..a2694edf0 --- /dev/null +++ b/docs/investigations/qam-frame-limit/tools/capture-case.sh @@ -0,0 +1,21 @@ +#!/bin/bash +# capture-case.sh [busy-loops] +# Pans the camera (right stick) for 14 s, records 10 s of the screen, and saves the matching slice +# of gamescope's DD_FRAMETRACE log plus the compositor's logcat lines into $WORK/runs/. +# Optional busy loops add CPU load inside the guest for 40 s. +: "${ADB_SERIAL:?set ADB_SERIAL}" "${WORK:?set WORK to a scratch directory}" +HERE="$(cd "$(dirname "$0")" && pwd)"; CTL="$(git rev-parse --show-toplevel)/tools/droiddeckctl" +n=$1; load=${2:-0}; out=$WORK/runs/$n; mkdir -p "$out" +[ "$load" -gt 0 ] && GT=10 "$HERE/guest.sh" "for i in \$(seq 1 $load); do nohup timeout 40 sh -c 'while :; do :; done' >/dev/null 2>&1 & done" && sleep 4 +adb -s "$ADB_SERIAL" logcat -c +t0=$(GT=10 "$HERE/guest.sh" 'tail -c 300 /tmp/ddtrace.log | tail -1 | cut -d" " -f1') +python3 "$CTL" input stick right 0.6 0 --hold 14000 >/dev/null 2>&1 & +sleep 2 +python3 "$CTL" record "$out/clip.mp4" --seconds 10 --display 0 >/dev/null 2>&1 +wait +t1=$(( t0 + 16000000000 )) +GT=60 "$HERE/guest.sh" "awk -v a=$t0 -v b=$t1 '\$1>=a && \$1<=b' /tmp/ddtrace.log" > "$out/trace.txt" +adb -s "$ADB_SERIAL" logcat -d | grep -E 'DroidDeckWayland|LsfgEngine|FrameGen' > "$out/log.txt" +# With patches/compositor-frame-trace.patch applied and files/comptrace.on present: +adb -s "$ADB_SERIAL" shell "su -c 'awk -v a=$t0 -v b=$t1 \"\\\$1>=a && \\\$1<=b\" /data/user/0/com.droiddeck.launcher/files/comptrace.log 2>/dev/null'" > "$out/ctrace.txt" +wc -l "$out"/trace.txt "$out"/ctrace.txt diff --git a/docs/investigations/qam-frame-limit/tools/guest.sh b/docs/investigations/qam-frame-limit/tools/guest.sh new file mode 100755 index 000000000..25247ae0e --- /dev/null +++ b/docs/investigations/qam-frame-limit/tools/guest.sh @@ -0,0 +1,9 @@ +#!/bin/bash +# Run a shell command in the running DroidDeck guest and print its output. +# Needs Setup > Diagnostics > Debugging tools on. GT sets the timeout (default 60 s). +: "${ADB_SERIAL:?set ADB_SERIAL}" +CTL="$(git rev-parse --show-toplevel)/tools/droiddeckctl" +python3 "$CTL" guest --timeout "${GT:-60}" -- sh -c "$1" 2>/dev/null | python3 -c 'import json,sys +t=sys.stdin.read(); t=t[t.index("{"):]; d=json.loads(t) +print(d.get("stdout",{}).get("text",""),end=""); print(d.get("stderr",{}).get("text",""),end="",file=sys.stderr) +if not d.get("ok"): print(json.dumps(d)[:500])' diff --git a/docs/investigations/qam-frame-limit/tools/shift.py b/docs/investigations/qam-frame-limit/tools/shift.py new file mode 100644 index 000000000..3c03f5d57 --- /dev/null +++ b/docs/investigations/qam-frame-limit/tools/shift.py @@ -0,0 +1,29 @@ +# shift.py : horizontal camera displacement per recorded frame during a pan. cv = step-size variation (judder), held = repeated frames. +import subprocess,sys,statistics as S,collections +v=sys.argv[1]; W,H=640,120 +pts=[float(x.strip(",")) for x in subprocess.run(["ffprobe","-v","error","-select_streams","v:0","-show_entries","frame=pts_time","-of","csv=p=0",v],capture_output=True,text=True).stdout.split()] +raw=subprocess.run(["ffmpeg","-v","error","-i",v,"-fps_mode","passthrough","-vf",f"crop=iw*0.62:ih*0.3:iw*0.33:ih*0.12,scale={W}:{H},format=gray","-f","rawvideo","-"],capture_output=True).stdout +n=len(raw)//(W*H) +prof=[] +for i in range(n): + f=raw[i*W*H:(i+1)*W*H] + prof.append([sum(f[y*W+x] for y in range(0,H,2)) for x in range(W)]) +def shift(a,b,R=60): + best=None + for s in range(-R,R+1): + lo,hi=max(0,s),min(W,W+s) + sad=sum(abs(a[x]-b[x-s]) for x in range(lo+R,hi-R)) + if best is None or sad2 else 2 +b=collections.defaultdict(list) +for t,dt,s in rows: b[int(t//win)].append((dt,s)) +for k in sorted(b): + xs=[s for dt,s in b[k]]; mv=[abs(s) for s in xs if s!=0] + zero=sum(1 for s in xs if s==0) + if len(mv)<5: print(f"{k*win:5.1f}s n={len(xs)} static"); continue + per_s=sum(abs(s) for s in xs)/win + print(f"{k*win:5.1f}s n={len(xs):3d} held={zero:3d} speed={per_s:6.0f}px/s step mean={S.mean(mv):5.2f} cv={S.pstdev(mv)/S.mean(mv):.2f} hist={dict(sorted(collections.Counter(mv).items()))}") diff --git a/docs/investigations/qam-frame-limit/tools/slip.py b/docs/investigations/qam-frame-limit/tools/slip.py new file mode 100644 index 000000000..3cd5ae145 --- /dev/null +++ b/docs/investigations/qam-frame-limit/tools/slip.py @@ -0,0 +1,18 @@ +# slip.py : for each 3+ slot gap in the gamescope trace, whether a game commit was waiting at the vblanks it skipped. +import sys +app="206420"; ev=[l.split() for l in open(sys.argv[1])] +pend={}; lastD=None; lastF=None; out=[]; vbs=[] +for e in ev: + t=int(e[0])/1e6; k=e[1] + if k=='V': vbs.append((t,len(pend),lastD,lastF)); continue + if len(e)<3 or e[2]!=app: continue + if k=='C': pend[e[3]]=t + elif k=='F': lastF=t + elif k=='D': + if lastD is not None and t-lastD>40: + # vblanks between: show pending count & time since last D/F + mids=[(round(v-lastD,1),p,round(v-(f or 0),1)) for v,p,d,f in vbs if lastD+5 [appid]: from the gamescope DD_FRAMETRACE log, the vblank slots between displayable game commits and frame_done -> next commit times. +import sys,collections,statistics as st +app=sys.argv[2] if len(sys.argv)>2 else "206420" +ev=[l.split() for l in open(sys.argv[1]) if len(l.split())>=2] +lastF=None; lastD=None; pend={} +lat=[]; cad=[]; firstV=None; vb=[] +for e in ev: + t=int(e[0])/1e6; k=e[1] + if k=='V': vb.append(t) + if len(e)<3 or e[2]!=app: continue + if k=='C': pend[e[3]]=t; + if k=='C' and lastF is not None: lat.append(t-lastF) + if k=='F': lastF=t + if k=='D': + if lastD is not None: cad.append(t-lastD) + lastD=t +ref=st.median([b-a for a,b in zip(vb,vb[1:])]) if len(vb)>2 else 16.67 +slots=collections.Counter(round(c/ref) for c in cad) +print(f"vblank {ref:.2f}ms game frames {len(cad)} display slots {dict(sorted(slots.items()))}") +if lat: + q=sorted(lat); print(f"F->next commit ms: median {st.median(q):.1f} p90 {q[int(len(q)*.9)]:.1f} max {q[-1]:.1f} over 31ms: {sum(1 for x in q if x>31)}") diff --git a/docs/investigations/qam-frame-limit/tools/vdiff.py b/docs/investigations/qam-frame-limit/tools/vdiff.py new file mode 100644 index 000000000..aef9c01b2 --- /dev/null +++ b/docs/investigations/qam-frame-limit/tools/vdiff.py @@ -0,0 +1,13 @@ +# vdiff.py : mean absolute luma change between consecutive screen-recording frames, with timestamps. +import subprocess,sys,json +v=sys.argv[1]; crop=sys.argv[2] if len(sys.argv)>2 else "iw*0.6:ih*0.5:iw*0.3:ih*0.2" +W,H=96,54 +pts=[float(x.strip(",")) for x in subprocess.run(["ffprobe","-v","error","-select_streams","v:0","-show_entries","frame=pts_time","-of","csv=p=0",v],capture_output=True,text=True).stdout.split()] +raw=subprocess.run(["ffmpeg","-v","error","-i",v,"-fps_mode","passthrough","-vf",f"crop={crop},scale={W}:{H},format=gray","-f","rawvideo","-"],capture_output=True).stdout +n=len(raw)//(W*H); prev=None; out=[] +for i in range(n): + f=raw[i*W*H:(i+1)*W*H] + d=0 if prev is None else sum(abs(a-b) for a,b in zip(f,prev))/(W*H) + out.append((pts[i] if i3 else v+".diff.json","w")) +print(n,len(pts))