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

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

[Marek Marczykowski-Górecki]

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

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?

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

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

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

[Marek Marczykowski-Górecki]

[-- 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 --]

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

[Jan Beulich]

On 25.03.2026 20:13, Marek Marczykowski-Górecki wrote:
> 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.

And in that earlier run, did the post-S3 delays also not occur?

Jan

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

[Jan Beulich]

On 25.03.2026 20:13, Marek Marczykowski-Górecki wrote:
> 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).

Pretty odd indeed. I assume you double checked the effect by going back
and forth between the two commits. If the effect persists, could you make
both binaries (xen-syms or xen.efi respectively, depending on which one
you use of the system) available somewhere for inspection? There has to
be some relevant difference, e.g. by addresses shifting slightly.

Another possible further step may be to move forward from that commit,
putting a revert of 5effd810c629 on top. If the behavioral effect is due
to particular layout of the linked images, the effect should re-surface
later (likely again at a seeming innocent change).

Jan

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

[Marek Marczykowski-Górecki]

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

On Thu, Mar 26, 2026 at 09:27:56AM +0100, Jan Beulich wrote:
> On 25.03.2026 20:13, Marek Marczykowski-Górecki wrote:
> > 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).
> 
> Pretty odd indeed. I assume you double checked the effect by going back
> and forth between the two commits.

Yes...

> If the effect persists, could you make
> both binaries (xen-syms or xen.efi respectively, depending on which one
> you use of the system) available somewhere for inspection? There has to
> be some relevant difference, e.g. by addresses shifting slightly.

Sure, here: https://salmon.qubes-os.org/~marmarek/xen-perf-weird.tar.gz

> Another possible further step may be to move forward from that commit,
> putting a revert of 5effd810c629 on top. If the behavioral effect is due
> to particular layout of the linked images, the effect should re-surface
> later (likely again at a seeming innocent change).

Good idea, will check.

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

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

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

[Marek Marczykowski-Górecki]

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

On Thu, Mar 26, 2026 at 09:21:16AM +0100, Jan Beulich wrote:
> On 25.03.2026 20:13, Marek Marczykowski-Górecki wrote:
> > 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.
> 
> And in that earlier run, did the post-S3 delays also not occur?

Regardless of the above message, the "bad" build had the post-S3 delays.

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

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

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

[Jan Beulich]

On 26.03.2026 13:44, Marek Marczykowski-Górecki wrote:
> On Thu, Mar 26, 2026 at 09:27:56AM +0100, Jan Beulich wrote:
>> On 25.03.2026 20:13, Marek Marczykowski-Górecki wrote:
>>> 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).
>>
>> Pretty odd indeed. I assume you double checked the effect by going back
>> and forth between the two commits.
> 
> Yes...
> 
>> If the effect persists, could you make
>> both binaries (xen-syms or xen.efi respectively, depending on which one
>> you use of the system) available somewhere for inspection? There has to
>> be some relevant difference, e.g. by addresses shifting slightly.
> 
> Sure, here: https://salmon.qubes-os.org/~marmarek/xen-perf-weird.tar.gz

While said commit changes the size of init_nonfatal_mce_checker() by 4
bytes, that doesn't lead to any other changes. I.e. all addresses remain
the same. I.e. I'm completely lost as to explaining the observed behavior
(or even just making a wild guess).

Jan

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

[Marek Marczykowski-Górecki]

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

On Thu, Mar 26, 2026 at 02:20:04PM +0100, Jan Beulich wrote:
> On 26.03.2026 13:44, Marek Marczykowski-Górecki wrote:
> > On Thu, Mar 26, 2026 at 09:27:56AM +0100, Jan Beulich wrote:
> >> On 25.03.2026 20:13, Marek Marczykowski-Górecki wrote:
> >>> 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).
> >>
> >> Pretty odd indeed. I assume you double checked the effect by going back
> >> and forth between the two commits.
> > 
> > Yes...
> > 
> >> If the effect persists, could you make
> >> both binaries (xen-syms or xen.efi respectively, depending on which one
> >> you use of the system) available somewhere for inspection? There has to
> >> be some relevant difference, e.g. by addresses shifting slightly.
> > 
> > Sure, here: https://salmon.qubes-os.org/~marmarek/xen-perf-weird.tar.gz
> 
> While said commit changes the size of init_nonfatal_mce_checker() by 4
> bytes, that doesn't lead to any other changes. I.e. all addresses remain
> the same. I.e. I'm completely lost as to explaining the observed behavior
> (or even just making a wild guess).

With staging-4.19 from a week ago +
5effd810c629d9a836e46ee321ca7409dad27212 reverted, I got the following
results:

30m after S3: 23, 22, 22, 23
1h after S3: 7, 25, 22, 8, 25

So, there are some fast runs, but most are in line with the "bad" case
above...

But, I have another idea why that seemingly no-op commit may change
something: maybe it's about stack content during/after the function
call, influencing some uninitialized variable down the road?

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

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

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

[Jan Beulich]

On 26.03.2026 16:53, Marek Marczykowski-Górecki wrote:
> On Thu, Mar 26, 2026 at 02:20:04PM +0100, Jan Beulich wrote:
>> On 26.03.2026 13:44, Marek Marczykowski-Górecki wrote:
>>> On Thu, Mar 26, 2026 at 09:27:56AM +0100, Jan Beulich wrote:
>>>> On 25.03.2026 20:13, Marek Marczykowski-Górecki wrote:
>>>>> 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).
>>>>
>>>> Pretty odd indeed. I assume you double checked the effect by going back
>>>> and forth between the two commits.
>>>
>>> Yes...
>>>
>>>> If the effect persists, could you make
>>>> both binaries (xen-syms or xen.efi respectively, depending on which one
>>>> you use of the system) available somewhere for inspection? There has to
>>>> be some relevant difference, e.g. by addresses shifting slightly.
>>>
>>> Sure, here: https://salmon.qubes-os.org/~marmarek/xen-perf-weird.tar.gz
>>
>> While said commit changes the size of init_nonfatal_mce_checker() by 4
>> bytes, that doesn't lead to any other changes. I.e. all addresses remain
>> the same. I.e. I'm completely lost as to explaining the observed behavior
>> (or even just making a wild guess).
> 
> With staging-4.19 from a week ago +
> 5effd810c629d9a836e46ee321ca7409dad27212 reverted, I got the following
> results:
> 
> 30m after S3: 23, 22, 22, 23
> 1h after S3: 7, 25, 22, 8, 25
> 
> So, there are some fast runs, but most are in line with the "bad" case
> above...
> 
> But, I have another idea why that seemingly no-op commit may change
> something: maybe it's about stack content during/after the function
> call, influencing some uninitialized variable down the road?

