Bug 200197

Summary: WARNING: CPU: 15 PID: 747 at /build/linux-jIx23a/linux-4.15.11/kernel/irq/chip.c:244 __irq_startup+0x5c/0x70
Product: Other Reporter: Luis Chamberlain (mcgrof)
Component: ModulesAssignee: other_modules
Status: NEW ---    
Severity: low    
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 4.15.11 Subsystem:
Regression: No Bisected commit-id:

Description Luis Chamberlain 2018-06-22 22:18:43 UTC 
Running qemu with KVM with two pts set will eventually trigger the following kernel warning:

Jun 19 22:51:46 linux417 kernel: [   10.863217] WARNING: CPU: 15 PID: 747 at /build/linux-jIx23a/linux-4.15.11/kernel/irq/chip.c:244 __irq_startup+0x5c/0x70
Jun 19 22:51:46 linux417 kernel: [   10.863218] Modules linked in: xfs libcrc32c bochs_drm ttm joydev drm_kms_helper serio_raw ppdev parport_pc drm sg pcspkr evdev parport button ip_tables x
_tables autofs4 ext4 crc16 mbcache jbd2 crc32c_generic fscrypto ecb crypto_simd cryptd glue_helper aes_x86_64 sd_mod ata_generic ata_piix libata psmouse e1000 scsi_mod i2c_piix4 floppy
Jun 19 22:51:46 linux417 kernel: [   10.863243] CPU: 15 PID: 747 Comm: (agetty) Not tainted 4.15.0-2-amd64 #1 Debian 4.15.11-1
Jun 19 22:51:46 linux417 kernel: [   10.863244] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.11.1-0-g0551a4be2c-prebuilt.qemu-project.org 04/01/2014
Jun 19 22:51:46 linux417 kernel: [   10.863247] RIP: 0010:__irq_startup+0x5c/0x70
Jun 19 22:51:46 linux417 kernel: [   10.863248] RSP: 0018:ffffb05e41a7bb00 EFLAGS: 00010046
Jun 19 22:51:46 linux417 kernel: [   10.863249] RAX: 0000000005030000 RBX: ffff8d6236811c00 RCX: 0000000000000004
Jun 19 22:51:46 linux417 kernel: [   10.863250] RDX: ffff8d6236811c00 RSI: 0000000000000001 RDI: ffff8d6236811c98
Jun 19 22:51:46 linux417 kernel: [   10.863251] RBP: 0000000000000004 R08: ffff8d6236400490 R09: ffff8d6236811c00
Jun 19 22:51:46 linux417 kernel: [   10.863252] R10: 0000000000000000 R11: 0000000000000040 R12: 0000000000000001
Jun 19 22:51:46 linux417 kernel: [   10.863253] R13: 0000000000000001 R14: 0000000000000000 R15: ffff8d622f063080
Jun 19 22:51:46 linux417 kernel: [   10.863258] FS:  00007fb80ab02dc0(0000) GS:ffff8d62371c0000(0000) knlGS:0000000000000000
Jun 19 22:51:46 linux417 kernel: [   10.863259] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun 19 22:51:46 linux417 kernel: [   10.863260] CR2: 00007fb80a4852c1 CR3: 00000002341c0000 CR4: 00000000000006e0
Jun 19 22:51:46 linux417 kernel: [   10.863277] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jun 19 22:51:46 linux417 kernel: [   10.863278] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Jun 19 22:51:46 linux417 kernel: [   10.863278] Call Trace:
Jun 19 22:51:46 linux417 kernel: [   10.863287]  irq_startup+0x57/0xe0
Jun 19 22:51:46 linux417 kernel: [   10.863290]  enable_irq+0x49/0x90
Jun 19 22:51:46 linux417 kernel: [   10.863296]  serial8250_do_startup+0x79d/0x810
Jun 19 22:51:46 linux417 kernel: [   10.863298]  uart_startup.part.22+0x5a/0x160
Jun 19 22:51:46 linux417 kernel: [   10.863303]  tty_port_open+0x89/0xd0
Jun 19 22:51:46 linux417 kernel: [   10.863305]  uart_open+0x3c/0x50
Jun 19 22:51:46 linux417 kernel: [   10.863307]  tty_open+0xf5/0x470
Jun 19 22:51:46 linux417 kernel: [   10.863311]  chrdev_open+0xc4/0x1d0
Jun 19 22:51:46 linux417 kernel: [   10.863313]  ? cdev_put.part.1+0x20/0x20
Jun 19 22:51:46 linux417 kernel: [   10.863316]  do_dentry_open+0x1b3/0x2f0
Jun 19 22:51:46 linux417 kernel: [   10.863320]  path_openat+0x611/0x1600
Jun 19 22:51:46 linux417 kernel: [   10.863324]  ? check_preempt_wakeup+0x102/0x230
Jun 19 22:51:46 linux417 kernel: [   10.863327]  do_filp_open+0x9b/0x110
Jun 19 22:51:46 linux417 kernel: [   10.863330]  ? tty_release_struct+0x2f/0x40
Jun 19 22:51:46 linux417 kernel: [   10.863332]  ? __check_object_size+0xaf/0x1b0
Jun 19 22:51:46 linux417 kernel: [   10.863334]  ? do_sys_open+0x1bd/0x250
Jun 19 22:51:46 linux417 kernel: [   10.863335]  do_sys_open+0x1bd/0x250
Jun 19 22:51:46 linux417 kernel: [   10.863341]  do_syscall_64+0x6e/0x130
Jun 19 22:51:46 linux417 kernel: [   10.863347]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Jun 19 22:51:46 linux417 kernel: [   10.863349] RIP: 0033:0x7fb80a6e83ab
Jun 19 22:51:46 linux417 kernel: [   10.863350] RSP: 002b:00007ffd76d3e310 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
Jun 19 22:51:46 linux417 kernel: [   10.863352] RAX: ffffffffffffffda RBX: 00005564a593f310 RCX: 00007fb80a6e83ab
Jun 19 22:51:46 linux417 kernel: [   10.863353] RDX: 0000000000080902 RSI: 00005564a5942970 RDI: 00000000ffffff9c
Jun 19 22:51:46 linux417 kernel: [   10.863354] RBP: 0000000000000015 R08: 00007ffd76d3e320 R09: 0000000000000000
Jun 19 22:51:46 linux417 kernel: [   10.863355] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000080902
Jun 19 22:51:46 linux417 kernel: [   10.863356] R13: 00005564a5942970 R14: 00005564a593f310 R15: 00005564a593ee70
Jun 19 22:51:46 linux417 kernel: [   10.863357] Code: 92 00 48 8b 93 a8 00 00 00 81 22 ff ff fe ff 48 8b 93 a8 00 00 00 81 22 ff ff fd ff 48 8b 93 a8 00 00 00 81 0a 00 00 40 00 5b c3 <0f> 0b eb be 48 89 df e8 28 ff ff ff 31 c0 eb e1 0f 1f 40 00 0f 
Jun 19 22:51:46 linux417 kernel: [   10.863383] ---[ end trace 92b708d2e2cee684 ]---


