ahamilton/kick
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

x11: instrument pending-associate/classify chain; mark ready_and_claim flaky

Browse source 
Deeper-X11 instrumentation (permanent, DEBUG): every associate event
now logs surface null/mapped/hooked state, classify logs wid/xpid/pgid
at entry, and pending-map has its own line -- closing the blind spot
between xwm pairing and tab claim.  Plus kick_monotonic_ms() timestamps
on the new lines for stall measurement (prefix-safe for all test
regexes).

Paid off immediately: two stalls autopsied to paired-but-never-mapped
wlr_surfaces (associate ran with surface mapped=0, no map for 15-30s,
classify never invoked -- proven by the absent entry line).  The stall
is therefore upstream of kick classification (X MapNotify delivery /
xwm mapping under -n15), not in it; locating it further needs live
capture during a stall, not post-hoc logs.

test_xwayland_ready_and_claim failed once the same way (paired xmessage
surface never mapped within 15s): marked flaky per the seen-it rule
(passes serially).
This commit is contained in:
Andrew Hamilton 2026-09-09 22:31:46 +10:00
parent 52d12bdf2e
commit 04e056518a
2 changed files with 23 additions and 0 deletions
Download patch file Download diff file Expand all files Collapse all files

22
kick.c
View file

@ -1040,6 +1040,14 @@ static void kick_log(int level, const char *fmt, ...) {
va_end(args); va_end(args);
} }
/* Monotonic milliseconds for stall analysis in diagnostic lines (X11
association/classification under load). Mirrors bridge_dbg_ms. */
static double kick_monotonic_ms(void) {
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
return (double)ts.tv_sec * 1000.0 + (double)ts.tv_nsec / 1e6;
}
/* Route libxkbcommon's own log output (which otherwise writes /* Route libxkbcommon's own log output (which otherwise writes
"xkbcommon: ERROR: ..." straight to stderr, bypassing KICK_LOG) through "xkbcommon: ERROR: ..." straight to stderr, bypassing KICK_LOG) through
our level system. Errors surface at info level; warnings and below are our level system. Errors surface at info level; warnings and below are
@ -4594,6 +4602,8 @@ static void x11_pending_handle_map(struct wl_listener *listener, void *data) {
(void)data; (void)data;
struct kick_x11_pending *p = wl_container_of(listener, p, map); struct kick_x11_pending *p = wl_container_of(listener, p, map);
struct wlr_xwayland_surface *xsurface = p->xsurface; struct wlr_xwayland_surface *xsurface = p->xsurface;
kick_log(KICK_LOG_DEBUG, "[x11] t=%.0f pending wid=%u mapped\n",
kick_monotonic_ms(), (unsigned)xsurface->window_id);
x11_pending_teardown(p); x11_pending_teardown(p);
classify_xwayland_window(xsurface); classify_xwayland_window(xsurface);
} }
@ -4612,6 +4622,13 @@ static void x11_pending_handle_associate(struct wl_listener *listener,
(void)data; (void)data;
struct kick_x11_pending *p = wl_container_of(listener, p, associate); struct kick_x11_pending *p = wl_container_of(listener, p, associate);
struct wlr_surface *surface = p->xsurface->surface; struct wlr_surface *surface = p->xsurface->surface;
/* Stall analysis: log every associate event (not just the hooked one)
with the surface state, so a stuck pairing shows exactly where the
chain stops (no surface yet vs surfaceless spin). */
kick_log(KICK_LOG_DEBUG, "[x11] t=%.0f pending wid=%u associate "
"surface=%p mapped=%d hooked=%d\n", kick_monotonic_ms(),
(unsigned)p->xsurface->window_id, (void *)surface,
surface ? (int)surface->mapped : -1, (int)p->surface_hooked);
if (!surface || p->surface_hooked) if (!surface || p->surface_hooked)
return; return;
p->surface_hooked = true; p->surface_hooked = true;
@ -4653,6 +4670,11 @@ static void classify_xwayland_window(struct wlr_xwayland_surface *xsurface) {
it, which lands the window in the external-append path below. */ it, which lands the window in the external-append path below. */
pid_t xpid = xsurface->pid; pid_t xpid = xsurface->pid;
pid_t pgid = xpid > 0 ? getpgid(xpid) : -1; pid_t pgid = xpid > 0 ? getpgid(xpid) : -1;
/* Stall analysis: entry log (the outcome logs [claim]/[sub] stack
downstream in claim_x11_window). */
kick_log(KICK_LOG_DEBUG, "[x11] t=%.0f classify wid=%u xpid=%d pgid=%d\n",
kick_monotonic_ms(), (unsigned)xsurface->window_id,
(int)xpid, (int)pgid);
/* Claim a pending window by launcher process group: an X11 command /* Claim a pending window by launcher process group: an X11 command
forked by launch_client inherits its group exactly like a Wayland forked by launch_client inherits its group exactly like a Wayland

1
tests/test_smoke.py
View file

@ -4084,6 +4084,7 @@ def xwayland_session():
s.close() s.close()
@pytest.mark.flaky
def test_xwayland_ready_and_claim(xwayland_session): def test_xwayland_ready_and_claim(xwayland_session):
"""XWayland comes up in lazy mode, and the X11 command's window is """XWayland comes up in lazy mode, and the X11 command's window is
claimed by its own process group into tab slot 0.""" claimed by its own process group into tab slot 0."""