Possible in principle, but not something which would change specifically
by said commit, or specifically across S3.

Jan

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

[Marek Marczykowski-Górecki]

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

Some further observation, this time regarding timers:

Just before S3:

    (XEN) [  150.264757] Dumping timer queues:
    (XEN) [  150.265181] CPU00:
    (XEN) [  150.265497]   ex=         736us timer=ffff82d040643540 cb=drivers/char/xhci-dbc.c#dbc_uart_poll(ffff82d0404e5e78)
    (XEN) [  150.266590]   ex=      460377us timer=ffff82d04065d2c0 cb=arch/x86/time.c#time_calibration(0000000000000000)
    (XEN) [  150.267636]   ex=     1377460us timer=ffff82d04065d220 cb=arch/x86/time.c#plt_overflow(0000000000000000)
    (XEN) [  150.268651]   ex=    13525100us timer=ffff82d040644c20 cb=arch/x86/cpu/mcheck/intel-nonfatal.c#mce_work_fn(0000000000000000)
    (XEN) [  150.269820] CPU02:
    (XEN) [  150.270126]   ex=      616653us timer=ffff830461931070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461931000)
    (XEN) [  150.271276] CPU04:
    (XEN) [  150.271577]   ex=      630577us timer=ffff830461935070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461935000)
    (XEN) [  150.272734]   ex=      634586us timer=ffff830461921070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461921000)
    (XEN) [  150.273884] CPU06:
    (XEN) [  150.274184]   ex=       44474us timer=ffff830461905070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461905000)
    (XEN) [  150.275334] CPU08:
    (XEN) [  150.275633]   ex=       11465us timer=ffff83046190d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046190d000)
    (XEN) [  150.276783] CPU09:
    (XEN) [  150.277083]   ex=       12465us timer=ffff830461909070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461909000)
    (XEN) [  150.278236] CPU10:
    (XEN) [  150.278536]   ex=       14464us timer=ffff830461901070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461901000)
    (XEN) [  150.279686] CPU11:
    (XEN) [  150.279986]   ex=       15464us timer=ffff830461911070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461911000)
    (XEN) [  150.281139] CPU12:
    (XEN) [  150.281438]   ex=       17463us timer=ffff830461919070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461919000)
    (XEN) [  150.282592] CPU13:
    (XEN) [  150.282890]   ex=      347090us timer=ffff830461941070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461941000)
    (XEN) [  150.284040] CPU14:
    (XEN) [  150.284341]   ex=       20462us timer=ffff83046191d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046191d000)
    (XEN) [  150.285496] CPU15:
    (XEN) [  150.285806]   ex=         470us timer=ffff83046192d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046192d000)
    (XEN) [  150.286972]   ex=       15316us timer=ffff8304619cdaa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff8304619cdae0)
    (XEN) [  150.288156]   ex=        6230us timer=ffff8304619e8ed0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
    (XEN) [  150.289192] CPU16:
    (XEN) [  150.289492]   ex=      633594us timer=ffff830461929070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461929000)
    (XEN) [  150.290642] CPU18:
    (XEN) [  150.290942]   ex=      614601us timer=ffff830461939070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461939000)
    (XEN) [  150.292094] CPU20:
    (XEN) [  150.292394]   ex=       27459us timer=ffff830461915070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461915000)
    (XEN) [  150.293553]   ex=       55316us timer=ffff830461979aa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff830461979ae0)
    (XEN) [  150.294744]   ex=       35413us timer=ffff83046198fdc0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
    (XEN) [  150.295776] CPU21:
    (XEN) [  150.296076]   ex=      617580us timer=ffff830461925070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461925000)

Just after S3:

    (XEN) [  164.462198] Dumping timer queues:
    (XEN) [  164.462630] CPU00:
    (XEN) [  164.462949]   ex=         768us timer=ffff82d040643540 cb=drivers/char/xhci-dbc.c#dbc_uart_poll(ffff82d0404e5e78)
    (XEN) [  164.464064]   ex=     1286532us timer=ffff82d04065d220 cb=arch/x86/time.c#plt_overflow(0000000000000000)
    (XEN) [  164.465099]   ex=      395997us timer=ffff830461921070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461921000)
    (XEN) [  164.466262]   ex=    15327843us timer=ffff82d040644c20 cb=arch/x86/cpu/mcheck/intel-nonfatal.c#mce_work_fn(0000000000000000)
    (XEN) [  164.467461] CPU02:
    (XEN) [  164.467773]   ex=       37756us timer=ffff830461931070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461931000)
    (XEN) [  164.468953] CPU04:
    (XEN) [  164.469267]   ex=      940042us timer=ffff830461935070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461935000)
    (XEN) [  164.470444] CPU06:
    (XEN) [  164.470759]   ex=      485896us timer=ffff830461905070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461905000)
    (XEN) [  164.471937] CPU08:
    (XEN) [  164.472251]   ex=      459720us timer=ffff83046190d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046190d000)
    (XEN) [  164.473430] CPU09:
    (XEN) [  164.473745]   ex=     1563081us timer=ffff830461909070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461909000)
    (XEN) [  164.474922] CPU10:
    (XEN) [  164.475237]   ex=      948204us timer=ffff830461901070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461901000)
    (XEN) [  164.476417] CPU11:
    (XEN) [  164.476732]   ex=      948071us timer=ffff830461911070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461911000)
    (XEN) [  164.477912] CPU12:
    (XEN) [  164.478219]   ex=      892163us timer=ffff830461919070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461919000)
    (XEN) [  164.479398] CPU13:
    (XEN) [  164.479713]   ex=      308429us timer=ffff830461941070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461941000)
    (XEN) [  164.480893] CPU14:
    (XEN) [  164.481208]   ex=      954493us timer=ffff83046191d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046191d000)
    (XEN) [  164.482386] CPU15:
    (XEN) [  164.482700]   ex=     1487692us timer=ffff83046192d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046192d000)
    (XEN) [  164.483881] CPU16:
    (XEN) [  164.484195]   ex=       22890us timer=ffff830461929070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461929000)
    (XEN) [  164.485373] CPU18:
    (XEN) [  164.485688]   ex=       85902us timer=ffff830461939070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461939000)
    (XEN) [  164.486864] CPU20:
    (XEN) [  164.487171]   ex=         895us timer=ffff830461915070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461915000)
    (XEN) [  164.488358]   ex=       17895us timer=ffff830461979aa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff830461979ae0)
    (XEN) [  164.489569]   ex=        2914us timer=ffff83046198fdc0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
    (XEN) [  164.490633] CPU21:
    (XEN) [  164.490947]   ex=      461154us timer=ffff830461925070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461925000)