This is reproduced by running qemu with two pts, so something like:
qemu-system-x86_64 -cpu kvm64 -enable-kvm -m 8192 -smp 4 \
  -nographic -boot order=d
  -monitor pty
  -serial stdio \
  -chardev pty,id=ttyS1 -device isa-serial,chardev=ttyS1 \
  -chardev pty,id=ttyS2 -device isa-serial,chardev=ttyS2 \

Reproduced on qemu 2.12.0.

Although the above triggers on v4.15 later kernels may also suffer it. The above was a debian v4.15 kernel. I'll test later when I have time with later kernels.

After this warning we get this splat:

Jun 19 22:51:46 linux417 kernel: [   10.863800] spurious APIC interrupt through vector ff on CPU#0, should never happen.
Jun 19 22:51:46 linux417 kernel: [   10.868143] do_IRQ: 11.33 No irq handler for vector
Jun 19 22:51:46 linux417 kernel: [   10.889122] ------------[ cut here ]------------
Jun 19 22:51:46 linux417 kernel: [   10.889124] Unbalanced enable for IRQ 4
Jun 19 22:51:46 linux417 kernel: [   10.889144] WARNING: CPU: 15 PID: 747 at /build/linux-jIx23a/linux-4.15.11/kernel/irq/manage.c:526 __enable_irq+0x2f/0x60
Jun 19 22:51:46 linux417 kernel: [   10.889145] Modules linked in: xfs libcrc32c bochs_drm ttm joydev drm_kms_helper serio_raw ppdev parport_pc drm sg pcspkr evdev parport button ip_tables x_tables autofs4 ext4 crc16 mbcache jbd2 crc32c_generic fscrypto ecb crypto_simd cryptd glue_helper aes_x86_64 sd_mod ata_generic ata_piix libata psmouse e1000 scsi_mod i2c_piix4 floppy
Jun 19 22:51:46 linux417 kernel: [   10.889161] CPU: 15 PID: 747 Comm: agetty Tainted: G        W        4.15.0-2-amd64 #1 Debian 4.15.11-1
Jun 19 22:51:46 linux417 kernel: [   10.889161] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.11.1-0-g0551a4be2c-prebuilt.qemu-project.org 04/01/2014
Jun 19 22:51:46 linux417 kernel: [   10.889162] RIP: 0010:__enable_irq+0x2f/0x60
Jun 19 22:51:46 linux417 kernel: [   10.889163] RSP: 0018:ffffb05e41a7bb30 EFLAGS: 00010082
Jun 19 22:51:46 linux417 kernel: [   10.889165] RAX: 0000000000000000 RBX: ffff8d6236811c00 RCX: 0000000000000006
Jun 19 22:51:46 linux417 kernel: [   10.889165] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffff8d62371d66f0
Jun 19 22:51:46 linux417 kernel: [   10.889166] RBP: 0000000000000004 R08: 0000000000000273 R09: 0000000000000004
Jun 19 22:51:46 linux417 kernel: [   10.889167] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000246
Jun 19 22:51:46 linux417 kernel: [   10.889167] R13: 0000000000000002 R14: 0000000000000000 R15: ffff8d622f063080
Jun 19 22:51:46 linux417 kernel: [   10.889171] FS:  00007f1d1e5c0580(0000) GS:ffff8d62371c0000(0000) knlGS:0000000000000000
Jun 19 22:51:46 linux417 kernel: [   10.889172] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jun 19 22:51:46 linux417 kernel: [   10.889172] CR2: 00007f1d1e037260 CR3: 00000002332fe000 CR4: 00000000000006e0
Jun 19 22:51:46 linux417 kernel: [   10.889185] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jun 19 22:51:46 linux417 kernel: [   10.889186] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Jun 19 22:51:46 linux417 kernel: [   10.889187] Call Trace:
Jun 19 22:51:46 linux417 kernel: [   10.889191]  enable_irq+0x49/0x90
Jun 19 22:51:46 linux417 kernel: [   10.889195]  serial8250_do_startup+0x79d/0x810
Jun 19 22:51:46 linux417 kernel: [   10.889196]  uart_startup.part.22+0x5a/0x160
Jun 19 22:51:46 linux417 kernel: [   10.889199]  tty_port_open+0x89/0xd0
Jun 19 22:51:46 linux417 kernel: [   10.889200]  uart_open+0x3c/0x50
Jun 19 22:51:46 linux417 kernel: [   10.889202]  tty_open+0xf5/0x470
Jun 19 22:51:46 linux417 kernel: [   10.889204]  chrdev_open+0xc4/0x1d0
Jun 19 22:51:46 linux417 kernel: [   10.889205]  ? cdev_put.part.1+0x20/0x20
Jun 19 22:51:46 linux417 kernel: [   10.889206]  do_dentry_open+0x1b3/0x2f0
Jun 19 22:51:46 linux417 kernel: [   10.889209]  path_openat+0x611/0x1600
Jun 19 22:51:46 linux417 kernel: [   10.889211]  ? update_load_avg+0x563/0x6c0
Jun 19 22:51:46 linux417 kernel: [   10.889212]  ? update_load_avg+0x563/0x6c0
Jun 19 22:51:46 linux417 kernel: [   10.889213]  ? set_next_entity+0xa1/0x200
Jun 19 22:51:46 linux417 kernel: [   10.889215]  do_filp_open+0x9b/0x110
Jun 19 22:51:46 linux417 kernel: [   10.889217]  ? __check_object_size+0xaf/0x1b0
Jun 19 22:51:46 linux417 kernel: [   10.889219]  ? do_sys_open+0x1bd/0x250
Jun 19 22:51:46 linux417 kernel: [   10.889220]  do_sys_open+0x1bd/0x250
Jun 19 22:51:46 linux417 kernel: [   10.889222]  do_syscall_64+0x6e/0x130
Jun 19 22:51:46 linux417 kernel: [   10.889225]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Jun 19 22:51:46 linux417 kernel: [   10.889226] RIP: 0033:0x7f1d1e0d1c6e
Jun 19 22:51:46 linux417 kernel: [   10.889227] RSP: 002b:00007fff107ebd00 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
Jun 19 22:51:46 linux417 kernel: [   10.889229] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f1d1e0d1c6e
Jun 19 22:51:46 linux417 kernel: [   10.889229] RDX: 0000000000000902 RSI: 00007fff107ec6a0 RDI: 00000000ffffff9c
Jun 19 22:51:46 linux417 kernel: [   10.889230] RBP: 00007fff107ec220 R08: 00007fff107ebd10 R09: 00007fff107eff3b
Jun 19 22:51:46 linux417 kernel: [   10.889231] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000003
Jun 19 22:51:46 linux417 kernel: [   10.889232] R13: 00007fff107eff3b R14: 00000000000002eb R15: 00007fff107ec6a0
Jun 19 22:51:46 linux417 kernel: [   10.889233] Code: 00 8b 87 f0 00 00 00 85 c0 74 0e 83 f8 01 75 1e f6 87 ed 00 00 00 08 74 1f 8b b7 9c 00 00 00 48 c7 c7 48 b8 e1 ab e8 51 f9 f9 ff <0f> 0b c3 83 e8 01 89 87 f0 00 00 00 c3 81 8f e8 00 00 00 00 04 
Jun 19 22:51:46 linux417 kernel: [   10.889254] ---[ end trace 92b708d2e2cee685 ]---


