Re: Recent upgrade of 4.13 -> 4.14 issue

Re: Recent upgrade of 4.13 -> 4.14 issue

[Liwei]

Hi list,
    This is a reply to the thread of the same title (linked here:
https://www.mail-archive.com/xen-devel@lists.xenproject.org/msg84916.html
) which I could not reply to because I receive this list by digest.

    I'm unclear if this is exactly the reason, but I experienced the
same symptoms when upgrading to 4.14. The issue does not occur if I
downgrade to 4.11 (the previous version that was provided by Debian).
Kernel is 5.9.11 and unchanged between xen versions.

    One thing I noticed is that if I disable the monitor/mwait
instructions on my CPU (Intel Xeon E5-2699 v4 ES), the stalls seem to
occur later into the boot. With the instructions enabled, the system
usually stalls less than a few minutes after boot; disabled, it can
last for tens of minutes.

    Further disabling the HPET or forcing the kernel to use PIT causes
it to be somewhat usable. The stalls still occur tens of minutes in
but somehow everything seems to continue chugging along fine?

    I've also verified that the stalls do not occur in all the above
cases if I just boot into the kernel without xen.

    When the stalls happen, I get the "rcu: INFO: rcu_sched detected
stalls on CPUs/tasks" backtraces printed on the console periodically,
but keystrokes don't do anything on the console, and I can't spawn new
SSH sessions even though pinging the system produces a reply. The last
item in the call trace is usually "xen_safe_halt", but I've seen it
occur for other functions related to btrfs and the network adapter as
well.

    Do let me know if there's anything I can provide to help
troubleshoot this. At the moment I've reverted to 4.11, but I can
temporarily switch over to 4.14 to collect any necessary information.

Liwei

Re: Recent upgrade of 4.13 -> 4.14 issue

[Jan Beulich]

On 15.12.2020 20:08, Liwei wrote:
> Hi list,
>     This is a reply to the thread of the same title (linked here:
> https://www.mail-archive.com/xen-devel@lists.xenproject.org/msg84916.html
> ) which I could not reply to because I receive this list by digest.
> 
>     I'm unclear if this is exactly the reason, but I experienced the
> same symptoms when upgrading to 4.14. The issue does not occur if I
> downgrade to 4.11 (the previous version that was provided by Debian).
> Kernel is 5.9.11 and unchanged between xen versions.
> 
>     One thing I noticed is that if I disable the monitor/mwait
> instructions on my CPU (Intel Xeon E5-2699 v4 ES), the stalls seem to
> occur later into the boot. With the instructions enabled, the system
> usually stalls less than a few minutes after boot; disabled, it can
> last for tens of minutes.
> 
>     Further disabling the HPET or forcing the kernel to use PIT causes
> it to be somewhat usable. The stalls still occur tens of minutes in
> but somehow everything seems to continue chugging along fine?

By "the kernel" do you really mean the kernel, or Xen?

>     I've also verified that the stalls do not occur in all the above
> cases if I just boot into the kernel without xen.
> 
>     When the stalls happen, I get the "rcu: INFO: rcu_sched detected
> stalls on CPUs/tasks" backtraces printed on the console periodically,
> but keystrokes don't do anything on the console, and I can't spawn new
> SSH sessions even though pinging the system produces a reply. The last
> item in the call trace is usually "xen_safe_halt", but I've seen it
> occur for other functions related to btrfs and the network adapter as
> well.

The kernel log may not be the only relevant thing here - the hypervisor
log may also need looking at (with full verbosity enabled and
preferably a debug build in use).

>     Do let me know if there's anything I can provide to help
> troubleshoot this. At the moment I've reverted to 4.11, but I can
> temporarily switch over to 4.14 to collect any necessary information.

In that earlier thread a number of things to try were suggested, iirc
(switching scheduler or disabling use of deep C states come to mind).
Did you experiment with those? If so, can you let us know of the
results, so we can see whether there's a pattern?

Jan

Re: Recent upgrade of 4.13 -> 4.14 issue

[Liwei]

Hi Jan,
    Response inline...

Liwei

On Wed, 16 Dec 2020 at 16:12, Jan Beulich <jbeulich@suse.com> wrote:
>
> On 15.12.2020 20:08, Liwei wrote:
> > Hi list,
> >     This is a reply to the thread of the same title (linked here:
> > https://www.mail-archive.com/xen-devel@lists.xenproject.org/msg84916.html
> > ) which I could not reply to because I receive this list by digest.
> >
> >     I'm unclear if this is exactly the reason, but I experienced the
> > same symptoms when upgrading to 4.14. The issue does not occur if I
> > downgrade to 4.11 (the previous version that was provided by Debian).
> > Kernel is 5.9.11 and unchanged between xen versions.
> >
> >     One thing I noticed is that if I disable the monitor/mwait
> > instructions on my CPU (Intel Xeon E5-2699 v4 ES), the stalls seem to
> > occur later into the boot. With the instructions enabled, the system
> > usually stalls less than a few minutes after boot; disabled, it can
> > last for tens of minutes.
> >
> >     Further disabling the HPET or forcing the kernel to use PIT causes
> > it to be somewhat usable. The stalls still occur tens of minutes in
> > but somehow everything seems to continue chugging along fine?
>
> By "the kernel" do you really mean the kernel, or Xen?

Sorry, I mean xen. Too used to thinking that xen isn't there when I'm
talking about dom0.

>
> >     I've also verified that the stalls do not occur in all the above
> > cases if I just boot into the kernel without xen.
> >
> >     When the stalls happen, I get the "rcu: INFO: rcu_sched detected
> > stalls on CPUs/tasks" backtraces printed on the console periodically,
> > but keystrokes don't do anything on the console, and I can't spawn new
> > SSH sessions even though pinging the system produces a reply. The last
> > item in the call trace is usually "xen_safe_halt", but I've seen it
> > occur for other functions related to btrfs and the network adapter as
> > well.
>
> The kernel log may not be the only relevant thing here - the hypervisor
> log may also need looking at (with full verbosity enabled and
> preferably a debug build in use).

I will build a debug version and get back to you on that. Do I just
have loglvl and guest_loglvl set to full, console to ring, and get the
entire serial spew? I recall that you wanted to see the I, q and r
outputs as well.

>
> >     Do let me know if there's anything I can provide to help
> > troubleshoot this. At the moment I've reverted to 4.11, but I can
> > temporarily switch over to 4.14 to collect any necessary information.
>
> In that earlier thread a number of things to try were suggested, iirc
> (switching scheduler or disabling use of deep C states come to mind).
> Did you experiment with those? If so, can you let us know of the
> results, so we can see whether there's a pattern?

1. Switching to credit didn't seem to make any difference in my case
2. I have tried with cpuidle=off and max_cstate=1, and it actually
provides the same result as when I have mwait/monitor & hpet turned
off (even when I leave mwait & hpet on in BIOS)
3. I could not try with dom0=PVH as my system reboots after(or while?)
the kernel is loaded/ing when I do that

I do realise, after working with the cpuidle=off and max_cstate=1
combination for a day, the system is actually limping. Most of the
visible issues seem to stem from storage hanging or responding very
slowly, but it might be due to the btrfs tasks hanging in the
background.

>
> Jan

Re: Recent upgrade of 4.13 -> 4.14 issue

[Jan Beulich]

On 16.12.2020 13:19, Liwei wrote:
> On Wed, 16 Dec 2020 at 16:12, Jan Beulich <jbeulich@suse.com> wrote:
>> On 15.12.2020 20:08, Liwei wrote:
>>> Hi list,
>>>     This is a reply to the thread of the same title (linked here:
>>> https://www.mail-archive.com/xen-devel@lists.xenproject.org/msg84916.html
>>> ) which I could not reply to because I receive this list by digest.
>>>
>>>     I'm unclear if this is exactly the reason, but I experienced the
>>> same symptoms when upgrading to 4.14. The issue does not occur if I
>>> downgrade to 4.11 (the previous version that was provided by Debian).
>>> Kernel is 5.9.11 and unchanged between xen versions.
>>>
>>>     One thing I noticed is that if I disable the monitor/mwait
>>> instructions on my CPU (Intel Xeon E5-2699 v4 ES), the stalls seem to
>>> occur later into the boot. With the instructions enabled, the system
>>> usually stalls less than a few minutes after boot; disabled, it can
>>> last for tens of minutes.
>>>
>>>     Further disabling the HPET or forcing the kernel to use PIT causes
>>> it to be somewhat usable. The stalls still occur tens of minutes in
>>> but somehow everything seems to continue chugging along fine?
>>
>> By "the kernel" do you really mean the kernel, or Xen?
> 
> Sorry, I mean xen. Too used to thinking that xen isn't there when I'm
> talking about dom0.
> 
>>
>>>     I've also verified that the stalls do not occur in all the above
>>> cases if I just boot into the kernel without xen.
>>>
>>>     When the stalls happen, I get the "rcu: INFO: rcu_sched detected
>>> stalls on CPUs/tasks" backtraces printed on the console periodically,
>>> but keystrokes don't do anything on the console, and I can't spawn new
>>> SSH sessions even though pinging the system produces a reply. The last
>>> item in the call trace is usually "xen_safe_halt", but I've seen it
>>> occur for other functions related to btrfs and the network adapter as
>>> well.
>>
>> The kernel log may not be the only relevant thing here - the hypervisor
>> log may also need looking at (with full verbosity enabled and
>> preferably a debug build in use).
> 
> I will build a debug version and get back to you on that. Do I just
> have loglvl and guest_loglvl set to full, console to ring, and get the
> entire serial spew? I recall that you wanted to see the I, q and r
> outputs as well.

Yes. The debug keys are kind of optional at a first step, but it won't
hurt if you include them unless your box is a really big one.

Jan

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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

Le 11/3/20 à 3:15 PM, Dario Faggioli a écrit :
> On Tue, 2020-11-03 at 14:23 +0100, Frédéric Pierret wrote:
>> Hi,
>>
> Hi,
> 
>> Some new info :). Marek has sent me a patch (
>> https://gist.github.com/marmarek/810ae5c079d218928535514b08a07716) to
>> help in debugging this issue.
>>
> Ok, thanks for the update (and thanks Mark for putthing together the
> patch).
> 
>> With default credit2 as scheduler, here are some log from two
>> successive crashes:
>> - https://gist.github.com/fepitre/76a1e154249c7326c743d6a6d004a67b
>> - https://gist.github.com/fepitre/ab00091980cb8110fb3d349aecc3a644
>>
> Right, this is what you see when you poke at the debug keys, after a
> freeze. It would be interesting to see if there is any trace of the
> debug output added in the patch _before_ the crash... But I appreciate
> that it's not really easy to achieve this.

I'll try to find this info in the next days.

>> Also, I've been testing "dom0=pvh" option and the system remains
>> stable since more than 24h. At least, I've not experimented any
>> freeze since I'm using this option.
>>
> PVH and what scheduler?

PVH and Credit2.

> I think it's quite clear that this is not a Credit2 bug, as it shows on
> Credit1 as well, but AFAIUI, with Credit2 it shows up more often?
> 
> Now we also have a (weak?) dependency on the type of dom0?

It seems so.

> What's the configuration that is currently working?
> Credit2 +PVH ?
> Credit1 + PVH ?
> Whatever + PVH ?

The only differences between Credit1 and 2 was that Credit2 was generating freezes faster than Credit1. Here is the output of `xl info` of the current "stable" running config:

"""
[admin@dom0 ~]$ xl info
host                   : dom0
release                : 5.4.72-2.qubes.x86_64
version                : #1 SMP Sun Oct 18 16:17:06 CEST 2020
machine                : x86_64
nr_cpus                : 16
max_cpu_id             : 63
nr_nodes               : 2
cores_per_socket       : 8
threads_per_core       : 1
cpu_mhz                : 2593.766
hw_caps                : bfebfbff:17bee3ff:2c100800:00000001:00000001:00000000:00000000:00000100
virt_caps              : pv hvm hvm_directio pv_directio hap
total_memory           : 163805
free_memory            : 11077
sharing_freed_memory   : 0
sharing_used_memory    : 0
outstanding_claims     : 0
free_cpus              : 0
xen_major              : 4
xen_minor              : 14
xen_extra              : .0
xen_version            : 4.14.0
xen_caps               : xen-3.0-x86_64 hvm-3.0-x86_32 hvm-3.0-x86_32p hvm-3.0-x86_64
xen_scheduler          : credit2
xen_pagesize           : 4096
platform_params        : virt_start=0xffff800000000000
xen_changeset          :
xen_commandline        : placeholder console=com2 dom0_mem=min:1024M dom0_mem=max:8192M iommu=no-igfx ucode=scan smt=off gnttab_max_frames=2048 gnttab_max_maptrack_frames=4096 loglvl=all guest_loglvl=all dom0=pvh
cc_compiler            : gcc (GCC) 10.2.1 20201016 (Red Hat 10.2.1-6)
cc_compile_by          : user
cc_compile_domain      : [unknown]
cc_compile_date        : Sat Oct 31 16:02:25 UTC 2020
build_id               : 0bbdc8aa6f34a2b27c3ac9842741bc022269f9ee
xend_config_format     : 4
"""

> Regards
> 

Regards,
Frédéric

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Dario Faggioli]

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

On Tue, 2020-11-03 at 14:23 +0100, Frédéric Pierret wrote:
> Hi,
>
Hi,