In the latter case, I see only one cb=common/sched/core.c#s_timer_fn
(two of them before). And also only one
cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer.

Is the s_timer_fn related to runqueues? I have two of them:

    (XEN) [   11.751480] Adding cpu 0 to runqueue 0
    (XEN) [   11.753580]  First cpu on runqueue, activating
    (XEN) [   11.755731] Adding cpu 2 to runqueue 0
    (XEN) [   11.757818] Adding cpu 4 to runqueue 0
    (XEN) [   11.759891] Adding cpu 6 to runqueue 0
    (XEN) [   11.761955] Adding cpu 8 to runqueue 0
    (XEN) [   11.764001] Adding cpu 9 to runqueue 0
    (XEN) [   11.766029] Adding cpu 10 to runqueue 0
    (XEN) [   11.768045] Adding cpu 11 to runqueue 0
    (XEN) [   11.770050] Adding cpu 12 to runqueue 1
    (XEN) [   11.772033]  First cpu on runqueue, activating
    (XEN) [   11.774051] Adding cpu 13 to runqueue 1
    (XEN) [   11.776047] Adding cpu 14 to runqueue 1
    (XEN) [   11.777993] Adding cpu 15 to runqueue 1
    (XEN) [   11.779913] Adding cpu 16 to runqueue 1
    (XEN) [   11.781872] Adding cpu 18 to runqueue 1
    (XEN) [   11.783912] Adding cpu 20 to runqueue 1
    (XEN) [   11.785855] Adding cpu 21 to runqueue 1

But when I force all CPUs into a single runqueue, there are still two of
those s_timer_fn timers (and also two cpufreq ones). And still only one
after S3. And still the issue after S3 persists.

Could the issue be related to those timer differences?


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

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

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

[Jan Beulich]

