Crashes in kernel with Trace Back

[Wendy Mitchell]

Brief Description
-----------------
STX: Crashes in kernel with Trace Back
kernel/cpuset.c:955 update_cpumasks_hier

Severity
--------
Major

Steps to Reproduce
------------------

1. The testcase boots two instances on compute (compute-1 with local_lvm backing). One instance has 27 vcpus in the flavor

| flavor:extra_specs | {"hw:cpu_policy": "dedicated", "aggregate_instance_extra_specs:storage": "local_lvm", "hw:numa_node.0": "0"}
 flavor:vcpus | 27
 OS-EXT-SRV-ATTR:hostname | tenant2-vm-42
OS-EXT-SRV-ATTR:instance_name | instance-0000002f
 wrs-res:topology | node:0, 1024MB, pgsize:2M, 1s,27c,1t, vcpus:0-26, pcpus:7,16,52,8,44,50,14,51,15,10,46,11,47,42,6,41,5,9,45,48,12,49,13,17,53,40,4, pol:ded, thr:pre

nova --os-username 'tenant2' --os-password 'Li69nux*' --os-project-name tenant2 --os-auth-url http://192.168.204.2:5000/v3 --os-user-domain-name Default --os-project-domain-name Default --os-region-name RegionOne boot --image 30907c74-c29d-4b6c-9c3a-6c6900696e45 --flavor 55218cee-4e9e-4925-bee1-308de6ac8493 --key-name keypair-tenant2 --availability-zone nova:compute-1 --nic net-id=10107d29-d294-4caa-98e0-0d6d2d80e3a9,vif-model=virtio --nic net-id=a838c71b-0936-46b2-b15e-959d23001a08,vif-model=virtio tenant2-vm-42 --poll'

2. Both instances were deleted successfully here
[2018-10-14 01:09:09,844] 2323 INFO MainThread vm_helper.delete_vms:: Deleting vm(s): ['76308c5d-dacb-43a7-a91e-3c932b27adc5', 'ad10817f-350c-47d5-81c5-ddc1a345a855']
...
[2018-10-14 01:09:41,340] 2395 INFO MainThread vm_helper.delete_vms:: VM(s) deleted successfully: ['76308c5d-dacb-43a7-a91e-3c932b27adc5', 'ad10817f-350c-47d5-81c5-ddc1a345a855']

Expected Behavior
------------------
Did not expect kernel crash on compute-1 in step 2

