Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1706845 > unrolled thread
| Started by | YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> |
|---|---|
| First post | 2017-08-08 21:30 +0200 |
| Last post | 2017-08-10 14:00 +0200 |
| Articles | 4 — 2 participants |
Back to article view | Back to linux.kernel
system hung up when offlining CPUs YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> - 2017-08-08 21:30 +0200
Re: system hung up when offlining CPUs Marc Zyngier <marc.zyngier@arm.com> - 2017-08-09 13:50 +0200
Re: system hung up when offlining CPUs YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> - 2017-08-09 21:10 +0200
Re: system hung up when offlining CPUs Marc Zyngier <marc.zyngier@arm.com> - 2017-08-10 14:00 +0200
| From | YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> |
|---|---|
| Date | 2017-08-08 21:30 +0200 |
| Subject | system hung up when offlining CPUs |
| Message-ID | <ucimu-4kC-21@gated-at.bofh.it> |
Hi Thomas,
When offlining all CPUs except cpu0, system hung up with the following message.
[...] INFO: task kworker/u384:1:1234 blocked for more than 120 seconds.
[...] Not tainted 4.12.0-rc6+ #19
[...] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[...] kworker/u384:1 D 0 1234 2 0x00000000
[...] Workqueue: writeback wb_workfn (flush-253:0)
[...] Call Trace:
[...] __schedule+0x28a/0x880
[...] schedule+0x36/0x80
[...] schedule_timeout+0x249/0x300
[...] ? __schedule+0x292/0x880
[...] __down_common+0xfc/0x132
[...] ? _xfs_buf_find+0x2bb/0x510 [xfs]
[...] __down+0x1d/0x1f
[...] down+0x41/0x50
[...] xfs_buf_lock+0x3c/0xf0 [xfs]
[...] _xfs_buf_find+0x2bb/0x510 [xfs]
[...] xfs_buf_get_map+0x2a/0x280 [xfs]
[...] xfs_buf_read_map+0x2d/0x180 [xfs]
[...] xfs_trans_read_buf_map+0xf5/0x310 [xfs]
[...] xfs_btree_read_buf_block.constprop.35+0x78/0xc0 [xfs]
[...] xfs_btree_lookup_get_block+0x88/0x160 [xfs]
[...] xfs_btree_lookup+0xd0/0x3b0 [xfs]
[...] ? xfs_allocbt_init_cursor+0x41/0xe0 [xfs]
[...] xfs_alloc_ag_vextent_near+0xaf/0xaa0 [xfs]
[...] xfs_alloc_ag_vextent+0x13c/0x150 [xfs]
[...] xfs_alloc_vextent+0x425/0x590 [xfs]
[...] xfs_bmap_btalloc+0x448/0x770 [xfs]
[...] xfs_bmap_alloc+0xe/0x10 [xfs]
[...] xfs_bmapi_write+0x61d/0xc10 [xfs]
[...] ? kmem_zone_alloc+0x96/0x100 [xfs]
[...] xfs_iomap_write_allocate+0x199/0x3a0 [xfs]
[...] xfs_map_blocks+0x1e8/0x260 [xfs]
[...] xfs_do_writepage+0x1ca/0x680 [xfs]
[...] write_cache_pages+0x26f/0x510
[...] ? xfs_vm_set_page_dirty+0x1d0/0x1d0 [xfs]
[...] ? blk_mq_dispatch_rq_list+0x305/0x410
[...] ? deadline_remove_request+0x7d/0xc0
[...] xfs_vm_writepages+0xb6/0xd0 [xfs]
[...] do_writepages+0x1c/0x70
[...] __writeback_single_inode+0x45/0x320
[...] writeback_sb_inodes+0x280/0x570
[...] __writeback_inodes_wb+0x8c/0xc0
[...] wb_writeback+0x276/0x310
[...] ? get_nr_dirty_inodes+0x4d/0x80
[...] wb_workfn+0x2d4/0x3b0
[...] process_one_work+0x149/0x360
[...] worker_thread+0x4d/0x3c0
[...] kthread+0x109/0x140
[...] ? rescuer_thread+0x380/0x380
[...] ? kthread_park+0x60/0x60
[...] ret_from_fork+0x25/0x30
I bisected upstream kernel. And I found that the following commit lead
the issue.
commit c5cb83bb337c25caae995d992d1cdf9b317f83de
Author: Thomas Gleixner <tglx@linutronix.de>
Date: Tue Jun 20 01:37:51 2017 +0200
genirq/cpuhotplug: Handle managed IRQs on CPU hotplug
Thanks,
Yasuaki Ishimatsu
[toc] | [next] | [standalone]
| From | Marc Zyngier <marc.zyngier@arm.com> |
|---|---|
| Date | 2017-08-09 13:50 +0200 |
| Message-ID | <ucxER-6xm-13@gated-at.bofh.it> |
| In reply to | #1706845 |
On Tue, 8 Aug 2017 15:25:35 -0400 YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> wrote: > Hi Thomas, > > When offlining all CPUs except cpu0, system hung up with the following message. > > [...] INFO: task kworker/u384:1:1234 blocked for more than 120 seconds. > [...] Not tainted 4.12.0-rc6+ #19 > [...] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [...] kworker/u384:1 D 0 1234 2 0x00000000 > [...] Workqueue: writeback wb_workfn (flush-253:0) > [...] Call Trace: > [...] __schedule+0x28a/0x880 > [...] schedule+0x36/0x80 > [...] schedule_timeout+0x249/0x300 > [...] ? __schedule+0x292/0x880 > [...] __down_common+0xfc/0x132 > [...] ? _xfs_buf_find+0x2bb/0x510 [xfs] > [...] __down+0x1d/0x1f > [...] down+0x41/0x50 > [...] xfs_buf_lock+0x3c/0xf0 [xfs] > [...] _xfs_buf_find+0x2bb/0x510 [xfs] > [...] xfs_buf_get_map+0x2a/0x280 [xfs] > [...] xfs_buf_read_map+0x2d/0x180 [xfs] > [...] xfs_trans_read_buf_map+0xf5/0x310 [xfs] > [...] xfs_btree_read_buf_block.constprop.35+0x78/0xc0 [xfs] > [...] xfs_btree_lookup_get_block+0x88/0x160 [xfs] > [...] xfs_btree_lookup+0xd0/0x3b0 [xfs] > [...] ? xfs_allocbt_init_cursor+0x41/0xe0 [xfs] > [...] xfs_alloc_ag_vextent_near+0xaf/0xaa0 [xfs] > [...] xfs_alloc_ag_vextent+0x13c/0x150 [xfs] > [...] xfs_alloc_vextent+0x425/0x590 [xfs] > [...] xfs_bmap_btalloc+0x448/0x770 [xfs] > [...] xfs_bmap_alloc+0xe/0x10 [xfs] > [...] xfs_bmapi_write+0x61d/0xc10 [xfs] > [...] ? kmem_zone_alloc+0x96/0x100 [xfs] > [...] xfs_iomap_write_allocate+0x199/0x3a0 [xfs] > [...] xfs_map_blocks+0x1e8/0x260 [xfs] > [...] xfs_do_writepage+0x1ca/0x680 [xfs] > [...] write_cache_pages+0x26f/0x510 > [...] ? xfs_vm_set_page_dirty+0x1d0/0x1d0 [xfs] > [...] ? blk_mq_dispatch_rq_list+0x305/0x410 > [...] ? deadline_remove_request+0x7d/0xc0 > [...] xfs_vm_writepages+0xb6/0xd0 [xfs] > [...] do_writepages+0x1c/0x70 > [...] __writeback_single_inode+0x45/0x320 > [...] writeback_sb_inodes+0x280/0x570 > [...] __writeback_inodes_wb+0x8c/0xc0 > [...] wb_writeback+0x276/0x310 > [...] ? get_nr_dirty_inodes+0x4d/0x80 > [...] wb_workfn+0x2d4/0x3b0 > [...] process_one_work+0x149/0x360 > [...] worker_thread+0x4d/0x3c0 > [...] kthread+0x109/0x140 > [...] ? rescuer_thread+0x380/0x380 > [...] ? kthread_park+0x60/0x60 > [...] ret_from_fork+0x25/0x30 > > > I bisected upstream kernel. And I found that the following commit lead > the issue. > > commit c5cb83bb337c25caae995d992d1cdf9b317f83de > Author: Thomas Gleixner <tglx@linutronix.de> > Date: Tue Jun 20 01:37:51 2017 +0200 > > genirq/cpuhotplug: Handle managed IRQs on CPU hotplug Can you please post your /proc/interrupts and details of which interrupt you think goes wrong? This backtrace is not telling us much in terms of where to start looking... Thanks, M. -- Without deviation from the norm, progress is not possible.
[toc] | [prev] | [next] | [standalone]
| From | YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> |
|---|---|
| Date | 2017-08-09 21:10 +0200 |
| Message-ID | <ucEwG-30X-15@gated-at.bofh.it> |
| In reply to | #1707275 |
Hi Marc,
On 08/09/2017 07:42 AM, Marc Zyngier wrote:
> On Tue, 8 Aug 2017 15:25:35 -0400
> YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> wrote:
>
>> Hi Thomas,
>>
>> When offlining all CPUs except cpu0, system hung up with the following message.
>>
>> [...] INFO: task kworker/u384:1:1234 blocked for more than 120 seconds.
>> [...] Not tainted 4.12.0-rc6+ #19
>> [...] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [...] kworker/u384:1 D 0 1234 2 0x00000000
>> [...] Workqueue: writeback wb_workfn (flush-253:0)
>> [...] Call Trace:
>> [...] __schedule+0x28a/0x880
>> [...] schedule+0x36/0x80
>> [...] schedule_timeout+0x249/0x300
>> [...] ? __schedule+0x292/0x880
>> [...] __down_common+0xfc/0x132
>> [...] ? _xfs_buf_find+0x2bb/0x510 [xfs]
>> [...] __down+0x1d/0x1f
>> [...] down+0x41/0x50
>> [...] xfs_buf_lock+0x3c/0xf0 [xfs]
>> [...] _xfs_buf_find+0x2bb/0x510 [xfs]
>> [...] xfs_buf_get_map+0x2a/0x280 [xfs]
>> [...] xfs_buf_read_map+0x2d/0x180 [xfs]
>> [...] xfs_trans_read_buf_map+0xf5/0x310 [xfs]
>> [...] xfs_btree_read_buf_block.constprop.35+0x78/0xc0 [xfs]
>> [...] xfs_btree_lookup_get_block+0x88/0x160 [xfs]
>> [...] xfs_btree_lookup+0xd0/0x3b0 [xfs]
>> [...] ? xfs_allocbt_init_cursor+0x41/0xe0 [xfs]
>> [...] xfs_alloc_ag_vextent_near+0xaf/0xaa0 [xfs]
>> [...] xfs_alloc_ag_vextent+0x13c/0x150 [xfs]
>> [...] xfs_alloc_vextent+0x425/0x590 [xfs]
>> [...] xfs_bmap_btalloc+0x448/0x770 [xfs]
>> [...] xfs_bmap_alloc+0xe/0x10 [xfs]
>> [...] xfs_bmapi_write+0x61d/0xc10 [xfs]
>> [...] ? kmem_zone_alloc+0x96/0x100 [xfs]
>> [...] xfs_iomap_write_allocate+0x199/0x3a0 [xfs]
>> [...] xfs_map_blocks+0x1e8/0x260 [xfs]
>> [...] xfs_do_writepage+0x1ca/0x680 [xfs]
>> [...] write_cache_pages+0x26f/0x510
>> [...] ? xfs_vm_set_page_dirty+0x1d0/0x1d0 [xfs]
>> [...] ? blk_mq_dispatch_rq_list+0x305/0x410
>> [...] ? deadline_remove_request+0x7d/0xc0
>> [...] xfs_vm_writepages+0xb6/0xd0 [xfs]
>> [...] do_writepages+0x1c/0x70
>> [...] __writeback_single_inode+0x45/0x320
>> [...] writeback_sb_inodes+0x280/0x570
>> [...] __writeback_inodes_wb+0x8c/0xc0
>> [...] wb_writeback+0x276/0x310
>> [...] ? get_nr_dirty_inodes+0x4d/0x80
>> [...] wb_workfn+0x2d4/0x3b0
>> [...] process_one_work+0x149/0x360
>> [...] worker_thread+0x4d/0x3c0
>> [...] kthread+0x109/0x140
>> [...] ? rescuer_thread+0x380/0x380
>> [...] ? kthread_park+0x60/0x60
>> [...] ret_from_fork+0x25/0x30
>>
>>
>> I bisected upstream kernel. And I found that the following commit lead
>> the issue.
>>
>> commit c5cb83bb337c25caae995d992d1cdf9b317f83de
>> Author: Thomas Gleixner <tglx@linutronix.de>
>> Date: Tue Jun 20 01:37:51 2017 +0200
>>
>> genirq/cpuhotplug: Handle managed IRQs on CPU hotplug
>
> Can you please post your /proc/interrupts and details of which
> interrupt you think goes wrong? This backtrace is not telling us much
> in terms of where to start looking...
Thank you for giving advise.
The issue is easily reproduced on physical/virtual machine by offling CPUs except cpu0.
Here are my /proc/interrupts on kvm guest before reproducing the issue. And when offlining
cpu1, the issue occurred. But when offling cpu0, the issue didn't occur.
CPU0 CPU1
0: 127 0 IO-APIC 2-edge timer
1: 10 0 IO-APIC 1-edge i8042
4: 227 0 IO-APIC 4-edge ttyS0
6: 3 0 IO-APIC 6-edge floppy
8: 0 0 IO-APIC 8-edge rtc0
9: 0 0 IO-APIC 9-fasteoi acpi
10: 10822 0 IO-APIC 10-fasteoi ehci_hcd:usb1, uhci_hcd:usb2, virtio3
11: 23 0 IO-APIC 11-fasteoi uhci_hcd:usb3, uhci_hcd:usb4, qxl
12: 15 0 IO-APIC 12-edge i8042
14: 218 0 IO-APIC 14-edge ata_piix
15: 0 0 IO-APIC 15-edge ata_piix
24: 0 0 PCI-MSI 49152-edge virtio0-config
25: 359 0 PCI-MSI 49153-edge virtio0-input.0
26: 1 0 PCI-MSI 49154-edge virtio0-output.0
27: 0 0 PCI-MSI 114688-edge virtio2-config
28: 1 3639 PCI-MSI 114689-edge virtio2-req.0
29: 0 0 PCI-MSI 98304-edge virtio1-config
30: 4 0 PCI-MSI 98305-edge virtio1-virtqueues
31: 189 0 PCI-MSI 65536-edge snd_hda_intel:card0
NMI: 0 0 Non-maskable interrupts
LOC: 16115 12845 Local timer interrupts
SPU: 0 0 Spurious interrupts
PMI: 0 0 Performance monitoring interrupts
IWI: 0 0 IRQ work interrupts
RTR: 0 0 APIC ICR read retries
RES: 3016 2135 Rescheduling interrupts
CAL: 3666 557 Function call interrupts
TLB: 65 12 TLB shootdowns
TRM: 0 0 Thermal event interrupts
THR: 0 0 Threshold APIC interrupts
DFR: 0 0 Deferred Error APIC interrupts
MCE: 0 0 Machine check exceptions
MCP: 1 1 Machine check polls
ERR: 0
MIS: 0
PIN: 0 0 Posted-interrupt notification event
NPI: 0 0 Nested posted-interrupt event
PIW: 0 0 Posted-interrupt wakeup event
Thanks,
Yasuaki Ishimatsu
>
> Thanks,
>
> M.
>
[toc] | [prev] | [next] | [standalone]
| From | Marc Zyngier <marc.zyngier@arm.com> |
|---|---|
| Date | 2017-08-10 14:00 +0200 |
| Message-ID | <ucUi6-55n-25@gated-at.bofh.it> |
| In reply to | #1707761 |
+ Christoph, since he's the one who came up with the idea On 09/08/17 20:09, YASUAKI ISHIMATSU wrote: > Hi Marc, > > On 08/09/2017 07:42 AM, Marc Zyngier wrote: >> On Tue, 8 Aug 2017 15:25:35 -0400 >> YASUAKI ISHIMATSU <yasu.isimatu@gmail.com> wrote: >> >>> Hi Thomas, >>> >>> When offlining all CPUs except cpu0, system hung up with the following message. >>> >>> [...] INFO: task kworker/u384:1:1234 blocked for more than 120 seconds. >>> [...] Not tainted 4.12.0-rc6+ #19 >>> [...] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. >>> [...] kworker/u384:1 D 0 1234 2 0x00000000 >>> [...] Workqueue: writeback wb_workfn (flush-253:0) >>> [...] Call Trace: >>> [...] __schedule+0x28a/0x880 >>> [...] schedule+0x36/0x80 >>> [...] schedule_timeout+0x249/0x300 >>> [...] ? __schedule+0x292/0x880 >>> [...] __down_common+0xfc/0x132 >>> [...] ? _xfs_buf_find+0x2bb/0x510 [xfs] >>> [...] __down+0x1d/0x1f >>> [...] down+0x41/0x50 >>> [...] xfs_buf_lock+0x3c/0xf0 [xfs] >>> [...] _xfs_buf_find+0x2bb/0x510 [xfs] >>> [...] xfs_buf_get_map+0x2a/0x280 [xfs] >>> [...] xfs_buf_read_map+0x2d/0x180 [xfs] >>> [...] xfs_trans_read_buf_map+0xf5/0x310 [xfs] >>> [...] xfs_btree_read_buf_block.constprop.35+0x78/0xc0 [xfs] >>> [...] xfs_btree_lookup_get_block+0x88/0x160 [xfs] >>> [...] xfs_btree_lookup+0xd0/0x3b0 [xfs] >>> [...] ? xfs_allocbt_init_cursor+0x41/0xe0 [xfs] >>> [...] xfs_alloc_ag_vextent_near+0xaf/0xaa0 [xfs] >>> [...] xfs_alloc_ag_vextent+0x13c/0x150 [xfs] >>> [...] xfs_alloc_vextent+0x425/0x590 [xfs] >>> [...] xfs_bmap_btalloc+0x448/0x770 [xfs] >>> [...] xfs_bmap_alloc+0xe/0x10 [xfs] >>> [...] xfs_bmapi_write+0x61d/0xc10 [xfs] >>> [...] ? kmem_zone_alloc+0x96/0x100 [xfs] >>> [...] xfs_iomap_write_allocate+0x199/0x3a0 [xfs] >>> [...] xfs_map_blocks+0x1e8/0x260 [xfs] >>> [...] xfs_do_writepage+0x1ca/0x680 [xfs] >>> [...] write_cache_pages+0x26f/0x510 >>> [...] ? xfs_vm_set_page_dirty+0x1d0/0x1d0 [xfs] >>> [...] ? blk_mq_dispatch_rq_list+0x305/0x410 >>> [...] ? deadline_remove_request+0x7d/0xc0 >>> [...] xfs_vm_writepages+0xb6/0xd0 [xfs] >>> [...] do_writepages+0x1c/0x70 >>> [...] __writeback_single_inode+0x45/0x320 >>> [...] writeback_sb_inodes+0x280/0x570 >>> [...] __writeback_inodes_wb+0x8c/0xc0 >>> [...] wb_writeback+0x276/0x310 >>> [...] ? get_nr_dirty_inodes+0x4d/0x80 >>> [...] wb_workfn+0x2d4/0x3b0 >>> [...] process_one_work+0x149/0x360 >>> [...] worker_thread+0x4d/0x3c0 >>> [...] kthread+0x109/0x140 >>> [...] ? rescuer_thread+0x380/0x380 >>> [...] ? kthread_park+0x60/0x60 >>> [...] ret_from_fork+0x25/0x30 >>> >>> >>> I bisected upstream kernel. And I found that the following commit lead >>> the issue. >>> >>> commit c5cb83bb337c25caae995d992d1cdf9b317f83de >>> Author: Thomas Gleixner <tglx@linutronix.de> >>> Date: Tue Jun 20 01:37:51 2017 +0200 >>> >>> genirq/cpuhotplug: Handle managed IRQs on CPU hotplug >> >> Can you please post your /proc/interrupts and details of which >> interrupt you think goes wrong? This backtrace is not telling us much >> in terms of where to start looking... > > Thank you for giving advise. > > The issue is easily reproduced on physical/virtual machine by offling CPUs except cpu0. > Here are my /proc/interrupts on kvm guest before reproducing the issue. And when offlining > cpu1, the issue occurred. But when offling cpu0, the issue didn't occur. > > CPU0 CPU1 > 0: 127 0 IO-APIC 2-edge timer > 1: 10 0 IO-APIC 1-edge i8042 > 4: 227 0 IO-APIC 4-edge ttyS0 > 6: 3 0 IO-APIC 6-edge floppy > 8: 0 0 IO-APIC 8-edge rtc0 > 9: 0 0 IO-APIC 9-fasteoi acpi > 10: 10822 0 IO-APIC 10-fasteoi ehci_hcd:usb1, uhci_hcd:usb2, virtio3 > 11: 23 0 IO-APIC 11-fasteoi uhci_hcd:usb3, uhci_hcd:usb4, qxl > 12: 15 0 IO-APIC 12-edge i8042 > 14: 218 0 IO-APIC 14-edge ata_piix > 15: 0 0 IO-APIC 15-edge ata_piix > 24: 0 0 PCI-MSI 49152-edge virtio0-config > 25: 359 0 PCI-MSI 49153-edge virtio0-input.0 > 26: 1 0 PCI-MSI 49154-edge virtio0-output.0 > 27: 0 0 PCI-MSI 114688-edge virtio2-config > 28: 1 3639 PCI-MSI 114689-edge virtio2-req.0 > 29: 0 0 PCI-MSI 98304-edge virtio1-config > 30: 4 0 PCI-MSI 98305-edge virtio1-virtqueues > 31: 189 0 PCI-MSI 65536-edge snd_hda_intel:card0 > NMI: 0 0 Non-maskable interrupts > LOC: 16115 12845 Local timer interrupts > SPU: 0 0 Spurious interrupts > PMI: 0 0 Performance monitoring interrupts > IWI: 0 0 IRQ work interrupts > RTR: 0 0 APIC ICR read retries > RES: 3016 2135 Rescheduling interrupts > CAL: 3666 557 Function call interrupts > TLB: 65 12 TLB shootdowns > TRM: 0 0 Thermal event interrupts > THR: 0 0 Threshold APIC interrupts > DFR: 0 0 Deferred Error APIC interrupts > MCE: 0 0 Machine check exceptions > MCP: 1 1 Machine check polls > ERR: 0 > MIS: 0 > PIN: 0 0 Posted-interrupt notification event > NPI: 0 0 Nested posted-interrupt event > PIW: 0 0 Posted-interrupt wakeup event I was able to reproduce this with an arm64 VM pretty easily. The issue is that (in the above case), IRQ27 is affine to CPU0, and IRQ28 to CPU1. If you have more CPUs, IRQ27 is affine to the first half of the CPUs, and IRQ28 to the others. When CPU1 is offlined, the fact that we have a "managed" interrupt affinity prevents the interrupt from being moved to CPU0, and you loose your disk. I don't think that's the expected effect... The opposite case (offlining CPU0) only "works" because you're not getting any config interrupt (IOW, you're lucky). I'm not sure how this is supposed to work. Shutting down the interrupt in migrate_one_irq() just breaks everything (unless the driver somehow knows about it, which doesn't seem to be the case). Christoph? M. -- Jazz is not dead. It just smells funny...
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web