On 27.03.2026 13:47, Marek Marczykowski-Górecki wrote:
> Some further observation, this time regarding timers:
> 
> Just before S3:
> 
>     (XEN) [  150.264757] Dumping timer queues:
>     (XEN) [  150.265181] CPU00:
>     (XEN) [  150.265497]   ex=         736us timer=ffff82d040643540 cb=drivers/char/xhci-dbc.c#dbc_uart_poll(ffff82d0404e5e78)
>     (XEN) [  150.266590]   ex=      460377us timer=ffff82d04065d2c0 cb=arch/x86/time.c#time_calibration(0000000000000000)
>     (XEN) [  150.267636]   ex=     1377460us timer=ffff82d04065d220 cb=arch/x86/time.c#plt_overflow(0000000000000000)
>     (XEN) [  150.268651]   ex=    13525100us timer=ffff82d040644c20 cb=arch/x86/cpu/mcheck/intel-nonfatal.c#mce_work_fn(0000000000000000)
>     (XEN) [  150.269820] CPU02:
>     (XEN) [  150.270126]   ex=      616653us timer=ffff830461931070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461931000)
>     (XEN) [  150.271276] CPU04:
>     (XEN) [  150.271577]   ex=      630577us timer=ffff830461935070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461935000)
>     (XEN) [  150.272734]   ex=      634586us timer=ffff830461921070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461921000)
>     (XEN) [  150.273884] CPU06:
>     (XEN) [  150.274184]   ex=       44474us timer=ffff830461905070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461905000)
>     (XEN) [  150.275334] CPU08:
>     (XEN) [  150.275633]   ex=       11465us timer=ffff83046190d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046190d000)
>     (XEN) [  150.276783] CPU09:
>     (XEN) [  150.277083]   ex=       12465us timer=ffff830461909070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461909000)
>     (XEN) [  150.278236] CPU10:
>     (XEN) [  150.278536]   ex=       14464us timer=ffff830461901070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461901000)
>     (XEN) [  150.279686] CPU11:
>     (XEN) [  150.279986]   ex=       15464us timer=ffff830461911070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461911000)
>     (XEN) [  150.281139] CPU12:
>     (XEN) [  150.281438]   ex=       17463us timer=ffff830461919070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461919000)
>     (XEN) [  150.282592] CPU13:
>     (XEN) [  150.282890]   ex=      347090us timer=ffff830461941070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461941000)
>     (XEN) [  150.284040] CPU14:
>     (XEN) [  150.284341]   ex=       20462us timer=ffff83046191d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046191d000)
>     (XEN) [  150.285496] CPU15:
>     (XEN) [  150.285806]   ex=         470us timer=ffff83046192d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046192d000)
>     (XEN) [  150.286972]   ex=       15316us timer=ffff8304619cdaa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff8304619cdae0)
>     (XEN) [  150.288156]   ex=        6230us timer=ffff8304619e8ed0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
>     (XEN) [  150.289192] CPU16:
>     (XEN) [  150.289492]   ex=      633594us timer=ffff830461929070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461929000)
>     (XEN) [  150.290642] CPU18:
>     (XEN) [  150.290942]   ex=      614601us timer=ffff830461939070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461939000)
>     (XEN) [  150.292094] CPU20:
>     (XEN) [  150.292394]   ex=       27459us timer=ffff830461915070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461915000)
>     (XEN) [  150.293553]   ex=       55316us timer=ffff830461979aa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff830461979ae0)
>     (XEN) [  150.294744]   ex=       35413us timer=ffff83046198fdc0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
>     (XEN) [  150.295776] CPU21:
>     (XEN) [  150.296076]   ex=      617580us timer=ffff830461925070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461925000)
> 
> Just after S3:
> 
>     (XEN) [  164.462198] Dumping timer queues:
>     (XEN) [  164.462630] CPU00:
>     (XEN) [  164.462949]   ex=         768us timer=ffff82d040643540 cb=drivers/char/xhci-dbc.c#dbc_uart_poll(ffff82d0404e5e78)
>     (XEN) [  164.464064]   ex=     1286532us timer=ffff82d04065d220 cb=arch/x86/time.c#plt_overflow(0000000000000000)
>     (XEN) [  164.465099]   ex=      395997us timer=ffff830461921070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461921000)
>     (XEN) [  164.466262]   ex=    15327843us timer=ffff82d040644c20 cb=arch/x86/cpu/mcheck/intel-nonfatal.c#mce_work_fn(0000000000000000)
>     (XEN) [  164.467461] CPU02:
>     (XEN) [  164.467773]   ex=       37756us timer=ffff830461931070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461931000)
>     (XEN) [  164.468953] CPU04:
>     (XEN) [  164.469267]   ex=      940042us timer=ffff830461935070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461935000)
>     (XEN) [  164.470444] CPU06:
>     (XEN) [  164.470759]   ex=      485896us timer=ffff830461905070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461905000)
>     (XEN) [  164.471937] CPU08:
>     (XEN) [  164.472251]   ex=      459720us timer=ffff83046190d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046190d000)
>     (XEN) [  164.473430] CPU09:
>     (XEN) [  164.473745]   ex=     1563081us timer=ffff830461909070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461909000)
>     (XEN) [  164.474922] CPU10:
>     (XEN) [  164.475237]   ex=      948204us timer=ffff830461901070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461901000)
>     (XEN) [  164.476417] CPU11:
>     (XEN) [  164.476732]   ex=      948071us timer=ffff830461911070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461911000)
>     (XEN) [  164.477912] CPU12:
>     (XEN) [  164.478219]   ex=      892163us timer=ffff830461919070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461919000)
>     (XEN) [  164.479398] CPU13:
>     (XEN) [  164.479713]   ex=      308429us timer=ffff830461941070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461941000)
>     (XEN) [  164.480893] CPU14:
>     (XEN) [  164.481208]   ex=      954493us timer=ffff83046191d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046191d000)
>     (XEN) [  164.482386] CPU15:
>     (XEN) [  164.482700]   ex=     1487692us timer=ffff83046192d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046192d000)
>     (XEN) [  164.483881] CPU16:
>     (XEN) [  164.484195]   ex=       22890us timer=ffff830461929070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461929000)
>     (XEN) [  164.485373] CPU18:
>     (XEN) [  164.485688]   ex=       85902us timer=ffff830461939070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461939000)
>     (XEN) [  164.486864] CPU20:
>     (XEN) [  164.487171]   ex=         895us timer=ffff830461915070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461915000)
>     (XEN) [  164.488358]   ex=       17895us timer=ffff830461979aa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff830461979ae0)
>     (XEN) [  164.489569]   ex=        2914us timer=ffff83046198fdc0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
>     (XEN) [  164.490633] CPU21:
>     (XEN) [  164.490947]   ex=      461154us timer=ffff830461925070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461925000)
> 
> In the latter case, I see only one cb=common/sched/core.c#s_timer_fn
> (two of them before). And also only one
> cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer.

Let's start with this one. It's active when the ondemand governor is in use,
and when a CPU isn't (in the process of being put into) a C-state. There
being only two instances means the system was reasonably idle at the time you
dumped the timer queues ahead of entering S3, and just slightly more idle
after getting back out of S3. I've just checked my Skylake: Without it ever
having gone through an S3 cycle, there's only one instance there when the
system is running nothing but an "xl dmesg".

If you place enough load on the system to keep all CPUs busy, more instances
of the timer should appear. How many of them it'll be does, however, also
depend on the scope of the policy (supplied by firmware). The topology ...

> Is the s_timer_fn related to runqueues? I have two of them:
> 
>     (XEN) [   11.751480] Adding cpu 0 to runqueue 0
>     (XEN) [   11.753580]  First cpu on runqueue, activating
>     (XEN) [   11.755731] Adding cpu 2 to runqueue 0
>     (XEN) [   11.757818] Adding cpu 4 to runqueue 0
>     (XEN) [   11.759891] Adding cpu 6 to runqueue 0
>     (XEN) [   11.761955] Adding cpu 8 to runqueue 0
>     (XEN) [   11.764001] Adding cpu 9 to runqueue 0
>     (XEN) [   11.766029] Adding cpu 10 to runqueue 0
>     (XEN) [   11.768045] Adding cpu 11 to runqueue 0
>     (XEN) [   11.770050] Adding cpu 12 to runqueue 1
>     (XEN) [   11.772033]  First cpu on runqueue, activating
>     (XEN) [   11.774051] Adding cpu 13 to runqueue 1
>     (XEN) [   11.776047] Adding cpu 14 to runqueue 1
>     (XEN) [   11.777993] Adding cpu 15 to runqueue 1
>     (XEN) [   11.779913] Adding cpu 16 to runqueue 1
>     (XEN) [   11.781872] Adding cpu 18 to runqueue 1
>     (XEN) [   11.783912] Adding cpu 20 to runqueue 1
>     (XEN) [   11.785855] Adding cpu 21 to runqueue 1

... of this system looks somewhat "interesting", judging from these CPU
numbers.