Actual Behavior
----------------
Crashes in kernel - see Call Trace below (from compute-1)
see kern.log starting at 1:05:53 to 2018-10-14T01:07:33.366 after launch of instance with 27 vcpu in step 2 above.

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009394] ------------[ cut here ]------------
2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009406] WARNING: CPU: 0 PID: 55779 at kernel/cpuset.c:955 update_cpumasks_hier+0x3d1/0x430
2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009407] Modules linked in: dm_snapshot cuse fuse xt_REDIRECT nf_nat_redirect ip6table_raw ip6table_mangle xt_nat xt_conntrack xt_mark xt_connmark iptable_raw xt_comment iptable_nat xt_CHECKSUM iptable_mangle nbd ebtable_filter ebtables tun openvswitch nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack binfmt_misc virtio_net nfsd auth_rpcgss nfsv3 nfs_acl nfs lockd grace fscache cls_u32 sch_sfq sch_htb ip6table_filter ip6_tables iptable_filter sunrpc dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio libcrc32c dm_mod iTCO_wdt iTCO_vendor_support intel_powerclamp coretemp kvm_intel kvm crc32_pclmul ghash_clmulni_intel aesni_intel glue_helper lrw gf128mul ablk_helper cryptd joydev lpc_ich mei_me mei i2c_i801 ioatdma ipmi_si ipmi_devintf ipmi_msghandler tpm_crb(O) acpi_power_meter ixgbevf(O) vfio_pci vfio_iommu_type1 vfio irqbypass ip_tables ext4 mbcache jbd2 xprtrdma(O) svcrdma(O) rpcrdma(O) nvmet_rdma(O) nvme_rdma(O) mlx4_en(O) ib_srp(O) ib_isert(O) ib_iser(O) rdma_rxe(O) mlx5_ib(O) sd_mod crc_t10dif crct10dif_generic mlx4_ib(O) mlx4_core(O) rdma_ucm(O) rdma_cm(O) iw_cm(O) ib_ucm(O) ib_uverbs(O) ib_cm(O) ib_core(O) crct10dif_pclmul crct10dif_common crc32c_intel ixgbe(O) igb i2c_algo_bit i2c_core ahci libahci mlx5_core(O) mlxfw(O) mlx_compat(O) devlink dca tpm_tis(O) tpm_tis_core(O) tpm(O) i40e(O) e1000e(O)

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009470] CPU: 0 PID: 55779 Comm: nova-compute Kdump: loaded Tainted: G O ------------ 3.10.0-862.11.6.el7.36.tis.x86_64 #1
2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009472] Hardware name: Intel Corporation S2600WT2R/S2600WT2R, BIOS SE5C610.86B.01.01.0022.062820171903 06/28/2017

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009473] Call Trace:

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009480] [<ffffffff9d7b4039>] dump_stack+0x19/0x1b
2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009487] [<ffffffff9d079a38>] __warn+0xd8/0x100

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009488] [<ffffffff9d079b7d>] warn_slowpath_null+0x1d/0x20

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009490] [<ffffffff9d109af1>] update_cpumasks_hier+0x3d1/0x430
2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009495] [<ffffffff9d1c8bfe>] ? __kmalloc+0x2e/0x2a0

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009497] [<ffffffff9d10534c>] ? cgroup_task_count+0x4c/0x60
2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009501] [<ffffffff9d31d33c>] ? heap_init+0x1c/0x50

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009503] [<ffffffff9d109fea>] cpuset_write_resmask+0x49a/0x9c0

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009504] [<ffffffff9d109b50>] ? update_cpumasks_hier+0x430/0x430

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009506] [<ffffffff9d101a94>] cgroup_file_write+0x1d4/0x2d0

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009510] [<ffffffff9d1e4738>] ? __sb_start_write+0x58/0x110

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009516] [<ffffffff9d2a71a7>] ? security_file_permission+0x27/0xa0

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009520] [<ffffffff9d1e17c0>] vfs_write+0xc0/0x1f0

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009521] [<ffffffff9d1e25ef>] SyS_write+0x7f/0xf0

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009526] [<ffffffff9d7c1fdb>] system_call_fastpath+0x22/0x27

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009527] ---[ end trace 6293f46623053f31 ]---

2018-10-14T01:05:53.803 compute-1 kernel: warning [ 9284.009628] ------------[ cut here ]------------

Reproducibility
---------------

System Configuration
--------------------
2 controller, 2 compute

Branch/Pull Time/Commit
-----------------------
Master as of: 2018-10-12_20-18-00

Timestamp/Logs
--------------
see inline

[Ghada Khalil (gkhalil)]

Requested more info from the reporter:
Aside from the kernel traceback in the logs, what was the system impact? I assume the compute node did not reboot.

[Erich Cordoba (ericho)]

This is a kernel warning, not a kernel crash. Some code in the kernel dumps the stack when an invalid situation is found, this seems to be one case of that.

The 27 vcpus is a valid number for your hardware? My guess is that nova-compute is trying to create a cpuset based on that number but the kernel is unable to do that and then the warning is printed. But is just a guess.

[Ghada Khalil (gkhalil)]

After follow-up with the reporter, she indicated that there was no system impact to these kernel logs (reported on two systems w/ similar hardware configs). Therefore, this is a lower priority item.

It would be good for a kernel person to investigate further.

[Bruce Jones (brucej)]

Saul can you please review these logs and determine if this is an actual bug or not? If it's a bug, assign it to Cindy's team with guidance on the fix.

[Saul Wold (sgw-starlingx)]

I agree with Erich's initial assessment, this is a Warning and based on the message might be that setting 27 vcpus might be incorrect, is this a test case that worked before?

What else has changed?

[Saul Wold (sgw-starlingx)]

@Wendy:

Can you please provide additional details about this hardware that this testcase ran on. Is this running on bare metal or in a VM? How many CPUs are in the bare metal or allocated to the VM? Did this test pass with an older version of StarlingX / Titanium Cloud? If so, when did it last pass?

Any other HW details you might thing important.

Thanks

[Wendy Mitchell (wmitchellwr)]

The lab for the trace above has the following:

