Re: Slow (higher scheduling latency?) system after S3 - regression 4.17 -> 4.19 ?

["Marek Marczykowski-Górecki" <marmarek@invisiblethingslab.com>]

[-- Attachment #1: Type: text/plain, Size: 3559 bytes --]

On Sat, Oct 25, 2025 at 02:23:23PM +0200, Marek Marczykowski-Górecki wrote:
> Hi,
> 
> After updating from Xen 4.17 to 4.19 it appears that I have some
> performance issues if system was suspended before. For now this is just
> vague observation, as I don't have much data yet.
> 
> Generally, the user observable effect is that audio playback (over
> Qubes's PV audio thing) becomes very choppy, beyond usefulness (cannot
> make audio calls anymore, music/video playback also becomes useless with
> some players. For me this suggests some increased latency in scheduling
> - maybe some timer fires too late?
> 
> This doesn't happen always, but I'd say quite often after S3, sometimes
> may need two or three suspend cycles to trigger the issue. But it's
> possible it is also some other factor, like which pCPU the VM gets
> scheduled on, maybe? But for now I didn't hit this issue before
> performing any S3. I don't have a reliable reproducer yet.
> 
> While I write it's related to 4.17 -> 4.19 update, there is also slight
> possibility it's related to hardware change (CFL -> MTL). But, it's
> unlikely, since I'd probably get much more bug reports about that (the
> stable Qubes version uses 4.17, and we have many users on MTL).
> 
> What would be the method to collect some useful debugging info? Some
> debug-keys (r? a?), some cmdline options?

In the meantime (sharing some of it on Matrix already), I managed to
build a much more isolated test. Specifically, a single PVH domU with
VLC, preloading 1s of audio (and not playing it really, the output is
set to a file). The specific command is:

    VLC_VERBOSE=3 vlc -I cli -A afile --no-loop --play-and-exit --run-time 1   ./melodigne-quiz-blind-test-187140.mp3

The domU rootfs (or rather: initramfs) is based on AppImage of VLC,
there is not much more inside, and the above command is called as part
of init script (and domU is terminated shortly after).

There is no persistent state in the test, the whole thing is network
booted from the same base. The only things changing between runs is xen
binary + toolstack.

In the output I'm looking for this line: main input debug: Stream buffering done (1018 ms in 2 ms)

Before S3 it takes 0-2ms, sometimes (rarely) 10ms (not sure why). Just
after S3 it takes very similar amount of time.
Then, I wait 30min, and run that command (or really the whole domU)
again a few times. I consider it "good" if I get at least one result
below 10ms. With this test in hand, I did run bisect between
staging-4.17 and staging-4.19. And here stuff gets interesting:

At 498a4ded74b3f062c52e42568223dc5858d27731 I get the following times
(in ms):

    30m after S3: 2, 2, 10, 10, 
    1h after S3: 2, 16, 16, 2, 17

At 5effd810c629d9a836e46ee321ca7409dad27212:

    30m after S3: 26, 27, 26, 15
    1h after S3: 24, 25, 37, 37, 25

This doesn't make any sense to me. There is a clear difference, yet
5effd810c629d9a836e46ee321ca7409dad27212 looks like a no-op change (at
least for this Intel system).
The earlier case is still not great, as there is still some
degradation after S3, but it gets significantly worse after that commit.

Console log of both versions:
https://gist.github.com/marmarek/ebcb0ff65dbdb31875e4e69db19e4729

In the "bad" case, I see this extra line:
(XEN) [    6.902973] Platform timer appears to have unexpectedly wrapped 1 times.

But in an earlier run of the same build it's not there.

-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]