Assuming the system was (supposedly) equally idle before and after S3,
the absence of the 2nd timer(s?) may indicate that some (background?)
load that was there before S3 didn't re-appear afterwards. Such
background load could be something which monitors and tunes the system.
(Yet as indicated, I'm looking at the CPUfreq part only right now. I'm
kind of hoping that a scheduler maintainer may look at the other aspect.)

> Could the issue be related to those timer differences?

Possibly. For the CPUfreq aspect you could simply turn that off to see if
it makes a difference. Or you could switch to a governor different from
the ondemand one.

With the ondemand governor, does the pattern (will require multiple runs)
change across S3 that "xenpm get-cpufreq-states" produces? For example,
does load move towards CPU0? (Thinking of it, did you check whether
interrupt affinities change across S3? More going to CPU0 could also be
part of the problem, for example.)

Jan

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

[Jürgen Groß]

[-- Attachment #1.1.1: Type: text/plain, Size: 10410 bytes --]

On 02.04.26 10:23, Jan Beulich wrote:
> On 27.03.2026 13:47, Marek Marczykowski-Górecki wrote:
>> Some further observation, this time regarding timers:
>>
>> Just before S3:
>>
>>      (XEN) [  150.264757] Dumping timer queues:
>>      (XEN) [  150.265181] CPU00:
>>      (XEN) [  150.265497]   ex=         736us timer=ffff82d040643540 cb=drivers/char/xhci-dbc.c#dbc_uart_poll(ffff82d0404e5e78)
>>      (XEN) [  150.266590]   ex=      460377us timer=ffff82d04065d2c0 cb=arch/x86/time.c#time_calibration(0000000000000000)
>>      (XEN) [  150.267636]   ex=     1377460us timer=ffff82d04065d220 cb=arch/x86/time.c#plt_overflow(0000000000000000)
>>      (XEN) [  150.268651]   ex=    13525100us timer=ffff82d040644c20 cb=arch/x86/cpu/mcheck/intel-nonfatal.c#mce_work_fn(0000000000000000)
>>      (XEN) [  150.269820] CPU02:
>>      (XEN) [  150.270126]   ex=      616653us timer=ffff830461931070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461931000)
>>      (XEN) [  150.271276] CPU04:
>>      (XEN) [  150.271577]   ex=      630577us timer=ffff830461935070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461935000)
>>      (XEN) [  150.272734]   ex=      634586us timer=ffff830461921070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461921000)
>>      (XEN) [  150.273884] CPU06:
>>      (XEN) [  150.274184]   ex=       44474us timer=ffff830461905070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461905000)
>>      (XEN) [  150.275334] CPU08:
>>      (XEN) [  150.275633]   ex=       11465us timer=ffff83046190d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046190d000)
>>      (XEN) [  150.276783] CPU09:
>>      (XEN) [  150.277083]   ex=       12465us timer=ffff830461909070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461909000)
>>      (XEN) [  150.278236] CPU10:
>>      (XEN) [  150.278536]   ex=       14464us timer=ffff830461901070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461901000)
>>      (XEN) [  150.279686] CPU11:
>>      (XEN) [  150.279986]   ex=       15464us timer=ffff830461911070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461911000)
>>      (XEN) [  150.281139] CPU12:
>>      (XEN) [  150.281438]   ex=       17463us timer=ffff830461919070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461919000)
>>      (XEN) [  150.282592] CPU13:
>>      (XEN) [  150.282890]   ex=      347090us timer=ffff830461941070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461941000)
>>      (XEN) [  150.284040] CPU14:
>>      (XEN) [  150.284341]   ex=       20462us timer=ffff83046191d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046191d000)
>>      (XEN) [  150.285496] CPU15:
>>      (XEN) [  150.285806]   ex=         470us timer=ffff83046192d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046192d000)
>>      (XEN) [  150.286972]   ex=       15316us timer=ffff8304619cdaa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff8304619cdae0)
>>      (XEN) [  150.288156]   ex=        6230us timer=ffff8304619e8ed0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
>>      (XEN) [  150.289192] CPU16:
>>      (XEN) [  150.289492]   ex=      633594us timer=ffff830461929070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461929000)
>>      (XEN) [  150.290642] CPU18:
>>      (XEN) [  150.290942]   ex=      614601us timer=ffff830461939070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461939000)
>>      (XEN) [  150.292094] CPU20:
>>      (XEN) [  150.292394]   ex=       27459us timer=ffff830461915070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461915000)
>>      (XEN) [  150.293553]   ex=       55316us timer=ffff830461979aa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff830461979ae0)
>>      (XEN) [  150.294744]   ex=       35413us timer=ffff83046198fdc0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
>>      (XEN) [  150.295776] CPU21:
>>      (XEN) [  150.296076]   ex=      617580us timer=ffff830461925070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461925000)
>>
>> Just after S3:
>>
>>      (XEN) [  164.462198] Dumping timer queues:
>>      (XEN) [  164.462630] CPU00:
>>      (XEN) [  164.462949]   ex=         768us timer=ffff82d040643540 cb=drivers/char/xhci-dbc.c#dbc_uart_poll(ffff82d0404e5e78)
>>      (XEN) [  164.464064]   ex=     1286532us timer=ffff82d04065d220 cb=arch/x86/time.c#plt_overflow(0000000000000000)
>>      (XEN) [  164.465099]   ex=      395997us timer=ffff830461921070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461921000)
>>      (XEN) [  164.466262]   ex=    15327843us timer=ffff82d040644c20 cb=arch/x86/cpu/mcheck/intel-nonfatal.c#mce_work_fn(0000000000000000)
>>      (XEN) [  164.467461] CPU02:
>>      (XEN) [  164.467773]   ex=       37756us timer=ffff830461931070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461931000)
>>      (XEN) [  164.468953] CPU04:
>>      (XEN) [  164.469267]   ex=      940042us timer=ffff830461935070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461935000)
>>      (XEN) [  164.470444] CPU06:
>>      (XEN) [  164.470759]   ex=      485896us timer=ffff830461905070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461905000)
>>      (XEN) [  164.471937] CPU08:
>>      (XEN) [  164.472251]   ex=      459720us timer=ffff83046190d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046190d000)
>>      (XEN) [  164.473430] CPU09:
>>      (XEN) [  164.473745]   ex=     1563081us timer=ffff830461909070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461909000)
>>      (XEN) [  164.474922] CPU10:
>>      (XEN) [  164.475237]   ex=      948204us timer=ffff830461901070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461901000)
>>      (XEN) [  164.476417] CPU11:
>>      (XEN) [  164.476732]   ex=      948071us timer=ffff830461911070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461911000)
>>      (XEN) [  164.477912] CPU12:
>>      (XEN) [  164.478219]   ex=      892163us timer=ffff830461919070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461919000)
>>      (XEN) [  164.479398] CPU13:
>>      (XEN) [  164.479713]   ex=      308429us timer=ffff830461941070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461941000)
>>      (XEN) [  164.480893] CPU14:
>>      (XEN) [  164.481208]   ex=      954493us timer=ffff83046191d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046191d000)
>>      (XEN) [  164.482386] CPU15:
>>      (XEN) [  164.482700]   ex=     1487692us timer=ffff83046192d070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff83046192d000)
>>      (XEN) [  164.483881] CPU16:
>>      (XEN) [  164.484195]   ex=       22890us timer=ffff830461929070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461929000)
>>      (XEN) [  164.485373] CPU18:
>>      (XEN) [  164.485688]   ex=       85902us timer=ffff830461939070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461939000)
>>      (XEN) [  164.486864] CPU20:
>>      (XEN) [  164.487171]   ex=         895us timer=ffff830461915070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461915000)
>>      (XEN) [  164.488358]   ex=       17895us timer=ffff830461979aa0 cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer(ffff830461979ae0)
>>      (XEN) [  164.489569]   ex=        2914us timer=ffff83046198fdc0 cb=common/sched/core.c#s_timer_fn(0000000000000000)
>>      (XEN) [  164.490633] CPU21:
>>      (XEN) [  164.490947]   ex=      461154us timer=ffff830461925070 cb=common/sched/core.c#vcpu_singleshot_timer_fn(ffff830461925000)
>>
>> In the latter case, I see only one cb=common/sched/core.c#s_timer_fn
>> (two of them before). And also only one
>> cb=drivers/cpufreq/cpufreq_ondemand.c#do_dbs_timer.
> 
> Let's start with this one. It's active when the ondemand governor is in use,
> and when a CPU isn't (in the process of being put into) a C-state. There
> being only two instances means the system was reasonably idle at the time you
> dumped the timer queues ahead of entering S3, and just slightly more idle
> after getting back out of S3. I've just checked my Skylake: Without it ever
> having gone through an S3 cycle, there's only one instance there when the
> system is running nothing but an "xl dmesg".
> 
> If you place enough load on the system to keep all CPUs busy, more instances
> of the timer should appear. How many of them it'll be does, however, also
> depend on the scope of the policy (supplied by firmware). The topology ...
> 
>> Is the s_timer_fn related to runqueues? I have two of them:
>>
>>      (XEN) [   11.751480] Adding cpu 0 to runqueue 0
>>      (XEN) [   11.753580]  First cpu on runqueue, activating
>>      (XEN) [   11.755731] Adding cpu 2 to runqueue 0
>>      (XEN) [   11.757818] Adding cpu 4 to runqueue 0
>>      (XEN) [   11.759891] Adding cpu 6 to runqueue 0
>>      (XEN) [   11.761955] Adding cpu 8 to runqueue 0
>>      (XEN) [   11.764001] Adding cpu 9 to runqueue 0
>>      (XEN) [   11.766029] Adding cpu 10 to runqueue 0
>>      (XEN) [   11.768045] Adding cpu 11 to runqueue 0
>>      (XEN) [   11.770050] Adding cpu 12 to runqueue 1
>>      (XEN) [   11.772033]  First cpu on runqueue, activating
>>      (XEN) [   11.774051] Adding cpu 13 to runqueue 1
>>      (XEN) [   11.776047] Adding cpu 14 to runqueue 1
>>      (XEN) [   11.777993] Adding cpu 15 to runqueue 1
>>      (XEN) [   11.779913] Adding cpu 16 to runqueue 1
>>      (XEN) [   11.781872] Adding cpu 18 to runqueue 1
>>      (XEN) [   11.783912] Adding cpu 20 to runqueue 1
>>      (XEN) [   11.785855] Adding cpu 21 to runqueue 1
> 
> ... of this system looks somewhat "interesting", judging from these CPU
> numbers.
> 
> Assuming the system was (supposedly) equally idle before and after S3,
> the absence of the 2nd timer(s?) may indicate that some (background?)
> load that was there before S3 didn't re-appear afterwards. Such
> background load could be something which monitors and tunes the system.
> (Yet as indicated, I'm looking at the CPUfreq part only right now. I'm
> kind of hoping that a scheduler maintainer may look at the other aspect.)