> Some new info :). Marek has sent me a patch ( 
> https://gist.github.com/marmarek/810ae5c079d218928535514b08a07716) to
> help in debugging this issue. 
>
Ok, thanks for the update (and thanks Mark for putthing together the
patch).

> With default credit2 as scheduler, here are some log from two
> successive crashes:
> - https://gist.github.com/fepitre/76a1e154249c7326c743d6a6d004a67b
> - https://gist.github.com/fepitre/ab00091980cb8110fb3d349aecc3a644
> 
Right, this is what you see when you poke at the debug keys, after a
freeze. It would be interesting to see if there is any trace of the
debug output added in the patch _before_ the crash... But I appreciate
that it's not really easy to achieve this.

> Also, I've been testing "dom0=pvh" option and the system remains
> stable since more than 24h. At least, I've not experimented any
> freeze since I'm using this option.
> 
PVH and what scheduler?

I think it's quite clear that this is not a Credit2 bug, as it shows on
Credit1 as well, but AFAIUI, with Credit2 it shows up more often?

Now we also have a (weak?) dependency on the type of dom0?

What's the configuration that is currently working?
Credit2 +PVH ?
Credit1 + PVH ?
Whatever + PVH ?

Regards
-- 
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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



Le 10/31/20 à 5:08 AM, marmarek@invisiblethingslab.com a écrit :
> On Sat, Oct 31, 2020 at 04:27:58AM +0100, Dario Faggioli wrote:
>> On Sat, 2020-10-31 at 03:54 +0100, marmarek@invisiblethingslab.com
>> wrote:
>>> On Sat, Oct 31, 2020 at 02:34:32AM +0000, Dario Faggioli wrote:
>>> (XEN) *** Dumping CPU7 host state: ***
>>> (XEN) Xen call trace:
>>> (XEN)    [<ffff82d040223625>] R _spin_lock+0x35/0x40
>>> (XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
>>> (XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
>>> (XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
>>> (XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
>>> (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
>>> (XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30
>>>
>>> And so on, for (almost?) all CPUs.
>>
>> Right. So, it seems like a live (I would say) lock. It might happen on
>> some resource which his shared among domains. And introduced (the
>> livelock, not the resource or the sharing) in 4.14.
>>
>> Just giving a quick look, I see that vmx_do_resume() calls
>> vmx_clear_vmcs() which calls on_selected_cpus() which takes the
>> call_lock spinlock.
>>
>> And none of these seems to have received much attention recently.
>>
>> But this is just a really basic analysis!
> 
> I've looked at on_selected_cpus() and my understanding is this:
> 1. take call_lock spinlock
> 2. set function+args+what cpus to be called in a global "call_data" variable
> 3. ask CPUs to execute that function (smp_send_call_function_mask() call)
> 4. wait for all requested CPUs to execute the function, still holding
> the spinlock
> 5. only then - release the spinlock
> 
> So, if any CPU does not execute requested function for any reason, it
> will keep the call_lock locked forever.
> 
> I don't see any CPU waiting on step 4, but also I don't see call traces
> from CPU3 and CPU8 in the log - that's because they are in guest (dom0
> here) context, right? I do see "guest state" dumps from them.
> The only three CPUs that do logged xen call traces and are not waiting on that
> spin lock are:
> 
> CPU0:
> (XEN) Xen call trace:
> (XEN)    [<ffff82d040240f89>] R vcpu_unblock+0x9/0x50
> (XEN)    [<ffff82d0402e0171>] S vcpu_kick+0x11/0x60
> (XEN)    [<ffff82d0402259c8>] S tasklet.c#do_tasklet_work+0x68/0xc0
> (XEN)    [<ffff82d040225a59>] S tasklet.c#tasklet_softirq_action+0x39/0x60
> (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
> (XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30
> 
> CPU4:
> (XEN) Xen call trace:
> (XEN)    [<ffff82d040227043>] R set_timer+0x133/0x220
> (XEN)    [<ffff82d040234e90>] S credit.c#csched_tick+0/0x3a0
> (XEN)    [<ffff82d04022660f>] S timer.c#timer_softirq_action+0x9f/0x300
> (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
> (XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20
> 
> CPU14:
> (XEN) Xen call trace:
> (XEN)    [<ffff82d040222dc0>] R do_softirq+0/0x10
> (XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20
> 
> I'm not sure if any of those is related to that spin lock,
> on_selected_cpus() call, or anything like that...
> 

Hi,
Some new info :). Marek has sent me a patch (https://gist.github.com/marmarek/810ae5c079d218928535514b08a07716) to help in debugging this issue. With default credit2 as scheduler, here are some log from two successive crashes:
- https://gist.github.com/fepitre/76a1e154249c7326c743d6a6d004a67b
- https://gist.github.com/fepitre/ab00091980cb8110fb3d349aecc3a644

Also, I've been testing "dom0=pvh" option and the system remains stable since more than 24h. At least, I've not experimented any freeze since I'm using this option.

I hope that would give some hints.

Regards,
Frédéric

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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



Le 10/31/20 à 5:08 AM, marmarek@invisiblethingslab.com a écrit :
> On Sat, Oct 31, 2020 at 04:27:58AM +0100, Dario Faggioli wrote:
>> On Sat, 2020-10-31 at 03:54 +0100, marmarek@invisiblethingslab.com
>> wrote:
>>> On Sat, Oct 31, 2020 at 02:34:32AM +0000, Dario Faggioli wrote:
>>> (XEN) *** Dumping CPU7 host state: ***
>>> (XEN) Xen call trace:
>>> (XEN)    [<ffff82d040223625>] R _spin_lock+0x35/0x40
>>> (XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
>>> (XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
>>> (XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
>>> (XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
>>> (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
>>> (XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30
>>>
>>> And so on, for (almost?) all CPUs.
>>
>> Right. So, it seems like a live (I would say) lock. It might happen on
>> some resource which his shared among domains. And introduced (the
>> livelock, not the resource or the sharing) in 4.14.
>>
>> Just giving a quick look, I see that vmx_do_resume() calls
>> vmx_clear_vmcs() which calls on_selected_cpus() which takes the
>> call_lock spinlock.
>>
>> And none of these seems to have received much attention recently.
>>
>> But this is just a really basic analysis!
> 
> I've looked at on_selected_cpus() and my understanding is this:
> 1. take call_lock spinlock
> 2. set function+args+what cpus to be called in a global "call_data" variable
> 3. ask CPUs to execute that function (smp_send_call_function_mask() call)
> 4. wait for all requested CPUs to execute the function, still holding
> the spinlock
> 5. only then - release the spinlock
> 
> So, if any CPU does not execute requested function for any reason, it
> will keep the call_lock locked forever.
> 
> I don't see any CPU waiting on step 4, but also I don't see call traces
> from CPU3 and CPU8 in the log - that's because they are in guest (dom0
> here) context, right? I do see "guest state" dumps from them.
> The only three CPUs that do logged xen call traces and are not waiting on that
> spin lock are:
> 
> CPU0:
> (XEN) Xen call trace:
> (XEN)    [<ffff82d040240f89>] R vcpu_unblock+0x9/0x50
> (XEN)    [<ffff82d0402e0171>] S vcpu_kick+0x11/0x60
> (XEN)    [<ffff82d0402259c8>] S tasklet.c#do_tasklet_work+0x68/0xc0
> (XEN)    [<ffff82d040225a59>] S tasklet.c#tasklet_softirq_action+0x39/0x60
> (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
> (XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30
> 
> CPU4:
> (XEN) Xen call trace:
> (XEN)    [<ffff82d040227043>] R set_timer+0x133/0x220
> (XEN)    [<ffff82d040234e90>] S credit.c#csched_tick+0/0x3a0
> (XEN)    [<ffff82d04022660f>] S timer.c#timer_softirq_action+0x9f/0x300
> (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
> (XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20
> 
> CPU14:
> (XEN) Xen call trace:
> (XEN)    [<ffff82d040222dc0>] R do_softirq+0/0x10
> (XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20
> 
> I'm not sure if any of those is related to that spin lock,
> on_selected_cpus() call, or anything like that...
> 

Hi,
Some newer logs here: https://gist.github.com/fepitre/5b2da8cf2ef976c0b885ce7bcfbf7313

You can have piece of serial console at hang freeze then debug keys 'd' and '0' blocked at one VCPU.

I hope that will help.

Regards,
Frédéric

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[marmarek]

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

On Sat, Oct 31, 2020 at 04:27:58AM +0100, Dario Faggioli wrote:
> On Sat, 2020-10-31 at 03:54 +0100, marmarek@invisiblethingslab.com
> wrote:
> > On Sat, Oct 31, 2020 at 02:34:32AM +0000, Dario Faggioli wrote:
> > (XEN) *** Dumping CPU7 host state: ***
> > (XEN) Xen call trace:
> > (XEN)    [<ffff82d040223625>] R _spin_lock+0x35/0x40
> > (XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
> > (XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
> > (XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
> > (XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
> > (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
> > (XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30
> > 
> > And so on, for (almost?) all CPUs.
>
> Right. So, it seems like a live (I would say) lock. It might happen on
> some resource which his shared among domains. And introduced (the
> livelock, not the resource or the sharing) in 4.14.
> 
> Just giving a quick look, I see that vmx_do_resume() calls
> vmx_clear_vmcs() which calls on_selected_cpus() which takes the
> call_lock spinlock.
> 
> And none of these seems to have received much attention recently.
> 
> But this is just a really basic analysis!

I've looked at on_selected_cpus() and my understanding is this:
1. take call_lock spinlock
2. set function+args+what cpus to be called in a global "call_data" variable
3. ask CPUs to execute that function (smp_send_call_function_mask() call)
4. wait for all requested CPUs to execute the function, still holding
the spinlock
5. only then - release the spinlock

So, if any CPU does not execute requested function for any reason, it
will keep the call_lock locked forever.

I don't see any CPU waiting on step 4, but also I don't see call traces
from CPU3 and CPU8 in the log - that's because they are in guest (dom0
here) context, right? I do see "guest state" dumps from them.
The only three CPUs that do logged xen call traces and are not waiting on that
spin lock are:

CPU0:
(XEN) Xen call trace:
(XEN)    [<ffff82d040240f89>] R vcpu_unblock+0x9/0x50
(XEN)    [<ffff82d0402e0171>] S vcpu_kick+0x11/0x60
(XEN)    [<ffff82d0402259c8>] S tasklet.c#do_tasklet_work+0x68/0xc0
(XEN)    [<ffff82d040225a59>] S tasklet.c#tasklet_softirq_action+0x39/0x60
(XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
(XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30

CPU4:
(XEN) Xen call trace:
(XEN)    [<ffff82d040227043>] R set_timer+0x133/0x220
(XEN)    [<ffff82d040234e90>] S credit.c#csched_tick+0/0x3a0
(XEN)    [<ffff82d04022660f>] S timer.c#timer_softirq_action+0x9f/0x300
(XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
(XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20

CPU14:
(XEN) Xen call trace:
(XEN)    [<ffff82d040222dc0>] R do_softirq+0/0x10
(XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20

I'm not sure if any of those is related to that spin lock,
on_selected_cpus() call, or anything like that...

-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Dario Faggioli]

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

On Sat, 2020-10-31 at 03:54 +0100, marmarek@invisiblethingslab.com
wrote:
> On Sat, Oct 31, 2020 at 02:34:32AM +0000, Dario Faggioli wrote:
> (XEN) *** Dumping CPU7 host state: ***
> (XEN) Xen call trace:
> (XEN)    [<ffff82d040223625>] R _spin_lock+0x35/0x40
> (XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
> (XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
> (XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
> (XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
> (XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
> (XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30
> 
> And so on, for (almost?) all CPUs.
> 
Yes, you're right.

So, I indeed saw the spin_lock() calls, but I somehow thought I had
seen them in the in the guests' contextes (for which, we probably don't
even print the callstak! :-O). Instead they're there in the host ones.

Sorry for the oversight.

> Note the '*' output is (I think) from a different instances of the
> freeze, so cannot be correlated with other outputs...
> 
> > Maybe they're stuck in the kernel, not in Xen? Thoughs ?
> 
> Given the above spin locks, I don't think so. But also, even if they
> are
> stuck in the kernel, it clearly happened after 4.13 -> 4.14
> upgrade...
> 
Right. So, it seems like a live (I would say) lock. It might happen on
some resource which his shared among domains. And introduced (the
livelock, not the resource or the sharing) in 4.14.

Just giving a quick look, I see that vmx_do_resume() calls
vmx_clear_vmcs() which calls on_selected_cpus() which takes the
call_lock spinlock.

And none of these seems to have received much attention recently.

But this is just a really basic analysis!

Regards
-- 
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Recent upgrade of 4.13 -> 4.14 issue

[marmarek]

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

On Sat, Oct 31, 2020 at 02:34:32AM +0000, Dario Faggioli wrote:
> On Tue, 2020-10-27 at 17:06 +0100, Frédéric Pierret wrote:
> > 
> > Ok the server got frozen just few minutes after my mail and I got
> > now:
> > 'r': https://gist.github.com/fepitre/78541f555902275d906d627de2420571
> >
> From the scheduler point of view, things seems fine:
> 
> (XEN) sched_smt_power_savings: disabled
> (XEN) NOW=770188952085
> (XEN) Online Cpus: 0-15
> (XEN) Cpupool 0:
> (XEN) Cpus: 0-15
> (XEN) Scheduling granularity: cpu, 1 CPU per sched-resource
> (XEN) Scheduler: SMP Credit Scheduler rev2 (credit2)
> (XEN) Active queues: 2
> (XEN) 	default-weight     = 256
> (XEN) Runqueue 0:
> (XEN) 	ncpus              = 8
> (XEN) 	cpus               = 0-7
> (XEN) 	max_weight         = 256
> (XEN) 	pick_bias          = 1
> (XEN) 	instload           = 7
> (XEN) 	aveload            = 2021119 (~770%)
> (XEN) 	idlers: 00000000,00000000
> (XEN) 	tickled: 00000000,00000000
> (XEN) 	fully idle cores: 00000000,00000000
> (XEN) Runqueue 1:
> (XEN) 	ncpus              = 8
> (XEN) 	cpus               = 8-15
> (XEN) 	max_weight         = 256
> (XEN) 	pick_bias          = 9
> (XEN) 	instload           = 8
> (XEN) 	aveload            = 2097259 (~800%)
> (XEN) 	idlers: 00000000,00000000
> (XEN) 	tickled: 00000000,00000200
> (XEN) 	fully idle cores: 00000000,00000000
> 
> The system is pretty busy, but not in overload.
> 
> Below we see that CPU 3 is running the idle vCPU, but it's not marked
> as neither idle nor tickled.
> 
> It may be running a tasklet (the one that dumps the debug key output, I
> guess).
> 
> Credits are fine, I don't see any strange values that may indicate
> anomalies or something.
> 
> All the CPUs are executing a vCPU, and there should be nothing that
> prevent them making progresses.
> 
> There is one vCPU which apparetnly want to run at 100% in pretty much
> all guests, and more than one in dom0.
> 
> And I think I saw some spin_lock() in the call stacks, in the partial
> report of '*' debug-key?

Yes, I see:

(XEN) *** Dumping CPU1 host state: ***
(...)
(XEN) Xen call trace:
(XEN)    [<ffff82d040223625>] R _spin_lock+0x35/0x40
(XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
(XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
(XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
(XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
(XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
(XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20
(...)
(XEN) *** Dumping CPU2 host state: ***
(XEN) Xen call trace:
(XEN)    [<ffff82d040223622>] R _spin_lock+0x32/0x40
(XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
(XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
(XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
(XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
(XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
(XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30

(XEN) *** Dumping CPU5 host state: ***
(XEN) Xen call trace:
(XEN)    [<ffff82d040223622>] R _spin_lock+0x32/0x40
(XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
(XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
(XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
(XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
(XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
(XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30

(XEN) *** Dumping CPU6 host state: ***
(XEN) Xen call trace:
(XEN)    [<ffff82d040223625>] R _spin_lock+0x35/0x40
(XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
(XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
(XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
(XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
(XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
(XEN)    [<ffff82d0402d64e6>] S x86_64/entry.S#process_softirqs+0x6/0x20

(XEN) *** Dumping CPU7 host state: ***
(XEN) Xen call trace:
(XEN)    [<ffff82d040223625>] R _spin_lock+0x35/0x40
(XEN)    [<ffff82d0402233cd>] S on_selected_cpus+0x1d/0xc0
(XEN)    [<ffff82d040284aba>] S vmx_do_resume+0xba/0x1b0
(XEN)    [<ffff82d0402df160>] S context_switch+0x110/0xa60
(XEN)    [<ffff82d04024310a>] S core.c#schedule+0x1aa/0x250
(XEN)    [<ffff82d040222d4a>] S softirq.c#__do_softirq+0x5a/0xa0
(XEN)    [<ffff82d040291b6b>] S vmx_asm_do_vmentry+0x2b/0x30

And so on, for (almost?) all CPUs.

Note the '*' output is (I think) from a different instances of the
freeze, so cannot be correlated with other outputs...

> Maybe they're stuck in the kernel, not in Xen? Thoughs ?

Given the above spin locks, I don't think so. But also, even if they are
stuck in the kernel, it clearly happened after 4.13 -> 4.14 upgrade...

> (XEN) Domain info:
> (XEN) 	Domain: 0 w 256 c 0 v 16
> (XEN) 	  1: [0.0] flags=0 cpu=5 credit=10553147 [w=256] load=17122
> (~6%)
> (XEN) 	  2: [0.1] flags=0 cpu=4 credit=10570606 [w=256] load=13569
> (~5%)
> (XEN) 	  3: [0.2] flags=0 cpu=7 credit=10605188 [w=256] load=13465
> (~5%)
> (XEN) 	  4: [0.3] flags=2 cpu=11 credit=9998469 [w=256] load=262144
> (~100%)
> (XEN) 	  5: [0.4] flags=0 cpu=0 credit=10533686 [w=256] load=13619
> (~5%)
> (XEN) 	  6: [0.5] flags=a cpu=9 credit=1101 [w=256] load=0 (~0%)
> (XEN) 	  7: [0.6] flags=2 cpu=2 credit=10621802 [w=256] load=13526
> (~5%)
> (XEN) 	  8: [0.7] flags=2 cpu=1 credit=10670607 [w=256] load=13453
> (~5%)
> (XEN) 	  9: [0.8] flags=2 cpu=7 credit=10649858 [w=256] load=13502
> (~5%)
> (XEN) 	 10: [0.9] flags=0 cpu=3 credit=10550566 [w=256] load=13477
> (~5%)
> (XEN) 	 11: [0.10] flags=2 cpu=4 credit=10644321 [w=256] load=13539
> (~5%)
> (XEN) 	 12: [0.11] flags=2 cpu=1 credit=10602374 [w=256] load=13471
> (~5%)
> (XEN) 	 13: [0.12] flags=0 cpu=6 credit=10617262 [w=256] load=13801
> (~5%)
> (XEN) 	 14: [0.13] flags=2 cpu=8 credit=9998664 [w=256] load=262144
> (~100%)
> (XEN) 	 15: [0.14] flags=0 cpu=3 credit=10603305 [w=256] load=17020
> (~6%)
> (XEN) 	 16: [0.15] flags=0 cpu=5 credit=10591312 [w=256] load=13523
> (~5%)
> (XEN) 	Domain: 1 w 256 c 0 v 2
> (XEN) 	 17: [1.0] flags=2 cpu=6 credit=4916769 [w=256] load=262144
> (~100%)
> (XEN) 	 18: [1.1] flags=0 cpu=13 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 2 w 256 c 0 v 2
> (XEN) 	 19: [2.0] flags=2 cpu=5 credit=4982064 [w=256] load=262144
> (~100%)
> (XEN) 	 20: [2.1] flags=0 cpu=14 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 3 w 256 c 0 v 2
> (XEN) 	 21: [3.0] flags=2 cpu=1 credit=5200781 [w=256] load=262144
> (~100%)
> (XEN) 	 22: [3.1] flags=0 cpu=5 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 4 w 256 c 0 v 2
> (XEN) 	 23: [4.0] flags=12 cpu=0 credit=5395149 [w=256] load=262144
> (~100%)
> (XEN) 	 24: [4.1] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 5 w 256 c 0 v 2
> (XEN) 	 25: [5.0] flags=2 cpu=2 credit=5306461 [w=256] load=262144
> (~100%)
> (XEN) 	 26: [5.1] flags=0 cpu=15 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 6 w 256 c 0 v 8
> (XEN) 	 27: [6.0] flags=12 cpu=10 credit=7915602 [w=256] load=262144
> (~100%)
> (XEN) 	 28: [6.1] flags=0 cpu=10 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 29: [6.2] flags=0 cpu=15 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 30: [6.3] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 31: [6.4] flags=0 cpu=0 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 32: [6.5] flags=0 cpu=6 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 33: [6.6] flags=0 cpu=11 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 34: [6.7] flags=0 cpu=9 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 7 w 256 c 0 v 2
> (XEN) 	 35: [7.0] flags=2 cpu=4 credit=5297013 [w=256] load=262144
> (~100%)
> (XEN) 	 36: [7.1] flags=0 cpu=11 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 8 w 256 c 0 v 4
> (XEN) 	 37: [8.0] flags=0 cpu=14 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 38: [8.1] flags=2 cpu=7 credit=5240630 [w=256] load=262144
> (~100%)
> (XEN) 	 39: [8.2] flags=0 cpu=13 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 40: [8.3] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 9 w 256 c 0 v 2
> (XEN) 	 41: [9.0] flags=0 cpu=0 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 42: [9.1] flags=12 cpu=13 credit=7910266 [w=256] load=262144
> (~100%)
> (XEN) 	Domain: 10 w 256 c 0 v 2
> (XEN) 	 43: [10.0] flags=12 cpu=12 credit=8045458 [w=256] load=262144
> (~100%)
> (XEN) 	 44: [10.1] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 11 w 256 c 0 v 2
> (XEN) 	 45: [11.0] flags=12 cpu=14 credit=7575284 [w=256] load=262144
> (~100%)
> (XEN) 	 46: [11.1] flags=0 cpu=12 credit=10500000 [w=256] load=0
> (~0%)
> (XEN) 	Domain: 12 w 256 c 0 v 2
> (XEN) 	 47: [12.0] flags=2 cpu=15 credit=8014099 [w=256] load=262144
> (~100%)
> (XEN) 	 48: [12.1] flags=0 cpu=6 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	Domain: 13 w 256 c 0 v 2
> (XEN) 	 49: [13.0] flags=0 cpu=7 credit=10500000 [w=256] load=0 (~0%)
> (XEN) 	 50: [13.1] flags=0 cpu=15 credit=10500000 [w=256] load=0
> (~0%)
> (XEN) Runqueue 0:
> (XEN) CPU[00] runq=0, sibling={0}, core={0-7}
> (XEN) 	run: [4.0] flags=2 cpu=0 credit=5255200 [w=256] load=262144
> (~100%)
> (XEN) CPU[01] runq=0, sibling={1}, core={0-7}
> (XEN) 	run: [3.0] flags=2 cpu=1 credit=5057668 [w=256] load=262144
> (~100%)
> (XEN) CPU[02] runq=0, sibling={2}, core={0-7}
> (XEN) 	run: [5.0] flags=12 cpu=2 credit=5180785 [w=256] load=262144
> (~100%)
> (XEN) CPU[03] runq=0, sibling={3}, core={0-7}
> (XEN) CPU[04] runq=0, sibling={4}, core={0-7}
> (XEN) 	run: [7.0] flags=2 cpu=4 credit=5215323 [w=256] load=262144
> (~100%)
> (XEN) CPU[05] runq=0, sibling={5}, core={0-7}
> (XEN) 	run: [2.0] flags=2 cpu=5 credit=4816142 [w=256] load=262144
> (~100%)
> (XEN) CPU[06] runq=0, sibling={6}, core={0-7}
> (XEN) 	run: [1.0] flags=2 cpu=6 credit=4755772 [w=256] load=262144
> (~100%)
> (XEN) CPU[07] runq=0, sibling={7}, core={0-7}
> (XEN) 	run: [8.1] flags=12 cpu=7 credit=5175342 [w=256] load=262144
> (~100%)
> (XEN) RUNQ:
> (XEN) Runqueue 1:
> (XEN) CPU[08] runq=1, sibling={8}, core={8-15}
> (XEN) 	run: [0.13] flags=2 cpu=8 credit=9998664 [w=256] load=262144
> (~100%)
> (XEN) CPU[09] runq=1, sibling={9}, core={8-15}
> (XEN) 	run: [0.5] flags=a cpu=9 credit=1101 [w=256] load=0 (~0%)
> (XEN) CPU[10] runq=1, sibling={10}, core={8-15}
> (XEN) 	run: [6.0] flags=2 cpu=10 credit=7764532 [w=256] load=262144
> (~100%)
> (XEN) CPU[11] runq=1, sibling={11}, core={8-15}
> (XEN) 	run: [0.3] flags=2 cpu=11 credit=9998469 [w=256] load=262144
> (~100%)
> (XEN) CPU[12] runq=1, sibling={12}, core={8-15}
> (XEN) 	run: [10.0] flags=2 cpu=12 credit=7967846 [w=256] load=262144
> (~100%)
> (XEN) CPU[13] runq=1, sibling={13}, core={8-15}
> (XEN) 	run: [9.1] flags=12 cpu=13 credit=7832232 [w=256] load=262144
> (~100%)
> (XEN) CPU[14] runq=1, sibling={14}, core={8-15}
> (XEN) 	run: [11.0] flags=2 cpu=14 credit=7509378 [w=256] load=262144
> (~100%)
> (XEN) CPU[15] runq=1, sibling={15}, core={8-15}
> (XEN) 	run: [12.0] flags=2 cpu=15 credit=7971164 [w=256] load=262144
> (~100%)
> (XEN) RUNQ:
> (XEN) CPUs info:
> (XEN) CPU[00] current=d4v0, curr=d4v0, prev=NULL
> (XEN) CPU[01] current=d3v0, curr=d3v0, prev=NULL
> (XEN) CPU[02] current=d5v0, curr=d5v0, prev=NULL
> (XEN) CPU[03] current=d[IDLE]v3, curr=d[IDLE]v3, prev=NULL
> (XEN) CPU[04] current=d7v0, curr=d7v0, prev=NULL
> (XEN) CPU[05] current=d2v0, curr=d2v0, prev=NULL
> (XEN) CPU[06] current=d1v0, curr=d1v0, prev=NULL
> (XEN) CPU[07] current=d8v1, curr=d8v1, prev=NULL
> (XEN) CPU[08] current=d0v13, curr=d0v13, prev=NULL
> (XEN) CPU[09] current=d0v5, curr=d0v5, prev=NULL
> (XEN) CPU[10] current=d6v0, curr=d6v0, prev=NULL
> (XEN) CPU[11] current=d0v3, curr=d0v3, prev=NULL
> (XEN) CPU[12] current=d10v0, curr=d10v0, prev=NULL
> (XEN) CPU[13] current=d9v1, curr=d9v1, prev=NULL
> (XEN) CPU[14] current=d11v0, curr=d11v0, prev=NULL
> (XEN) CPU[15] current=d12v0, curr=d12v0, prev=NULL
> 



-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Dario Faggioli]

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

On Tue, 2020-10-27 at 17:06 +0100, Frédéric Pierret wrote:
> 
> Ok the server got frozen just few minutes after my mail and I got
> now:
> 'r': https://gist.github.com/fepitre/78541f555902275d906d627de2420571
>
From the scheduler point of view, things seems fine:

(XEN) sched_smt_power_savings: disabled
(XEN) NOW=770188952085
(XEN) Online Cpus: 0-15
(XEN) Cpupool 0:
(XEN) Cpus: 0-15
(XEN) Scheduling granularity: cpu, 1 CPU per sched-resource
(XEN) Scheduler: SMP Credit Scheduler rev2 (credit2)
(XEN) Active queues: 2
(XEN) 	default-weight     = 256
(XEN) Runqueue 0:
(XEN) 	ncpus              = 8
(XEN) 	cpus               = 0-7
(XEN) 	max_weight         = 256
(XEN) 	pick_bias          = 1
(XEN) 	instload           = 7
(XEN) 	aveload            = 2021119 (~770%)
(XEN) 	idlers: 00000000,00000000
(XEN) 	tickled: 00000000,00000000
(XEN) 	fully idle cores: 00000000,00000000
(XEN) Runqueue 1:
(XEN) 	ncpus              = 8
(XEN) 	cpus               = 8-15
(XEN) 	max_weight         = 256
(XEN) 	pick_bias          = 9
(XEN) 	instload           = 8
(XEN) 	aveload            = 2097259 (~800%)
(XEN) 	idlers: 00000000,00000000
(XEN) 	tickled: 00000000,00000200
(XEN) 	fully idle cores: 00000000,00000000

The system is pretty busy, but not in overload.

Below we see that CPU 3 is running the idle vCPU, but it's not marked
as neither idle nor tickled.

It may be running a tasklet (the one that dumps the debug key output, I
guess).

Credits are fine, I don't see any strange values that may indicate
anomalies or something.

All the CPUs are executing a vCPU, and there should be nothing that
prevent them making progresses.

There is one vCPU which apparetnly want to run at 100% in pretty much
all guests, and more than one in dom0.

And I think I saw some spin_lock() in the call stacks, in the partial
report of '*' debug-key?

Maybe they're stuck in the kernel, not in Xen? Thoughs ?


(XEN) Domain info:
(XEN) 	Domain: 0 w 256 c 0 v 16
(XEN) 	  1: [0.0] flags=0 cpu=5 credit=10553147 [w=256] load=17122
(~6%)
(XEN) 	  2: [0.1] flags=0 cpu=4 credit=10570606 [w=256] load=13569
(~5%)
(XEN) 	  3: [0.2] flags=0 cpu=7 credit=10605188 [w=256] load=13465
(~5%)
(XEN) 	  4: [0.3] flags=2 cpu=11 credit=9998469 [w=256] load=262144
(~100%)
(XEN) 	  5: [0.4] flags=0 cpu=0 credit=10533686 [w=256] load=13619
(~5%)
(XEN) 	  6: [0.5] flags=a cpu=9 credit=1101 [w=256] load=0 (~0%)
(XEN) 	  7: [0.6] flags=2 cpu=2 credit=10621802 [w=256] load=13526
(~5%)
(XEN) 	  8: [0.7] flags=2 cpu=1 credit=10670607 [w=256] load=13453
(~5%)
(XEN) 	  9: [0.8] flags=2 cpu=7 credit=10649858 [w=256] load=13502
(~5%)
(XEN) 	 10: [0.9] flags=0 cpu=3 credit=10550566 [w=256] load=13477
(~5%)
(XEN) 	 11: [0.10] flags=2 cpu=4 credit=10644321 [w=256] load=13539
(~5%)
(XEN) 	 12: [0.11] flags=2 cpu=1 credit=10602374 [w=256] load=13471
(~5%)
(XEN) 	 13: [0.12] flags=0 cpu=6 credit=10617262 [w=256] load=13801
(~5%)
(XEN) 	 14: [0.13] flags=2 cpu=8 credit=9998664 [w=256] load=262144
(~100%)
(XEN) 	 15: [0.14] flags=0 cpu=3 credit=10603305 [w=256] load=17020
(~6%)
(XEN) 	 16: [0.15] flags=0 cpu=5 credit=10591312 [w=256] load=13523
(~5%)
(XEN) 	Domain: 1 w 256 c 0 v 2
(XEN) 	 17: [1.0] flags=2 cpu=6 credit=4916769 [w=256] load=262144
(~100%)
(XEN) 	 18: [1.1] flags=0 cpu=13 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 2 w 256 c 0 v 2
(XEN) 	 19: [2.0] flags=2 cpu=5 credit=4982064 [w=256] load=262144
(~100%)
(XEN) 	 20: [2.1] flags=0 cpu=14 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 3 w 256 c 0 v 2
(XEN) 	 21: [3.0] flags=2 cpu=1 credit=5200781 [w=256] load=262144
(~100%)
(XEN) 	 22: [3.1] flags=0 cpu=5 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 4 w 256 c 0 v 2
(XEN) 	 23: [4.0] flags=12 cpu=0 credit=5395149 [w=256] load=262144
(~100%)
(XEN) 	 24: [4.1] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 5 w 256 c 0 v 2
(XEN) 	 25: [5.0] flags=2 cpu=2 credit=5306461 [w=256] load=262144
(~100%)
(XEN) 	 26: [5.1] flags=0 cpu=15 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 6 w 256 c 0 v 8
(XEN) 	 27: [6.0] flags=12 cpu=10 credit=7915602 [w=256] load=262144
(~100%)
(XEN) 	 28: [6.1] flags=0 cpu=10 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 29: [6.2] flags=0 cpu=15 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 30: [6.3] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 31: [6.4] flags=0 cpu=0 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 32: [6.5] flags=0 cpu=6 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 33: [6.6] flags=0 cpu=11 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 34: [6.7] flags=0 cpu=9 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 7 w 256 c 0 v 2
(XEN) 	 35: [7.0] flags=2 cpu=4 credit=5297013 [w=256] load=262144
(~100%)
(XEN) 	 36: [7.1] flags=0 cpu=11 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 8 w 256 c 0 v 4
(XEN) 	 37: [8.0] flags=0 cpu=14 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 38: [8.1] flags=2 cpu=7 credit=5240630 [w=256] load=262144
(~100%)
(XEN) 	 39: [8.2] flags=0 cpu=13 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 40: [8.3] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 9 w 256 c 0 v 2
(XEN) 	 41: [9.0] flags=0 cpu=0 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 42: [9.1] flags=12 cpu=13 credit=7910266 [w=256] load=262144
(~100%)
(XEN) 	Domain: 10 w 256 c 0 v 2
(XEN) 	 43: [10.0] flags=12 cpu=12 credit=8045458 [w=256] load=262144
(~100%)
(XEN) 	 44: [10.1] flags=0 cpu=8 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 11 w 256 c 0 v 2
(XEN) 	 45: [11.0] flags=12 cpu=14 credit=7575284 [w=256] load=262144
(~100%)
(XEN) 	 46: [11.1] flags=0 cpu=12 credit=10500000 [w=256] load=0
(~0%)
(XEN) 	Domain: 12 w 256 c 0 v 2
(XEN) 	 47: [12.0] flags=2 cpu=15 credit=8014099 [w=256] load=262144
(~100%)
(XEN) 	 48: [12.1] flags=0 cpu=6 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	Domain: 13 w 256 c 0 v 2
(XEN) 	 49: [13.0] flags=0 cpu=7 credit=10500000 [w=256] load=0 (~0%)
(XEN) 	 50: [13.1] flags=0 cpu=15 credit=10500000 [w=256] load=0
(~0%)
(XEN) Runqueue 0:
(XEN) CPU[00] runq=0, sibling={0}, core={0-7}
(XEN) 	run: [4.0] flags=2 cpu=0 credit=5255200 [w=256] load=262144
(~100%)
(XEN) CPU[01] runq=0, sibling={1}, core={0-7}
(XEN) 	run: [3.0] flags=2 cpu=1 credit=5057668 [w=256] load=262144
(~100%)
(XEN) CPU[02] runq=0, sibling={2}, core={0-7}
(XEN) 	run: [5.0] flags=12 cpu=2 credit=5180785 [w=256] load=262144
(~100%)
(XEN) CPU[03] runq=0, sibling={3}, core={0-7}
(XEN) CPU[04] runq=0, sibling={4}, core={0-7}
(XEN) 	run: [7.0] flags=2 cpu=4 credit=5215323 [w=256] load=262144
(~100%)
(XEN) CPU[05] runq=0, sibling={5}, core={0-7}
(XEN) 	run: [2.0] flags=2 cpu=5 credit=4816142 [w=256] load=262144
(~100%)
(XEN) CPU[06] runq=0, sibling={6}, core={0-7}
(XEN) 	run: [1.0] flags=2 cpu=6 credit=4755772 [w=256] load=262144
(~100%)
(XEN) CPU[07] runq=0, sibling={7}, core={0-7}
(XEN) 	run: [8.1] flags=12 cpu=7 credit=5175342 [w=256] load=262144
(~100%)
(XEN) RUNQ:
(XEN) Runqueue 1:
(XEN) CPU[08] runq=1, sibling={8}, core={8-15}
(XEN) 	run: [0.13] flags=2 cpu=8 credit=9998664 [w=256] load=262144
(~100%)
(XEN) CPU[09] runq=1, sibling={9}, core={8-15}
(XEN) 	run: [0.5] flags=a cpu=9 credit=1101 [w=256] load=0 (~0%)
(XEN) CPU[10] runq=1, sibling={10}, core={8-15}
(XEN) 	run: [6.0] flags=2 cpu=10 credit=7764532 [w=256] load=262144
(~100%)
(XEN) CPU[11] runq=1, sibling={11}, core={8-15}
(XEN) 	run: [0.3] flags=2 cpu=11 credit=9998469 [w=256] load=262144
(~100%)
(XEN) CPU[12] runq=1, sibling={12}, core={8-15}
(XEN) 	run: [10.0] flags=2 cpu=12 credit=7967846 [w=256] load=262144
(~100%)
(XEN) CPU[13] runq=1, sibling={13}, core={8-15}
(XEN) 	run: [9.1] flags=12 cpu=13 credit=7832232 [w=256] load=262144
(~100%)
(XEN) CPU[14] runq=1, sibling={14}, core={8-15}
(XEN) 	run: [11.0] flags=2 cpu=14 credit=7509378 [w=256] load=262144
(~100%)
(XEN) CPU[15] runq=1, sibling={15}, core={8-15}
(XEN) 	run: [12.0] flags=2 cpu=15 credit=7971164 [w=256] load=262144
(~100%)
(XEN) RUNQ:
(XEN) CPUs info:
(XEN) CPU[00] current=d4v0, curr=d4v0, prev=NULL
(XEN) CPU[01] current=d3v0, curr=d3v0, prev=NULL
(XEN) CPU[02] current=d5v0, curr=d5v0, prev=NULL
(XEN) CPU[03] current=d[IDLE]v3, curr=d[IDLE]v3, prev=NULL
(XEN) CPU[04] current=d7v0, curr=d7v0, prev=NULL
(XEN) CPU[05] current=d2v0, curr=d2v0, prev=NULL
(XEN) CPU[06] current=d1v0, curr=d1v0, prev=NULL
(XEN) CPU[07] current=d8v1, curr=d8v1, prev=NULL
(XEN) CPU[08] current=d0v13, curr=d0v13, prev=NULL
(XEN) CPU[09] current=d0v5, curr=d0v5, prev=NULL
(XEN) CPU[10] current=d6v0, curr=d6v0, prev=NULL
(XEN) CPU[11] current=d0v3, curr=d0v3, prev=NULL
(XEN) CPU[12] current=d10v0, curr=d10v0, prev=NULL
(XEN) CPU[13] current=d9v1, curr=d9v1, prev=NULL
(XEN) CPU[14] current=d11v0, curr=d11v0, prev=NULL
(XEN) CPU[15] current=d12v0, curr=d12v0, prev=NULL

-- 
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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

---- On Tue, 27 Oct 2020 10:22:42 +0100 Dario Faggioli <dfaggioli@suse.com> wrote ----



On Tue, 2020-10-27 at 06:58 +0100, Jürgen Groß wrote: 
> On 26.10.20 17:31, Dario Faggioli wrote: 
> > 
> > Or did you have something completely different in mind, and I'm 
> > missing 
> > it? 
> 
> No, I think you are right. I mixed that up with __context_switch() 
> not 
> being called. 
> 
Right. 
 
> Sorry for the noise, 
> 
Sure, no problem. 
 
In fact, this issue is apparently scheduler independent. It indeed 
seemd to be related to the other report we have "BUG: credit=sched2 
machine hang when using DRAKVUF", but there it looks like it is 
scheduler-dependant. 
 
Might it be something that lies somewhere else, but Credit2 is 
triggering it faster/easier? (Just thinking out loud...) 
 
For Frederic, what happens is that dom0 hangs, right? So you're able to 
poke at Xen with some debugkeys (like 'r' for the scheduler's status, 
and the ones for the domain's vCPUs)? 
 
If yes, it may be useful to see the output. 
 
Regards 
-- 
Dario Faggioli, Ph.D 
http://about.me/dario.faggioli 
Virtualization Software Engineer 
SUSE Labs, SUSE https://www.suse.com/ 
------------------------------------------------------------------- 
<<This happens because _I_ choose it to happen!>> (Raistlin Majere) 






First of all, sorry for the possible duplicates. I had network issue due to subsequent freezes (...) while writing to you and Marek has not received my previous mails so here the info. 

 

 

To answer your question Dario, yes dom0 hangs totally and VMs too. In the case of `sched=credit`, I've succeeded to obtain the output of 'r' debug-keys in serial console: 

``` 

(XEN) sched_smt_power_savings: disabled 

(XEN) NOW=72810702614697 

(XEN) Online Cpus: 0-15 

(XEN) Cpupool 0: 

(XEN) Cpus: 0-15 

(XEN) Scheduling granularity: cpu, 1 CPU per sched-resource 

(XEN) Scheduler: SMP Credit Scheduler (credit) 

(XEN) info: 

(XEN)     ncpus              = 16 

(XEN)     master             = 0 

(XEN)     credit             = 4800 

(XEN)     credit balance     = 608 

(XEN)     weight             = 12256 

(XEN)     runq_sort          = 996335 

(XEN)     default-weight     = 256 

(XEN)     tslice             = 30ms 

(XEN)     ratelimit          = 1000us 

(XEN)     credits per msec   = 10 

(XEN)     ticks per tslice   = 3 

(XEN)     migration delay    = 0us 

(XEN) idlers: 00000000,00003c99 

(XEN) active units: 

(XEN)       1: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0] 

(XEN)       2: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0] 

(XEN)       3: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0] 

(XEN)       4: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0] 

(XEN)       5: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0] 

(XEN)       6: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0] 

(XEN)       7: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0] 

(XEN) CPUs info: 

(XEN) CPU[00] current=d[IDLE]v0, curr=d[IDLE]v0, prev=NULL 

(XEN) CPU[00] nr_run=0, sort=996334, sibling={0}, core={0-7} 

(XEN) CPU[01] current=d0v11, curr=d0v11, prev=NULL 

(XEN) CPU[01] nr_run=1, sort=996335, sibling={1}, core={0-7} 

(XEN)     run: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0] 

(XEN)       1: [32767.1] pri=-64 flags=0 cpu=1 

(XEN) CPU[02] current=d0v7, curr=d0v7, prev=NULL 

(XEN) CPU[02] nr_run=1, sort=996335, sibling={2}, core={0-7} 

(XEN)     run: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0] 

(XEN)       1: [32767.2] pri=-64 flags=0 cpu=2 

(XEN) CPU[03] current=d[IDLE]v3, curr=d[IDLE]v3, prev=NULL 

(XEN) CPU[03] nr_run=0, sort=996329, sibling={3}, core={0-7} 

(XEN) CPU[04] current=d[IDLE]v4, curr=d[IDLE]v4, prev=NULL 

(XEN) CPU[04] nr_run=0, sort=996325, sibling={4}, core={0-7} 

(XEN) CPU[05] current=d0v5, curr=d0v5, prev=NULL 

(XEN) CPU[05] nr_run=1, sort=996334, sibling={5}, core={0-7} 

(XEN)     run: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0] 

(XEN)       1: [32767.5] pri=-64 flags=0 cpu=5 

(XEN) CPU[06] current=d0v1, curr=d0v1, prev=NULL 

(XEN) CPU[06] nr_run=1, sort=996334, sibling={6}, core={0-7} 

(XEN)     run: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0] 

(XEN)       1: [32767.6] pri=-64 flags=0 cpu=6 

(XEN) CPU[07] current=d[IDLE]v7, curr=d[IDLE]v7, prev=NULL 

(XEN) CPU[07] nr_run=0, sort=996303, sibling={7}, core={0-7} 

(XEN) CPU[08] current=d[IDLE]v8, curr=d[IDLE]v8, prev=NULL 

(XEN) CPU[08] nr_run=2, sort=996335, sibling={8}, core={8-15} 

(XEN)       1: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0] 

(XEN) CPU[09] current=d19v1, curr=d19v1, prev=NULL 

(XEN) CPU[09] nr_run=1, sort=996335, sibling={9}, core={8-15} 

(XEN)     run: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0] 

(XEN)       1: [32767.9] pri=-64 flags=0 cpu=9 

(XEN) CPU[10] current=d[IDLE]v10, curr=d[IDLE]v10, prev=NULL 

(XEN) CPU[10] nr_run=0, sort=996334, sibling={10}, core={8-15} 

(XEN) CPU[11] current=d[IDLE]v11, curr=d[IDLE]v11, prev=NULL 

(XEN) CPU[11] nr_run=0, sort=996331, sibling={11}, core={8-15} 

(XEN) CPU[12] current=d[IDLE]v12, curr=d[IDLE]v12, prev=NULL 

(XEN) CPU[12] nr_run=0, sort=996333, sibling={12}, core={8-15} 

(XEN) CPU[13] current=d[IDLE]v13, curr=d[IDLE]v13, prev=NULL 

(XEN) CPU[13] nr_run=0, sort=996334, sibling={13}, core={8-15} 

(XEN) CPU[14] current=d0v14, curr=d0v14, prev=NULL 

(XEN) CPU[14] nr_run=1, sort=990383, sibling={14}, core={8-15} 

(XEN)     run: [0.14] pri=0 flags=0 cpu=14 credit=-514 [w=2000,cap=0] 

(XEN)       1: [32767.14] pri=-64 flags=0 cpu=14 

(XEN) CPU[15] current=d0v6, curr=d0v6, prev=NULL 

(XEN) CPU[15] nr_run=1, sort=996335, sibling={15}, core={8-15} 

(XEN)     run: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0] 

(XEN)       1: [32767.15] pri=-64 flags=0 cpu=15 

``` 

 

I attempt to get '*' but that blocked my serial console, at least I was not able to interact with it few minutes later. I'll try to get other info too. I've also uploaded the piece of this huge '*' dump here: https://gist.github.com/fepitre/36923fbc08cc2fd8bdb59b81e73a6c2e 

 

Right after, I've restarted with the default value of 'sched' (credit2) and just few minutes later I obtained: 

'r': https://gist.github.com/fepitre/78541f555902275d906d627de2420571 

'q': https://gist.github.com/fepitre/0ddf6b5e8fdb3152d24337d83fdc345e 

'I': https://gist.github.com/fepitre/50c68233d08ad1e495edf7e0e146838b 

 

Tell me if I can provide any other info from serial console. 

 

Regards, 

Frédéric

[-- Attachment #2: Type: text/html, Size: 12807 bytes --]

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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



Le 10/27/20 à 10:22 AM, Dario Faggioli a écrit :
> On Tue, 2020-10-27 at 06:58 +0100, Jürgen Groß wrote:
>> On 26.10.20 17:31, Dario Faggioli wrote:
>>>
>>> Or did you have something completely different in mind, and I'm
>>> missing
>>> it?
>>
>> No, I think you are right. I mixed that up with __context_switch()
>> not
>> being called.
>>
> Right.
> 
>> Sorry for the noise,
>>
> Sure, no problem.
> 
> In fact, this issue is apparently scheduler independent. It indeed
> seemd to be related to the other report we have "BUG: credit=sched2
> machine hang when using DRAKVUF", but there it looks like it is
> scheduler-dependant.
> 
> Might it be something that lies somewhere else, but Credit2 is
> triggering it faster/easier? (Just thinking out loud...)
> 
> For Frederic, what happens is that dom0 hangs, right? So you're able to
> poke at Xen with some debugkeys (like 'r' for the scheduler's status,
> and the ones for the domain's vCPUs)?
> 
> If yes, it may be useful to see the output.
> 
> Regards
> 

First of all, sorry for the possible duplicates. I had network issue due to subsequent freezes (...) while writing to you and Marek has not received my previous mails so here the info.


To answer your question Dario, yes dom0 hangs totally and VMs too. In the case of `sched=credit`, I've succeeded to obtain the output of 'r' debug-keys in serial console:
```
(XEN) sched_smt_power_savings: disabled
(XEN) NOW=72810702614697
(XEN) Online Cpus: 0-15
(XEN) Cpupool 0:
(XEN) Cpus: 0-15
(XEN) Scheduling granularity: cpu, 1 CPU per sched-resource
(XEN) Scheduler: SMP Credit Scheduler (credit)
(XEN) info:
(XEN) 	ncpus              = 16
(XEN) 	master             = 0
(XEN) 	credit             = 4800
(XEN) 	credit balance     = 608
(XEN) 	weight             = 12256
(XEN) 	runq_sort          = 996335
(XEN) 	default-weight     = 256
(XEN) 	tslice             = 30ms
(XEN) 	ratelimit          = 1000us
(XEN) 	credits per msec   = 10
(XEN) 	ticks per tslice   = 3
(XEN) 	migration delay    = 0us
(XEN) idlers: 00000000,00003c99
(XEN) active units:
(XEN) 	  1: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0]
(XEN) 	  2: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0]
(XEN) 	  3: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0]
(XEN) 	  4: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0]
(XEN) 	  5: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0]
(XEN) 	  6: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0]
(XEN) 	  7: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0]
(XEN) CPUs info:
(XEN) CPU[00] current=d[IDLE]v0, curr=d[IDLE]v0, prev=NULL
(XEN) CPU[00] nr_run=0, sort=996334, sibling={0}, core={0-7}
(XEN) CPU[01] current=d0v11, curr=d0v11, prev=NULL
(XEN) CPU[01] nr_run=1, sort=996335, sibling={1}, core={0-7}
(XEN) 	run: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0]
(XEN) 	  1: [32767.1] pri=-64 flags=0 cpu=1
(XEN) CPU[02] current=d0v7, curr=d0v7, prev=NULL
(XEN) CPU[02] nr_run=1, sort=996335, sibling={2}, core={0-7}
(XEN) 	run: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0]
(XEN) 	  1: [32767.2] pri=-64 flags=0 cpu=2
(XEN) CPU[03] current=d[IDLE]v3, curr=d[IDLE]v3, prev=NULL
(XEN) CPU[03] nr_run=0, sort=996329, sibling={3}, core={0-7}
(XEN) CPU[04] current=d[IDLE]v4, curr=d[IDLE]v4, prev=NULL
(XEN) CPU[04] nr_run=0, sort=996325, sibling={4}, core={0-7}
(XEN) CPU[05] current=d0v5, curr=d0v5, prev=NULL
(XEN) CPU[05] nr_run=1, sort=996334, sibling={5}, core={0-7}
(XEN) 	run: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0]
(XEN) 	  1: [32767.5] pri=-64 flags=0 cpu=5
(XEN) CPU[06] current=d0v1, curr=d0v1, prev=NULL
(XEN) CPU[06] nr_run=1, sort=996334, sibling={6}, core={0-7}
(XEN) 	run: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0]
(XEN) 	  1: [32767.6] pri=-64 flags=0 cpu=6
(XEN) CPU[07] current=d[IDLE]v7, curr=d[IDLE]v7, prev=NULL
(XEN) CPU[07] nr_run=0, sort=996303, sibling={7}, core={0-7}
(XEN) CPU[08] current=d[IDLE]v8, curr=d[IDLE]v8, prev=NULL
(XEN) CPU[08] nr_run=2, sort=996335, sibling={8}, core={8-15}
(XEN) 	  1: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0]
(XEN) CPU[09] current=d19v1, curr=d19v1, prev=NULL
(XEN) CPU[09] nr_run=1, sort=996335, sibling={9}, core={8-15}
(XEN) 	run: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0]
(XEN) 	  1: [32767.9] pri=-64 flags=0 cpu=9
(XEN) CPU[10] current=d[IDLE]v10, curr=d[IDLE]v10, prev=NULL
(XEN) CPU[10] nr_run=0, sort=996334, sibling={10}, core={8-15}
(XEN) CPU[11] current=d[IDLE]v11, curr=d[IDLE]v11, prev=NULL
(XEN) CPU[11] nr_run=0, sort=996331, sibling={11}, core={8-15}
(XEN) CPU[12] current=d[IDLE]v12, curr=d[IDLE]v12, prev=NULL
(XEN) CPU[12] nr_run=0, sort=996333, sibling={12}, core={8-15}
(XEN) CPU[13] current=d[IDLE]v13, curr=d[IDLE]v13, prev=NULL
(XEN) CPU[13] nr_run=0, sort=996334, sibling={13}, core={8-15}
(XEN) CPU[14] current=d0v14, curr=d0v14, prev=NULL
(XEN) CPU[14] nr_run=1, sort=990383, sibling={14}, core={8-15}
(XEN) 	run: [0.14] pri=0 flags=0 cpu=14 credit=-514 [w=2000,cap=0]
(XEN) 	  1: [32767.14] pri=-64 flags=0 cpu=14
(XEN) CPU[15] current=d0v6, curr=d0v6, prev=NULL
(XEN) CPU[15] nr_run=1, sort=996335, sibling={15}, core={8-15}
(XEN) 	run: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0]
(XEN) 	  1: [32767.15] pri=-64 flags=0 cpu=15
```

I attempt to get '*' but that blocked my serial console, at least I was not able to interact with it few minutes later. I'll try to get other info too. I've also uploaded the piece of this huge '*' dump here: https://gist.github.com/fepitre/36923fbc08cc2fd8bdb59b81e73a6c2e

Right after, I've restarted with the default value of 'sched' (credit2) and just few minutes later I obtained:
'r': https://gist.github.com/fepitre/78541f555902275d906d627de2420571
'q': https://gist.github.com/fepitre/0ddf6b5e8fdb3152d24337d83fdc345e
'I': https://gist.github.com/fepitre/50c68233d08ad1e495edf7e0e146838b

Tell me if I can provide any other info from serial console.

Regards,
Frédéric



[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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



Le 10/27/20 à 4:42 PM, Frédéric Pierret a écrit :
> 
> 
> Le 10/27/20 à 10:22 AM, Dario Faggioli a écrit :
>> On Tue, 2020-10-27 at 06:58 +0100, Jürgen Groß wrote:
>>> On 26.10.20 17:31, Dario Faggioli wrote:
>>>>
>>>> Or did you have something completely different in mind, and I'm
>>>> missing
>>>> it?
>>>
>>> No, I think you are right. I mixed that up with __context_switch()
>>> not
>>> being called.
>>>
>> Right.
>>
>>> Sorry for the noise,
>>>
>> Sure, no problem.
>>
>> In fact, this issue is apparently scheduler independent. It indeed
>> seemd to be related to the other report we have "BUG: credit=sched2
>> machine hang when using DRAKVUF", but there it looks like it is
>> scheduler-dependant.
>>
>> Might it be something that lies somewhere else, but Credit2 is
>> triggering it faster/easier? (Just thinking out loud...)
>>
>> For Frederic, what happens is that dom0 hangs, right? So you're able to
>> poke at Xen with some debugkeys (like 'r' for the scheduler's status,
>> and the ones for the domain's vCPUs)?
>>
>> If yes, it may be useful to see the output.
>>
>> Regards
>>
> 
> I'm having some new info with respect to your request. Yes dom0 hangs and I can interact with serial console. I've succeeded to obtain the output of 'r' debug-keys:
> 
> ```
> (XEN) sched_smt_power_savings: disabled
> (XEN) NOW=72810702614697
> (XEN) Online Cpus: 0-15
> (XEN) Cpupool 0:
> (XEN) Cpus: 0-15
> (XEN) Scheduling granularity: cpu, 1 CPU per sched-resource
> (XEN) Scheduler: SMP Credit Scheduler (credit)
> (XEN) info:
> (XEN)     ncpus              = 16
> (XEN)     master             = 0
> (XEN)     credit             = 4800
> (XEN)     credit balance     = 608
> (XEN)     weight             = 12256
> (XEN)     runq_sort          = 996335
> (XEN)     default-weight     = 256
> (XEN)     tslice             = 30ms
> (XEN)     ratelimit          = 1000us
> (XEN)     credits per msec   = 10
> (XEN)     ticks per tslice   = 3
> (XEN)     migration delay    = 0us
> (XEN) idlers: 00000000,00003c99
> (XEN) active units:
> (XEN)       1: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0]
> (XEN)       2: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0]
> (XEN)       3: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0]
> (XEN)       4: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0]
> (XEN)       5: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0]
> (XEN)       6: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0]
> (XEN)       7: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0]
> (XEN) CPUs info:
> (XEN) CPU[00] current=d[IDLE]v0, curr=d[IDLE]v0, prev=NULL
> (XEN) CPU[00] nr_run=0, sort=996334, sibling={0}, core={0-7}
> (XEN) CPU[01] current=d0v11, curr=d0v11, prev=NULL
> (XEN) CPU[01] nr_run=1, sort=996335, sibling={1}, core={0-7}
> (XEN)     run: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0]
> (XEN)       1: [32767.1] pri=-64 flags=0 cpu=1
> (XEN) CPU[02] current=d0v7, curr=d0v7, prev=NULL
> (XEN) CPU[02] nr_run=1, sort=996335, sibling={2}, core={0-7}
> (XEN)     run: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0]
> (XEN)       1: [32767.2] pri=-64 flags=0 cpu=2
> (XEN) CPU[03] current=d[IDLE]v3, curr=d[IDLE]v3, prev=NULL
> (XEN) CPU[03] nr_run=0, sort=996329, sibling={3}, core={0-7}
> (XEN) CPU[04] current=d[IDLE]v4, curr=d[IDLE]v4, prev=NULL
> (XEN) CPU[04] nr_run=0, sort=996325, sibling={4}, core={0-7}
> (XEN) CPU[05] current=d0v5, curr=d0v5, prev=NULL
> (XEN) CPU[05] nr_run=1, sort=996334, sibling={5}, core={0-7}
> (XEN)     run: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0]
> (XEN)       1: [32767.5] pri=-64 flags=0 cpu=5
> (XEN) CPU[06] current=d0v1, curr=d0v1, prev=NULL
> (XEN) CPU[06] nr_run=1, sort=996334, sibling={6}, core={0-7}
> (XEN)     run: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0]
> (XEN)       1: [32767.6] pri=-64 flags=0 cpu=6
> (XEN) CPU[07] current=d[IDLE]v7, curr=d[IDLE]v7, prev=NULL
> (XEN) CPU[07] nr_run=0, sort=996303, sibling={7}, core={0-7}
> (XEN) CPU[08] current=d[IDLE]v8, curr=d[IDLE]v8, prev=NULL
> (XEN) CPU[08] nr_run=2, sort=996335, sibling={8}, core={8-15}
> (XEN)       1: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0]
> (XEN) CPU[09] current=d19v1, curr=d19v1, prev=NULL
> (XEN) CPU[09] nr_run=1, sort=996335, sibling={9}, core={8-15}
> (XEN)     run: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0]
> (XEN)       1: [32767.9] pri=-64 flags=0 cpu=9
> (XEN) CPU[10] current=d[IDLE]v10, curr=d[IDLE]v10, prev=NULL
> (XEN) CPU[10] nr_run=0, sort=996334, sibling={10}, core={8-15}
> (XEN) CPU[11] current=d[IDLE]v11, curr=d[IDLE]v11, prev=NULL
> (XEN) CPU[11] nr_run=0, sort=996331, sibling={11}, core={8-15}
> (XEN) CPU[12] current=d[IDLE]v12, curr=d[IDLE]v12, prev=NULL
> (XEN) CPU[12] nr_run=0, sort=996333, sibling={12}, core={8-15}
> (XEN) CPU[13] current=d[IDLE]v13, curr=d[IDLE]v13, prev=NULL
> (XEN) CPU[13] nr_run=0, sort=996334, sibling={13}, core={8-15}
> (XEN) CPU[14] current=d0v14, curr=d0v14, prev=NULL
> (XEN) CPU[14] nr_run=1, sort=990383, sibling={14}, core={8-15}
> (XEN)     run: [0.14] pri=0 flags=0 cpu=14 credit=-514 [w=2000,cap=0]
> (XEN)       1: [32767.14] pri=-64 flags=0 cpu=14
> (XEN) CPU[15] current=d0v6, curr=d0v6, prev=NULL
> (XEN) CPU[15] nr_run=1, sort=996335, sibling={15}, core={8-15}
> (XEN)     run: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0]
> (XEN)       1: [32767.15] pri=-64 flags=0 cpu=15
> ```
> 
> I attempt to get '*' but that blocked my serial console, at least I was not able to interact with it few minutes later. I'll try to get other info too. I've also uploaded the piece of this huge '*' dump here: https://gist.github.com/fepitre/36923fbc08cc2fd8bdb59b81e73a6c2e
> 
> Regards

Ok the server got frozen just few minutes after my mail and I got now:
'r': https://gist.github.com/fepitre/78541f555902275d906d627de2420571
'q': https://gist.github.com/fepitre/0ddf6b5e8fdb3152d24337d83fdc345e
'I': https://gist.github.com/fepitre/50c68233d08ad1e495edf7e0e146838b

Tell me if I can provide any other info from serial console.

Regards,
Frédéric

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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



Le 10/27/20 à 10:22 AM, Dario Faggioli a écrit :
> On Tue, 2020-10-27 at 06:58 +0100, Jürgen Groß wrote:
>> On 26.10.20 17:31, Dario Faggioli wrote:
>>>
>>> Or did you have something completely different in mind, and I'm
>>> missing
>>> it?
>>
>> No, I think you are right. I mixed that up with __context_switch()
>> not
>> being called.
>>
> Right.
> 
>> Sorry for the noise,
>>
> Sure, no problem.
> 
> In fact, this issue is apparently scheduler independent. It indeed
> seemd to be related to the other report we have "BUG: credit=sched2
> machine hang when using DRAKVUF", but there it looks like it is
> scheduler-dependant.
> 
> Might it be something that lies somewhere else, but Credit2 is
> triggering it faster/easier? (Just thinking out loud...)
> 
> For Frederic, what happens is that dom0 hangs, right? So you're able to
> poke at Xen with some debugkeys (like 'r' for the scheduler's status,
> and the ones for the domain's vCPUs)?
> 
> If yes, it may be useful to see the output.
> 
> Regards
> 

I'm having some new info with respect to your request. Yes dom0 hangs and I can interact with serial console. I've succeeded to obtain the output of 'r' debug-keys:

```
(XEN) sched_smt_power_savings: disabled
(XEN) NOW=72810702614697
(XEN) Online Cpus: 0-15
(XEN) Cpupool 0:
(XEN) Cpus: 0-15
(XEN) Scheduling granularity: cpu, 1 CPU per sched-resource
(XEN) Scheduler: SMP Credit Scheduler (credit)
(XEN) info:
(XEN) 	ncpus              = 16
(XEN) 	master             = 0
(XEN) 	credit             = 4800
(XEN) 	credit balance     = 608
(XEN) 	weight             = 12256
(XEN) 	runq_sort          = 996335
(XEN) 	default-weight     = 256
(XEN) 	tslice             = 30ms
(XEN) 	ratelimit          = 1000us
(XEN) 	credits per msec   = 10
(XEN) 	ticks per tslice   = 3
(XEN) 	migration delay    = 0us
(XEN) idlers: 00000000,00003c99
(XEN) active units:
(XEN) 	  1: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0]
(XEN) 	  2: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0]
(XEN) 	  3: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0]
(XEN) 	  4: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0]
(XEN) 	  5: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0]
(XEN) 	  6: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0]
(XEN) 	  7: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0]
(XEN) CPUs info:
(XEN) CPU[00] current=d[IDLE]v0, curr=d[IDLE]v0, prev=NULL
(XEN) CPU[00] nr_run=0, sort=996334, sibling={0}, core={0-7}
(XEN) CPU[01] current=d0v11, curr=d0v11, prev=NULL
(XEN) CPU[01] nr_run=1, sort=996335, sibling={1}, core={0-7}
(XEN) 	run: [0.11] pri=-1 flags=0 cpu=1 credit=-55 [w=2000,cap=0]
(XEN) 	  1: [32767.1] pri=-64 flags=0 cpu=1
(XEN) CPU[02] current=d0v7, curr=d0v7, prev=NULL
(XEN) CPU[02] nr_run=1, sort=996335, sibling={2}, core={0-7}
(XEN) 	run: [0.7] pri=-1 flags=0 cpu=2 credit=50 [w=2000,cap=0]
(XEN) 	  1: [32767.2] pri=-64 flags=0 cpu=2
(XEN) CPU[03] current=d[IDLE]v3, curr=d[IDLE]v3, prev=NULL
(XEN) CPU[03] nr_run=0, sort=996329, sibling={3}, core={0-7}
(XEN) CPU[04] current=d[IDLE]v4, curr=d[IDLE]v4, prev=NULL
(XEN) CPU[04] nr_run=0, sort=996325, sibling={4}, core={0-7}
(XEN) CPU[05] current=d0v5, curr=d0v5, prev=NULL
(XEN) CPU[05] nr_run=1, sort=996334, sibling={5}, core={0-7}
(XEN) 	run: [0.5] pri=-1 flags=0 cpu=5 credit=239 [w=2000,cap=0]
(XEN) 	  1: [32767.5] pri=-64 flags=0 cpu=5
(XEN) CPU[06] current=d0v1, curr=d0v1, prev=NULL
(XEN) CPU[06] nr_run=1, sort=996334, sibling={6}, core={0-7}
(XEN) 	run: [0.1] pri=-1 flags=0 cpu=6 credit=214 [w=2000,cap=0]
(XEN) 	  1: [32767.6] pri=-64 flags=0 cpu=6
(XEN) CPU[07] current=d[IDLE]v7, curr=d[IDLE]v7, prev=NULL
(XEN) CPU[07] nr_run=0, sort=996303, sibling={7}, core={0-7}
(XEN) CPU[08] current=d[IDLE]v8, curr=d[IDLE]v8, prev=NULL
(XEN) CPU[08] nr_run=2, sort=996335, sibling={8}, core={8-15}
(XEN) 	  1: [0.4] pri=-1 flags=0 cpu=8 credit=115 [w=2000,cap=0]
(XEN) CPU[09] current=d19v1, curr=d19v1, prev=NULL
(XEN) CPU[09] nr_run=1, sort=996335, sibling={9}, core={8-15}
(XEN) 	run: [19.1] pri=-2 flags=0 cpu=9 credit=-241 [w=256,cap=0]
(XEN) 	  1: [32767.9] pri=-64 flags=0 cpu=9
(XEN) CPU[10] current=d[IDLE]v10, curr=d[IDLE]v10, prev=NULL
(XEN) CPU[10] nr_run=0, sort=996334, sibling={10}, core={8-15}
(XEN) CPU[11] current=d[IDLE]v11, curr=d[IDLE]v11, prev=NULL
(XEN) CPU[11] nr_run=0, sort=996331, sibling={11}, core={8-15}
(XEN) CPU[12] current=d[IDLE]v12, curr=d[IDLE]v12, prev=NULL
(XEN) CPU[12] nr_run=0, sort=996333, sibling={12}, core={8-15}
(XEN) CPU[13] current=d[IDLE]v13, curr=d[IDLE]v13, prev=NULL
(XEN) CPU[13] nr_run=0, sort=996334, sibling={13}, core={8-15}
(XEN) CPU[14] current=d0v14, curr=d0v14, prev=NULL
(XEN) CPU[14] nr_run=1, sort=990383, sibling={14}, core={8-15}
(XEN) 	run: [0.14] pri=0 flags=0 cpu=14 credit=-514 [w=2000,cap=0]
(XEN) 	  1: [32767.14] pri=-64 flags=0 cpu=14
(XEN) CPU[15] current=d0v6, curr=d0v6, prev=NULL
(XEN) CPU[15] nr_run=1, sort=996335, sibling={15}, core={8-15}
(XEN) 	run: [0.6] pri=-2 flags=0 cpu=15 credit=-177 [w=2000,cap=0]
(XEN) 	  1: [32767.15] pri=-64 flags=0 cpu=15
```

I attempt to get '*' but that blocked my serial console, at least I was not able to interact with it few minutes later. I'll try to get other info too. I've also uploaded the piece of this huge '*' dump here: https://gist.github.com/fepitre/36923fbc08cc2fd8bdb59b81e73a6c2e

Regards

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Dario Faggioli]

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

On Tue, 2020-10-27 at 06:58 +0100, Jürgen Groß wrote:
> On 26.10.20 17:31, Dario Faggioli wrote:
> > 
> > Or did you have something completely different in mind, and I'm
> > missing
> > it?
> 
> No, I think you are right. I mixed that up with __context_switch()
> not
> being called.
> 
Right.

> Sorry for the noise,
> 
Sure, no problem.

In fact, this issue is apparently scheduler independent. It indeed
seemd to be related to the other report we have "BUG: credit=sched2
machine hang when using DRAKVUF", but there it looks like it is
scheduler-dependant.

Might it be something that lies somewhere else, but Credit2 is
triggering it faster/easier? (Just thinking out loud...)

For Frederic, what happens is that dom0 hangs, right? So you're able to
poke at Xen with some debugkeys (like 'r' for the scheduler's status,
and the ones for the domain's vCPUs)?

If yes, it may be useful to see the output.

Regards
-- 
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Recent upgrade of 4.13 -> 4.14 issue

[Jürgen Groß]

On 26.10.20 17:31, Dario Faggioli wrote:
> On Mon, 2020-10-26 at 15:30 +0100, Jürgen Groß wrote:
>> On 26.10.20 14:54, Andrew Cooper wrote:
>>> On 26/10/2020 13:37, Frédéric Pierret wrote:
>>>>
>>>> If anyone would have any idea of what's going on, that would be
>>>> very
>>>> appreciated. Thank you.
>>>
>>> Does booting Xen with `sched=credit` make a difference?
>>
>> Hmm, I think I have spotted a problem in credit2 which could explain
>> the
>> hang:
>>
>> csched2_unit_wake() will NOT put the sched unit on a runqueue in case
>> it
>> has CSFLAG_scheduled set. This bit will be reset only in
>> csched2_context_saved().
>>
> Exactly, it does not put it back there. However, if it finds a vCPU
> with the CSFLAG_scheduled flag set, It should set
> CSFLAG_delayed_runq_add flag.
> 
> Unless curr_on_cpu(cpu)==unit or unit_on_runq(svc)==true... which
> should not be the case. Or where you saying that we actually are in one
> of this situations?
> 
> In fact...
> 
>> So in case a vcpu (and its unit, of course) is blocked and there has
>> been no other vcpu active on its physical cpu but the idle vcpu,
>> there
>> will be no call of csched2_context_saved(). This will block the vcpu
>> to become active in theory for eternity, in case there is no need to
>> run another vcpu on the physical cpu.
>>
> ...I maybe am not seeing what exact situation and sequence of events
> you're exactly thinking to. What I see is this: [*]
> 
> - vCPU V is running, i.e., CSFLAG_scheduled is set
> - vCPU V blocks
> - we enter schedule()
>    - schedule calls do_schedule() --> csched2_schedule()
>      - we pick idle, so CSFLAG_delayed_runq_add is set for V
>    - schedule calls sched_context_switch()
>      - sched_context_switch() calls context_switch()
>        - context_switch() calls sched_context_switched()
>          - sched_context_switched() calls:
>            - vcpu_context_saved()
>            - unit_context_saved()
>              - unit_context_saved() calls sched_context_saved() -->
>                                            csched2_context_saved()
>                - csched2_context_saved():
>                  - clears CSFLAG_scheduled
>                  - checks (and clear) CSFLAG_delayed_runq_add
> 
> [*] this assumes granularity 1, i.e., no core-scheduling and no
>      rendezvous. Or was core-scheduling actually enabled?
> 
> And if CSFLAG_delayed_runq_add is set **and** the vCPU is runnable, the
> task is added back to the runqueue.
> 
> So, even if we don't do the actual context switch (i.e., we don't call
> __context_switch() ) if the next vCPU that we pick when vCPU V blocks
> is the idle one, it looks to me that we go get to call
> csched2_context_saved().
> 
> And it also looks to me that, when we get to that, if the vCPU is
> runnable, even if it has the CSFLAG_scheduled still set, we do put it
> back to the runqueue.
> 
> And if the vCPU blocked, but csched2_unit_wake() run while
> CSFLAG_scheduled was still set, it indeed should mean that the vCPU
> itself will be runnable again when we get to csched2_context_saved().
> 
> Or did you have something completely different in mind, and I'm missing
> it?

No, I think you are right. I mixed that up with __context_switch() not
being called.

Sorry for the noise,


Juergen

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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



Le 10/26/20 à 6:54 PM, Dario Faggioli a écrit :
> On Mon, 2020-10-26 at 17:11 +0100, Frédéric Pierret wrote:
>> Le 10/26/20 à 2:54 PM, Andrew Cooper a écrit :
>>>> If anyone would have any idea of what's going on, that would be
>>>> very
>>>> appreciated. Thank you.
>>>
>>> Does booting Xen with `sched=credit` make a difference?
>>>
>>> ~Andrew
>>
>> Thank you Andrew. Since your mail I'm currently testing this on
>> production and it's clearly more stable than this morning. I will not
>> say yet it's solved because yesterday I had some few hours of
>> stability too. but clearly, it's encouraging because this morning it
>> was just hell every 15/30 minutes.
>>
> Ok, yes, let us know if the credit scheduler seems to not suffer from
> the issue.
> 

Yes unfortunately, I had few hours of stability but it just end up to:

```
[15883.967829] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[15883.967868] rcu: 	12-...0: (75 ticks this GP) idle=5c6/1/0x4000000000000000 softirq=139356/139357 fqs=14879
[15883.967884] 	(detected by 0, t=60002 jiffies, g=460221, q=89)
[15883.967901] Sending NMI from CPU 0 to CPUs 12:
[15893.970590] rcu: rcu_sched kthread starved for 9994 jiffies! g460221 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=9
[15893.970622] rcu: RCU grace-period kthread stack dump:
[15893.970631] rcu_sched       R  running task        0    10      2 0x80004008
[15893.970645] Call Trace:
[15893.970658]  ? xen_hypercall_xen_version+0xa/0x20
[15893.970670]  ? xen_force_evtchn_callback+0x9/0x10
[15893.970679]  ? check_events+0x12/0x20
[15893.970687]  ? xen_restore_fl_direct+0x1f/0x20
[15893.970697]  ? _raw_spin_unlock_irqrestore+0x14/0x20
[15893.970708]  ? force_qs_rnp+0x6f/0x170
[15893.970715]  ? rcu_nocb_unlock_irqrestore+0x30/0x30
[15893.970724]  ? rcu_gp_fqs_loop+0x234/0x2a0
[15893.970732]  ? rcu_gp_kthread+0xb5/0x140
[15893.970740]  ? rcu_gp_init+0x470/0x470
[15893.970748]  ? kthread+0x115/0x140
[15893.970756]  ? __kthread_bind_mask+0x60/0x60
[15893.970764]  ? ret_from_fork+0x35/0x40
[16063.972793] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[16063.972825] rcu: 	12-...0: (75 ticks this GP) idle=5c6/1/0x4000000000000000 softirq=139356/139357 fqs=57364
[16063.972840] 	(detected by 5, t=240007 jiffies, g=460221, q=6439)
[16063.972855] Sending NMI from CPU 5 to CPUs 12:
[16243.977769] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[16243.977802] rcu: 	12-...0: (75 ticks this GP) idle=5c6/1/0x4000000000000000 softirq=139356/139357 fqs=99504
[16243.977817] 	(detected by 11, t=420012 jiffies, g=460221, q=6710)
[16243.977830] Sending NMI from CPU 11 to CPUs 12:
[16253.980496] rcu: rcu_sched kthread starved for 10001 jiffies! g460221 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=9
[16253.980528] rcu: RCU grace-period kthread stack dump:
[16253.980537] rcu_sched       R  running task        0    10      2 0x80004008
[16253.980550] Call Trace:
[16253.980563]  ? xen_hypercall_xen_version+0xa/0x20
[16253.980575]  ? xen_force_evtchn_callback+0x9/0x10
[16253.980584]  ? check_events+0x12/0x20
[16253.980592]  ? xen_restore_fl_direct+0x1f/0x20
[16253.980602]  ? _raw_spin_unlock_irqrestore+0x14/0x20
[16253.980613]  ? force_qs_rnp+0x6f/0x170
[16253.980620]  ? rcu_nocb_unlock_irqrestore+0x30/0x30
[16253.980629]  ? rcu_gp_fqs_loop+0x234/0x2a0
[16253.980637]  ? rcu_gp_kthread+0xb5/0x140
[16253.980645]  ? rcu_gp_init+0x470/0x470
[16253.980653]  ? kthread+0x115/0x140
[16253.980661]  ? __kthread_bind_mask+0x60/0x60
[16253.980669]  ? ret_from_fork+0x35/0x40
[16423.982735] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[16423.982789] rcu: 	12-...0: (75 ticks this GP) idle=5c6/1/0x4000000000000000 softirq=139356/139357 fqs=139435
[16423.982820] 	(detected by 10, t=600017 jiffies, g=460221, q=7354)
[16423.982842] Sending NMI from CPU 10 to CPUs 12:
[16433.984844] rcu: rcu_sched kthread starved for 10001 jiffies! g460221 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=3
[16433.984875] rcu: RCU grace-period kthread stack dump:
[16433.984885] rcu_sched       R  running task        0    10      2 0x80004000
[16433.984897] Call Trace:
[16433.984910]  ? xen_hypercall_xen_version+0xa/0x20
[16433.984922]  ? xen_force_evtchn_callback+0x9/0x10
[16433.984931]  ? check_events+0x12/0x20
[16433.984939]  ? xen_restore_fl_direct+0x1f/0x20
[16433.984949]  ? _raw_spin_unlock_irqrestore+0x14/0x20
[16433.984960]  ? force_qs_rnp+0x6f/0x170
[16433.984967]  ? rcu_nocb_unlock_irqrestore+0x30/0x30
[16433.984976]  ? rcu_gp_fqs_loop+0x234/0x2a0
[16433.984984]  ? rcu_gp_kthread+0xb5/0x140
[16433.984992]  ? rcu_gp_init+0x470/0x470
[16433.985000]  ? kthread+0x115/0x140
[16433.985007]  ? __kthread_bind_mask+0x60/0x60
[16433.985015]  ? ret_from_fork+0x35/0x40
[16603.987677] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[16603.987710] rcu: 	12-...0: (75 ticks this GP) idle=5c6/1/0x4000000000000000 softirq=139356/139357 fqs=179313
[16603.987725] 	(detected by 0, t=780022 jiffies, g=460221, q=7869)
[16603.987740] Sending NMI from CPU 0 to CPUs 12:
[16783.992658] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[16783.992710] rcu: 	12-...0: (75 ticks this GP) idle=5c6/1/0x4000000000000000 softirq=139356/139357 fqs=219106
[16783.992741] 	(detected by 13, t=960027 jiffies, g=460221, q=8300)
[16783.992768] Sending NMI from CPU 13 to CPUs 12:
[16793.995873] rcu: rcu_sched kthread starved for 10000 jiffies! g460221 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=4
[16793.995906] rcu: RCU grace-period kthread stack dump:
[16793.995915] rcu_sched       R  running task        0    10      2 0x80004000
[16793.995930] Call Trace:
[16793.995948]  ? xen_hypercall_xen_version+0xa/0x20
[16793.995963]  ? xen_force_evtchn_callback+0x9/0x10
[16793.995972]  ? check_events+0x12/0x20
[16793.995979]  ? xen_restore_fl_direct+0x1f/0x20
[16793.995992]  ? _raw_spin_unlock_irqrestore+0x14/0x20
[16793.996004]  ? force_qs_rnp+0x6f/0x170
[16793.996012]  ? rcu_nocb_unlock_irqrestore+0x30/0x30
[16793.996021]  ? rcu_gp_fqs_loop+0x234/0x2a0
[16793.996029]  ? rcu_gp_kthread+0xb5/0x140
[16793.996037]  ? rcu_gp_init+0x470/0x470
[16793.996046]  ? kthread+0x115/0x140
[16793.996054]  ? __kthread_bind_mask+0x60/0x60
[16793.996062]  ? ret_from_fork+0x35/0x40
```

> I'm curious about another thing, though. You mentioned, in your
> previous email (and in the subject :-)) that this is a 4.13 -> 4.14
> issue for you?

This is indeed happening since I've updated xen-4.14 from 4.13 and 4.13 was totally stable for me. Server was running for months without any issue.
  
> Does that mean that the problem was not there on 4.13?
> 
> I'm asking because Credit2 was already the default scheduler in 4.13.
> 
> So, unless you were configuring things differently, you were already
> using it there.

Normally, there is a new custom patch for S3 resume from Marek (in CC) and he would be much more able than me to precise some very specific changes with respect to 4.13.

> If this is the case, it would hint at the fact that something that
> changed between .13 and .14 could be the cause.
> 
> Regards
> 

Thank you again for your help.

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Dario Faggioli]

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

On Mon, 2020-10-26 at 17:11 +0100, Frédéric Pierret wrote:
> Le 10/26/20 à 2:54 PM, Andrew Cooper a écrit :
> > > If anyone would have any idea of what's going on, that would be
> > > very
> > > appreciated. Thank you.
> > 
> > Does booting Xen with `sched=credit` make a difference?
> > 
> > ~Andrew
> 
> Thank you Andrew. Since your mail I'm currently testing this on
> production and it's clearly more stable than this morning. I will not
> say yet it's solved because yesterday I had some few hours of
> stability too. but clearly, it's encouraging because this morning it
> was just hell every 15/30 minutes.
> 
Ok, yes, let us know if the credit scheduler seems to not suffer from
the issue.

I'm curious about another thing, though. You mentioned, in your
previous email (and in the subject :-)) that this is a 4.13 -> 4.14
issue for you?

Does that mean that the problem was not there on 4.13?

I'm asking because Credit2 was already the default scheduler in 4.13. 

So, unless you were configuring things differently, you were already
using it there.

If this is the case, it would hint at the fact that something that
changed between .13 and .14 could be the cause.

Regards
-- 
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Recent upgrade of 4.13 -> 4.14 issue

[Dario Faggioli]

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

On Mon, 2020-10-26 at 15:30 +0100, Jürgen Groß wrote:
> On 26.10.20 14:54, Andrew Cooper wrote:
> > On 26/10/2020 13:37, Frédéric Pierret wrote:
> > > 
> > > If anyone would have any idea of what's going on, that would be
> > > very
> > > appreciated. Thank you.
> > 
> > Does booting Xen with `sched=credit` make a difference?
> 
> Hmm, I think I have spotted a problem in credit2 which could explain
> the
> hang:
> 
> csched2_unit_wake() will NOT put the sched unit on a runqueue in case
> it
> has CSFLAG_scheduled set. This bit will be reset only in
> csched2_context_saved().
> 
Exactly, it does not put it back there. However, if it finds a vCPU
with the CSFLAG_scheduled flag set, It should set
CSFLAG_delayed_runq_add flag.

Unless curr_on_cpu(cpu)==unit or unit_on_runq(svc)==true... which
should not be the case. Or where you saying that we actually are in one
of this situations?

In fact...

> So in case a vcpu (and its unit, of course) is blocked and there has
> been no other vcpu active on its physical cpu but the idle vcpu,
> there
> will be no call of csched2_context_saved(). This will block the vcpu
> to become active in theory for eternity, in case there is no need to
> run another vcpu on the physical cpu.
> 
...I maybe am not seeing what exact situation and sequence of events
you're exactly thinking to. What I see is this: [*]

- vCPU V is running, i.e., CSFLAG_scheduled is set
- vCPU V blocks
- we enter schedule()
  - schedule calls do_schedule() --> csched2_schedule()
    - we pick idle, so CSFLAG_delayed_runq_add is set for V
  - schedule calls sched_context_switch()
    - sched_context_switch() calls context_switch()
      - context_switch() calls sched_context_switched()
        - sched_context_switched() calls:
          - vcpu_context_saved()
          - unit_context_saved()
            - unit_context_saved() calls sched_context_saved() -->    
                                          csched2_context_saved()
              - csched2_context_saved():
                - clears CSFLAG_scheduled
                - checks (and clear) CSFLAG_delayed_runq_add

[*] this assumes granularity 1, i.e., no core-scheduling and no 
    rendezvous. Or was core-scheduling actually enabled?

And if CSFLAG_delayed_runq_add is set **and** the vCPU is runnable, the
task is added back to the runqueue.

So, even if we don't do the actual context switch (i.e., we don't call
__context_switch() ) if the next vCPU that we pick when vCPU V blocks
is the idle one, it looks to me that we go get to call
csched2_context_saved().

And it also looks to me that, when we get to that, if the vCPU is
runnable, even if it has the CSFLAG_scheduled still set, we do put it
back to the runqueue.

And if the vCPU blocked, but csched2_unit_wake() run while
CSFLAG_scheduled was still set, it indeed should mean that the vCPU
itself will be runnable again when we get to csched2_context_saved().

Or did you have something completely different in mind, and I'm missing
it?


Regards
-- 
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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



Le 10/26/20 à 2:54 PM, Andrew Cooper a écrit :
> On 26/10/2020 13:37, Frédéric Pierret wrote:
>> Hi all,
>>
>> I'm experiencing problem with a HP ProLiant DL360p Gen8 and recent
>> upgrade of 4.13 -> 4.14. dom0 and the entire system becomes unstable
>> and freeze at some point.
>>
>> I've managed to get three pieces of logs (last one after a reboot and
>> just before total freeze) by connecting to the serial console with
>> loglvl options and also redirecting linux kernel output to the serial
>> console:
>>
>> ```
>> [ 2150.954883] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
>> [ 2150.954934] rcu:     7-...0: (3 GPs behind)
>> idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=14673
>> [ 2150.954962]     (detected by 12, t=60002 jiffies, g=236593, q=126)
>> [ 2150.954984] Sending NMI from CPU 12 to CPUs 7:
>> [ 2160.968519] rcu: rcu_sched kthread starved for 10008 jiffies!
>> g236593 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=9
>> [ 2160.968568] rcu: RCU grace-period kthread stack dump:
>> [ 2160.968586] rcu_sched       R  running task        0    10      2
>> 0x80004000
>> [ 2160.968612] Call Trace:
>> [ 2160.968634]  ? xen_hypercall_xen_version+0xa/0x20
>> [ 2160.968658]  ? xen_force_evtchn_callback+0x9/0x10
>> [ 2160.968918]  ? check_events+0x12/0x20
>> [ 2160.968946]  ? schedule+0x39/0xa0
>> [ 2160.968964]  ? schedule_timeout+0x96/0x150
>> [ 2160.968981]  ? __next_timer_interrupt+0xd0/0xd0
>> [ 2160.969002]  ? rcu_gp_fqs_loop+0xea/0x2a0
>> [ 2160.969019]  ? rcu_gp_kthread+0xb5/0x140
>> [ 2160.969035]  ? rcu_gp_init+0x470/0x470
>> [ 2160.969052]  ? kthread+0x115/0x140
>> [ 2160.969067]  ? __kthread_bind_mask+0x60/0x60
>> [ 2160.969085]  ? ret_from_fork+0x35/0x40
>> ```
>>
>> and also
>>
>> ```
>> [ 2495.945931] CPU: 14 PID: 24181 Comm: Xorg Not tainted
>> 5.4.72-2.qubes.x86_64 #1
>> [ 2495.945954] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
>> 05/24/2019
>> [ 2495.945984] RIP: e030:smp_call_function_many+0x20a/0x270
>> [ 2495.946004] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff
>> 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90
>> 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
>> 8a
>> [ 2495.946051] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
>> [ 2495.946068] RAX: 0000000000000003 RBX: 0000000000000010 RCX:
>> 0000000000000007
>> [ 2495.946090] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI:
>> 0000000000000007
>> [ 2495.946113] RBP: ffffffff81082fc0 R08: 0000000000000007 R09:
>> 0000000000000000
>> [ 2495.946134] R10: 0000000000000000 R11: ffffffff8265b6a8 R12:
>> 0000000000000000
>> [ 2495.946156] R13: 0000000000000001 R14: 0000000000029ac0 R15:
>> ffff8882415a9b00
>> [ 2495.946211] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000)
>> knlGS:0000000000000000
>> [ 2495.946235] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 2495.946253] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4:
>> 0000000000040660
>> [ 2495.946290] Call Trace:
>> [ 2495.946314]  ? do_kernel_range_flush+0x50/0x50
>> [ 2495.946334]  on_each_cpu+0x28/0x50
>> [ 2495.946354]  decrease_reservation+0x22f/0x310
>> [ 2495.946377]  alloc_xenballooned_pages+0xeb/0x120
>> [ 2495.946396]  ? __kmalloc+0x183/0x260
>> [ 2495.946413]  gnttab_alloc_pages+0x11/0x40
>> [ 2495.946434]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
>> [ 2495.946454]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
>> [ 2495.946479]  do_vfs_ioctl+0x2fb/0x490
>> [ 2495.946500]  ? syscall_trace_enter+0x1d1/0x2c0
>> [ 2495.946551]  ksys_ioctl+0x5e/0x90
>> [ 2495.946567]  __x64_sys_ioctl+0x16/0x20
>> [ 2495.946583]  do_syscall_64+0x5b/0xf0
>> [ 2495.946601]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
>> [ 2495.946620] RIP: 0033:0x7a0d51f763bb
>> [ 2495.946727] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00
>> 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00
>> 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
>> 48
>> [ 2495.946804] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX:
>> 0000000000000010
>> [ 2495.946863] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:
>> 00007a0d51f763bb
>> [ 2495.946885] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI:
>> 0000000000000009
>> [ 2495.946939] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09:
>> 00007a0d51a30010
>> [ 2495.946998] R10: 0000000000000000 R11: 0000000000000206 R12:
>> 00007fffc48d5060
>> [ 2495.947020] R13: 0000000000000001 R14: 0000000000000009 R15:
>> 0000000000000001
>> [ 2510.964667] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
>> [ 2510.964716] rcu:     7-...0: (3 GPs behind)
>> idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=96182
>> [ 2510.964744]     (detected by 12, t=420012 jiffies, g=236593, q=11404)
>> [ 2510.964769] Sending NMI from CPU 12 to CPUs 7:
>> [ 2523.945643] watchdog: BUG: soft lockup - CPU#14 stuck for 22s!
>> [Xorg:24181]
>> [ 2523.945686] Modules linked in: snd_seq_dummy snd_hrtimer snd_seq
>> snd_seq_device snd_timer snd soundcore br_netfilter xt_physdev
>> xen_netback loop bridge stp llc rfkill ebtable_filter ebtables
>> ip6table_filter ip
>> 6_tables iptable_filter intel_rapl_msr iTCO_wdt ipmi_ssif
>> iTCO_vendor_support intel_rapl_common sb_edac rapl raid456
>> async_raid6_recov async_memcpy async_pq async_xor async_tx xor
>> raid6_pq pcspkr joydev hpilo lpc
>> _ich hpwdt ioatdma dca tg3 r8169 ipmi_si ipmi_devintf ipmi_msghandler
>> acpi_power_meter xenfs ip_tables dm_thin_pool dm_persistent_data
>> libcrc32c dm_bio_prison dm_crypt uas usb_storage uhci_hcd
>> crct10dif_pclmul cr
>> c32_pclmul crc32c_intel ghash_clmulni_intel mgag200 drm_kms_helper
>> serio_raw drm_vram_helper ttm drm ata_generic pata_acpi i2c_algo_bit
>> ehci_pci ehci_hcd xhci_pci xhci_hcd hpsa scsi_transport_sas
>> xen_privcmd xen_
>> pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput
>> pkcs8_key_parser
>> [ 2523.945934] CPU: 14 PID: 24181 Comm: Xorg Tainted: G
>> L    5.4.72-2.qubes.x86_64 #1
>> [ 2523.945960] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
>> 05/24/2019
>> [ 2523.945989] RIP: e030:smp_call_function_many+0x20a/0x270
>> [ 2523.946010] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff
>> 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90
>> 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
>> 8a
>> [ 2523.946057] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
>> [ 2523.946075] RAX: 0000000000000003 RBX: 0000000000000010 RCX:
>> 0000000000000007
>> [ 2523.946097] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI:
>> 0000000000000007
>> [ 2523.946119] RBP: ffffffff81082fc0 R08: 0000000000000007 R09:
>> 0000000000000000
>> [ 2523.946162] R10: 0000000000000000 R11: ffffffff8265b6a8 R12:
>> 0000000000000000
>> [ 2523.946184] R13: 0000000000000001 R14: 0000000000029ac0 R15:
>> ffff8882415a9b00
>> [ 2523.946233] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000)
>> knlGS:0000000000000000
>> [ 2523.946256] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 2523.946275] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4:
>> 0000000000040660
>> [ 2523.946313] Call Trace:
>> [ 2523.946336]  ? do_kernel_range_flush+0x50/0x50
>> [ 2523.946356]  on_each_cpu+0x28/0x50
>> [ 2523.946376]  decrease_reservation+0x22f/0x310
>> [ 2523.946397]  alloc_xenballooned_pages+0xeb/0x120
>> [ 2523.946418]  ? __kmalloc+0x183/0x260
>> [ 2523.946434]  gnttab_alloc_pages+0x11/0x40
>> [ 2523.946457]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
>> [ 2523.946478]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
>> [ 2523.946502]  do_vfs_ioctl+0x2fb/0x490
>> [ 2523.946559]  ? syscall_trace_enter+0x1d1/0x2c0
>> [ 2523.946578]  ksys_ioctl+0x5e/0x90
>> [ 2523.946594]  __x64_sys_ioctl+0x16/0x20
>> [ 2523.946610]  do_syscall_64+0x5b/0xf0
>> [ 2523.946713]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
>> [ 2523.946738] RIP: 0033:0x7a0d51f763bb
>> [ 2523.946782] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00
>> 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00
>> 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
>> 48
>> [ 2523.946867] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX:
>> 0000000000000010
>> [ 2523.946927] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:
>> 00007a0d51f763bb
>> [ 2523.946950] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI:
>> 0000000000000009
>> [ 2523.946972] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09:
>> 00007a0d51a30010
>> [ 2523.947029] R10: 0000000000000000 R11: 0000000000000206 R12:
>> 00007fffc48d5060
>> [ 2523.947051] R13: 0000000000000001 R14: 0000000000000009 R15:
>> 0000000000000001
>> ```
>>
>> and finally
>>
>> ```
>> [ 1597.971380] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
>> [ 1597.971409] rcu:     0-...0: (5 ticks this GP) idle=cd2/0/0x1
>> softirq=59121/59122 fqs=14998
>> [ 1597.971420] rcu:     7-...0: (2 ticks this GP)
>> idle=e9e/1/0x4000000000000000 softirq=49519/49519 fqs=14998
>> [ 1597.971431]     (detected by 11, t=60002 jiffies, g=234321, q=83)
>> [ 1597.971441] Sending NMI from CPU 11 to CPUs 0:
>> [ 1597.972452] NMI backtrace for cpu 0
>> [ 1597.972453] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
>> 5.4.72-2.qubes.x86_64 #1
>> [ 1597.972453] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
>> 05/24/2019
>> [ 1597.972454] RIP: e030:xen_hypercall_sched_op+0xa/0x20
>> [ 1597.972454] Code: 51 41 53 b8 1c 00 00 00 0f 05 41 5b 59 c3 cc cc
>> cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc 51 41 53 b8 1d 00 00
>> 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc
>> cc
>> [ 1597.972455] RSP: e02b:ffffc90001403d88 EFLAGS: 00000002
>> [ 1597.972456] RAX: 0000000000000000 RBX: ffff888241215f80 RCX:
>> ffffffff810013aa
>> [ 1597.972456] RDX: ffff88823c070428 RSI: ffffc90001403da8 RDI:
>> 0000000000000003
>> [ 1597.972456] RBP: ffff8882365d8bf0 R08: ffffffff8265b6a0 R09:
>> 0000000000000000
>> [ 1597.972457] R10: 0000000000000000 R11: 0000000000000202 R12:
>> 0000000000000049
>> [ 1597.972457] R13: 0000000000000100 R14: ffff8882422b6640 R15:
>> 0000000000000001
>> [ 1597.972458] FS:  0000729633b7d700(0000) GS:ffff888241200000(0000)
>> knlGS:0000000000000000
>> [ 1597.972458] CS:  10000e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 1597.972458] CR2: 000077f6508c47c0 CR3: 000000020d006000 CR4:
>> 0000000000040660
>> [ 1597.972459] Call Trace:
>> [ 1597.972459]  <IRQ>
>> [ 1597.972459]  ? xen_poll_irq+0x73/0xa0
>> [ 1597.972459]  ? xen_qlock_wait+0x7b/0x80
>> [ 1597.972460]  ? pv_wait_head_or_lock+0x85/0xb0
>> [ 1597.972460]  ? __pv_queued_spin_lock_slowpath+0xb5/0x1b0
>> [ 1597.972460]  ? _raw_spin_lock_irqsave+0x32/0x40
>> [ 1597.972461]  ? bfq_finish_requeue_request+0xb5/0x120
>> [ 1597.972461]  ? blk_mq_free_request+0x3a/0xf0
>> [ 1597.972461]  ? scsi_end_request+0x95/0x140
>> [ 1597.972461]  ? scsi_io_completion+0x74/0x190
>> [ 1597.972462]  ? blk_done_softirq+0xea/0x180
>> [ 1597.972462]  ? __do_softirq+0xd9/0x2c8
>> [ 1597.972462]  ? irq_exit+0xcf/0x110
>> [ 1597.972462]  ? xen_evtchn_do_upcall+0x2c/0x40
>> [ 1597.972463]  ? xen_do_hypervisor_callback+0x29/0x40
>> [ 1597.972463]  </IRQ>
>> [ 1597.972463]  ? xen_hypercall_sched_op+0xa/0x20
>> [ 1597.972464]  ? xen_hypercall_sched_op+0xa/0x20
>> [ 1597.972464]  ? xen_safe_halt+0xc/0x20
>> [ 1597.972464]  ? default_idle+0x1a/0x140
>> [ 1597.972465]  ? cpuidle_idle_call+0x139/0x190
>> [ 1597.972465]  ? do_idle+0x73/0xd0
>> [ 1597.972465]  ? cpu_startup_entry+0x19/0x20
>> [ 1597.972466]  ? start_kernel+0x68a/0x6bf
>> [ 1597.972466]  ? xen_start_kernel+0x6a2/0x6c1
>> [ 1597.972470] Sending NMI from CPU 11 to CPUs 7:
>> [ 1607.976873] rcu: rcu_sched kthread starved for 10007 jiffies!
>> g234321 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=11
>> [ 1607.976924] rcu: RCU grace-period kthread stack dump:
>> [ 1607.976942] rcu_sched       I    0    10      2 0x80004000
>> [ 1607.976972] Call Trace:
>> [ 1607.976999]  __schedule+0x217/0x570
>> [ 1607.977020]  ? schedule+0x39/0xa0
>> [ 1607.977038]  ? schedule_timeout+0x96/0x150
>> [ 1607.977056]  ? __next_timer_interrupt+0xd0/0xd0
>> [ 1607.977079]  ? rcu_gp_fqs_loop+0xea/0x2a0
>> [ 1607.977096]  ? rcu_gp_kthread+0xb5/0x140
>> [ 1607.977112]  ? rcu_gp_init+0x470/0x470
>> [ 1607.977130]  ? kthread+0x115/0x140
>> [ 1607.977145]  ? __kthread_bind_mask+0x60/0x60
>> [ 1607.977164]  ? ret_from_fork+0x35/0x40
>> ```
>>
>> I've tried to increase memory, set maximum of dom0 vcps to 1 or 4, pin
>> vcpus too, multiple 5.4 kernels tool...no luck.
>>
>> I've also observed that some (never the same) VM (PVH or HVM) fail to
>> start randomly because of being stuck at boot time with analog stack
>> trace as the first piece of log provided above. Those VM are
>> impossible to desroy and then it "propagates" though dom0 with the two
>> latest piece of codes.
>>
>> If anyone would have any idea of what's going on, that would be very
>> appreciated. Thank you.
> 
> Does booting Xen with `sched=credit` make a difference?
> 
> ~Andrew
> 

Thank you Andrew. Since your mail I'm currently testing this on production and it's clearly more stable than this morning. I will not say yet it's solved because yesterday I had some few hours of stability too. but clearly, it's encouraging because this morning it was just hell every 15/30 minutes.

If that helps, the server has two physical processors and 8 cores each.

Best,
Frédéric

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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

Re: Recent upgrade of 4.13 -> 4.14 issue

[Jürgen Groß]

On 26.10.20 14:54, Andrew Cooper wrote:
> On 26/10/2020 13:37, Frédéric Pierret wrote:
>> Hi all,
>>
>> I'm experiencing problem with a HP ProLiant DL360p Gen8 and recent
>> upgrade of 4.13 -> 4.14. dom0 and the entire system becomes unstable
>> and freeze at some point.
>>
>> I've managed to get three pieces of logs (last one after a reboot and
>> just before total freeze) by connecting to the serial console with
>> loglvl options and also redirecting linux kernel output to the serial
>> console:
>>
>> ```
>> [ 2150.954883] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
>> [ 2150.954934] rcu:     7-...0: (3 GPs behind)
>> idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=14673
>> [ 2150.954962]     (detected by 12, t=60002 jiffies, g=236593, q=126)
>> [ 2150.954984] Sending NMI from CPU 12 to CPUs 7:
>> [ 2160.968519] rcu: rcu_sched kthread starved for 10008 jiffies!
>> g236593 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=9
>> [ 2160.968568] rcu: RCU grace-period kthread stack dump:
>> [ 2160.968586] rcu_sched       R  running task        0    10      2
>> 0x80004000
>> [ 2160.968612] Call Trace:
>> [ 2160.968634]  ? xen_hypercall_xen_version+0xa/0x20
>> [ 2160.968658]  ? xen_force_evtchn_callback+0x9/0x10
>> [ 2160.968918]  ? check_events+0x12/0x20
>> [ 2160.968946]  ? schedule+0x39/0xa0
>> [ 2160.968964]  ? schedule_timeout+0x96/0x150
>> [ 2160.968981]  ? __next_timer_interrupt+0xd0/0xd0
>> [ 2160.969002]  ? rcu_gp_fqs_loop+0xea/0x2a0
>> [ 2160.969019]  ? rcu_gp_kthread+0xb5/0x140
>> [ 2160.969035]  ? rcu_gp_init+0x470/0x470
>> [ 2160.969052]  ? kthread+0x115/0x140
>> [ 2160.969067]  ? __kthread_bind_mask+0x60/0x60
>> [ 2160.969085]  ? ret_from_fork+0x35/0x40
>> ```
>>
>> and also
>>
>> ```
>> [ 2495.945931] CPU: 14 PID: 24181 Comm: Xorg Not tainted
>> 5.4.72-2.qubes.x86_64 #1
>> [ 2495.945954] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
>> 05/24/2019
>> [ 2495.945984] RIP: e030:smp_call_function_many+0x20a/0x270
>> [ 2495.946004] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff
>> 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90
>> 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
>> 8a
>> [ 2495.946051] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
>> [ 2495.946068] RAX: 0000000000000003 RBX: 0000000000000010 RCX:
>> 0000000000000007
>> [ 2495.946090] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI:
>> 0000000000000007
>> [ 2495.946113] RBP: ffffffff81082fc0 R08: 0000000000000007 R09:
>> 0000000000000000
>> [ 2495.946134] R10: 0000000000000000 R11: ffffffff8265b6a8 R12:
>> 0000000000000000
>> [ 2495.946156] R13: 0000000000000001 R14: 0000000000029ac0 R15:
>> ffff8882415a9b00
>> [ 2495.946211] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000)
>> knlGS:0000000000000000
>> [ 2495.946235] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 2495.946253] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4:
>> 0000000000040660
>> [ 2495.946290] Call Trace:
>> [ 2495.946314]  ? do_kernel_range_flush+0x50/0x50
>> [ 2495.946334]  on_each_cpu+0x28/0x50
>> [ 2495.946354]  decrease_reservation+0x22f/0x310
>> [ 2495.946377]  alloc_xenballooned_pages+0xeb/0x120
>> [ 2495.946396]  ? __kmalloc+0x183/0x260
>> [ 2495.946413]  gnttab_alloc_pages+0x11/0x40
>> [ 2495.946434]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
>> [ 2495.946454]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
>> [ 2495.946479]  do_vfs_ioctl+0x2fb/0x490
>> [ 2495.946500]  ? syscall_trace_enter+0x1d1/0x2c0
>> [ 2495.946551]  ksys_ioctl+0x5e/0x90
>> [ 2495.946567]  __x64_sys_ioctl+0x16/0x20
>> [ 2495.946583]  do_syscall_64+0x5b/0xf0
>> [ 2495.946601]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
>> [ 2495.946620] RIP: 0033:0x7a0d51f763bb
>> [ 2495.946727] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00
>> 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00
>> 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
>> 48
>> [ 2495.946804] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX:
>> 0000000000000010
>> [ 2495.946863] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:
>> 00007a0d51f763bb
>> [ 2495.946885] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI:
>> 0000000000000009
>> [ 2495.946939] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09:
>> 00007a0d51a30010
>> [ 2495.946998] R10: 0000000000000000 R11: 0000000000000206 R12:
>> 00007fffc48d5060
>> [ 2495.947020] R13: 0000000000000001 R14: 0000000000000009 R15:
>> 0000000000000001
>> [ 2510.964667] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
>> [ 2510.964716] rcu:     7-...0: (3 GPs behind)
>> idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=96182
>> [ 2510.964744]     (detected by 12, t=420012 jiffies, g=236593, q=11404)
>> [ 2510.964769] Sending NMI from CPU 12 to CPUs 7:
>> [ 2523.945643] watchdog: BUG: soft lockup - CPU#14 stuck for 22s!
>> [Xorg:24181]
>> [ 2523.945686] Modules linked in: snd_seq_dummy snd_hrtimer snd_seq
>> snd_seq_device snd_timer snd soundcore br_netfilter xt_physdev
>> xen_netback loop bridge stp llc rfkill ebtable_filter ebtables
>> ip6table_filter ip
>> 6_tables iptable_filter intel_rapl_msr iTCO_wdt ipmi_ssif
>> iTCO_vendor_support intel_rapl_common sb_edac rapl raid456
>> async_raid6_recov async_memcpy async_pq async_xor async_tx xor
>> raid6_pq pcspkr joydev hpilo lpc
>> _ich hpwdt ioatdma dca tg3 r8169 ipmi_si ipmi_devintf ipmi_msghandler
>> acpi_power_meter xenfs ip_tables dm_thin_pool dm_persistent_data
>> libcrc32c dm_bio_prison dm_crypt uas usb_storage uhci_hcd
>> crct10dif_pclmul cr
>> c32_pclmul crc32c_intel ghash_clmulni_intel mgag200 drm_kms_helper
>> serio_raw drm_vram_helper ttm drm ata_generic pata_acpi i2c_algo_bit
>> ehci_pci ehci_hcd xhci_pci xhci_hcd hpsa scsi_transport_sas
>> xen_privcmd xen_
>> pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput
>> pkcs8_key_parser
>> [ 2523.945934] CPU: 14 PID: 24181 Comm: Xorg Tainted: G
>> L    5.4.72-2.qubes.x86_64 #1
>> [ 2523.945960] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
>> 05/24/2019
>> [ 2523.945989] RIP: e030:smp_call_function_many+0x20a/0x270
>> [ 2523.946010] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff
>> 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90
>> 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
>> 8a
>> [ 2523.946057] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
>> [ 2523.946075] RAX: 0000000000000003 RBX: 0000000000000010 RCX:
>> 0000000000000007
>> [ 2523.946097] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI:
>> 0000000000000007
>> [ 2523.946119] RBP: ffffffff81082fc0 R08: 0000000000000007 R09:
>> 0000000000000000
>> [ 2523.946162] R10: 0000000000000000 R11: ffffffff8265b6a8 R12:
>> 0000000000000000
>> [ 2523.946184] R13: 0000000000000001 R14: 0000000000029ac0 R15:
>> ffff8882415a9b00
>> [ 2523.946233] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000)
>> knlGS:0000000000000000
>> [ 2523.946256] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 2523.946275] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4:
>> 0000000000040660
>> [ 2523.946313] Call Trace:
>> [ 2523.946336]  ? do_kernel_range_flush+0x50/0x50
>> [ 2523.946356]  on_each_cpu+0x28/0x50
>> [ 2523.946376]  decrease_reservation+0x22f/0x310
>> [ 2523.946397]  alloc_xenballooned_pages+0xeb/0x120
>> [ 2523.946418]  ? __kmalloc+0x183/0x260
>> [ 2523.946434]  gnttab_alloc_pages+0x11/0x40
>> [ 2523.946457]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
>> [ 2523.946478]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
>> [ 2523.946502]  do_vfs_ioctl+0x2fb/0x490
>> [ 2523.946559]  ? syscall_trace_enter+0x1d1/0x2c0
>> [ 2523.946578]  ksys_ioctl+0x5e/0x90
>> [ 2523.946594]  __x64_sys_ioctl+0x16/0x20
>> [ 2523.946610]  do_syscall_64+0x5b/0xf0
>> [ 2523.946713]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
>> [ 2523.946738] RIP: 0033:0x7a0d51f763bb
>> [ 2523.946782] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00
>> 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00
>> 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
>> 48
>> [ 2523.946867] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX:
>> 0000000000000010
>> [ 2523.946927] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:
>> 00007a0d51f763bb
>> [ 2523.946950] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI:
>> 0000000000000009
>> [ 2523.946972] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09:
>> 00007a0d51a30010
>> [ 2523.947029] R10: 0000000000000000 R11: 0000000000000206 R12:
>> 00007fffc48d5060
>> [ 2523.947051] R13: 0000000000000001 R14: 0000000000000009 R15:
>> 0000000000000001
>> ```
>>
>> and finally
>>
>> ```
>> [ 1597.971380] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
>> [ 1597.971409] rcu:     0-...0: (5 ticks this GP) idle=cd2/0/0x1
>> softirq=59121/59122 fqs=14998
>> [ 1597.971420] rcu:     7-...0: (2 ticks this GP)
>> idle=e9e/1/0x4000000000000000 softirq=49519/49519 fqs=14998
>> [ 1597.971431]     (detected by 11, t=60002 jiffies, g=234321, q=83)
>> [ 1597.971441] Sending NMI from CPU 11 to CPUs 0:
>> [ 1597.972452] NMI backtrace for cpu 0
>> [ 1597.972453] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
>> 5.4.72-2.qubes.x86_64 #1
>> [ 1597.972453] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
>> 05/24/2019
>> [ 1597.972454] RIP: e030:xen_hypercall_sched_op+0xa/0x20
>> [ 1597.972454] Code: 51 41 53 b8 1c 00 00 00 0f 05 41 5b 59 c3 cc cc
>> cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc 51 41 53 b8 1d 00 00
>> 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc
>> cc
>> [ 1597.972455] RSP: e02b:ffffc90001403d88 EFLAGS: 00000002
>> [ 1597.972456] RAX: 0000000000000000 RBX: ffff888241215f80 RCX:
>> ffffffff810013aa
>> [ 1597.972456] RDX: ffff88823c070428 RSI: ffffc90001403da8 RDI:
>> 0000000000000003
>> [ 1597.972456] RBP: ffff8882365d8bf0 R08: ffffffff8265b6a0 R09:
>> 0000000000000000
>> [ 1597.972457] R10: 0000000000000000 R11: 0000000000000202 R12:
>> 0000000000000049
>> [ 1597.972457] R13: 0000000000000100 R14: ffff8882422b6640 R15:
>> 0000000000000001
>> [ 1597.972458] FS:  0000729633b7d700(0000) GS:ffff888241200000(0000)
>> knlGS:0000000000000000
>> [ 1597.972458] CS:  10000e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 1597.972458] CR2: 000077f6508c47c0 CR3: 000000020d006000 CR4:
>> 0000000000040660
>> [ 1597.972459] Call Trace:
>> [ 1597.972459]  <IRQ>
>> [ 1597.972459]  ? xen_poll_irq+0x73/0xa0
>> [ 1597.972459]  ? xen_qlock_wait+0x7b/0x80
>> [ 1597.972460]  ? pv_wait_head_or_lock+0x85/0xb0
>> [ 1597.972460]  ? __pv_queued_spin_lock_slowpath+0xb5/0x1b0
>> [ 1597.972460]  ? _raw_spin_lock_irqsave+0x32/0x40
>> [ 1597.972461]  ? bfq_finish_requeue_request+0xb5/0x120
>> [ 1597.972461]  ? blk_mq_free_request+0x3a/0xf0
>> [ 1597.972461]  ? scsi_end_request+0x95/0x140
>> [ 1597.972461]  ? scsi_io_completion+0x74/0x190
>> [ 1597.972462]  ? blk_done_softirq+0xea/0x180
>> [ 1597.972462]  ? __do_softirq+0xd9/0x2c8
>> [ 1597.972462]  ? irq_exit+0xcf/0x110
>> [ 1597.972462]  ? xen_evtchn_do_upcall+0x2c/0x40
>> [ 1597.972463]  ? xen_do_hypervisor_callback+0x29/0x40
>> [ 1597.972463]  </IRQ>
>> [ 1597.972463]  ? xen_hypercall_sched_op+0xa/0x20
>> [ 1597.972464]  ? xen_hypercall_sched_op+0xa/0x20
>> [ 1597.972464]  ? xen_safe_halt+0xc/0x20
>> [ 1597.972464]  ? default_idle+0x1a/0x140
>> [ 1597.972465]  ? cpuidle_idle_call+0x139/0x190
>> [ 1597.972465]  ? do_idle+0x73/0xd0
>> [ 1597.972465]  ? cpu_startup_entry+0x19/0x20
>> [ 1597.972466]  ? start_kernel+0x68a/0x6bf
>> [ 1597.972466]  ? xen_start_kernel+0x6a2/0x6c1
>> [ 1597.972470] Sending NMI from CPU 11 to CPUs 7:
>> [ 1607.976873] rcu: rcu_sched kthread starved for 10007 jiffies!
>> g234321 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=11
>> [ 1607.976924] rcu: RCU grace-period kthread stack dump:
>> [ 1607.976942] rcu_sched       I    0    10      2 0x80004000
>> [ 1607.976972] Call Trace:
>> [ 1607.976999]  __schedule+0x217/0x570
>> [ 1607.977020]  ? schedule+0x39/0xa0
>> [ 1607.977038]  ? schedule_timeout+0x96/0x150
>> [ 1607.977056]  ? __next_timer_interrupt+0xd0/0xd0
>> [ 1607.977079]  ? rcu_gp_fqs_loop+0xea/0x2a0
>> [ 1607.977096]  ? rcu_gp_kthread+0xb5/0x140
>> [ 1607.977112]  ? rcu_gp_init+0x470/0x470
>> [ 1607.977130]  ? kthread+0x115/0x140
>> [ 1607.977145]  ? __kthread_bind_mask+0x60/0x60
>> [ 1607.977164]  ? ret_from_fork+0x35/0x40
>> ```
>>
>> I've tried to increase memory, set maximum of dom0 vcps to 1 or 4, pin
>> vcpus too, multiple 5.4 kernels tool...no luck.
>>
>> I've also observed that some (never the same) VM (PVH or HVM) fail to
>> start randomly because of being stuck at boot time with analog stack
>> trace as the first piece of log provided above. Those VM are
>> impossible to desroy and then it "propagates" though dom0 with the two
>> latest piece of codes.
>>
>> If anyone would have any idea of what's going on, that would be very
>> appreciated. Thank you.
> 
> Does booting Xen with `sched=credit` make a difference?

Hmm, I think I have spotted a problem in credit2 which could explain the
hang:

csched2_unit_wake() will NOT put the sched unit on a runqueue in case it
has CSFLAG_scheduled set. This bit will be reset only in
csched2_context_saved().

So in case a vcpu (and its unit, of course) is blocked and there has
been no other vcpu active on its physical cpu but the idle vcpu, there
will be no call of csched2_context_saved(). This will block the vcpu
to become active in theory for eternity, in case there is no need to
run another vcpu on the physical cpu.

Thoughts?


Juergen

Re: Recent upgrade of 4.13 -> 4.14 issue

[Andrew Cooper]

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

On 26/10/2020 13:37, Frédéric Pierret wrote:
> Hi all,
>
> I'm experiencing problem with a HP ProLiant DL360p Gen8 and recent
> upgrade of 4.13 -> 4.14. dom0 and the entire system becomes unstable
> and freeze at some point.
>
> I've managed to get three pieces of logs (last one after a reboot and
> just before total freeze) by connecting to the serial console with
> loglvl options and also redirecting linux kernel output to the serial
> console:
>
> ```
> [ 2150.954883] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 2150.954934] rcu:     7-...0: (3 GPs behind)
> idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=14673
> [ 2150.954962]     (detected by 12, t=60002 jiffies, g=236593, q=126)
> [ 2150.954984] Sending NMI from CPU 12 to CPUs 7:
> [ 2160.968519] rcu: rcu_sched kthread starved for 10008 jiffies!
> g236593 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=9
> [ 2160.968568] rcu: RCU grace-period kthread stack dump:
> [ 2160.968586] rcu_sched       R  running task        0    10      2
> 0x80004000
> [ 2160.968612] Call Trace:
> [ 2160.968634]  ? xen_hypercall_xen_version+0xa/0x20
> [ 2160.968658]  ? xen_force_evtchn_callback+0x9/0x10
> [ 2160.968918]  ? check_events+0x12/0x20
> [ 2160.968946]  ? schedule+0x39/0xa0
> [ 2160.968964]  ? schedule_timeout+0x96/0x150
> [ 2160.968981]  ? __next_timer_interrupt+0xd0/0xd0
> [ 2160.969002]  ? rcu_gp_fqs_loop+0xea/0x2a0
> [ 2160.969019]  ? rcu_gp_kthread+0xb5/0x140
> [ 2160.969035]  ? rcu_gp_init+0x470/0x470
> [ 2160.969052]  ? kthread+0x115/0x140
> [ 2160.969067]  ? __kthread_bind_mask+0x60/0x60
> [ 2160.969085]  ? ret_from_fork+0x35/0x40
> ```
>
> and also
>
> ```
> [ 2495.945931] CPU: 14 PID: 24181 Comm: Xorg Not tainted
> 5.4.72-2.qubes.x86_64 #1
> [ 2495.945954] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
> 05/24/2019
> [ 2495.945984] RIP: e030:smp_call_function_many+0x20a/0x270
> [ 2495.946004] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff
> 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90
> 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
> 8a
> [ 2495.946051] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
> [ 2495.946068] RAX: 0000000000000003 RBX: 0000000000000010 RCX:
> 0000000000000007
> [ 2495.946090] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI:
> 0000000000000007
> [ 2495.946113] RBP: ffffffff81082fc0 R08: 0000000000000007 R09:
> 0000000000000000
> [ 2495.946134] R10: 0000000000000000 R11: ffffffff8265b6a8 R12:
> 0000000000000000
> [ 2495.946156] R13: 0000000000000001 R14: 0000000000029ac0 R15:
> ffff8882415a9b00
> [ 2495.946211] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000)
> knlGS:0000000000000000
> [ 2495.946235] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 2495.946253] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4:
> 0000000000040660
> [ 2495.946290] Call Trace:
> [ 2495.946314]  ? do_kernel_range_flush+0x50/0x50
> [ 2495.946334]  on_each_cpu+0x28/0x50
> [ 2495.946354]  decrease_reservation+0x22f/0x310
> [ 2495.946377]  alloc_xenballooned_pages+0xeb/0x120
> [ 2495.946396]  ? __kmalloc+0x183/0x260
> [ 2495.946413]  gnttab_alloc_pages+0x11/0x40
> [ 2495.946434]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
> [ 2495.946454]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
> [ 2495.946479]  do_vfs_ioctl+0x2fb/0x490
> [ 2495.946500]  ? syscall_trace_enter+0x1d1/0x2c0
> [ 2495.946551]  ksys_ioctl+0x5e/0x90
> [ 2495.946567]  __x64_sys_ioctl+0x16/0x20
> [ 2495.946583]  do_syscall_64+0x5b/0xf0
> [ 2495.946601]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 2495.946620] RIP: 0033:0x7a0d51f763bb
> [ 2495.946727] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00
> 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00
> 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
> 48
> [ 2495.946804] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX:
> 0000000000000010
> [ 2495.946863] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:
> 00007a0d51f763bb
> [ 2495.946885] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI:
> 0000000000000009
> [ 2495.946939] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09:
> 00007a0d51a30010
> [ 2495.946998] R10: 0000000000000000 R11: 0000000000000206 R12:
> 00007fffc48d5060
> [ 2495.947020] R13: 0000000000000001 R14: 0000000000000009 R15:
> 0000000000000001
> [ 2510.964667] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 2510.964716] rcu:     7-...0: (3 GPs behind)
> idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=96182
> [ 2510.964744]     (detected by 12, t=420012 jiffies, g=236593, q=11404)
> [ 2510.964769] Sending NMI from CPU 12 to CPUs 7:
> [ 2523.945643] watchdog: BUG: soft lockup - CPU#14 stuck for 22s!
> [Xorg:24181]
> [ 2523.945686] Modules linked in: snd_seq_dummy snd_hrtimer snd_seq
> snd_seq_device snd_timer snd soundcore br_netfilter xt_physdev
> xen_netback loop bridge stp llc rfkill ebtable_filter ebtables
> ip6table_filter ip
> 6_tables iptable_filter intel_rapl_msr iTCO_wdt ipmi_ssif
> iTCO_vendor_support intel_rapl_common sb_edac rapl raid456
> async_raid6_recov async_memcpy async_pq async_xor async_tx xor
> raid6_pq pcspkr joydev hpilo lpc
> _ich hpwdt ioatdma dca tg3 r8169 ipmi_si ipmi_devintf ipmi_msghandler
> acpi_power_meter xenfs ip_tables dm_thin_pool dm_persistent_data
> libcrc32c dm_bio_prison dm_crypt uas usb_storage uhci_hcd
> crct10dif_pclmul cr
> c32_pclmul crc32c_intel ghash_clmulni_intel mgag200 drm_kms_helper
> serio_raw drm_vram_helper ttm drm ata_generic pata_acpi i2c_algo_bit
> ehci_pci ehci_hcd xhci_pci xhci_hcd hpsa scsi_transport_sas
> xen_privcmd xen_
> pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput
> pkcs8_key_parser
> [ 2523.945934] CPU: 14 PID: 24181 Comm: Xorg Tainted: G            
> L    5.4.72-2.qubes.x86_64 #1
> [ 2523.945960] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
> 05/24/2019
> [ 2523.945989] RIP: e030:smp_call_function_many+0x20a/0x270
> [ 2523.946010] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff
> 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90
> 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
> 8a
> [ 2523.946057] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
> [ 2523.946075] RAX: 0000000000000003 RBX: 0000000000000010 RCX:
> 0000000000000007
> [ 2523.946097] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI:
> 0000000000000007
> [ 2523.946119] RBP: ffffffff81082fc0 R08: 0000000000000007 R09:
> 0000000000000000
> [ 2523.946162] R10: 0000000000000000 R11: ffffffff8265b6a8 R12:
> 0000000000000000
> [ 2523.946184] R13: 0000000000000001 R14: 0000000000029ac0 R15:
> ffff8882415a9b00
> [ 2523.946233] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000)
> knlGS:0000000000000000
> [ 2523.946256] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 2523.946275] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4:
> 0000000000040660
> [ 2523.946313] Call Trace:
> [ 2523.946336]  ? do_kernel_range_flush+0x50/0x50
> [ 2523.946356]  on_each_cpu+0x28/0x50
> [ 2523.946376]  decrease_reservation+0x22f/0x310
> [ 2523.946397]  alloc_xenballooned_pages+0xeb/0x120
> [ 2523.946418]  ? __kmalloc+0x183/0x260
> [ 2523.946434]  gnttab_alloc_pages+0x11/0x40
> [ 2523.946457]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
> [ 2523.946478]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
> [ 2523.946502]  do_vfs_ioctl+0x2fb/0x490
> [ 2523.946559]  ? syscall_trace_enter+0x1d1/0x2c0
> [ 2523.946578]  ksys_ioctl+0x5e/0x90
> [ 2523.946594]  __x64_sys_ioctl+0x16/0x20
> [ 2523.946610]  do_syscall_64+0x5b/0xf0
> [ 2523.946713]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [ 2523.946738] RIP: 0033:0x7a0d51f763bb
> [ 2523.946782] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00
> 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00
> 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
> 48
> [ 2523.946867] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX:
> 0000000000000010
> [ 2523.946927] RAX: ffffffffffffffda RBX: 0000000000001000 RCX:
> 00007a0d51f763bb
> [ 2523.946950] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI:
> 0000000000000009
> [ 2523.946972] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09:
> 00007a0d51a30010
> [ 2523.947029] R10: 0000000000000000 R11: 0000000000000206 R12:
> 00007fffc48d5060
> [ 2523.947051] R13: 0000000000000001 R14: 0000000000000009 R15:
> 0000000000000001
> ```
>
> and finally
>
> ```
> [ 1597.971380] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
> [ 1597.971409] rcu:     0-...0: (5 ticks this GP) idle=cd2/0/0x1
> softirq=59121/59122 fqs=14998
> [ 1597.971420] rcu:     7-...0: (2 ticks this GP)
> idle=e9e/1/0x4000000000000000 softirq=49519/49519 fqs=14998
> [ 1597.971431]     (detected by 11, t=60002 jiffies, g=234321, q=83)
> [ 1597.971441] Sending NMI from CPU 11 to CPUs 0:
> [ 1597.972452] NMI backtrace for cpu 0
> [ 1597.972453] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
> 5.4.72-2.qubes.x86_64 #1
> [ 1597.972453] Hardware name: HP ProLiant DL360p Gen8, BIOS P71
> 05/24/2019
> [ 1597.972454] RIP: e030:xen_hypercall_sched_op+0xa/0x20
> [ 1597.972454] Code: 51 41 53 b8 1c 00 00 00 0f 05 41 5b 59 c3 cc cc
> cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc 51 41 53 b8 1d 00 00
> 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc
> cc
> [ 1597.972455] RSP: e02b:ffffc90001403d88 EFLAGS: 00000002
> [ 1597.972456] RAX: 0000000000000000 RBX: ffff888241215f80 RCX:
> ffffffff810013aa
> [ 1597.972456] RDX: ffff88823c070428 RSI: ffffc90001403da8 RDI:
> 0000000000000003
> [ 1597.972456] RBP: ffff8882365d8bf0 R08: ffffffff8265b6a0 R09:
> 0000000000000000
> [ 1597.972457] R10: 0000000000000000 R11: 0000000000000202 R12:
> 0000000000000049
> [ 1597.972457] R13: 0000000000000100 R14: ffff8882422b6640 R15:
> 0000000000000001
> [ 1597.972458] FS:  0000729633b7d700(0000) GS:ffff888241200000(0000)
> knlGS:0000000000000000
> [ 1597.972458] CS:  10000e030 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 1597.972458] CR2: 000077f6508c47c0 CR3: 000000020d006000 CR4:
> 0000000000040660
> [ 1597.972459] Call Trace:
> [ 1597.972459]  <IRQ>
> [ 1597.972459]  ? xen_poll_irq+0x73/0xa0
> [ 1597.972459]  ? xen_qlock_wait+0x7b/0x80
> [ 1597.972460]  ? pv_wait_head_or_lock+0x85/0xb0
> [ 1597.972460]  ? __pv_queued_spin_lock_slowpath+0xb5/0x1b0
> [ 1597.972460]  ? _raw_spin_lock_irqsave+0x32/0x40
> [ 1597.972461]  ? bfq_finish_requeue_request+0xb5/0x120
> [ 1597.972461]  ? blk_mq_free_request+0x3a/0xf0
> [ 1597.972461]  ? scsi_end_request+0x95/0x140
> [ 1597.972461]  ? scsi_io_completion+0x74/0x190
> [ 1597.972462]  ? blk_done_softirq+0xea/0x180
> [ 1597.972462]  ? __do_softirq+0xd9/0x2c8
> [ 1597.972462]  ? irq_exit+0xcf/0x110
> [ 1597.972462]  ? xen_evtchn_do_upcall+0x2c/0x40
> [ 1597.972463]  ? xen_do_hypervisor_callback+0x29/0x40
> [ 1597.972463]  </IRQ>
> [ 1597.972463]  ? xen_hypercall_sched_op+0xa/0x20
> [ 1597.972464]  ? xen_hypercall_sched_op+0xa/0x20
> [ 1597.972464]  ? xen_safe_halt+0xc/0x20
> [ 1597.972464]  ? default_idle+0x1a/0x140
> [ 1597.972465]  ? cpuidle_idle_call+0x139/0x190
> [ 1597.972465]  ? do_idle+0x73/0xd0
> [ 1597.972465]  ? cpu_startup_entry+0x19/0x20
> [ 1597.972466]  ? start_kernel+0x68a/0x6bf
> [ 1597.972466]  ? xen_start_kernel+0x6a2/0x6c1
> [ 1597.972470] Sending NMI from CPU 11 to CPUs 7:
> [ 1607.976873] rcu: rcu_sched kthread starved for 10007 jiffies!
> g234321 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=11
> [ 1607.976924] rcu: RCU grace-period kthread stack dump:
> [ 1607.976942] rcu_sched       I    0    10      2 0x80004000
> [ 1607.976972] Call Trace:
> [ 1607.976999]  __schedule+0x217/0x570
> [ 1607.977020]  ? schedule+0x39/0xa0
> [ 1607.977038]  ? schedule_timeout+0x96/0x150
> [ 1607.977056]  ? __next_timer_interrupt+0xd0/0xd0
> [ 1607.977079]  ? rcu_gp_fqs_loop+0xea/0x2a0
> [ 1607.977096]  ? rcu_gp_kthread+0xb5/0x140
> [ 1607.977112]  ? rcu_gp_init+0x470/0x470
> [ 1607.977130]  ? kthread+0x115/0x140
> [ 1607.977145]  ? __kthread_bind_mask+0x60/0x60
> [ 1607.977164]  ? ret_from_fork+0x35/0x40
> ```
>
> I've tried to increase memory, set maximum of dom0 vcps to 1 or 4, pin
> vcpus too, multiple 5.4 kernels tool...no luck.
>
> I've also observed that some (never the same) VM (PVH or HVM) fail to
> start randomly because of being stuck at boot time with analog stack
> trace as the first piece of log provided above. Those VM are
> impossible to desroy and then it "propagates" though dom0 with the two
> latest piece of codes.
>
> If anyone would have any idea of what's going on, that would be very
> appreciated. Thank you.

Does booting Xen with `sched=credit` make a difference?

~Andrew


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

Recent upgrade of 4.13 -> 4.14 issue

[Frédéric Pierret]

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

Hi all,

I'm experiencing problem with a HP ProLiant DL360p Gen8 and recent upgrade of 4.13 -> 4.14. dom0 and the entire system becomes unstable and freeze at some point.

I've managed to get three pieces of logs (last one after a reboot and just before total freeze) by connecting to the serial console with loglvl options and also redirecting linux kernel output to the serial console:

```
[ 2150.954883] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 2150.954934] rcu: 	7-...0: (3 GPs behind) idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=14673
[ 2150.954962] 	(detected by 12, t=60002 jiffies, g=236593, q=126)
[ 2150.954984] Sending NMI from CPU 12 to CPUs 7:
[ 2160.968519] rcu: rcu_sched kthread starved for 10008 jiffies! g236593 f0x0 RCU_GP_DOING_FQS(6) ->state=0x0 ->cpu=9
[ 2160.968568] rcu: RCU grace-period kthread stack dump:
[ 2160.968586] rcu_sched       R  running task        0    10      2 0x80004000
[ 2160.968612] Call Trace:
[ 2160.968634]  ? xen_hypercall_xen_version+0xa/0x20
[ 2160.968658]  ? xen_force_evtchn_callback+0x9/0x10
[ 2160.968918]  ? check_events+0x12/0x20
[ 2160.968946]  ? schedule+0x39/0xa0
[ 2160.968964]  ? schedule_timeout+0x96/0x150
[ 2160.968981]  ? __next_timer_interrupt+0xd0/0xd0
[ 2160.969002]  ? rcu_gp_fqs_loop+0xea/0x2a0
[ 2160.969019]  ? rcu_gp_kthread+0xb5/0x140
[ 2160.969035]  ? rcu_gp_init+0x470/0x470
[ 2160.969052]  ? kthread+0x115/0x140
[ 2160.969067]  ? __kthread_bind_mask+0x60/0x60
[ 2160.969085]  ? ret_from_fork+0x35/0x40
```

and also

```
[ 2495.945931] CPU: 14 PID: 24181 Comm: Xorg Not tainted 5.4.72-2.qubes.x86_64 #1
[ 2495.945954] Hardware name: HP ProLiant DL360p Gen8, BIOS P71 05/24/2019
[ 2495.945984] RIP: e030:smp_call_function_many+0x20a/0x270
[ 2495.946004] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
8a
[ 2495.946051] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
[ 2495.946068] RAX: 0000000000000003 RBX: 0000000000000010 RCX: 0000000000000007
[ 2495.946090] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI: 0000000000000007
[ 2495.946113] RBP: ffffffff81082fc0 R08: 0000000000000007 R09: 0000000000000000
[ 2495.946134] R10: 0000000000000000 R11: ffffffff8265b6a8 R12: 0000000000000000
[ 2495.946156] R13: 0000000000000001 R14: 0000000000029ac0 R15: ffff8882415a9b00
[ 2495.946211] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000) knlGS:0000000000000000
[ 2495.946235] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2495.946253] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4: 0000000000040660
[ 2495.946290] Call Trace:
[ 2495.946314]  ? do_kernel_range_flush+0x50/0x50
[ 2495.946334]  on_each_cpu+0x28/0x50
[ 2495.946354]  decrease_reservation+0x22f/0x310
[ 2495.946377]  alloc_xenballooned_pages+0xeb/0x120
[ 2495.946396]  ? __kmalloc+0x183/0x260
[ 2495.946413]  gnttab_alloc_pages+0x11/0x40
[ 2495.946434]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
[ 2495.946454]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
[ 2495.946479]  do_vfs_ioctl+0x2fb/0x490
[ 2495.946500]  ? syscall_trace_enter+0x1d1/0x2c0
[ 2495.946551]  ksys_ioctl+0x5e/0x90
[ 2495.946567]  __x64_sys_ioctl+0x16/0x20
[ 2495.946583]  do_syscall_64+0x5b/0xf0
[ 2495.946601]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 2495.946620] RIP: 0033:0x7a0d51f763bb
[ 2495.946727] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
48
[ 2495.946804] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[ 2495.946863] RAX: ffffffffffffffda RBX: 0000000000001000 RCX: 00007a0d51f763bb
[ 2495.946885] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI: 0000000000000009
[ 2495.946939] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09: 00007a0d51a30010
[ 2495.946998] R10: 0000000000000000 R11: 0000000000000206 R12: 00007fffc48d5060
[ 2495.947020] R13: 0000000000000001 R14: 0000000000000009 R15: 0000000000000001
[ 2510.964667] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 2510.964716] rcu: 	7-...0: (3 GPs behind) idle=842/1/0x4000000000000000 softirq=64670/64671 fqs=96182
[ 2510.964744] 	(detected by 12, t=420012 jiffies, g=236593, q=11404)
[ 2510.964769] Sending NMI from CPU 12 to CPUs 7:
[ 2523.945643] watchdog: BUG: soft lockup - CPU#14 stuck for 22s! [Xorg:24181]
[ 2523.945686] Modules linked in: snd_seq_dummy snd_hrtimer snd_seq snd_seq_device snd_timer snd soundcore br_netfilter xt_physdev xen_netback loop bridge stp llc rfkill ebtable_filter ebtables ip6table_filter ip
6_tables iptable_filter intel_rapl_msr iTCO_wdt ipmi_ssif iTCO_vendor_support intel_rapl_common sb_edac rapl raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq pcspkr joydev hpilo lpc
_ich hpwdt ioatdma dca tg3 r8169 ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter xenfs ip_tables dm_thin_pool dm_persistent_data libcrc32c dm_bio_prison dm_crypt uas usb_storage uhci_hcd crct10dif_pclmul cr
c32_pclmul crc32c_intel ghash_clmulni_intel mgag200 drm_kms_helper serio_raw drm_vram_helper ttm drm ata_generic pata_acpi i2c_algo_bit ehci_pci ehci_hcd xhci_pci xhci_hcd hpsa scsi_transport_sas xen_privcmd xen_
pciback xen_blkback xen_gntalloc xen_gntdev xen_evtchn uinput pkcs8_key_parser
[ 2523.945934] CPU: 14 PID: 24181 Comm: Xorg Tainted: G             L    5.4.72-2.qubes.x86_64 #1
[ 2523.945960] Hardware name: HP ProLiant DL360p Gen8, BIOS P71 05/24/2019
[ 2523.945989] RIP: e030:smp_call_function_many+0x20a/0x270
[ 2523.946010] Code: 8a 00 3b 05 4c b5 69 01 89 c7 0f 83 89 fe ff ff 48 63 c7 49 8b 17 48 03 14 c5 80 f9 3d 82 8b 42 18 a8 01 74 09 f3 90 8b 42 18 <a8> 01 75 f7 eb c9 48 c7 c2 a0 6f 82 82 4c 89 f6 89 df e8 bf b2
8a
[ 2523.946057] RSP: e02b:ffffc90003aa7cf0 EFLAGS: 00000202
[ 2523.946075] RAX: 0000000000000003 RBX: 0000000000000010 RCX: 0000000000000007
[ 2523.946097] RDX: ffff8882413ef640 RSI: 0000000000000010 RDI: 0000000000000007
[ 2523.946119] RBP: ffffffff81082fc0 R08: 0000000000000007 R09: 0000000000000000
[ 2523.946162] R10: 0000000000000000 R11: ffffffff8265b6a8 R12: 0000000000000000
[ 2523.946184] R13: 0000000000000001 R14: 0000000000029ac0 R15: ffff8882415a9b00
[ 2523.946233] FS:  00007a0d51a91a40(0000) GS:ffff888241580000(0000) knlGS:0000000000000000
[ 2523.946256] CS:  e030 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2523.946275] CR2: 000070abab15a000 CR3: 00000001e18ee000 CR4: 0000000000040660
[ 2523.946313] Call Trace:
[ 2523.946336]  ? do_kernel_range_flush+0x50/0x50
[ 2523.946356]  on_each_cpu+0x28/0x50
[ 2523.946376]  decrease_reservation+0x22f/0x310
[ 2523.946397]  alloc_xenballooned_pages+0xeb/0x120
[ 2523.946418]  ? __kmalloc+0x183/0x260
[ 2523.946434]  gnttab_alloc_pages+0x11/0x40
[ 2523.946457]  gntdev_alloc_map+0x12f/0x250 [xen_gntdev]
[ 2523.946478]  gntdev_ioctl_map_grant_ref+0x73/0x1d0 [xen_gntdev]
[ 2523.946502]  do_vfs_ioctl+0x2fb/0x490
[ 2523.946559]  ? syscall_trace_enter+0x1d1/0x2c0
[ 2523.946578]  ksys_ioctl+0x5e/0x90
[ 2523.946594]  __x64_sys_ioctl+0x16/0x20
[ 2523.946610]  do_syscall_64+0x5b/0xf0
[ 2523.946713]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 2523.946738] RIP: 0033:0x7a0d51f763bb
[ 2523.946782] Code: 0f 1e fa 48 8b 05 dd aa 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ad aa 0c 00 f7 d8 64 89 01
48
[ 2523.946867] RSP: 002b:00007fffc48d5058 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[ 2523.946927] RAX: ffffffffffffffda RBX: 0000000000001000 RCX: 00007a0d51f763bb
[ 2523.946950] RDX: 00007fffc48d5060 RSI: 0000000000184700 RDI: 0000000000000009
[ 2523.946972] RBP: 00007fffc48d5100 R08: 00007fffc48d512c R09: 00007a0d51a30010
[ 2523.947029] R10: 0000000000000000 R11: 0000000000000206 R12: 00007fffc48d5060
[ 2523.947051] R13: 0000000000000001 R14: 0000000000000009 R15: 0000000000000001
```

and finally

```
[ 1597.971380] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 1597.971409] rcu: 	0-...0: (5 ticks this GP) idle=cd2/0/0x1 softirq=59121/59122 fqs=14998
[ 1597.971420] rcu: 	7-...0: (2 ticks this GP) idle=e9e/1/0x4000000000000000 softirq=49519/49519 fqs=14998
[ 1597.971431] 	(detected by 11, t=60002 jiffies, g=234321, q=83)
[ 1597.971441] Sending NMI from CPU 11 to CPUs 0:
[ 1597.972452] NMI backtrace for cpu 0
[ 1597.972453] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.4.72-2.qubes.x86_64 #1
[ 1597.972453] Hardware name: HP ProLiant DL360p Gen8, BIOS P71 05/24/2019
[ 1597.972454] RIP: e030:xen_hypercall_sched_op+0xa/0x20
[ 1597.972454] Code: 51 41 53 b8 1c 00 00 00 0f 05 41 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc 51 41 53 b8 1d 00 00 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc
cc
[ 1597.972455] RSP: e02b:ffffc90001403d88 EFLAGS: 00000002
[ 1597.972456] RAX: 0000000000000000 RBX: ffff888241215f80 RCX: ffffffff810013aa
[ 1597.972456] RDX: ffff88823c070428 RSI: ffffc90001403da8 RDI: 0000000000000003
[ 1597.972456] RBP: ffff8882365d8bf0 R08: ffffffff8265b6a0 R09: 0000000000000000
[ 1597.972457] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000000049
[ 1597.972457] R13: 0000000000000100 R14: ffff8882422b6640 R15: 0000000000000001
[ 1597.972458] FS:  0000729633b7d700(0000) GS:ffff888241200000(0000) knlGS:0000000000000000
[ 1597.972458] CS:  10000e030 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1597.972458] CR2: 000077f6508c47c0 CR3: 000000020d006000 CR4: 0000000000040660
[ 1597.972459] Call Trace:
[ 1597.972459]  <IRQ>
[ 1597.972459]  ? xen_poll_irq+0x73/0xa0
[ 1597.972459]  ? xen_qlock_wait+0x7b/0x80
[ 1597.972460]  ? pv_wait_head_or_lock+0x85/0xb0
[ 1597.972460]  ? __pv_queued_spin_lock_slowpath+0xb5/0x1b0
[ 1597.972460]  ? _raw_spin_lock_irqsave+0x32/0x40
[ 1597.972461]  ? bfq_finish_requeue_request+0xb5/0x120
[ 1597.972461]  ? blk_mq_free_request+0x3a/0xf0
[ 1597.972461]  ? scsi_end_request+0x95/0x140
[ 1597.972461]  ? scsi_io_completion+0x74/0x190
[ 1597.972462]  ? blk_done_softirq+0xea/0x180
[ 1597.972462]  ? __do_softirq+0xd9/0x2c8
[ 1597.972462]  ? irq_exit+0xcf/0x110
[ 1597.972462]  ? xen_evtchn_do_upcall+0x2c/0x40
[ 1597.972463]  ? xen_do_hypervisor_callback+0x29/0x40
[ 1597.972463]  </IRQ>
[ 1597.972463]  ? xen_hypercall_sched_op+0xa/0x20
[ 1597.972464]  ? xen_hypercall_sched_op+0xa/0x20
[ 1597.972464]  ? xen_safe_halt+0xc/0x20
[ 1597.972464]  ? default_idle+0x1a/0x140
[ 1597.972465]  ? cpuidle_idle_call+0x139/0x190
[ 1597.972465]  ? do_idle+0x73/0xd0
[ 1597.972465]  ? cpu_startup_entry+0x19/0x20
[ 1597.972466]  ? start_kernel+0x68a/0x6bf
[ 1597.972466]  ? xen_start_kernel+0x6a2/0x6c1
[ 1597.972470] Sending NMI from CPU 11 to CPUs 7:
[ 1607.976873] rcu: rcu_sched kthread starved for 10007 jiffies! g234321 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=11
[ 1607.976924] rcu: RCU grace-period kthread stack dump:
[ 1607.976942] rcu_sched       I    0    10      2 0x80004000
[ 1607.976972] Call Trace:
[ 1607.976999]  __schedule+0x217/0x570
[ 1607.977020]  ? schedule+0x39/0xa0
[ 1607.977038]  ? schedule_timeout+0x96/0x150
[ 1607.977056]  ? __next_timer_interrupt+0xd0/0xd0
[ 1607.977079]  ? rcu_gp_fqs_loop+0xea/0x2a0
[ 1607.977096]  ? rcu_gp_kthread+0xb5/0x140
[ 1607.977112]  ? rcu_gp_init+0x470/0x470
[ 1607.977130]  ? kthread+0x115/0x140
[ 1607.977145]  ? __kthread_bind_mask+0x60/0x60
[ 1607.977164]  ? ret_from_fork+0x35/0x40
```

I've tried to increase memory, set maximum of dom0 vcps to 1 or 4, pin vcpus too, multiple 5.4 kernels tool...no luck.

I've also observed that some (never the same) VM (PVH or HVM) fail to start randomly because of being stuck at boot time with analog stack trace as the first piece of log provided above. Those VM are impossible to desroy and then it "propagates" though dom0 with the two latest piece of codes.

If anyone would have any idea of what's going on, that would be very appreciated. Thank you.

Frédéric

[-- Attachment #1.1.2: OpenPGP_0x484010B5CDC576E2.asc --]
[-- Type: application/pgp-keys, Size: 3143 bytes --]

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