And then we have blocking more than 120 seconds warnings:

Jun 19 22:55:39 linux417 kernel: [  242.652127] INFO: task kworker/27:2:351 blocked for more than 120 seconds.
Jun 19 22:55:39 linux417 kernel: [  242.661387]       Tainted: G        W        4.15.0-2-amd64 #1 Debian 4.15.11-1
Jun 19 22:55:39 linux417 kernel: [  242.670626] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 19 22:55:39 linux417 kernel: [  242.680951] kworker/27:2    D    0   351      2 0x80000000
Jun 19 22:55:39 linux417 kernel: [  242.680963] Workqueue: events slab_caches_to_rcu_destroy_workfn
Jun 19 22:55:39 linux417 kernel: [  242.680964] Call Trace:
Jun 19 22:55:39 linux417 kernel: [  242.680974]  ? __schedule+0x297/0x8b0
Jun 19 22:55:39 linux417 kernel: [  242.680977]  schedule+0x28/0x80
Jun 19 22:55:39 linux417 kernel: [  242.680981]  schedule_timeout+0x1e6/0x370
Jun 19 22:55:39 linux417 kernel: [  242.680985]  ? __slab_free+0x15a/0x300
Jun 19 22:55:39 linux417 kernel: [  242.680987]  ? __slab_free+0x15a/0x300
Jun 19 22:55:39 linux417 kernel: [  242.680990]  ? rcu_barrier_func+0x35/0x50
Jun 19 22:55:39 linux417 kernel: [  242.680992]  wait_for_completion+0x12c/0x190
Jun 19 22:55:39 linux417 kernel: [  242.680997]  ? wake_up_q+0x70/0x70
Jun 19 22:55:39 linux417 kernel: [  242.680999]  _rcu_barrier+0x124/0x180
Jun 19 22:55:39 linux417 kernel: [  242.681002]  slab_caches_to_rcu_destroy_workfn+0x8f/0xe0
Jun 19 22:55:39 linux417 kernel: [  242.681006]  process_one_work+0x17b/0x370
Jun 19 22:55:39 linux417 kernel: [  242.681009]  worker_thread+0x2e/0x390
Jun 19 22:55:39 linux417 kernel: [  242.681011]  ? process_one_work+0x370/0x370
Jun 19 22:55:39 linux417 kernel: [  242.681169]  kthread+0x113/0x130
Jun 19 22:55:39 linux417 kernel: [  242.681175]  ? kthread_create_worker_on_cpu+0x70/0x70
Jun 19 22:55:39 linux417 kernel: [  242.681180]  ret_from_fork+0x35/0x40
Jun 19 22:57:40 linux417 kernel: [  363.484325] INFO: task kworker/27:2:351 blocked for more than 120 seconds.
Jun 19 22:57:40 linux417 kernel: [  363.494585]       Tainted: G        W        4.15.0-2-amd64 #1 Debian 4.15.11-1
Jun 19 22:57:40 linux417 kernel: [  363.502931] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 19 22:57:40 linux417 kernel: [  363.511982] kworker/27:2    D    0   351      2 0x80000000
Jun 19 22:57:40 linux417 kernel: [  363.511993] Workqueue: events slab_caches_to_rcu_destroy_workfn
Jun 19 22:57:40 linux417 kernel: [  363.511995] Call Trace:
Jun 19 22:57:40 linux417 kernel: [  363.512003]  ? __schedule+0x297/0x8b0
Jun 19 22:57:40 linux417 kernel: [  363.512032]  schedule+0x28/0x80
Jun 19 22:57:40 linux417 kernel: [  363.512035]  schedule_timeout+0x1e6/0x370
Jun 19 22:57:40 linux417 kernel: [  363.512039]  ? __slab_free+0x15a/0x300
Jun 19 22:57:40 linux417 kernel: [  363.512040]  ? __slab_free+0x15a/0x300
Jun 19 22:57:40 linux417 kernel: [  363.512043]  ? rcu_barrier_func+0x35/0x50
Jun 19 22:57:40 linux417 kernel: [  363.512045]  wait_for_completion+0x12c/0x190
Jun 19 22:57:40 linux417 kernel: [  363.512049]  ? wake_up_q+0x70/0x70
Jun 19 22:57:40 linux417 kernel: [  363.512052]  _rcu_barrier+0x124/0x180
Jun 19 22:57:40 linux417 kernel: [  363.512054]  slab_caches_to_rcu_destroy_workfn+0x8f/0xe0
Jun 19 22:57:40 linux417 kernel: [  363.512058]  process_one_work+0x17b/0x370
Jun 19 22:57:40 linux417 kernel: [  363.512061]  worker_thread+0x2e/0x390
Jun 19 22:57:40 linux417 kernel: [  363.512062]  ? process_one_work+0x370/0x370
Jun 19 22:57:40 linux417 kernel: [  363.512064]  kthread+0x113/0x130
Jun 19 22:57:40 linux417 kernel: [  363.512066]  ? kthread_create_worker_on_cpu+0x70/0x70
Jun 19 22:57:40 linux417 kernel: [  363.512068]  ret_from_fork+0x35/0x40