The s_timer_fn() will be active only if a CPU is just running a vcpu. So
it is similar to the do_dbs_timer() in this regard.


Juergen

[-- Attachment #1.1.2: OpenPGP public key --]
[-- Type: application/pgp-keys, Size: 3743 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 495 bytes --]

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

[Marek Marczykowski-Górecki]

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

On Fri, Mar 27, 2026 at 01:47:55PM +0100, Marek Marczykowski-Górecki wrote:
> Some further observation, this time regarding timers:

In the meantime Roger suggested it might be about C-states. So, I just
tried booting with max_cstate=0. I got this:

    [2026-04-02 11:41:57] (XEN) [    4.327519] mwait-idle: disabled

But then xenpm reports C1 is still used:

    # xenpm get-cpuidle-states 
    Max possible C-state: C0

    cpu id               : 0
    total C-states       : 2
    idle time(ms)        : 3727115
    C0                   : transition [                   0]
                           residency  [             3769835 ms]
    C1                   : transition [                   0]
                           residency  [                   0 ms]

    cpu id               : 1
    total C-states       : 2
    idle time(ms)        : 3763654
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769838 ms]

    cpu id               : 2
    total C-states       : 2
    idle time(ms)        : 3729168
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769838 ms]

    cpu id               : 3
    total C-states       : 2
    idle time(ms)        : 3750226
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769840 ms]

    cpu id               : 4
    total C-states       : 2
    idle time(ms)        : 3726369
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769840 ms]

    cpu id               : 5
    total C-states       : 2
    idle time(ms)        : 3755733
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769840 ms]

    cpu id               : 6
    total C-states       : 2
    idle time(ms)        : 3725747
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769841 ms]

    cpu id               : 7
    total C-states       : 2
    idle time(ms)        : 3730190
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769841 ms]

    cpu id               : 8
    total C-states       : 2
    idle time(ms)        : 3716485
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769841 ms]

    cpu id               : 9
    total C-states       : 2
    idle time(ms)        : 3710830
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769842 ms]

    cpu id               : 10
    total C-states       : 2
    idle time(ms)        : 3704881
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769842 ms]

    cpu id               : 11
    total C-states       : 2
    idle time(ms)        : 3719333
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769842 ms]

    cpu id               : 12
    total C-states       : 2
    idle time(ms)        : 3715059
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769842 ms]

    cpu id               : 13
    total C-states       : 2
    idle time(ms)        : 3711681
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769843 ms]

    cpu id               : 14
    total C-states       : 2
    idle time(ms)        : 3709380
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769843 ms]

    cpu id               : 15
    total C-states       : 2
    idle time(ms)        : 3720119
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769843 ms]

    cpu id               : 16
    total C-states       : 2
    idle time(ms)        : 3737637
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769844 ms]

    cpu id               : 17
    total C-states       : 2
    idle time(ms)        : 3737662
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769844 ms]

    cpu id               : 18
    total C-states       : 2
    idle time(ms)        : 3729870
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769844 ms]

    cpu id               : 19
    total C-states       : 2
    idle time(ms)        : 3745564
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769845 ms]

    cpu id               : 20
    total C-states       : 2
    idle time(ms)        : 3717089
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769845 ms]

    cpu id               : 21
    total C-states       : 2
    idle time(ms)        : 3590257
    C0                   : transition [                   1]
                           residency  [                   0 ms]
    C1                   : transition [                   1]
                           residency  [             3769845 ms]