StarlingX load with CentOS 7.5 kernel (tbd on whether it happens on load with an earlier kernel version)
- Does not appear to be running bare metal
Hyperthreading is enabled
The

Processor Model: Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz
Processors: 2
Physical Cores Per Processor: 18
Hyper-Threading: Yes

Function Processor Logical Cores

Platform - 1 physical core assigned on processor 0
Platform Processor 0 : 0,36

vSwitch - 18 physical cores on each of the processors
vSwitch Processor 0 : 1-2,37-38

1 shared pysical core on processor 0
VMs Processor 0 : 4-17,40-53
Processor 1 : 18-35,54-71

Also reproduced on another system with the following info:
wcp 61-62 is 2 controller system
controller-0 has the following settings
Processor Model: Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz
Processors: 2
Physical Cores Per Processor: 18
Hyper-Threading: Yes

Platform Processor 0 : 0-1,36-37
vSwitch Processor 0 : 2-3,38-39
Shared Processor 0 : 4,40
VMs Processor 0 : 5-17,41-53
Processor 1 : 18-35,54-71

[Ghada Khalil (gkhalil)]

There is a terminology inconsistency. The test was run on baremetal; as in on a hardware lab, not in a virtual env.

[Saul Wold (sgw-starlingx)]

@Wendy,

Thanks for the additional information, I am still concerned that the setting of 27 cpus is too many for the configuration mentioned above.

Can you please confirm that this worked with a prior release on that same hardware with the 27 vcpus setting?

Can the GDC team reproduce this?

[Wendy Mitchell (wmitchellwr)]

Adding kern.log from the following version under test
3.10.0-862.3.2.el7.1.tis.x86_64

see log time starting here
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395795] ------------[ cut here ]------------
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395807] WARNING: CPU: 1 PID: 48742 at kernel/cpuset.c:955 update_cpumasks_hier+0x3d1/0x430
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395808] Modules linked in: cuse fuse iptable_raw iptable_nat nf_nat_ipv4 nf_nat xt_CHECKSUM iptable_mangle dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio nbd igb_uio(O) uio ebtable_filter ebtables binfmt_misc drbd(O) nfsv3 nfs fscache virtio_net bridge stp llc cls_u32 sch_sfq sch_htb bonding nf_log_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables nf_log_ipv4 nf_log_common xt_LOG xt_limit nf_conntrack_ipv4 nf_defrag_ipv4 xt_comment xt_multiport xt_conntrack nf_conntrack libcrc32c iptable_filter dm_mod iTCO_wdt iTCO_vendor_support intel_powerclamp coretemp kvm_intel kvm crc32_pclmul ghash_clmulni_intel aesni_intel glue_helper lrw gf128mul ablk_helper cryptd lpc_ich mei_me joydev mei i2c_i801 ioatdma ipmi_si ipmi_devintf ipmi_msghandler acpi_power_meter wrs_avp(O) vfio_pci irqbypass vfio_iommu_type1 vfio ixgbevf(O) nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables ext4 mbcache jbd2 xprtrdma(O) svcrdma(O) rpcrdma(O) nvmet_rdma(O) nvme_rdma(O) mlx4_en(O) ib_srp(O) ib_isert(O) ib_iser(O) rdma_rxe(O) mlx5_ib(O) sd_mod crc_t10dif crct10dif_generic crct10dif_pclmul crct10dif_common crc32c_intel ahci igb libahci i2c_algo_bit i2c_core mlx5_core(O) mlxfw(O) mlx4_ib(O) mlx4_core(O) devlink rdma_ucm(O) rdma_cm(O) iw_cm(O) ib_ucm(O) ib_uverbs(O) ib_cm(O) ib_core(O) mlx_compat(O) ixgbe(O) dca tpm_tis(O) tpm_tis_core(O) tpm(O) i40e(O) e1000e(O)
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395872] CPU: 1 PID: 48742 Comm: nova-compute Kdump: loaded Tainted: G O ------------ 3.10.0-862.3.2.el7.1.tis.x86_64 #1
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395874] Hardware name: Intel Corporation S2600WT2R/S2600WT2R, BIOS SE5C610.86B.01.01.0015.012820160943 01/28/2016
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395874] Call Trace:
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395882] [<ffffffff95db01d0>] dump_stack+0x19/0x1b
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395886] [<ffffffff95677fd8>] __warn+0xd8/0x100
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395887] [<ffffffff9567811d>] warn_slowpath_null+0x1d/0x20
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395889] [<ffffffff95707de1>] update_cpumasks_hier+0x3d1/0x430
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395893] [<ffffffff957c590e>] ? __kmalloc+0x2e/0x2a0
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395895] [<ffffffff9570363c>] ? cgroup_task_count+0x4c/0x60
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395902] [<ffffffff959198bc>] ? heap_init+0x1c/0x50
2018-10-31T18:50:35.702 controller-0 kernel: warning [ 959.395903] [<ffffffff957082da>] cpuset_write_resmask+0x49a/0x9c0
2018-10-31T18:50:35.702 controller-0 kernel: warni...

