Re: [PATCH 0/2] genirq/affinity: try to make sure online CPU is assgined to irq vector

[Laurence Oberman]

On Tue, 2018-01-16 at 12:25 +0100, Thomas Gleixner wrote:
> On Tue, 16 Jan 2018, Ming Lei wrote:
> 
> > On Mon, Jan 15, 2018 at 09:40:36AM -0800, Christoph Hellwig wrote:
> > > On Tue, Jan 16, 2018 at 12:03:43AM +0800, Ming Lei wrote:
> > > > Hi,
> > > > 
> > > > These two patches fixes IO hang issue reported by Laurence.
> > > > 
> > > > 84676c1f21 ("genirq/affinity: assign vectors to all possible
> > > > CPUs")
> > > > may cause one irq vector assigned to all offline CPUs, then
> > > > this vector
> > > > can't handle irq any more.
> > > 
> > > Well, that very much was the intention of managed
> > > interrupts.ÂÂWhy
> > > does the device raise an interrupt for a queue that has no online
> > > cpu assigned to it?
> > 
> > It is because of irq_create_affinity_masks().
> 
> That still does not answer the question. If the interrupt for a queue
> is
> assigned to an offline CPU, then the queue should not be used and
> never
> raise an interrupt. That's how managed interrupts have been designed.
> 
> Thanks,
> 
> 	tglx
> 
> 
> 
> 

I captured a full boot log for this issue for Microsemi, I will send it
to Don Brace.
I enabled all the HPSA debug and here is snippet

[ÂÂÂÂ0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-4.15.0-
rc4.noming+ root=/dev/mapper/rhel_ibclient-root ro crashkernel=512M@64M
 rd.lvm.lv=rhel_ibclient/root rd.lvm.lv=rhel_ibclient/swap
log_buf_len=54M console=ttyS1,115200n8 scsi_mod.use_blk_mq=y
dm_mod.use_blk_mq=y
[ÂÂÂÂ0.000000] Memory: 7834908K/1002852K available (8397K kernel code,
3012K rwdata, 3660K rodata, 2184K init, 15344K bss, 2356808K reserved,
0K cma-reserved)
[ÂÂÂÂ0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=32,
Nodes=2
[ÂÂÂÂ0.000000] ftrace: allocating 33084 entries in 130 pages
[ÂÂÂÂ0.000000] Running RCU self tests
[ÂÂÂÂ0.000000] Hierarchical RCU implementation.
[ÂÂÂÂ0.000000]Â	RCU lockdep checking is enabled.
[ÂÂÂÂ0.000000]Â	RCU restricting CPUs from NR_CPUS=8192 to
nr_cpu_ids=32.
[ÂÂÂÂ0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16,
nr_cpu_ids=32
[ÂÂÂÂ0.000000] NR_IRQS: 524544, nr_irqs: 1088, preallocated irqs: 16
..
..
ÂÂÂÂ0.190147] smp: Brought up 2 nodes, 16 CPUs
[ÂÂÂÂ0.192006] smpboot: Max logical packages: 4
[ÂÂÂÂ0.193007] smpboot: Total of 16 processors activated (76776.33
BogoMIPS)
[ÂÂÂÂ0.940640] node 0 initialised, 10803218 pages in 743ms
[ÂÂÂÂ1.005449] node 1 initialised, 11812066 pages in 807ms
..
..
[ÂÂÂÂ7.440896] hpsa 0000:05:00.0: can't disable ASPM; OS doesn't have
ASPM control
[ÂÂÂÂ7.442071] hpsa 0000:05:00.0: Logical aborts not supported
[ÂÂÂÂ7.442075] hpsa 0000:05:00.0: HP SSD Smart Path aborts not
supported
[ÂÂÂÂ7.442164] hpsa 0000:05:00.0: Controller Configuration information
[ÂÂÂÂ7.442167] hpsa 0000:05:00.0: ------------------------------------
[ÂÂÂÂ7.442173] hpsa 0000:05:00.0:ÂÂÂÂSignature = CISS
[ÂÂÂÂ7.442177] hpsa 0000:05:00.0:ÂÂÂÂSpec Number = 3
[ÂÂÂÂ7.442182] hpsa 0000:05:00.0:ÂÂÂÂTransport methods supported =
0x7a000007
[ÂÂÂÂ7.442186] hpsa 0000:05:00.0:ÂÂÂÂTransport methods active = 0x3
[ÂÂÂÂ7.442190] hpsa 0000:05:00.0:ÂÂÂÂRequested transport Method = 0x2
[ÂÂÂÂ7.442194] hpsa 0000:05:00.0:ÂÂÂÂCoalesce Interrupt Delay = 0x0
[ÂÂÂÂ7.442198] hpsa 0000:05:00.0:ÂÂÂÂCoalesce Interrupt Count = 0x1
[ÂÂÂÂ7.442202] hpsa 0000:05:00.0:ÂÂÂÂMax outstanding commands = 1024
[ÂÂÂÂ7.442206] hpsa 0000:05:00.0:ÂÂÂÂBus Types = 0x200000
[ÂÂÂÂ7.442220] hpsa 0000:05:00.0:ÂÂÂÂServer Name = 2M21220149
[ÂÂÂÂ7.442224] hpsa 0000:05:00.0:ÂÂÂÂHeartbeat Counter = 0xd23
[ÂÂÂÂ7.442224]Â
[ÂÂÂÂ7.442224]Â
..
..
 246.751135] INFO: task systemd-udevd:413 blocked for more than 120
seconds.
[ÂÂ246.788008]ÂÂÂÂÂÂÂTainted: GÂÂÂÂÂÂÂÂÂÂIÂÂÂÂÂÂ4.15.0-rc4.noming+ #1
[ÂÂ246.822380] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ÂÂ246.865594] systemd-udevdÂÂÂDÂÂÂÂ0ÂÂÂ413ÂÂÂÂ411 0x80000004
[ÂÂ246.895519] Call Trace:
[ÂÂ246.909713]ÂÂ? __schedule+0x340/0xc20
[ÂÂ246.930236]ÂÂschedule+0x32/0x80
[ÂÂ246.947905]ÂÂschedule_timeout+0x23d/0x450
[ÂÂ246.970047]ÂÂ? find_held_lock+0x2d/0x90
[ÂÂ246.991774]ÂÂ? wait_for_completion_io+0x108/0x170
[ÂÂ247.018172]ÂÂio_schedule_timeout+0x19/0x40
[ÂÂ247.041208]ÂÂwait_for_completion_io+0x110/0x170
[ÂÂ247.067326]ÂÂ? wake_up_q+0x70/0x70
[ÂÂ247.086801]ÂÂhpsa_scsi_do_simple_cmd+0xc6/0x100 [hpsa]
[ÂÂ247.114315]ÂÂhpsa_scsi_do_simple_cmd_with_retry+0xb7/0x1c0 [hpsa]
[ÂÂ247.146629]ÂÂhpsa_scsi_do_inquiry+0x73/0xd0 [hpsa]
[ÂÂ247.174118]ÂÂhpsa_init_one+0x12cb/0x1a59 [hpsa]
[ÂÂ247.199851]ÂÂ? __pm_runtime_resume+0x55/0x70
[ÂÂ247.224527]ÂÂlocal_pci_probe+0x3f/0xa0
[ÂÂ247.246034]ÂÂpci_device_probe+0x146/0x1b0
[ÂÂ247.268413]ÂÂdriver_probe_device+0x2b3/0x4a0
[ÂÂ247.291868]ÂÂ__driver_attach+0xda/0xe0
[ÂÂ247.313370]ÂÂ? driver_probe_device+0x4a0/0x4a0
[ÂÂ247.338399]ÂÂbus_for_each_dev+0x6a/0xb0
[ÂÂ247.359912]ÂÂbus_add_driver+0x41/0x260
[ÂÂ247.380244]ÂÂdriver_register+0x5b/0xd0
[ÂÂ247.400811]ÂÂ? 0xffffffffc016b000
[ÂÂ247.418819]ÂÂhpsa_init+0x38/0x1000 [hpsa]
[ÂÂ247.440763]ÂÂ? 0xffffffffc016b000
[ÂÂ247.459451]ÂÂdo_one_initcall+0x4d/0x19c
[ÂÂ247.480539]ÂÂ? do_init_module+0x22/0x220
[ÂÂ247.502575]ÂÂ? rcu_read_lock_sched_held+0x64/0x70
[ÂÂ247.529549]ÂÂ? kmem_cache_alloc_trace+0x1f7/0x260
[ÂÂ247.556204]ÂÂ? do_init_module+0x22/0x220
[ÂÂ247.578633]ÂÂdo_init_module+0x5a/0x220
[ÂÂ247.600322]ÂÂload_module+0x21e8/0x2a50
[ÂÂ247.621648]ÂÂ? __symbol_put+0x60/0x60
[ÂÂ247.642796]ÂÂSYSC_finit_module+0x94/0xe0
[ÂÂ247.665336]ÂÂentry_SYSCALL_64_fastpath+0x1f/0x96
[ÂÂ247.691751] RIP: 0033:0x7fc63d6527f9
[ÂÂ247.712308] RSP: 002b:00007ffdf1659ba8 EFLAGS: 00000246 ORIG_RAX:
0000000000000139
[ÂÂ247.755272] RAX: ffffffffffffffda RBX: 0000556b524c5f70 RCX:
00007fc63d6527f9
[ÂÂ247.795779] RDX: 0000000000000000 RSI: 00007fc63df6f099 RDI:
0000000000000008
[ÂÂ247.836413] RBP: 00007fc63df6f099 R08: 0000000000000000 R09:
0000556b524be760
[ÂÂ247.876395] R10: 0000000000000008 R11: 0000000000000246 R12:
0000000000000000
[ÂÂ247.917597] R13: 0000556b524c5f10 R14: 0000000000020000 R15:
0000000000000000
[ÂÂ247.957272]Â
[ÂÂ247.957272] Showing all locks held in the system:
[ÂÂ247.992019] 1 lock held by khungtaskd/118:
[ÂÂ248.015019]ÂÂ#0:ÂÂ(tasklist_lock){.+.+}, at: [<000000004ef3538d>]
debug_show_all_locks+0x39/0x1b0
[ÂÂ248.064600] 2 locks held by systemd-udevd/413:
[ÂÂ248.090031]ÂÂ#0:ÂÂ(&dev->mutex){....}, at: [<000000002a395ec8>]
__driver_attach+0x4a/0xe0
[ÂÂ248.136620]ÂÂ#1:ÂÂ(&dev->mutex){....}, at: [<00000000d9def23c>]
__driver_attach+0x58/0xe0
[ÂÂ248.183245]Â
[ÂÂ248.191675] =============================================
[ÂÂ248.191675]Â
[ÂÂ314.825134] dracut-initqueue[437]: Warning: dracut-initqueue timeout
- starting timeout scripts
[ÂÂ315.368421] dracut-initqueue[437]: Warning: dracut-initqueue timeout
- starting timeout scripts
[ÂÂ315.894373] dracut-initqueue[437]: Warning: dracut-initqueue timeout
- starting timeout scripts
[ÂÂ316.418385] dracut-initqueue[437]: Warning: dracut-initqueue timeout
- starting timeout scripts
[ÂÂ316.944461] dracut-initqueue[437]: Warning: dracut-initqueue timeout
- starting timeout scripts
[ÂÂ317.466708] dracut-initqueue[437]: Warning: dracut-initqueue timeout
- starting timeout scripts
[ÂÂ317.994380] dracut-initqueue[437]: Warning: dracut-initqueue timeout
- starti