And the issue still happens...

Honestly, I'm confused about the above output. The system is mostly
idle, but I wouldn't expect it to be _that_ idle - there is xenstored +
xenconsoled running, plus occasional xl create for testing with
short-lived domU. Does it really all happen only on CPU0 here?

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

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

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

[Jan Beulich]

On 02.04.2026 15:02, Marek Marczykowski-Górecki wrote:
> On Fri, Mar 27, 2026 at 01:47:55PM +0100, Marek Marczykowski-Górecki wrote:
>> Some further observation, this time regarding timers:
> 
> In the meantime Roger suggested it might be about C-states. So, I just
> tried booting with max_cstate=0. I got this:
> 
>     [2026-04-02 11:41:57] (XEN) [    4.327519] mwait-idle: disabled
> 
> But then xenpm reports C1 is still used:

Of course, that represents use of the HLT insn.

Jan

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

[Marek Marczykowski-Górecki]

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

On Thu, Apr 02, 2026 at 03:02:15PM +0200, Marek Marczykowski-Górecki wrote:
> On Fri, Mar 27, 2026 at 01:47:55PM +0100, Marek Marczykowski-Górecki wrote:
> > Some further observation, this time regarding timers:
> 
> In the meantime Roger suggested it might be about C-states. So, I just
> tried booting with max_cstate=0. I got this:

We had a design session on this issue, and managed to find (thanks Roger!)
that adding:

    tsc_mode='always_emulate'

to the domU config fixes the issue. Now, the question is how to fix it
properly...

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

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

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

[Marek Marczykowski-Górecki]

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

On Fri, Apr 03, 2026 at 03:55:07PM +0200, Marek Marczykowski-Górecki wrote:
> On Thu, Apr 02, 2026 at 03:02:15PM +0200, Marek Marczykowski-Górecki wrote:
> > On Fri, Mar 27, 2026 at 01:47:55PM +0100, Marek Marczykowski-Górecki wrote:
> > > Some further observation, this time regarding timers:
> > 
> > In the meantime Roger suggested it might be about C-states. So, I just
> > tried booting with max_cstate=0. I got this:
> 
> We had a design session on this issue, and managed to find (thanks Roger!)
> that adding:
> 
>     tsc_mode='always_emulate'
> 
> to the domU config fixes the issue. Now, the question is how to fix it
> properly...

I also did another test with NTP inside domU (after host S3):

$ ntpdate -q pool.ntp.org
2026-04-06 00:07:01.559218 (+0200) -0.216281 +/- 0.012486 pool.ntp.org 141.144.241.16 s2 no-leap
$ ntpdate -q pool.ntp.org
2026-04-06 00:57:40.852612 (+0200) -0.255782 +/- 0.013022 pool.ntp.org 185.252.140.125 s2 no-leap
$ ntpdate -q pool.ntp.org
2026-04-06 13:07:57.647126 (+0200) -0.791802 +/- 0.056578 pool.ntp.org 185.248.188.98 s1 no-leap
$ ntpdate -q pool.ntp.org
2026-04-06 13:08:01.844118 (+0200) -0.832599 +/- 0.012563 pool.ntp.org 185.248.188.98 s1 no-leap
$ ntpdate -q 141.144.241.16
2026-04-06 13:08:47.835271 (+0200) -0.819725 +/- 0.028655 141.144.241.16 s2 no-leap
$ ntpdate -q 141.144.241.16
2026-04-06 13:08:51.290526 (+0200) -0.833668 +/- 0.015501 141.144.241.16 s2 no-leap
$ ntpdate -q 141.144.241.16
2026-04-06 13:08:56.136567 (+0200) -0.832294 +/- 0.014493 141.144.241.16 s2 no-leap
$ ntpdate -q 141.144.241.16
2026-04-06 17:21:41.017554 (+0200) -1.044511 +/- 0.021817 141.144.241.16 s2 no-leap

So, domU's clock definitely drifts.

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

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

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

[Jan Beulich]