[Saul Wold (sgw-starlingx)]

@Wendy,

Coming back to this, thanks for the dmesg output, but I would also like to know if you can please confirm that this worked with a prior release on that same hardware with the 27 vcpus setting?

This is a Warning, we should see if if this is an issue with the 7.6 kernel also.

Can the GDC team reproduce this?

[Wendy Mitchell (wmitchellwr)]

Reran the original testcase several times against an earlier version of the kernel (on one of the systems that had been used to reproduced this originally with only 25 vcpu).

The call trace above was not observed in the older version.

2019-02-08T16:00:21.051 localhost kernel: notice [ 0.000000] Linux version 3.10.0-693.2.2.el7.33.tis.x86_64 (<email address hidden>) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-16) (GCC) ) #1 SMP PREEMPT Fri Mar 16 11:10:55 EDT 2018

Processor Model: Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz
Processors: 2
Physical Cores Per Processor: 18
Hyper-Threading: Yes

Platform Processor 0 : 0-1,36-37
vSwitch Processor 0 : 2-3,38-39
Shared Processor 0 : 4,40
VMs Processor 0 : 5-17,41-53
Processor 1 : 18-35,54-71

[Wendy Mitchell (wmitchellwr)]

Will upload kern.logs from the older version shortly.

[Saul Wold (sgw-starlingx)]

@Wendy,

I am a little confused now, was the warning on the system with 25 vcpus or on a system with more vcpus? If it was with the system with 25 vcpus then the Warning makes sense since you asked for 27 vpcus!

Also the older test was with the same kernel version3.10.0.693, so the only thing could be hardware related.

Can you confirm the warning was only on the system with 25 vcpus? If so we can close this as invalid.

[Wendy Mitchell (wmitchellwr)]

To be clear, the problem was originally reproduced on 2 separate systems.
(Tried reproducing it today with kernel version3.10.0.693 and the same number of vcpus that had been used for that particular system previously to reproduce it.)

It had originally been reproduced with kernel version3.10.0-862

[Saul Wold (sgw-starlingx)]

Wendy, coming back this again after the 7.6 update and a newer kernel, can you let me know if it reproduces with the newest kernel version 3.10.0-957.1.3.el7.

I will then have to look at the differences from Redhat between versions 693 -> 862

[Wendy Mitchell (wmitchellwr)]

I am not hitting this issue with the latest build with upstream from BUILD_ID="20190331T233001Z”
Linux version 3.10.0-957.1.3.el7.1.tis.x86_64 (mockbuild@f02338164d80) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-36) (GCC) ) #1 SMP PREEMPT Mon Apr 1 00:10:09 UTC 2019

A lot of things have changed though with containerization so it is hard to say if I am going to be able to reproduce it.
https://bugs.launchpad.net/starlingx/+bug/1798099

The 3 behaviors I see when retesting (with instance in the same scenarios with larger number of vcpus in the flavor) are as follows:
a. schedules and launches or resizes succesfully
b. schedulers for resize or migration for example (but the instance will error if NUMA topology cannot fit)
c. attempts to schedule but fails (and instance goes to error)

In all scenarios I tested, I am not seeing the traceback in question in the kern.log.

[Ghada Khalil (gkhalil)]

Closing as the issue appears to be fixed with the latest kernel included in stx master.

[Ghada Khalil (gkhalil)]

To be more specific, the issue is not reproducible in the lastest stx loads. However, given we have a newer kernel, there is a good chance, the issue was addressed in the new kernel. Therefore, setting the status to "Fix Released"