On 03.04.2026 15:55, Marek Marczykowski-Górecki wrote:
> On Thu, Apr 02, 2026 at 03:02:15PM +0200, Marek Marczykowski-Górecki wrote:
>> On Fri, Mar 27, 2026 at 01:47:55PM +0100, Marek Marczykowski-Górecki wrote:
>>> Some further observation, this time regarding timers:
>>
>> In the meantime Roger suggested it might be about C-states. So, I just
>> tried booting with max_cstate=0. I got this:
> 
> We had a design session on this issue, and managed to find (thanks Roger!)
> that adding:
> 
>     tsc_mode='always_emulate'
> 
> to the domU config fixes the issue. Now, the question is how to fix it
> properly...

Seeing also the remarks on Matrix, what we will hence need to figure is what
TSC parameters (of the system and/or the VM) change across suspend. As per
Matrix everything looked at so far was apparently stable.

Jan

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

[Marek Marczykowski-Górecki]

[-- Attachment #1.1: Type: text/plain, Size: 2354 bytes --]

On Tue, Apr 07, 2026 at 08:14:42AM +0200, Jan Beulich wrote:
> On 03.04.2026 15:55, Marek Marczykowski-Górecki wrote:
> > On Thu, Apr 02, 2026 at 03:02:15PM +0200, Marek Marczykowski-Górecki wrote:
> >> On Fri, Mar 27, 2026 at 01:47:55PM +0100, Marek Marczykowski-Górecki wrote:
> >>> Some further observation, this time regarding timers:
> >>
> >> In the meantime Roger suggested it might be about C-states. So, I just
> >> tried booting with max_cstate=0. I got this:
> > 
> > We had a design session on this issue, and managed to find (thanks Roger!)
> > that adding:
> > 
> >     tsc_mode='always_emulate'
> > 
> > to the domU config fixes the issue. Now, the question is how to fix it
> > properly...
> 
> Seeing also the remarks on Matrix, what we will hence need to figure is what
> TSC parameters (of the system and/or the VM) change across suspend. As per
> Matrix everything looked at so far was apparently stable.

I added some more logging (based on 
https://sandpile.org/x86/msr.htm | grep TSC) - see attached debug patch.
The output before and after S3:

    ==> msr-before.txt <==
    (XEN) [  118.910886] MSR 00000010: 000000cd6d18d6c1
    (XEN) [  118.911110] MSR 0000003b: 0000000000000000
    (XEN) [  118.911331] MSR c0000103: 0000000000000000
    (XEN) [  118.911559] Fixup #GP[0000]: ffff82d04029ad8d [arch/x86/cpu/intel.c#debug_tsc+0x76/0x84] -> ffff82d04029ad83
    (XEN) [  118.912029] MSR 000006e0: 0000000000000000
    (XEN) [  118.912253] MSR 000000e7: 000000064cf8ec5e
    (XEN) [  118.912473] MSR 000000e8: 000000065d09c019
    (XEN) [  118.912687] MSR 0000064e: 000000052ec83116


    ==> msr-after.txt <==
    (XEN) [  146.396099] MSR 00000010: 00000012fac68ccd
    (XEN) [  146.396329] MSR 0000003b: 0000000000000000
    (XEN) [  146.396553] MSR c0000103: 0000000000000000
    (XEN) [  146.396777] Fixup #GP[0000]: ffff82d04029ad8d [arch/x86/cpu/intel.c#debug_tsc+0x76/0x84] -> ffff82d04029ad83
    (XEN) [  146.397248] MSR 000006e0: 0000000000000000
    (XEN) [  146.397470] MSR 000000e7: 00000001e41a578a
    (XEN) [  146.397690] MSR 000000e8: 000000017dc5b211
    (XEN) [  146.397909] MSR 0000064e: 000000014eddbe8f

Nothing interesting here...

What other values would make sense to compare?

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

[-- Attachment #1.2: 0001-DEBUG-TSC.patch --]
[-- Type: text/plain, Size: 1697 bytes --]

From 2d1bd9c15e605136c7817fe824a7c429cbfb137d Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Marek=20Marczykowski-G=C3=B3recki?=
 <marmarek@invisiblethingslab.com>
Date: Tue, 7 Apr 2026 13:55:41 +0200
Subject: [PATCH] DEBUG TSC

---
 xen/arch/x86/cpu/intel.c | 28 ++++++++++++++++++++++++++++
 1 file changed, 28 insertions(+)

diff --git a/xen/arch/x86/cpu/intel.c b/xen/arch/x86/cpu/intel.c
index 51a3d1c4b5f3..846c6a704a3f 100644
--- a/xen/arch/x86/cpu/intel.c
+++ b/xen/arch/x86/cpu/intel.c
@@ -4,6 +4,7 @@
 #include <xen/sched.h>
 #include <xen/smp.h>
 #include <xen/string.h>
+#include <xen/keyhandler.h>
 
 #include <asm/apic.h>
 #include <asm/i387.h>
@@ -675,3 +676,30 @@ void __init intel_init_arat(void)
     if ( opt_arat && cpu_has_arat )
         setup_force_cpu_cap(X86_FEATURE_XEN_ARAT);
 }
+
+static void cf_check debug_tsc(unsigned char key)
+{
+    uint64_t val;
+    int msr_idx[] = { 0x10,         // TSC
+                      0x3b,         // TSC_ADJUST
+                      0xc0000103,   // TSC_AUX
+                      0xc0000104,   // TSC_RATIO
+                      0x06e0,       // TSC_DEADLINE
+                      0xe7,         // MPERF
+                      0xe8,         // APERF
+                      0x64e,        // PPERF
+                      0 };
+
+    for ( int i = 0; msr_idx[i]; i++ )
+    {
+        if ( !rdmsr_safe(msr_idx[i], &val) )
+            printk("MSR %08x: %016lx\n", msr_idx[i], val);
+    }
+}
+
+static int __init cf_check register_debug_tsc(void)
+{
+    register_keyhandler('1', debug_tsc, "Extra TSC debug", false);
+    return 0;
+}
+__initcall(register_debug_tsc);
-- 
2.53.0


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