[BUGFIX,1/1] block, bfq: add requeue-request hook

Message ID	20180205190510.5499-2-paolo.valente@linaro.org
State	Superseded
Headers	show Delivered-To: patch@linaro.org Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67; From: Paolo Valente <paolo.valente@linaro.org> To: Jens Axboe <axboe@kernel.dk> Cc: linux-block@vger.kernel.org, linux-kernel@vger.kernel.org, ulf.hansson@linaro.org, broonie@kernel.org, linus.walleij@linaro.org, bfq-iosched@googlegroups.com, oleksandr@natalenko.name, alban.browaeys@gmail.com, ming.lei@redhat.com, ivan@ludios.org, 169364@studenti.unimore.it, Paolo Valente <paolo.valente@linaro.org>, Serena Ziviani <ziviani.serena@gmail.com> Subject: [PATCH BUGFIX 1/1] block, bfq: add requeue-request hook Date: Mon, 5 Feb 2018 20:05:10 +0100 Message-Id: <20180205190510.5499-2-paolo.valente@linaro.org> In-Reply-To: <20180205190510.5499-1-paolo.valente@linaro.org> References: <20180205190510.5499-1-paolo.valente@linaro.org> Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk
Series	block, bfq: handle requeues of I/O requests \| expand [BUGFIX,0/1] block, bfq: handle requeues of I/O requests [BUGFIX,1/1] block, bfq: add requeue-request hook

Paolo Valente Feb. 5, 2018, 7:05 p.m. UTC

Commit 'a6a252e64914 ("blk-mq-sched: decide how to handle flush rq via
RQF_FLUSH_SEQ")' makes all non-flush re-prepared requests for a device
be re-inserted into the active I/O scheduler for that device. As a
consequence, I/O schedulers may get the same request inserted again,
even several times, without a finish_request invoked on that request
before each re-insertion.

This fact is the cause of the failure reported in [1]. For an I/O
scheduler, every re-insertion of the same re-prepared request is
equivalent to the insertion of a new request. For schedulers like
mq-deadline or kyber, this fact causes no harm. In contrast, it
confuses a stateful scheduler like BFQ, which keeps state for an I/O
request, until the finish_request hook is invoked on the request. In
particular, BFQ may get stuck, waiting forever for the number of
request dispatches, of the same request, to be balanced by an equal
number of request completions (while there will be one completion for
that request). In this state, BFQ may refuse to serve I/O requests
from other bfq_queues. The hang reported in [1] then follows.

However, the above re-prepared requests undergo a requeue, thus the
requeue_request hook of the active elevator is invoked for these
requests, if set. This commit then addresses the above issue by
properly implementing the hook requeue_request in BFQ.

[1] https://marc.info/?l=linux-block&m=151211117608676

Reported-by: Ivan Kozik <ivan@ludios.org>
Reported-by: Alban Browaeys <alban.browaeys@gmail.com>
Signed-off-by: Paolo Valente <paolo.valente@linaro.org>

Signed-off-by: Serena Ziviani <ziviani.serena@gmail.com>

---
 block/bfq-iosched.c | 101 +++++++++++++++++++++++++++++++++++++++-------------
 1 file changed, 76 insertions(+), 25 deletions(-)

-- 
2.15.1

Mike Galbraith Feb. 6, 2018, 4:22 a.m. UTC | #1

Hi Paolo,

I applied this to master.today, flipped udev back to bfq and took it
for a spin.  Unfortunately, box fairly quickly went boom under load.

[  454.739975] ------------[ cut here ]------------
[  454.739979] list_add corruption. prev->next should be next (000000005f99a42a), but was           (null). (prev=00000000fc569ec9).
[  454.739989] WARNING: CPU: 3 PID: 0 at lib/list_debug.c:28 __list_add_valid+0x6a/0x70
[  454.739990] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) nls_iso8859_1(E) nls_cp437(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) snd_hda_codec_hdmi(E) coretemp(E) snd_hda_codec_realtek(E) snd_hda_codec_generic(E) kvm_intel(E) kvm(E) snd_hda_intel(E) snd_hda_codec(E) snd_hwdep(E) snd_hda_core(E) snd_pcm(E) irqbypass(E) snd_timer(E) joydev(E) crct10dif_pclmul(E) snd(E) r8169(E) crc32_pclmul(E) mii(E) mei_me(E) soundcore(E)
[  454.740011]  crc32c_intel(E) iTCO_wdt(E) ghash_clmulni_intel(E) iTCO_vendor_support(E) pcbc(E) mei(E) lpc_ich(E) aesni_intel(E) i2c_i801(E) mfd_core(E) aes_x86_64(E) shpchp(E) intel_smartconnect(E) crypto_simd(E) glue_helper(E) cryptd(E) pcspkr(E) fan(E) thermal(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) sunrpc(E) sr_mod(E) cdrom(E) hid_logitech_hidpp(E) hid_logitech_dj(E) uas(E) usb_storage(E) hid_generic(E) usbhid(E) nouveau(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) fb_sys_fops(E) ahci(E) xhci_pci(E) ttm(E) libahci(E) ehci_pci(E) xhci_hcd(E) ehci_hcd(E) libata(E) drm(E) usbcore(E) video(E) button(E) sd_mod(E) vfat(E) fat(E) virtio_blk(E) virtio_mmio(E) virtio_pci(E) virtio_ring(E) virtio(E) ext4(E) crc16(E) mbcache(E) jbd2(E) loop(E) sg(E)
[  454.740038]  dm_multipath(E) dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)
[  454.740043] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G            E    4.15.0.ge237f98-master #605
[  454.740044] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
[  454.740046] RIP: 0010:__list_add_valid+0x6a/0x70
[  454.740047] RSP: 0018:ffff88041ecc3ca8 EFLAGS: 00010096
[  454.740048] RAX: 0000000000000075 RBX: ffff8803f33fa8c0 RCX: 0000000000000006
[  454.740049] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff88041ecd5570
[  454.740050] RBP: ffff8803f596d7e0 R08: 0000000000000000 R09: 0000000000000368
[  454.740051] R10: 0000000000000000 R11: ffff88041ecc3a30 R12: ffff8803eb1c8828
[  454.740052] R13: ffff8803f33fa940 R14: ffff8803f5852600 R15: ffff8803f596d810
[  454.740053] FS:  0000000000000000(0000) GS:ffff88041ecc0000(0000) knlGS:0000000000000000
[  454.740054] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  454.740055] CR2: 00000000014d9788 CR3: 0000000001e0a006 CR4: 00000000001606e0
[  454.740056] Call Trace:
[  454.740058]  <IRQ>
[  454.740062]  blk_flush_complete_seq+0x2b1/0x370
[  454.740065]  flush_end_io+0x18c/0x280
[  454.740074]  scsi_end_request+0x95/0x1e0 [scsi_mod]
[  454.740079]  scsi_io_completion+0xbb/0x5d0 [scsi_mod]
[  454.740082]  __blk_mq_complete_request+0xb7/0x180
[  454.740084]  blk_mq_complete_request+0x50/0x90
[  454.740087]  ? scsi_vpd_tpg_id+0x90/0x90 [scsi_mod]
[  454.740095]  ata_scsi_qc_complete+0x1d8/0x470 [libata]
[  454.740100]  ata_qc_complete_multiple+0x87/0xd0 [libata]
[  454.740103]  ahci_handle_port_interrupt+0xd4/0x4e0 [libahci]
[  454.740105]  ahci_handle_port_intr+0x6f/0xb0 [libahci]
[  454.740107]  ahci_single_level_irq_intr+0x3b/0x60 [libahci]
[  454.740110]  __handle_irq_event_percpu+0x40/0x1a0
[  454.740112]  handle_irq_event_percpu+0x20/0x50
[  454.740114]  handle_irq_event+0x36/0x60
[  454.740116]  handle_edge_irq+0x90/0x190
[  454.740118]  handle_irq+0x1c/0x30
[  454.740120]  do_IRQ+0x43/0xd0
[  454.740122]  common_interrupt+0xa2/0xa2
[  454.740123]  </IRQ>
[  454.740125] RIP: 0010:cpuidle_enter_state+0xec/0x250
[  454.740126] RSP: 0018:ffff880187febec0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd
[  454.740127] RAX: ffff88041ece0040 RBX: ffff88041ece77e8 RCX: 000000000000001f
[  454.740128] RDX: 0000000000000000 RSI: fffffffd9cb7bc38 RDI: 0000000000000000
[  454.740129] RBP: 0000000000000005 R08: 0000000000000006 R09: 000000000000024f
[  454.740130] R10: 0000000000000205 R11: 0000000000000018 R12: 0000000000000003
[  454.740131] R13: 00000069e09a3c87 R14: 0000000000000003 R15: 00000069e09d450c
[  454.740134]  do_idle+0x16a/0x1d0
[  454.740136]  cpu_startup_entry+0x19/0x20
[  454.740138]  start_secondary+0x14e/0x190
[  454.740140]  secondary_startup_64+0xa5/0xb0
[  454.740141] Code: fe 31 c0 48 c7 c7 a0 61 bf 81 e8 12 f7 d8 ff 0f ff 31 c0 c3 48 89 d1 48 c7 c7 50 61 bf 81 48 89 f2 48 89 c6 31 c0 e8 f6 f6 d8 ff <0f> ff 31 c0 c3 90 48 8b 07 48 b9 00 01 00 00 00 00 ad de 48 8b 
[  454.740159] ---[ end trace c2b6ab81731e93a0 ]---
[  454.740278] ------------[ cut here ]------------
[  454.740281] list_del corruption. prev->next should be 0000000056dbdea8, but was 00000000577efd13
[  454.740286] WARNING: CPU: 3 PID: 0 at lib/list_debug.c:53 __list_del_entry_valid+0x7c/0xa0
[  454.740287] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) nls_iso8859_1(E) nls_cp437(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) snd_hda_codec_hdmi(E) coretemp(E) snd_hda_codec_realtek(E) snd_hda_codec_generic(E) kvm_intel(E) kvm(E) snd_hda_intel(E) snd_hda_codec(E) snd_hwdep(E) snd_hda_core(E) snd_pcm(E) irqbypass(E) snd_timer(E) joydev(E) crct10dif_pclmul(E) snd(E) r8169(E) crc32_pclmul(E) mii(E) mei_me(E) soundcore(E)
[  454.740302]  crc32c_intel(E) iTCO_wdt(E) ghash_clmulni_intel(E) iTCO_vendor_support(E) pcbc(E) mei(E) lpc_ich(E) aesni_intel(E) i2c_i801(E) mfd_core(E) aes_x86_64(E) shpchp(E) intel_smartconnect(E) crypto_simd(E) glue_helper(E) cryptd(E) pcspkr(E) fan(E) thermal(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) sunrpc(E) sr_mod(E) cdrom(E) hid_logitech_hidpp(E) hid_logitech_dj(E) uas(E) usb_storage(E) hid_generic(E) usbhid(E) nouveau(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) fb_sys_fops(E) ahci(E) xhci_pci(E) ttm(E) libahci(E) ehci_pci(E) xhci_hcd(E) ehci_hcd(E) libata(E) drm(E) usbcore(E) video(E) button(E) sd_mod(E) vfat(E) fat(E) virtio_blk(E) virtio_mmio(E) virtio_pci(E) virtio_ring(E) virtio(E) ext4(E) crc16(E) mbcache(E) jbd2(E) loop(E) sg(E)
[  454.740321]  dm_multipath(E) dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)
[  454.740324] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        W   E    4.15.0.ge237f98-master #605
[  454.740325] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
[  454.740327] RIP: 0010:__list_del_entry_valid+0x7c/0xa0
[  454.740328] RSP: 0018:ffff88041ecc3cb8 EFLAGS: 00010096
[  454.740329] RAX: 0000000000000054 RBX: ffff8803f33fa8c0 RCX: 0000000000000006
[  454.740330] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff88041ecd5570
[  454.740331] RBP: ffff8803f596d7e0 R08: 0000000000000101 R09: 000000000000039d
[  454.740332] R10: 0000000000000000 R11: ffff88041ecc3a40 R12: ffff8803eb1c8828
[  454.740333] R13: ffff8803f596d7f0 R14: 0000000000000000 R15: ffff8803f33fa940
[  454.740334] FS:  0000000000000000(0000) GS:ffff88041ecc0000(0000) knlGS:0000000000000000
[  454.740335] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  454.740336] CR2: 00000000014d9788 CR3: 0000000001e0a006 CR4: 00000000001606e0
[  454.740337] Call Trace:
[  454.740338]  <IRQ>
[  454.740340]  blk_flush_complete_seq+0x16e/0x370
[  454.740343]  mq_flush_data_end_io+0xb0/0x110
[  454.740348]  scsi_end_request+0x95/0x1e0 [scsi_mod]
[  454.740352]  scsi_io_completion+0x10b/0x5d0 [scsi_mod]
[  454.740354]  __blk_mq_complete_request+0xb7/0x180
[  454.740355]  blk_mq_complete_request+0x50/0x90
[  454.740359]  ? scsi_vpd_tpg_id+0x90/0x90 [scsi_mod]
[  454.740364]  ata_scsi_qc_complete+0x1d8/0x470 [libata]
[  454.740368]  ata_qc_complete_multiple+0x87/0xd0 [libata]
[  454.740371]  ahci_handle_port_interrupt+0xd4/0x4e0 [libahci]
[  454.740373]  ahci_handle_port_intr+0x6f/0xb0 [libahci]
[  454.740374]  ahci_single_level_irq_intr+0x3b/0x60 [libahci]
[  454.740377]  __handle_irq_event_percpu+0x40/0x1a0
[  454.740379]  handle_irq_event_percpu+0x20/0x50
[  454.740380]  handle_irq_event+0x36/0x60
[  454.740382]  handle_edge_irq+0x90/0x190
[  454.740383]  handle_irq+0x1c/0x30
[  454.740385]  do_IRQ+0x43/0xd0
[  454.740386]  common_interrupt+0xa2/0xa2
[  454.740387]  </IRQ>
[  454.740389] RIP: 0010:cpuidle_enter_state+0xec/0x250
[  454.740389] RSP: 0018:ffff880187febec0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd
[  454.740391] RAX: ffff88041ece0040 RBX: ffff88041ece77e8 RCX: 000000000000001f
[  454.740392] RDX: 0000000000000000 RSI: fffffffd9cb7bc38 RDI: 0000000000000000
[  454.740393] RBP: 0000000000000005 R08: 0000000000000006 R09: 000000000000024f
[  454.740393] R10: 0000000000000205 R11: 0000000000000018 R12: 0000000000000003
[  454.740394] R13: 00000069e0a06158 R14: 0000000000000003 R15: 00000069e0a1e8c6
[  454.740397]  do_idle+0x16a/0x1d0
[  454.740399]  cpu_startup_entry+0x19/0x20
[  454.740400]  start_secondary+0x14e/0x190
[  454.740402]  secondary_startup_64+0xa5/0xb0
[  454.740403] Code: ff 31 c0 c3 48 89 fe 31 c0 48 c7 c7 80 62 bf 81 e8 8a f6 d8 ff 0f ff 31 c0 c3 48 89 fe 31 c0 48 c7 c7 40 62 bf 81 e8 74 f6 d8 ff <0f> ff 31 c0 c3 48 89 fe 31 c0 48 c7 c7 08 62 bf 81 e8 5e f6 d8 
[  454.740421] ---[ end trace c2b6ab81731e93a1 ]---
[  454.740429] BUG: unable to handle kernel NULL pointer dereference at           (null)
[  454.740980] IP: __list_del_entry_valid+0x25/0xa0
[  454.741509] PGD 0 P4D 0 
[  454.742026] Oops: 0000 [#1] SMP PTI
[  454.742525] Dumping ftrace buffer:
[  454.743040]    (ftrace buffer empty)
[  454.743529] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) nls_iso8859_1(E) nls_cp437(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) snd_hda_codec_hdmi(E) coretemp(E) snd_hda_codec_realtek(E) snd_hda_codec_generic(E) kvm_intel(E) kvm(E) snd_hda_intel(E) snd_hda_codec(E) snd_hwdep(E) snd_hda_core(E) snd_pcm(E) irqbypass(E) snd_timer(E) joydev(E) crct10dif_pclmul(E) snd(E) r8169(E) crc32_pclmul(E) mii(E) mei_me(E) soundcore(E)
[  454.745917]  crc32c_intel(E) iTCO_wdt(E) ghash_clmulni_intel(E) iTCO_vendor_support(E) pcbc(E) mei(E) lpc_ich(E) aesni_intel(E) i2c_i801(E) mfd_core(E) aes_x86_64(E) shpchp(E) intel_smartconnect(E) crypto_simd(E) glue_helper(E) cryptd(E) pcspkr(E) fan(E) thermal(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) sunrpc(E) sr_mod(E) cdrom(E) hid_logitech_hidpp(E) hid_logitech_dj(E) uas(E) usb_storage(E) hid_generic(E) usbhid(E) nouveau(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) fb_sys_fops(E) ahci(E) xhci_pci(E) ttm(E) libahci(E) ehci_pci(E) xhci_hcd(E) ehci_hcd(E) libata(E) drm(E) usbcore(E) video(E) button(E) sd_mod(E) vfat(E) fat(E) virtio_blk(E) virtio_mmio(E) virtio_pci(E) virtio_ring(E) virtio(E) ext4(E) crc16(E) mbcache(E) jbd2(E) loop(E) sg(E)
[  454.748901]  dm_multipath(E) dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)
[  454.749679] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G        W   E    4.15.0.ge237f98-master #605
[  454.750472] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
[  454.751273] RIP: 0010:__list_del_entry_valid+0x25/0xa0
[  454.752057] RSP: 0018:ffff88041ecc3cb8 EFLAGS: 00010007
[  454.752842] RAX: 0000000000000000 RBX: ffff8803f5852580 RCX: dead000000000200
[  454.753633] RDX: 0000000000000000 RSI: ffff8803f596d7e0 RDI: ffff8803f5852600
[  454.754427] RBP: ffff8803f596d7e0 R08: 0000000000000004 R09: 0000000000000000
[  454.755220] R10: ffff8803f71583d0 R11: 0000000000001000 R12: ffff8803eb1c8828
[  454.756010] R13: ffff8803f596d800 R14: 0000000000000000 R15: ffff8803f5852600
[  454.756798] FS:  0000000000000000(0000) GS:ffff88041ecc0000(0000) knlGS:0000000000000000
[  454.757591] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  454.758383] CR2: 0000000000000000 CR3: 0000000001e0a006 CR4: 00000000001606e0
[  454.759194] Call Trace:
[  454.760012]  <IRQ>
[  454.760802]  blk_flush_complete_seq+0x16e/0x370
[  454.761636]  mq_flush_data_end_io+0xb0/0x110
[  454.762488]  scsi_end_request+0x95/0x1e0 [scsi_mod]
[  454.763295]  scsi_io_completion+0x10b/0x5d0 [scsi_mod]
[  454.764099]  __blk_mq_complete_request+0xb7/0x180
[  454.764906]  blk_mq_complete_request+0x50/0x90
[  454.765715]  ? scsi_vpd_tpg_id+0x90/0x90 [scsi_mod]
[  454.766528]  ata_scsi_qc_complete+0x1d8/0x470 [libata]
[  454.767357]  ata_qc_complete_multiple+0x87/0xd0 [libata]
[  454.768187]  ahci_handle_port_interrupt+0xd4/0x4e0 [libahci]
[  454.769001]  ahci_handle_port_intr+0x6f/0xb0 [libahci]
[  454.769812]  ahci_single_level_irq_intr+0x3b/0x60 [libahci]
[  454.770625]  __handle_irq_event_percpu+0x40/0x1a0
[  454.771437]  handle_irq_event_percpu+0x20/0x50
[  454.772248]  handle_irq_event+0x36/0x60
[  454.773053]  handle_edge_irq+0x90/0x190
[  454.773857]  handle_irq+0x1c/0x30
[  454.774660]  do_IRQ+0x43/0xd0
[  454.775460]  common_interrupt+0xa2/0xa2
[  454.776283]  </IRQ>
[  454.777075] RIP: 0010:cpuidle_enter_state+0xec/0x250
[  454.777870] RSP: 0018:ffff880187febec0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdd
[  454.778678] RAX: ffff88041ece0040 RBX: ffff88041ece77e8 RCX: 000000000000001f
[  454.779487] RDX: 0000000000000000 RSI: fffffffd9cb7bc38 RDI: 0000000000000000
[  454.780299] RBP: 0000000000000005 R08: 0000000000000006 R09: 000000000000024f
[  454.781110] R10: 0000000000000205 R11: 0000000000000018 R12: 0000000000000003
[  454.781919] R13: 00000069e0a06158 R14: 0000000000000003 R15: 00000069e0a1e8c6
[  454.782729]  do_idle+0x16a/0x1d0
[  454.783533]  cpu_startup_entry+0x19/0x20
[  454.784339]  start_secondary+0x14e/0x190
[  454.785146]  secondary_startup_64+0xa5/0xb0
[  454.785954] Code: 0f ff 31 c0 c3 90 48 8b 07 48 b9 00 01 00 00 00 00 ad de 48 8b 57 08 48 39 c8 74 26 48 b9 00 02 00 00 00 00 ad de 48 39 ca 74 5c <48> 8b 12 48 39 d7 75 3e 48 8b 50 08 48 39 d7 75 1f b8 01 00 00 
[  454.786836] RIP: __list_del_entry_valid+0x25/0xa0 RSP: ffff88041ecc3cb8
[  454.787704] CR2: 0000000000000000

Oleksandr Natalenko Feb. 6, 2018, 7:44 a.m. UTC | #2

Hi, Paolo.

I can confirm that this patch fixes cfdisk hang for me. I've also tried 
to trigger the issue Mike has encountered, but with no luck (maybe, I 
wasn't insistent enough, just was doing dd on usb-storage device in the 
VM).

So, with regard to cfdisk hang on usb-storage:

Tested-by: Oleksandr Natalenko <oleksandr@natalenko.name>


Thank you.

Mike Galbraith Feb. 6, 2018, 7:56 a.m. UTC | #3

On Tue, 2018-02-06 at 08:44 +0100, Oleksandr Natalenko wrote:
> Hi, Paolo.

> 

> I can confirm that this patch fixes cfdisk hang for me. I've also tried 

> to trigger the issue Mike has encountered, but with no luck (maybe, I 

> wasn't insistent enough, just was doing dd on usb-storage device in the 

> VM).

I was doing kbuilds, and it blew up on me twice.  Switching back to cfq
seemed to confirm it was indeed the patch causing trouble, but that's
by no means a certainty.

	-Mike

Oleksandr Natalenko Feb. 6, 2018, 8:37 a.m. UTC | #4

Hi.

06.02.2018 08:56, Mike Galbraith wrote:
> I was doing kbuilds, and it blew up on me twice.  Switching back to cfq

> seemed to confirm it was indeed the patch causing trouble, but that's

> by no means a certainty.

Just to note, I was using v4.15.1, not the latest git HEAD. Are you able 
to reproduce it on the stable kernel? Also, assuming this issue might be 
unrelated to the BFQ itself, did you manage to reproduce the trouble 
with another blk-mq scheduler (not CFQ, but mq-deadline/Kyber)?

Regards,
   Oleksandr

Mike Galbraith Feb. 6, 2018, 8:47 a.m. UTC | #5

On Tue, 2018-02-06 at 09:37 +0100, Oleksandr Natalenko wrote:
> Hi.

> 

> 06.02.2018 08:56, Mike Galbraith wrote:

> > I was doing kbuilds, and it blew up on me twice.  Switching back to cfq

> > seemed to confirm it was indeed the patch causing trouble, but that's

> > by no means a certainty.

> 

> Just to note, I was using v4.15.1, not the latest git HEAD. Are you able 

> to reproduce it on the stable kernel?


I didn't even try to wedge it into 4.15.1, tested it as posted.

>  Also, assuming this issue might be 

> unrelated to the BFQ itself, did you manage to reproduce the trouble 

> with another blk-mq scheduler (not CFQ, but mq-deadline/Kyber)?


I can give another scheduler a go this afternoon.

	-Mike

Paolo Valente Feb. 6, 2018, 9:38 a.m. UTC | #6

> Il giorno 06 feb 2018, alle ore 08:56, Mike Galbraith <efault@gmx.de> ha scritto:

> 

> On Tue, 2018-02-06 at 08:44 +0100, Oleksandr Natalenko wrote:

>> Hi, Paolo.

>> 

>> I can confirm that this patch fixes cfdisk hang for me. I've also tried 

>> to trigger the issue Mike has encountered, but with no luck (maybe, I 

>> wasn't insistent enough, just was doing dd on usb-storage device in the 

>> VM).

> 

> I was doing kbuilds, and it blew up on me twice.  Switching back to cfq

> seemed to confirm it was indeed the patch causing trouble, but that's

> by no means a certainty.

> 

Hi Mike,
as you can imagine, I didn't get any failure in my pre-submission
tests on this patch.  In addition, it is not that easy to link this
patch, which just adds some internal bfq housekeeping in case of a
requeue, with a corruption of external lists for general I/O
management.

In this respect, as Oleksandr comments point out, by switching from
cfq to bfq, you switch between much more than two schedulers.  Anyway,
who knows ...

Maybe this report will ring a bell with some block-layer expert, or,
hopefully, next feedback will help puzzle this out.

Thanks,
Paolo

> 	-Mike

Mike Galbraith Feb. 6, 2018, 11:57 a.m. UTC | #7

On Tue, 2018-02-06 at 10:38 +0100, Paolo Valente wrote:
> 

> Hi Mike,

> as you can imagine, I didn't get any failure in my pre-submission

> tests on this patch.  In addition, it is not that easy to link this

> patch, which just adds some internal bfq housekeeping in case of a

> requeue, with a corruption of external lists for general I/O

> management.

> 

> In this respect, as Oleksandr comments point out, by switching from

> cfq to bfq, you switch between much more than two schedulers.  Anyway,

> who knows ...


Not me.  Box seems to be fairly sure that it is bfq.  Twice again box
went belly up on me in fairly short order with bfq, but seemed fine
with deadline.  I'm currently running deadline again, and box again
seems solid, thought I won't say _is_ solid until it's been happily
trundling along with deadline for a quite a bit longer.

I was ssh'd in during the last episode, got this out.  I should be
getting crash dumps, but seems kdump is only working intermittently
atm.  I did get one earlier, but 3 of 4 times not.  Hohum.

[  484.179292] BUG: unable to handle kernel paging request at ffffffffa0817000
[  484.179436] IP: __trace_note_message+0x1f/0xd0
[  484.179576] PGD 1e0c067 P4D 1e0c067 PUD 1e0d063 PMD 3faff2067 PTE 0
[  484.179719] Oops: 0000 [#1] SMP PTI
[  484.179861] Dumping ftrace buffer:
[  484.180011]    (ftrace buffer empty)
[  484.180138] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) nls_iso8859_1(E) nls_cp437(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) snd_hda_codec_hdmi(E) coretemp(E) kvm_intel(E) snd_hda_codec_realtek(E) kvm(E) snd_hda_codec_generic(E) snd_hda_intel(E) snd_hda_codec(E) sr_mod(E) snd_hwdep(E) cdrom(E) joydev(E) snd_hda_core(E) snd_pcm(E) snd_timer(E) irqbypass(E) snd(E) crct10dif_pclmul(E) crc32_pclmul(E) crc32c_intel(E) r8169(E)
[  484.180740]  iTCO_wdt(E) ghash_clmulni_intel(E) mii(E) iTCO_vendor_support(E) pcbc(E) aesni_intel(E) soundcore(E) aes_x86_64(E) shpchp(E) crypto_simd(E) lpc_ich(E) glue_helper(E) i2c_i801(E) mei_me(E) mfd_core(E) mei(E) cryptd(E) intel_smartconnect(E) pcspkr(E) fan(E) thermal(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) sunrpc(E) hid_logitech_hidpp(E) hid_logitech_dj(E) uas(E) usb_storage(E) hid_generic(E) usbhid(E) nouveau(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) fb_sys_fops(E) ahci(E) xhci_pci(E) ehci_pci(E) libahci(E) ttm(E) ehci_hcd(E) xhci_hcd(E) libata(E) drm(E) usbcore(E) video(E) button(E) sd_mod(E) vfat(E) fat(E) virtio_blk(E) virtio_mmio(E) virtio_pci(E) virtio_ring(E) virtio(E) ext4(E) crc16(E) mbcache(E) jbd2(E) loop(E) sg(E) dm_multipath(E)
[  484.181421]  dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)
[  484.181583] CPU: 3 PID: 500 Comm: kworker/3:1H Tainted: G            E    4.15.0.ge237f98-master #609
[  484.181746] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
[  484.181910] Workqueue: kblockd blk_mq_requeue_work
[  484.182076] RIP: 0010:__trace_note_message+0x1f/0xd0
[  484.182250] RSP: 0018:ffff8803f45bfc20 EFLAGS: 00010282
[  484.182436] RAX: 0000000000000000 RBX: ffffffffa0817000 RCX: 00000000ffff8803
[  484.182622] RDX: ffffffff81bf514d RSI: 0000000000000000 RDI: ffffffffa0817000
[  484.182810] RBP: ffff8803f45bfc80 R08: 0000000000000041 R09: ffff8803f69cc5d0
[  484.182998] R10: ffff8803f80b47d0 R11: 0000000000001000 R12: ffff8803f45e8000
[  484.183185] R13: 000000000000000d R14: 0000000000000000 R15: ffff8803fba112c0
[  484.183372] FS:  0000000000000000(0000) GS:ffff88041ecc0000(0000) knlGS:0000000000000000
[  484.183561] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  484.183747] CR2: ffffffffa0817000 CR3: 0000000001e0a006 CR4: 00000000001606e0
[  484.183934] Call Trace:
[  484.184122]  bfq_put_queue+0xd3/0xe0
[  484.184305]  bfq_finish_requeue_request+0x72/0x350
[  484.184493]  __blk_mq_requeue_request+0x8f/0x120
[  484.184678]  blk_mq_dispatch_rq_list+0x342/0x550
[  484.184866]  ? kyber_dispatch_request+0xd0/0xd0
[  484.185053]  blk_mq_sched_dispatch_requests+0xf7/0x180
[  484.185238]  __blk_mq_run_hw_queue+0x58/0xd0
[  484.185429]  __blk_mq_delay_run_hw_queue+0x99/0xa0
[  484.185614]  blk_mq_run_hw_queue+0x54/0xf0
[  484.185805]  blk_mq_run_hw_queues+0x4b/0x60
[  484.185994]  blk_mq_requeue_work+0x13a/0x150
[  484.186192]  process_one_work+0x147/0x350
[  484.186383]  worker_thread+0x47/0x3e0
[  484.186572]  kthread+0xf8/0x130
[  484.186760]  ? rescuer_thread+0x360/0x360
[  484.186948]  ? kthread_stop+0x120/0x120
[  484.187137]  ret_from_fork+0x35/0x40
[  484.187321] Code: ff 48 89 44 24 10 e9 58 fd ff ff 90 55 48 89 e5 41 55 41 54 53 48 89 fb 48 83 ec 48 48 89 4c 24 30 4c 89 44 24 38 4c 89 4c 24 40 <83> 3f 02 0f 85 87 00 00 00 f6 43 21 04 75 0b 48 83 c4 48 5b 41 
[  484.187525] RIP: __trace_note_message+0x1f/0xd0 RSP: ffff8803f45bfc20
[  484.187727] CR2: ffffffffa0817000

Oleksandr Natalenko Feb. 6, 2018, 12:16 p.m. UTC | #8

Hi.

06.02.2018 12:57, Mike Galbraith wrote:
> Not me.  Box seems to be fairly sure that it is bfq.  Twice again box

> went belly up on me in fairly short order with bfq, but seemed fine

> with deadline.  I'm currently running deadline again, and box again

> seems solid, thought I won't say _is_ solid until it's been happily

> trundling along with deadline for a quite a bit longer.


Sorry for the noise, but just to make it clear, are we talking about 
"deadline" or "mq-deadline" now?

Paolo Valente Feb. 6, 2018, 12:26 p.m. UTC | #9

> Il giorno 06 feb 2018, alle ore 12:57, Mike Galbraith <efault@gmx.de> ha scritto:

> 

> On Tue, 2018-02-06 at 10:38 +0100, Paolo Valente wrote:

>> 

>> Hi Mike,

>> as you can imagine, I didn't get any failure in my pre-submission

>> tests on this patch.  In addition, it is not that easy to link this

>> patch, which just adds some internal bfq housekeeping in case of a

>> requeue, with a corruption of external lists for general I/O

>> management.

>> 

>> In this respect, as Oleksandr comments point out, by switching from

>> cfq to bfq, you switch between much more than two schedulers.  Anyway,

>> who knows ...

> 

> Not me.  Box seems to be fairly sure that it is bfq.


Yeah, sorry for the too short comment: what I meant is that cfq (and
deadline) are in legacy blk, while bfq is in blk-mq.  So, to use bfq,
you must also switch from legacy-blk I/O stack to blk-mq I/O stack.


>  Twice again box

> went belly up on me in fairly short order with bfq, but seemed fine

> with deadline.  I'm currently running deadline again, and box again

> seems solid, thought I won't say _is_ solid until it's been happily

> trundling along with deadline for a quite a bit longer.

> 


As Oleksadr asked too, is it deadline or mq-deadline?

> I was ssh'd in during the last episode, got this out.  I should be

> getting crash dumps, but seems kdump is only working intermittently

> atm.  I did get one earlier, but 3 of 4 times not.  Hohum.

> 

> [  484.179292] BUG: unable to handle kernel paging request at ffffffffa0817000

> [  484.179436] IP: __trace_note_message+0x1f/0xd0

> [  484.179576] PGD 1e0c067 P4D 1e0c067 PUD 1e0d063 PMD 3faff2067 PTE 0

> [  484.179719] Oops: 0000 [#1] SMP PTI

> [  484.179861] Dumping ftrace buffer:

> [  484.180011]    (ftrace buffer empty)

> [  484.180138] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) nls_iso8859_1(E) nls_cp437(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) snd_hda_codec_hdmi(E) coretemp(E) kvm_intel(E) snd_hda_codec_realtek(E) kvm(E) snd_hda_codec_generic(E) snd_hda_intel(E) snd_hda_codec(E) sr_mod(E) snd_hwdep(E) cdrom(E) joydev(E) snd_hda_core(E) snd_pcm(E) snd_timer(E) irqbypass(E) snd(E) crct10dif_pclmul(E) crc32_pclmul(E) crc32c_intel(E) r8169(E)

> [  484.180740]  iTCO_wdt(E) ghash_clmulni_intel(E) mii(E) iTCO_vendor_support(E) pcbc(E) aesni_intel(E) soundcore(E) aes_x86_64(E) shpchp(E) crypto_simd(E) lpc_ich(E) glue_helper(E) i2c_i801(E) mei_me(E) mfd_core(E) mei(E) cryptd(E) intel_smartconnect(E) pcspkr(E) fan(E) thermal(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) sunrpc(E) hid_logitech_hidpp(E) hid_logitech_dj(E) uas(E) usb_storage(E) hid_generic(E) usbhid(E) nouveau(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) fb_sys_fops(E) ahci(E) xhci_pci(E) ehci_pci(E) libahci(E) ttm(E) ehci_hcd(E) xhci_hcd(E) libata(E) drm(E) usbcore(E) video(E) button(E) sd_mod(E) vfat(E) fat(E) virtio_blk(E) virtio_mmio(E) virtio_pci(E) virtio_ring(E) virtio(E) ext4(E) crc16(E) mbcache(E) jbd2(E) loop(E) sg(E) dm_multipath(E)

> [  484.181421]  dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)

> [  484.181583] CPU: 3 PID: 500 Comm: kworker/3:1H Tainted: G            E    4.15.0.ge237f98-master #609

> [  484.181746] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013

> [  484.181910] Workqueue: kblockd blk_mq_requeue_work

> [  484.182076] RIP: 0010:__trace_note_message+0x1f/0xd0

> [  484.182250] RSP: 0018:ffff8803f45bfc20 EFLAGS: 00010282

> [  484.182436] RAX: 0000000000000000 RBX: ffffffffa0817000 RCX: 00000000ffff8803

> [  484.182622] RDX: ffffffff81bf514d RSI: 0000000000000000 RDI: ffffffffa0817000

> [  484.182810] RBP: ffff8803f45bfc80 R08: 0000000000000041 R09: ffff8803f69cc5d0

> [  484.182998] R10: ffff8803f80b47d0 R11: 0000000000001000 R12: ffff8803f45e8000

> [  484.183185] R13: 000000000000000d R14: 0000000000000000 R15: ffff8803fba112c0

> [  484.183372] FS:  0000000000000000(0000) GS:ffff88041ecc0000(0000) knlGS:0000000000000000

> [  484.183561] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> [  484.183747] CR2: ffffffffa0817000 CR3: 0000000001e0a006 CR4: 00000000001606e0

> [  484.183934] Call Trace:

> [  484.184122]  bfq_put_queue+0xd3/0xe0

> [  484.184305]  bfq_finish_requeue_request+0x72/0x350

> [  484.184493]  __blk_mq_requeue_request+0x8f/0x120

> [  484.184678]  blk_mq_dispatch_rq_list+0x342/0x550

> [  484.184866]  ? kyber_dispatch_request+0xd0/0xd0

> [  484.185053]  blk_mq_sched_dispatch_requests+0xf7/0x180

> [  484.185238]  __blk_mq_run_hw_queue+0x58/0xd0

> [  484.185429]  __blk_mq_delay_run_hw_queue+0x99/0xa0

> [  484.185614]  blk_mq_run_hw_queue+0x54/0xf0

> [  484.185805]  blk_mq_run_hw_queues+0x4b/0x60

> [  484.185994]  blk_mq_requeue_work+0x13a/0x150

> [  484.186192]  process_one_work+0x147/0x350

> [  484.186383]  worker_thread+0x47/0x3e0

> [  484.186572]  kthread+0xf8/0x130

> [  484.186760]  ? rescuer_thread+0x360/0x360

> [  484.186948]  ? kthread_stop+0x120/0x120

> [  484.187137]  ret_from_fork+0x35/0x40

> [  484.187321] Code: ff 48 89 44 24 10 e9 58 fd ff ff 90 55 48 89 e5 41 55 41 54 53 48 89 fb 48 83 ec 48 48 89 4c 24 30 4c 89 44 24 38 4c 89 4c 24 40 <83> 3f 02 0f 85 87 00 00 00 f6 43 21 04 75 0b 48 83 c4 48 5b 41 

> [  484.187525] RIP: __trace_note_message+0x1f/0xd0 RSP: ffff8803f45bfc20

> [  484.187727] CR2: ffffffffa0817000


ok, right in the middle of bfq this time ... Was this the first OOPS in your kernel log?

Thanks,
Paolo

Paolo Valente Feb. 6, 2018, 12:40 p.m. UTC | #10

> Il giorno 06 feb 2018, alle ore 13:26, Paolo Valente <paolo.valente@linaro.org> ha scritto:

> 

> 

> 

>> Il giorno 06 feb 2018, alle ore 12:57, Mike Galbraith <efault@gmx.de> ha scritto:

>> 

>> On Tue, 2018-02-06 at 10:38 +0100, Paolo Valente wrote:

>>> 

>>> Hi Mike,

>>> as you can imagine, I didn't get any failure in my pre-submission

>>> tests on this patch.  In addition, it is not that easy to link this

>>> patch, which just adds some internal bfq housekeeping in case of a

>>> requeue, with a corruption of external lists for general I/O

>>> management.

>>> 

>>> In this respect, as Oleksandr comments point out, by switching from

>>> cfq to bfq, you switch between much more than two schedulers.  Anyway,

>>> who knows ...

>> 

>> Not me.  Box seems to be fairly sure that it is bfq.

> 

> Yeah, sorry for the too short comment: what I meant is that cfq (and

> deadline) are in legacy blk, while bfq is in blk-mq.  So, to use bfq,

> you must also switch from legacy-blk I/O stack to blk-mq I/O stack.

> 

> 

>> Twice again box

>> went belly up on me in fairly short order with bfq, but seemed fine

>> with deadline.  I'm currently running deadline again, and box again

>> seems solid, thought I won't say _is_ solid until it's been happily

>> trundling along with deadline for a quite a bit longer.

>> 

> 

> As Oleksadr asked too, is it deadline or mq-deadline?

> 

>> I was ssh'd in during the last episode, got this out.  I should be

>> getting crash dumps, but seems kdump is only working intermittently

>> atm.  I did get one earlier, but 3 of 4 times not.  Hohum.

>> 

>> [  484.179292] BUG: unable to handle kernel paging request at ffffffffa0817000

>> [  484.179436] IP: __trace_note_message+0x1f/0xd0

>> [  484.179576] PGD 1e0c067 P4D 1e0c067 PUD 1e0d063 PMD 3faff2067 PTE 0

>> [  484.179719] Oops: 0000 [#1] SMP PTI

>> [  484.179861] Dumping ftrace buffer:

>> [  484.180011]    (ftrace buffer empty)

>> [  484.180138] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) nls_iso8859_1(E) nls_cp437(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) snd_hda_codec_hdmi(E) coretemp(E) kvm_intel(E) snd_hda_codec_realtek(E) kvm(E) snd_hda_codec_generic(E) snd_hda_intel(E) snd_hda_codec(E) sr_mod(E) snd_hwdep(E) cdrom(E) joydev(E) snd_hda_core(E) snd_pcm(E) snd_timer(E) irqbypass(E) snd(E) crct10dif_pclmul(E) crc32_pclmul(E) crc32c_intel(E) r8169(E)

>> [  484.180740]  iTCO_wdt(E) ghash_clmulni_intel(E) mii(E) iTCO_vendor_support(E) pcbc(E) aesni_intel(E) soundcore(E) aes_x86_64(E) shpchp(E) crypto_simd(E) lpc_ich(E) glue_helper(E) i2c_i801(E) mei_me(E) mfd_core(E) mei(E) cryptd(E) intel_smartconnect(E) pcspkr(E) fan(E) thermal(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) sunrpc(E) hid_logitech_hidpp(E) hid_logitech_dj(E) uas(E) usb_storage(E) hid_generic(E) usbhid(E) nouveau(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) fb_sys_fops(E) ahci(E) xhci_pci(E) ehci_pci(E) libahci(E) ttm(E) ehci_hcd(E) xhci_hcd(E) libata(E) drm(E) usbcore(E) video(E) button(E) sd_mod(E) vfat(E) fat(E) virtio_blk(E) virtio_mmio(E) virtio_pci(E) virtio_ring(E) virtio(E) ext4(E) crc16(E) mbcache(E) jbd2(E) loop(E) sg(E) dm_multipath(E)

>> [  484.181421]  dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)

>> [  484.181583] CPU: 3 PID: 500 Comm: kworker/3:1H Tainted: G            E    4.15.0.ge237f98-master #609

>> [  484.181746] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013

>> [  484.181910] Workqueue: kblockd blk_mq_requeue_work

>> [  484.182076] RIP: 0010:__trace_note_message+0x1f/0xd0

>> [  484.182250] RSP: 0018:ffff8803f45bfc20 EFLAGS: 00010282

>> [  484.182436] RAX: 0000000000000000 RBX: ffffffffa0817000 RCX: 00000000ffff8803

>> [  484.182622] RDX: ffffffff81bf514d RSI: 0000000000000000 RDI: ffffffffa0817000

>> [  484.182810] RBP: ffff8803f45bfc80 R08: 0000000000000041 R09: ffff8803f69cc5d0

>> [  484.182998] R10: ffff8803f80b47d0 R11: 0000000000001000 R12: ffff8803f45e8000

>> [  484.183185] R13: 000000000000000d R14: 0000000000000000 R15: ffff8803fba112c0

>> [  484.183372] FS:  0000000000000000(0000) GS:ffff88041ecc0000(0000) knlGS:0000000000000000

>> [  484.183561] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

>> [  484.183747] CR2: ffffffffa0817000 CR3: 0000000001e0a006 CR4: 00000000001606e0

>> [  484.183934] Call Trace:

>> [  484.184122]  bfq_put_queue+0xd3/0xe0

>> [  484.184305]  bfq_finish_requeue_request+0x72/0x350

>> [  484.184493]  __blk_mq_requeue_request+0x8f/0x120

>> [  484.184678]  blk_mq_dispatch_rq_list+0x342/0x550

>> [  484.184866]  ? kyber_dispatch_request+0xd0/0xd0

>> [  484.185053]  blk_mq_sched_dispatch_requests+0xf7/0x180

>> [  484.185238]  __blk_mq_run_hw_queue+0x58/0xd0

>> [  484.185429]  __blk_mq_delay_run_hw_queue+0x99/0xa0

>> [  484.185614]  blk_mq_run_hw_queue+0x54/0xf0

>> [  484.185805]  blk_mq_run_hw_queues+0x4b/0x60

>> [  484.185994]  blk_mq_requeue_work+0x13a/0x150

>> [  484.186192]  process_one_work+0x147/0x350

>> [  484.186383]  worker_thread+0x47/0x3e0

>> [  484.186572]  kthread+0xf8/0x130

>> [  484.186760]  ? rescuer_thread+0x360/0x360

>> [  484.186948]  ? kthread_stop+0x120/0x120

>> [  484.187137]  ret_from_fork+0x35/0x40

>> [  484.187321] Code: ff 48 89 44 24 10 e9 58 fd ff ff 90 55 48 89 e5 41 55 41 54 53 48 89 fb 48 83 ec 48 48 89 4c 24 30 4c 89 44 24 38 4c 89 4c 24 40 <83> 3f 02 0f 85 87 00 00 00 f6 43 21 04 75 0b 48 83 c4 48 5b 41 

>> [  484.187525] RIP: __trace_note_message+0x1f/0xd0 RSP: ffff8803f45bfc20

>> [  484.187727] CR2: ffffffffa0817000

> 

> ok, right in the middle of bfq this time ... Was this the first OOPS in your kernel log?

> 


I've just tried a
list *(__trace_note_message+0x1f)
with gdb, hoping that your image is close enough to mine.  But the
output doesn't say much.

Thanks,
Paolo

> Thanks,

> Paolo

> 

> -- 

> You received this message because you are subscribed to the Google Groups "bfq-iosched" group.

> To unsubscribe from this group and stop receiving emails from it, send an email to bfq-iosched+unsubscribe@googlegroups.com.

> For more options, visit https://groups.google.com/d/optout.

Holger Hoffstätte Feb. 6, 2018, 12:43 p.m. UTC | #11

On 02/06/18 13:26, Paolo Valente wrote:
(..)
> As Oleksadr asked too, is it deadline or mq-deadline?


You can use deadline as alias as long as blk-mq is active.
This doesn't work when mq-deadline is built as a module, but that
doesn't seem to be the problem here.
 
>> [  484.179292] BUG: unable to handle kernel paging request at ffffffffa0817000

>> [  484.179436] IP: __trace_note_message+0x1f/0xd0

>> [  484.179576] PGD 1e0c067 P4D 1e0c067 PUD 1e0d063 PMD 3faff2067 PTE 0

>> [  484.179719] Oops: 0000 [#1] SMP PTI

>> [  484.179861] Dumping ftrace buffer:

>> [  484.180011]    (ftrace buffer empty)

>> [  484.180138] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_mangle(E) nf_conntrack_netbios_ns(E) nf_conntrack_broadcast(E) nf_conntrack_ipv4(E) nf_defrag_ipv4(E) ip_tables(E) xt_conntrack(E) nf_conntrack(E) ip6table_filter(E) ip6_tables(E) x_tables(E) nls_iso8859_1(E) nls_cp437(E) intel_rapl(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) snd_hda_codec_hdmi(E) coretemp(E) kvm_intel(E) snd_hda_codec_realtek(E) kvm(E) snd_hda_codec_generic(E) snd_hda_intel(E) snd_hda_codec(E) sr_mod(E) snd_hwdep(E) cdrom(E) joydev(E) snd_hda_core(E) snd_pcm(E) snd_timer(E) irqbypass(E) snd(E) crct10dif_pclmul(E) crc32_pclmul(E) crc32c_intel(E) r8169(E)

>> [  484.180740]  iTCO_wdt(E) ghash_clmulni_intel(E) mii(E) iTCO_vendor_support(E) pcbc(E) aesni_intel(E) soundcore(E) aes_x86_64(E) shpchp(E) crypto_simd(E) lpc_ich(E) glue_helper(E) i2c_i801(E) mei_me(E) mfd_core(E) mei(E) cryptd(E) intel_smartconnect(E) pcspkr(E) fan(E) thermal(E) nfsd(E) auth_rpcgss(E) nfs_acl(E) lockd(E) grace(E) sunrpc(E) hid_logitech_hidpp(E) hid_logitech_dj(E) uas(E) usb_storage(E) hid_generic(E) usbhid(E) nouveau(E) wmi(E) i2c_algo_bit(E) drm_kms_helper(E) syscopyarea(E) sysfillrect(E) sysimgblt(E) fb_sys_fops(E) ahci(E) xhci_pci(E) ehci_pci(E) libahci(E) ttm(E) ehci_hcd(E) xhci_hcd(E) libata(E) drm(E) usbcore(E) video(E) button(E) sd_mod(E) vfat(E) fat(E) virtio_blk(E) virtio_mmio(E) virtio_pci(E) virtio_ring(E) virtio(E) ext4(E) crc16(E) mbcache(E) jbd2(E) loop(E) sg(E) dm_multipath(E)

>> [  484.181421]  dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)

>> [  484.181583] CPU: 3 PID: 500 Comm: kworker/3:1H Tainted: G            E    4.15.0.ge237f98-master #609

>> [  484.181746] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013

>> [  484.181910] Workqueue: kblockd blk_mq_requeue_work

>> [  484.182076] RIP: 0010:__trace_note_message+0x1f/0xd0

>> [  484.182250] RSP: 0018:ffff8803f45bfc20 EFLAGS: 00010282

>> [  484.182436] RAX: 0000000000000000 RBX: ffffffffa0817000 RCX: 00000000ffff8803

>> [  484.182622] RDX: ffffffff81bf514d RSI: 0000000000000000 RDI: ffffffffa0817000

>> [  484.182810] RBP: ffff8803f45bfc80 R08: 0000000000000041 R09: ffff8803f69cc5d0

>> [  484.182998] R10: ffff8803f80b47d0 R11: 0000000000001000 R12: ffff8803f45e8000

>> [  484.183185] R13: 000000000000000d R14: 0000000000000000 R15: ffff8803fba112c0

>> [  484.183372] FS:  0000000000000000(0000) GS:ffff88041ecc0000(0000) knlGS:0000000000000000

>> [  484.183561] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

>> [  484.183747] CR2: ffffffffa0817000 CR3: 0000000001e0a006 CR4: 00000000001606e0

>> [  484.183934] Call Trace:

>> [  484.184122]  bfq_put_queue+0xd3/0xe0

>> [  484.184305]  bfq_finish_requeue_request+0x72/0x350

>> [  484.184493]  __blk_mq_requeue_request+0x8f/0x120

>> [  484.184678]  blk_mq_dispatch_rq_list+0x342/0x550

>> [  484.184866]  ? kyber_dispatch_request+0xd0/0xd0

>> [  484.185053]  blk_mq_sched_dispatch_requests+0xf7/0x180

>> [  484.185238]  __blk_mq_run_hw_queue+0x58/0xd0

>> [  484.185429]  __blk_mq_delay_run_hw_queue+0x99/0xa0

>> [  484.185614]  blk_mq_run_hw_queue+0x54/0xf0

>> [  484.185805]  blk_mq_run_hw_queues+0x4b/0x60

>> [  484.185994]  blk_mq_requeue_work+0x13a/0x150

>> [  484.186192]  process_one_work+0x147/0x350

>> [  484.186383]  worker_thread+0x47/0x3e0

>> [  484.186572]  kthread+0xf8/0x130

>> [  484.186760]  ? rescuer_thread+0x360/0x360

>> [  484.186948]  ? kthread_stop+0x120/0x120

>> [  484.187137]  ret_from_fork+0x35/0x40

>> [  484.187321] Code: ff 48 89 44 24 10 e9 58 fd ff ff 90 55 48 89 e5 41 55 41 54 53 48 89 fb 48 83 ec 48 48 89 4c 24 30 4c 89 44 24 38 4c 89 4c 24 40 <83> 3f 02 0f 85 87 00 00 00 f6 43 21 04 75 0b 48 83 c4 48 5b 41 

>> [  484.187525] RIP: __trace_note_message+0x1f/0xd0 RSP: ffff8803f45bfc20

>> [  484.187727] CR2: ffffffffa0817000

> 

> ok, right in the middle of bfq this time ... Was this the first OOPS in your kernel log?


A much more interesting question to me is why there is kyber in the middle. :)

Holger

Holger Hoffstätte Feb. 6, 2018, 1:40 p.m. UTC | #12

The plot thickens!

Just as I was about to post that I didn't have any problems - because
I didn't have any - I decided to do a second test, activated bfq on my
workstation, on a hunch typed "sync" and .. the machine locked up, hard.

Rebooted, activated bfq, typed sync..sync hangs. Luckily this time
a second terminal was still alive, so I could capture a trace for
your enjoyment:

Feb  6 14:28:17 ragnarok kernel: io scheduler bfq registered
Feb  6 14:28:20 ragnarok kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000030
Feb  6 14:28:20 ragnarok kernel: IP: bfq_put_queue+0x10b/0x130 [bfq]
Feb  6 14:28:20 ragnarok kernel: PGD 0 P4D 0 
Feb  6 14:28:20 ragnarok kernel: Oops: 0000 [#1] SMP PTI
Feb  6 14:28:20 ragnarok kernel: Modules linked in: bfq lz4 lz4_compress lz4_decompress nfs lockd grace sunrpc autofs4 sch_fq_codel it87 hwmon_vid x86_pkg_temp_thermal snd_hda_codec_realtek coretemp radeon crc32_pclmul snd_hda_codec_generic crc32c_intel pcbc snd_hda_codec_hdmi i2c_algo_bit aesni_intel drm_kms_helper aes_x86_64 uvcvideo syscopyarea crypto_simd snd_hda_intel sysfillrect cryptd snd_usb_audio sysimgblt videobuf2_vmalloc glue_helper fb_sys_fops snd_hda_codec snd_hwdep videobuf2_memops ttm videobuf2_v4l2 snd_usbmidi_lib videobuf2_core snd_rawmidi snd_hda_core drm snd_seq_device videodev snd_pcm i2c_i801 usbhid snd_timer i2c_core snd backlight soundcore r8169 parport_pc mii parport
Feb  6 14:28:20 ragnarok kernel: CPU: 0 PID: 4 Comm: kworker/0:0H Not tainted 4.14.18 #1
Feb  6 14:28:20 ragnarok kernel: Hardware name: Gigabyte Technology Co., Ltd. P67-DS3-B3/P67-DS3-B3, BIOS F1 05/06/2011
Feb  6 14:28:20 ragnarok kernel: Workqueue: kblockd blk_mq_requeue_work
Feb  6 14:28:20 ragnarok kernel: task: ffff88060395a1c0 task.stack: ffffc90000044000
Feb  6 14:28:20 ragnarok kernel: RIP: 0010:bfq_put_queue+0x10b/0x130 [bfq]
Feb  6 14:28:20 ragnarok kernel: RSP: 0018:ffffc90000047ca0 EFLAGS: 00010286
Feb  6 14:28:20 ragnarok kernel: RAX: 0000000000000008 RBX: ffff8806023db690 RCX: 0000000000000000
Feb  6 14:28:20 ragnarok kernel: RDX: 0000000000000000 RSI: ffff880601bb39b0 RDI: ffff880601a56400
Feb  6 14:28:20 ragnarok kernel: RBP: 0000000001bb3980 R08: 0000000000000053 R09: ffff8806023db690
Feb  6 14:28:20 ragnarok kernel: R10: 000000001dd0f11e R11: 00000000080a011b R12: ffff880601a56400
Feb  6 14:28:20 ragnarok kernel: R13: ffff8806023dbed0 R14: 0000000000000053 R15: 0000000000000000
Feb  6 14:28:20 ragnarok kernel: FS:  0000000000000000(0000) GS:ffff88061f400000(0000) knlGS:0000000000000000
Feb  6 14:28:20 ragnarok kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Feb  6 14:28:20 ragnarok kernel: CR2: 0000000000000030 CR3: 000000000200a002 CR4: 00000000000606f0
Feb  6 14:28:20 ragnarok kernel: Call Trace:
Feb  6 14:28:20 ragnarok kernel:  bfq_finish_requeue_request+0x4b/0x370 [bfq]
Feb  6 14:28:20 ragnarok kernel:  __blk_mq_requeue_request+0x57/0x130
Feb  6 14:28:20 ragnarok kernel:  blk_mq_dispatch_rq_list+0x1b3/0x510
Feb  6 14:28:20 ragnarok kernel:  ? __bfq_bfqd_reset_in_service+0x20/0x70 [bfq]
Feb  6 14:28:20 ragnarok kernel:  ? bfq_bfqq_expire+0x212/0x740 [bfq]
Feb  6 14:28:20 ragnarok kernel:  blk_mq_sched_dispatch_requests+0xf0/0x170
Feb  6 14:28:20 ragnarok kernel:  __blk_mq_run_hw_queue+0x4e/0x90
Feb  6 14:28:20 ragnarok kernel:  __blk_mq_delay_run_hw_queue+0x73/0x80
Feb  6 14:28:20 ragnarok kernel:  blk_mq_run_hw_queue+0x53/0x150
Feb  6 14:28:20 ragnarok kernel:  blk_mq_run_hw_queues+0x3a/0x50
Feb  6 14:28:20 ragnarok kernel:  blk_mq_requeue_work+0x104/0x110
Feb  6 14:28:20 ragnarok kernel:  process_one_work+0x1d4/0x3d0
Feb  6 14:28:20 ragnarok kernel:  worker_thread+0x2b/0x3c0
Feb  6 14:28:20 ragnarok kernel:  ? process_one_work+0x3d0/0x3d0
Feb  6 14:28:20 ragnarok kernel:  kthread+0x117/0x130
Feb  6 14:28:20 ragnarok kernel:  ? kthread_create_on_node+0x40/0x40
Feb  6 14:28:20 ragnarok kernel:  ret_from_fork+0x1f/0x30
Feb  6 14:28:20 ragnarok kernel: Code: c1 e8 06 83 e0 01 48 83 f8 01 45 19 f6 e8 ce 3a 00 00 41 83 e6 ee 48 89 c7 41 83 c6 53 e8 9e 3a 00 00 49 89 d9 45 89 f0 44 89 f9 <48> 8b 70 28 48 c7 c2 d8 00 25 a0 55 4c 89 ef e8 11 ba ea e0 8b 
Feb  6 14:28:20 ragnarok kernel: RIP: bfq_put_queue+0x10b/0x130 [bfq] RSP: ffffc90000047ca0
Feb  6 14:28:20 ragnarok kernel: CR2: 0000000000000030
Feb  6 14:28:20 ragnarok kernel: ---[ end trace 8b782ace30a4e7d8 ]---

Yes, this is 4.14.x but with most-of block/4.16, rock-solid otherwise (in daily use).
Looks like there is something wrong with this patch after all..

cheers
Holger

Mike Galbraith Feb. 6, 2018, 1:46 p.m. UTC | #13

On Tue, 2018-02-06 at 13:16 +0100, Oleksandr Natalenko wrote:
> Hi.

> 

> 06.02.2018 12:57, Mike Galbraith wrote:

> > Not me.  Box seems to be fairly sure that it is bfq.  Twice again box

> > went belly up on me in fairly short order with bfq, but seemed fine

> > with deadline.  I'm currently running deadline again, and box again

> > seems solid, thought I won't say _is_ solid until it's been happily

> > trundling along with deadline for a quite a bit longer.

> 

> Sorry for the noise, but just to make it clear, are we talking about 

> "deadline" or "mq-deadline" now?


mq-deadline.

Mike Galbraith Feb. 6, 2018, 1:47 p.m. UTC | #14

On Tue, 2018-02-06 at 13:26 +0100, Paolo Valente wrote:
> 

> ok, right in the middle of bfq this time ... Was this the first OOPS in your kernel log?


Yeah.

Oleksandr Natalenko Feb. 6, 2018, 2:07 p.m. UTC | #15

Hi.

06.02.2018 14:46, Mike Galbraith wrote:
>> Sorry for the noise, but just to make it clear, are we talking about

>> "deadline" or "mq-deadline" now?

> 

> mq-deadline.


Okay, I've spent a little bit more time on stressing the VM with BFQ + 
this patch enabled, and managed to get it crashed relatively easy just 
by traversing through all the files in the /usr and reading them. 3 
stacktraces from different boots are below:

===
[   33.147909] BUG: unable to handle kernel NULL pointer dereference at  
          (null)
[   33.156874] IP: blk_flush_complete_seq+0x20a/0x300
[   33.160400] PGD 0 P4D 0
[   33.162682] Oops: 0002 [#1] PREEMPT SMP PTI
[   33.166091] Modules linked in: crct10dif_pclmul crc32_pclmul 
ghash_clmulni_intel pcbc nls_iso8859_1 nls_cp437 aesni_intel vfat 
aes_x86_64 crypto_simd fat glue_helper cryptd bochs_drm ttm iTCO_wdt 
drm_kms_helper iTCO_vendor_support ppdev psmouse drm input_leds 
led_class syscopyarea intel_agp parport_pc joydev parport evdev rtc_cmos 
mousedev intel_gtt mac_hid i2c_i801 sysfillrect lpc_ich sysimgblt 
agpgart fb_sys_fops qemu_fw_cfg sch_fq_codel ip_tables x_tables 
hid_generic usbhid hid xfs libcrc32c crc32c_generic dm_mod raid10 md_mod 
sr_mod cdrom sd_mod uhci_hcd ahci libahci xhci_pci serio_raw atkbd 
libata ehci_pci virtio_net libps2 xhci_hcd ehci_hcd crc32c_intel 
scsi_mod virtio_pci usbcore virtio_ring usb_common virtio i8042 serio
[   33.226238] CPU: 0 PID: 0 Comm: BFS/0 Not tainted 4.15.0-pf2 #1
[   33.232823] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 
0.0.0 02/06/2015
[   33.245062] RIP: 0010:blk_flush_complete_seq+0x20a/0x300
[   33.247781] RSP: 0018:ffff88001f803ed0 EFLAGS: 00010086
[   33.250184] RAX: ffff8800199b5e00 RBX: ffff8800199b5de0 RCX: 
ffff8800197f72a8
[   33.253220] RDX: 0000000000000000 RSI: ffff8800199b5e10 RDI: 
ffff8800197f7200
[   33.257429] RBP: ffff8800194090a0 R08: ffff8800199b5df0 R09: 
0000000000000000
[   33.260756] R10: ffff88001df2b600 R11: ffff88001f803ce8 R12: 
0000000000000000
[   33.268840] R13: ffff8800199b5e30 R14: 0000000000000046 R15: 
ffff8800199b5de0
[   33.272722] FS:  0000000000000000(0000) GS:ffff88001f800000(0000) 
knlGS:0000000000000000
[   33.276798] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   33.278981] CR2: 0000000000000000 CR3: 0000000004008003 CR4: 
00000000003606f0
[   33.282078] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
0000000000000000
[   33.285566] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
0000000000000400
[   33.289322] Call Trace:
[   33.291094]  <IRQ>
[   33.294208]  mq_flush_data_end_io+0xb3/0xf0
[   33.301226]  scsi_end_request+0x90/0x1e0 [scsi_mod]
[   33.303660]  scsi_io_completion+0x237/0x650 [scsi_mod]
[   33.306833]  flush_smp_call_function_queue+0x7c/0xf0
[   33.311369]  smp_call_function_single_interrupt+0x32/0xf0
[   33.314245]  call_function_single_interrupt+0xa2/0xb0
[   33.316755]  </IRQ>
[   33.318365] RIP: 0010:native_safe_halt+0x2/0x10
[   33.321988] RSP: 0018:ffffffff82003ea0 EFLAGS: 00000202 ORIG_RAX: 
ffffffffffffff04
[   33.324995] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 
0000000000000000
[   33.334532] RDX: 0000000000000000 RSI: ffffffff81e43850 RDI: 
ffffffff81e43a9d
[   33.336643] RBP: ffffffff82128080 R08: 0000000e7441b6ce R09: 
ffff88001a4c2c00
[   33.339282] R10: 0000000000000000 R11: ffff88001bceb7f0 R12: 
ffffffff81ea5c92
[   33.344597] R13: 0000000000000000 R14: 0000000000000000 R15: 
000000001e07cd69
[   33.346526]  default_idle+0x18/0x130
[   33.347929]  do_idle+0x167/0x1d0
[   33.349201]  cpu_startup_entry+0x6f/0x80
[   33.350553]  start_kernel+0x4c2/0x4e2
[   33.351822]  secondary_startup_64+0xa5/0xb0
[   33.354470] Code: 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 00 00 49 c1 
e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 00 00 48 89 
56 08 <48> 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00 00 48 89 97
[   33.364997] RIP: blk_flush_complete_seq+0x20a/0x300 RSP: 
ffff88001f803ed0
[   33.366759] CR2: 0000000000000000
[   33.367921] ---[ end trace 5179c1a9cbc4eaa2 ]---
[   33.369413] Kernel panic - not syncing: Fatal exception in interrupt
[   33.372089] Kernel Offset: disabled
[   33.374413] ---[ end Kernel panic - not syncing: Fatal exception in 
interrupt
===

===
[   30.937747] BUG: unable to handle kernel NULL pointer dereference at 
0000000000000028
[   30.940984] IP: bfq_put_queue+0x10b/0x130
[   30.941609] PGD 0 P4D 0
[   30.941976] Oops: 0000 [#1] PREEMPT SMP PTI
[   30.942560] Modules linked in: crct10dif_pclmul crc32_pclmul 
ghash_clmulni_intel nls_iso8859_1 bochs_drm pcbc nls_cp437 vfat ttm 
aesni_intel fat aes_x86_64 crypto_simd glue_helper cryptd drm_kms_helper 
iTCO_wdt drm ppdev iTCO_vendor_support input_leds psmouse led_class 
intel_agp parport_pc joydev mousedev intel_gtt syscopyarea parport 
rtc_cmos evdev sysfillrect sysimgblt agpgart fb_sys_fops i2c_i801 
mac_hid qemu_fw_cfg lpc_ich sch_fq_codel ip_tables x_tables xfs 
libcrc32c crc32c_generic dm_mod raid10 md_mod hid_generic usbhid hid 
sr_mod cdrom sd_mod uhci_hcd ahci libahci serio_raw virtio_net xhci_pci 
ehci_pci atkbd libata libps2 xhci_hcd virtio_pci ehci_hcd virtio_ring 
crc32c_intel scsi_mod usbcore i8042 usb_common virtio serio
[   30.955195] CPU: 2 PID: 181 Comm: kworker/2:1H Not tainted 4.15.0-pf2 
#1
[   30.956649] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 
0.0.0 02/06/2015
[   30.958404] Workqueue: kblockd blk_mq_requeue_work
[   30.959128] RIP: 0010:bfq_put_queue+0x10b/0x130
[   30.960330] RSP: 0018:ffffc90000617c98 EFLAGS: 00010282
[   30.961574] RAX: 0000000000000000 RBX: ffff88001d537210 RCX: 
00000000ffffffff
[   30.962990] RDX: 0000000000000000 RSI: ffff880018a300d8 RDI: 
ffff88001d537240
[   30.964114] RBP: 0000000018a300a8 R08: 0000000000000041 R09: 
ffff88001d537210
[   30.965449] R10: 0000000000432a7f R11: 000000000002000b R12: 
ffff88001d537240
[   30.966798] R13: ffff88001941d6d9 R14: 0000000000000041 R15: 
00000000ffffffff
[   30.969154] FS:  0000000000000000(0000) GS:ffff88001f900000(0000) 
knlGS:0000000000000000
[   30.972781] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   30.974310] CR2: 0000000000000028 CR3: 0000000004008004 CR4: 
00000000003606e0
[   30.975544] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
0000000000000000
[   30.976963] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
0000000000000400
[   30.980515] Call Trace:
[   30.981893]  bfq_finish_requeue_request+0x54/0x380
[   30.983499]  __blk_mq_requeue_request+0x5c/0x140
[   30.988010]  blk_mq_dispatch_rq_list+0x1b4/0x4c0
[   30.989621]  ? __switch_to_asm+0x34/0x70
[   30.991699]  ? __switch_to_asm+0x40/0x70
[   30.994801]  ? stub_ptregs_64+0x11/0x30
[   30.996506]  blk_mq_sched_dispatch_requests+0x105/0x190
[   30.998842]  __blk_mq_run_hw_queue+0x80/0x90
[   31.002840]  __blk_mq_delay_run_hw_queue+0x92/0xe0
[   31.004873]  blk_mq_run_hw_queue+0x25/0x90
[   31.006766]  blk_mq_run_hw_queues+0x3a/0x50
[   31.008725]  blk_mq_requeue_work+0x116/0x140
[   31.011034]  process_one_work+0x1df/0x420
[   31.012841]  worker_thread+0x2b/0x3d0
[   31.014371]  ? process_one_work+0x420/0x420
[   31.016165]  kthread+0x113/0x130
[   31.018432]  ? kthread_create_on_node+0x70/0x70
[   31.020638]  ? do_group_exit+0x33/0xa0
[   31.022188]  ret_from_fork+0x35/0x40
[   31.024845] Code: c1 e8 06 83 e0 01 48 83 f8 01 45 19 f6 e8 be 3b 00 
00 41 83 e6 ee 48 89 c7 41 83 c6 53 e8 8e 3b 00 00 49 89 d9 45 89 f0 44 
89 f9 <48> 8b 70 28 48 c7 c2 12 be e5 81 55 4c 89 ef e8 11 0f e0 ff 8b
[   31.037915] RIP: bfq_put_queue+0x10b/0x130 RSP: ffffc90000617c98
[   31.040346] CR2: 0000000000000028
[   31.042889] ---[ end trace 11f85b2ea2b00253 ]---
[   31.046478] note: kworker/2:1H[181] exited with preempt_count 1
===

===
[   48.629969] BUG: unable to handle kernel NULL pointer dereference at  
          (null)
[   48.632678] IP: blk_flush_complete_seq+0x20a/0x300
[   48.637504] PGD 0 P4D 0
[   48.639647] Oops: 0002 [#1] PREEMPT SMP PTI
[   48.641496] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat 
crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel 
aes_x86_64 crypto_simd glue_helper bochs_drm cryptd ttm ppdev 
drm_kms_helper iTCO_wdt iTCO_vendor_support input_leds led_class 
intel_agp psmouse joydev drm intel_gtt parport_pc mousedev syscopyarea 
sysfillrect sysimgblt evdev fb_sys_fops parport lpc_ich agpgart mac_hid 
i2c_i801 qemu_fw_cfg rtc_cmos sch_fq_codel ip_tables x_tables xfs 
libcrc32c crc32c_generic dm_mod raid10 hid_generic md_mod usbhid hid 
sr_mod cdrom sd_mod uhci_hcd ahci xhci_pci libahci serio_raw ehci_pci 
atkbd xhci_hcd ehci_hcd virtio_net libps2 libata crc32c_intel scsi_mod 
virtio_pci usbcore virtio_ring usb_common virtio i8042 serio
[   48.663536] CPU: 3 PID: 175 Comm: kworker/3:1H Not tainted 4.15.0-pf2 
#1
[   48.668487] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 
0.0.0 02/06/2015
[   48.672290] Workqueue: kblockd blk_mq_run_work_fn
[   48.674271] RIP: 0010:blk_flush_complete_seq+0x20a/0x300
[   48.676939] RSP: 0000:ffff88001f983ed0 EFLAGS: 00010086
[   48.679617] RAX: ffff88001d721b60 RBX: ffff88001d721b40 RCX: 
ffff8800192f26a8
[   48.681937] RDX: 0000000000000000 RSI: ffff88001d721b70 RDI: 
ffff8800192f2600
[   48.684117] RBP: ffff88001da3a140 R08: ffff88001d721b50 R09: 
0000000000000000
[   48.688197] R10: ffff8800176fdb00 R11: 0000000000000040 R12: 
0000000000000000
[   48.690628] R13: ffff88001d721b90 R14: 0000000000000046 R15: 
ffff88001d721b40
[   48.693943] FS:  0000000000000000(0000) GS:ffff88001f980000(0000) 
knlGS:0000000000000000
[   48.698935] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   48.701592] CR2: 0000000000000000 CR3: 0000000004008002 CR4: 
00000000003606e0
[   48.703861] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 
0000000000000000
[   48.705994] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 
0000000000000400
[   48.708165] Call Trace:
[   48.709827]  <IRQ>
[   48.712631]  mq_flush_data_end_io+0xb3/0xf0
[   48.714419]  scsi_end_request+0x90/0x1e0 [scsi_mod]
[   48.717553]  scsi_io_completion+0x237/0x650 [scsi_mod]
[   48.721822]  flush_smp_call_function_queue+0x7c/0xf0
[   48.726672]  smp_call_function_single_interrupt+0x32/0xf0
[   48.733743]  call_function_single_interrupt+0xa2/0xb0
[   48.737194]  </IRQ>
[   48.738656] RIP: 0010:_raw_spin_unlock_irqrestore+0x11/0x40
[   48.741128] RSP: 0000:ffffc900005e3d30 EFLAGS: 00000293 ORIG_RAX: 
ffffffffffffff04
[   48.745138] RAX: 0000000000000001 RBX: ffff88001d640000 RCX: 
0000000000000012
[   48.747764] RDX: 0000000000040000 RSI: 0000000000000293 RDI: 
0000000000000293
[   48.752698] RBP: 0000000000000293 R08: ffffffffffffffff R09: 
0000000000000090
[   48.755910] R10: 0000000000432a3f R11: 000000000002000b R12: 
0000000000000000
[   48.760517] R13: ffff8800199ef800 R14: ffff880018d29948 R15: 
ffff8800199ef800
[   48.771214]  ata_scsi_queuecmd+0xa0/0x210 [libata]
[   48.774631]  scsi_dispatch_cmd+0xe8/0x260 [scsi_mod]
[   48.777489]  scsi_queue_rq+0x4cf/0x560 [scsi_mod]
[   48.782246]  blk_mq_dispatch_rq_list+0x8f/0x4c0
[   48.787614]  blk_mq_sched_dispatch_requests+0x105/0x190
[   48.790303]  __blk_mq_run_hw_queue+0x80/0x90
[   48.795313]  process_one_work+0x1df/0x420
[   48.798006]  worker_thread+0x2b/0x3d0
[   48.801376]  ? process_one_work+0x420/0x420
[   48.804226]  kthread+0x113/0x130
[   48.806674]  ? kthread_create_on_node+0x70/0x70
[   48.809640]  ret_from_fork+0x35/0x40
[   48.812834] Code: 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 00 00 49 c1 
e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 00 00 48 89 
56 08 <48> 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00 00 48 89 97
[   48.822452] RIP: blk_flush_complete_seq+0x20a/0x300 RSP: 
ffff88001f983ed0
[   48.824908] CR2: 0000000000000000
[   48.830677] ---[ end trace 4e5ef1b3dcbb32c5 ]---
[   48.833655] Kernel panic - not syncing: Fatal exception in interrupt
[   48.836166] Kernel Offset: disabled
[   48.837150] ---[ end Kernel panic - not syncing: Fatal exception in 
interrupt
===

Revoking my Tested-by tag (:.

Mike Galbraith Feb. 6, 2018, 2:07 p.m. UTC | #16

On Tue, 2018-02-06 at 13:43 +0100, Holger Hoffstätte wrote:
> 

> A much more interesting question to me is why there is kyber in the middle. :)


Yeah, given per sysfs I have zero devices using kyber.

	-Mike

Paolo Valente Feb. 6, 2018, 2:50 p.m. UTC | #17

> Il giorno 06 feb 2018, alle ore 15:07, Oleksandr Natalenko <oleksandr@natalenko.name> ha scritto:

> 

> Hi.

> 

> 06.02.2018 14:46, Mike Galbraith wrote:

>>> Sorry for the noise, but just to make it clear, are we talking about

>>> "deadline" or "mq-deadline" now?

>> mq-deadline.

> 

> Okay, I've spent a little bit more time on stressing the VM with BFQ + this patch enabled, and managed to get it crashed relatively easy just by traversing through all the files in the /usr and reading them. 3 stacktraces from different boots are below:

> 

> ===

> [   33.147909] BUG: unable to handle kernel NULL pointer dereference at           (null)

> [   33.156874] IP: blk_flush_complete_seq+0x20a/0x300

> [   33.160400] PGD 0 P4D 0

> [   33.162682] Oops: 0002 [#1] PREEMPT SMP PTI

> [   33.166091] Modules linked in: crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc nls_iso8859_1 nls_cp437 aesni_intel vfat aes_x86_64 crypto_simd fat glue_helper cryptd bochs_drm ttm iTCO_wdt drm_kms_helper iTCO_vendor_support ppdev psmouse drm input_leds led_class syscopyarea intel_agp parport_pc joydev parport evdev rtc_cmos mousedev intel_gtt mac_hid i2c_i801 sysfillrect lpc_ich sysimgblt agpgart fb_sys_fops qemu_fw_cfg sch_fq_codel ip_tables x_tables hid_generic usbhid hid xfs libcrc32c crc32c_generic dm_mod raid10 md_mod sr_mod cdrom sd_mod uhci_hcd ahci libahci xhci_pci serio_raw atkbd libata ehci_pci virtio_net libps2 xhci_hcd ehci_hcd crc32c_intel scsi_mod virtio_pci usbcore virtio_ring usb_common virtio i8042 serio

> [   33.226238] CPU: 0 PID: 0 Comm: BFS/0 Not tainted 4.15.0-pf2 #1

> [   33.232823] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015

> [   33.245062] RIP: 0010:blk_flush_complete_seq+0x20a/0x300

> [   33.247781] RSP: 0018:ffff88001f803ed0 EFLAGS: 00010086

> [   33.250184] RAX: ffff8800199b5e00 RBX: ffff8800199b5de0 RCX: ffff8800197f72a8

> [   33.253220] RDX: 0000000000000000 RSI: ffff8800199b5e10 RDI: ffff8800197f7200

> [   33.257429] RBP: ffff8800194090a0 R08: ffff8800199b5df0 R09: 0000000000000000

> [   33.260756] R10: ffff88001df2b600 R11: ffff88001f803ce8 R12: 0000000000000000

> [   33.268840] R13: ffff8800199b5e30 R14: 0000000000000046 R15: ffff8800199b5de0

> [   33.272722] FS:  0000000000000000(0000) GS:ffff88001f800000(0000) knlGS:0000000000000000

> [   33.276798] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> [   33.278981] CR2: 0000000000000000 CR3: 0000000004008003 CR4: 00000000003606f0

> [   33.282078] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

> [   33.285566] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

> [   33.289322] Call Trace:

> [   33.291094]  <IRQ>

> [   33.294208]  mq_flush_data_end_io+0xb3/0xf0

> [   33.301226]  scsi_end_request+0x90/0x1e0 [scsi_mod]

> [   33.303660]  scsi_io_completion+0x237/0x650 [scsi_mod]

> [   33.306833]  flush_smp_call_function_queue+0x7c/0xf0

> [   33.311369]  smp_call_function_single_interrupt+0x32/0xf0

> [   33.314245]  call_function_single_interrupt+0xa2/0xb0

> [   33.316755]  </IRQ>

> [   33.318365] RIP: 0010:native_safe_halt+0x2/0x10

> [   33.321988] RSP: 0018:ffffffff82003ea0 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff04

> [   33.324995] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000

> [   33.334532] RDX: 0000000000000000 RSI: ffffffff81e43850 RDI: ffffffff81e43a9d

> [   33.336643] RBP: ffffffff82128080 R08: 0000000e7441b6ce R09: ffff88001a4c2c00

> [   33.339282] R10: 0000000000000000 R11: ffff88001bceb7f0 R12: ffffffff81ea5c92

> [   33.344597] R13: 0000000000000000 R14: 0000000000000000 R15: 000000001e07cd69

> [   33.346526]  default_idle+0x18/0x130

> [   33.347929]  do_idle+0x167/0x1d0

> [   33.349201]  cpu_startup_entry+0x6f/0x80

> [   33.350553]  start_kernel+0x4c2/0x4e2

> [   33.351822]  secondary_startup_64+0xa5/0xb0

> [   33.354470] Code: 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 00 00 49 c1 e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 00 00 48 89 56 08 <48> 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00 00 48 89 97

> [   33.364997] RIP: blk_flush_complete_seq+0x20a/0x300 RSP: ffff88001f803ed0

> [   33.366759] CR2: 0000000000000000

> [   33.367921] ---[ end trace 5179c1a9cbc4eaa2 ]---

> [   33.369413] Kernel panic - not syncing: Fatal exception in interrupt

> [   33.372089] Kernel Offset: disabled

> [   33.374413] ---[ end Kernel panic - not syncing: Fatal exception in interrupt

> ===

> 

> ===

> [   30.937747] BUG: unable to handle kernel NULL pointer dereference at 0000000000000028

> [   30.940984] IP: bfq_put_queue+0x10b/0x130

> [   30.941609] PGD 0 P4D 0

> [   30.941976] Oops: 0000 [#1] PREEMPT SMP PTI

> [   30.942560] Modules linked in: crct10dif_pclmul crc32_pclmul ghash_clmulni_intel nls_iso8859_1 bochs_drm pcbc nls_cp437 vfat ttm aesni_intel fat aes_x86_64 crypto_simd glue_helper cryptd drm_kms_helper iTCO_wdt drm ppdev iTCO_vendor_support input_leds psmouse led_class intel_agp parport_pc joydev mousedev intel_gtt syscopyarea parport rtc_cmos evdev sysfillrect sysimgblt agpgart fb_sys_fops i2c_i801 mac_hid qemu_fw_cfg lpc_ich sch_fq_codel ip_tables x_tables xfs libcrc32c crc32c_generic dm_mod raid10 md_mod hid_generic usbhid hid sr_mod cdrom sd_mod uhci_hcd ahci libahci serio_raw virtio_net xhci_pci ehci_pci atkbd libata libps2 xhci_hcd virtio_pci ehci_hcd virtio_ring crc32c_intel scsi_mod usbcore i8042 usb_common virtio serio

> [   30.955195] CPU: 2 PID: 181 Comm: kworker/2:1H Not tainted 4.15.0-pf2 #1

> [   30.956649] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015

> [   30.958404] Workqueue: kblockd blk_mq_requeue_work

> [   30.959128] RIP: 0010:bfq_put_queue+0x10b/0x130

> [   30.960330] RSP: 0018:ffffc90000617c98 EFLAGS: 00010282

> [   30.961574] RAX: 0000000000000000 RBX: ffff88001d537210 RCX: 00000000ffffffff

> [   30.962990] RDX: 0000000000000000 RSI: ffff880018a300d8 RDI: ffff88001d537240

> [   30.964114] RBP: 0000000018a300a8 R08: 0000000000000041 R09: ffff88001d537210

> [   30.965449] R10: 0000000000432a7f R11: 000000000002000b R12: ffff88001d537240

> [   30.966798] R13: ffff88001941d6d9 R14: 0000000000000041 R15: 00000000ffffffff

> [   30.969154] FS:  0000000000000000(0000) GS:ffff88001f900000(0000) knlGS:0000000000000000

> [   30.972781] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> [   30.974310] CR2: 0000000000000028 CR3: 0000000004008004 CR4: 00000000003606e0

> [   30.975544] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

> [   30.976963] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

> [   30.980515] Call Trace:

> [   30.981893]  bfq_finish_requeue_request+0x54/0x380

> [   30.983499]  __blk_mq_requeue_request+0x5c/0x140

> [   30.988010]  blk_mq_dispatch_rq_list+0x1b4/0x4c0

> [   30.989621]  ? __switch_to_asm+0x34/0x70

> [   30.991699]  ? __switch_to_asm+0x40/0x70

> [   30.994801]  ? stub_ptregs_64+0x11/0x30

> [   30.996506]  blk_mq_sched_dispatch_requests+0x105/0x190

> [   30.998842]  __blk_mq_run_hw_queue+0x80/0x90

> [   31.002840]  __blk_mq_delay_run_hw_queue+0x92/0xe0

> [   31.004873]  blk_mq_run_hw_queue+0x25/0x90

> [   31.006766]  blk_mq_run_hw_queues+0x3a/0x50

> [   31.008725]  blk_mq_requeue_work+0x116/0x140

> [   31.011034]  process_one_work+0x1df/0x420

> [   31.012841]  worker_thread+0x2b/0x3d0

> [   31.014371]  ? process_one_work+0x420/0x420

> [   31.016165]  kthread+0x113/0x130

> [   31.018432]  ? kthread_create_on_node+0x70/0x70

> [   31.020638]  ? do_group_exit+0x33/0xa0

> [   31.022188]  ret_from_fork+0x35/0x40

> [   31.024845] Code: c1 e8 06 83 e0 01 48 83 f8 01 45 19 f6 e8 be 3b 00 00 41 83 e6 ee 48 89 c7 41 83 c6 53 e8 8e 3b 00 00 49 89 d9 45 89 f0 44 89 f9 <48> 8b 70 28 48 c7 c2 12 be e5 81 55 4c 89 ef e8 11 0f e0 ff 8b

> [   31.037915] RIP: bfq_put_queue+0x10b/0x130 RSP: ffffc90000617c98

> [   31.040346] CR2: 0000000000000028

> [   31.042889] ---[ end trace 11f85b2ea2b00253 ]---

> [   31.046478] note: kworker/2:1H[181] exited with preempt_count 1

> ===

> 


Could you please do a
gdb <buildir>/block/bfq-iosched.o # or vmlinux.o if bfq is builtin
list *(bfq_finish_requeue_request+0x54)
list *(bfq_put_queue+0x10b)
for me?

Thanks,
Paolo

> ===

> [   48.629969] BUG: unable to handle kernel NULL pointer dereference at           (null)

> [   48.632678] IP: blk_flush_complete_seq+0x20a/0x300

> [   48.637504] PGD 0 P4D 0

> [   48.639647] Oops: 0002 [#1] PREEMPT SMP PTI

> [   48.641496] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel aes_x86_64 crypto_simd glue_helper bochs_drm cryptd ttm ppdev drm_kms_helper iTCO_wdt iTCO_vendor_support input_leds led_class intel_agp psmouse joydev drm intel_gtt parport_pc mousedev syscopyarea sysfillrect sysimgblt evdev fb_sys_fops parport lpc_ich agpgart mac_hid i2c_i801 qemu_fw_cfg rtc_cmos sch_fq_codel ip_tables x_tables xfs libcrc32c crc32c_generic dm_mod raid10 hid_generic md_mod usbhid hid sr_mod cdrom sd_mod uhci_hcd ahci xhci_pci libahci serio_raw ehci_pci atkbd xhci_hcd ehci_hcd virtio_net libps2 libata crc32c_intel scsi_mod virtio_pci usbcore virtio_ring usb_common virtio i8042 serio

> [   48.663536] CPU: 3 PID: 175 Comm: kworker/3:1H Not tainted 4.15.0-pf2 #1

> [   48.668487] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015

> [   48.672290] Workqueue: kblockd blk_mq_run_work_fn

> [   48.674271] RIP: 0010:blk_flush_complete_seq+0x20a/0x300

> [   48.676939] RSP: 0000:ffff88001f983ed0 EFLAGS: 00010086

> [   48.679617] RAX: ffff88001d721b60 RBX: ffff88001d721b40 RCX: ffff8800192f26a8

> [   48.681937] RDX: 0000000000000000 RSI: ffff88001d721b70 RDI: ffff8800192f2600

> [   48.684117] RBP: ffff88001da3a140 R08: ffff88001d721b50 R09: 0000000000000000

> [   48.688197] R10: ffff8800176fdb00 R11: 0000000000000040 R12: 0000000000000000

> [   48.690628] R13: ffff88001d721b90 R14: 0000000000000046 R15: ffff88001d721b40

> [   48.693943] FS:  0000000000000000(0000) GS:ffff88001f980000(0000) knlGS:0000000000000000

> [   48.698935] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> [   48.701592] CR2: 0000000000000000 CR3: 0000000004008002 CR4: 00000000003606e0

> [   48.703861] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

> [   48.705994] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

> [   48.708165] Call Trace:

> [   48.709827]  <IRQ>

> [   48.712631]  mq_flush_data_end_io+0xb3/0xf0

> [   48.714419]  scsi_end_request+0x90/0x1e0 [scsi_mod]

> [   48.717553]  scsi_io_completion+0x237/0x650 [scsi_mod]

> [   48.721822]  flush_smp_call_function_queue+0x7c/0xf0

> [   48.726672]  smp_call_function_single_interrupt+0x32/0xf0

> [   48.733743]  call_function_single_interrupt+0xa2/0xb0

> [   48.737194]  </IRQ>

> [   48.738656] RIP: 0010:_raw_spin_unlock_irqrestore+0x11/0x40

> [   48.741128] RSP: 0000:ffffc900005e3d30 EFLAGS: 00000293 ORIG_RAX: ffffffffffffff04

> [   48.745138] RAX: 0000000000000001 RBX: ffff88001d640000 RCX: 0000000000000012

> [   48.747764] RDX: 0000000000040000 RSI: 0000000000000293 RDI: 0000000000000293

> [   48.752698] RBP: 0000000000000293 R08: ffffffffffffffff R09: 0000000000000090

> [   48.755910] R10: 0000000000432a3f R11: 000000000002000b R12: 0000000000000000

> [   48.760517] R13: ffff8800199ef800 R14: ffff880018d29948 R15: ffff8800199ef800

> [   48.771214]  ata_scsi_queuecmd+0xa0/0x210 [libata]

> [   48.774631]  scsi_dispatch_cmd+0xe8/0x260 [scsi_mod]

> [   48.777489]  scsi_queue_rq+0x4cf/0x560 [scsi_mod]

> [   48.782246]  blk_mq_dispatch_rq_list+0x8f/0x4c0

> [   48.787614]  blk_mq_sched_dispatch_requests+0x105/0x190

> [   48.790303]  __blk_mq_run_hw_queue+0x80/0x90

> [   48.795313]  process_one_work+0x1df/0x420

> [   48.798006]  worker_thread+0x2b/0x3d0

> [   48.801376]  ? process_one_work+0x420/0x420

> [   48.804226]  kthread+0x113/0x130

> [   48.806674]  ? kthread_create_on_node+0x70/0x70

> [   48.809640]  ret_from_fork+0x35/0x40

> [   48.812834] Code: 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 00 00 49 c1 e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 00 00 48 89 56 08 <48> 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00 00 48 89 97

> [   48.822452] RIP: blk_flush_complete_seq+0x20a/0x300 RSP: ffff88001f983ed0

> [   48.824908] CR2: 0000000000000000

> [   48.830677] ---[ end trace 4e5ef1b3dcbb32c5 ]---

> [   48.833655] Kernel panic - not syncing: Fatal exception in interrupt

> [   48.836166] Kernel Offset: disabled

> [   48.837150] ---[ end Kernel panic - not syncing: Fatal exception in interrupt

> ===

> 

> Revoking my Tested-by tag (:.

Paolo Valente Feb. 6, 2018, 2:55 p.m. UTC | #18

> Il giorno 06 feb 2018, alle ore 14:40, Holger Hoffstätte <holger@applied-asynchrony.com> ha scritto:

> 

> 

> The plot thickens!

> 


Yep, the culprit seems clearer, though ...

> Just as I was about to post that I didn't have any problems - because

> I didn't have any - I decided to do a second test, activated bfq on my

> workstation, on a hunch typed "sync" and .. the machine locked up, hard.

> 

> Rebooted, activated bfq, typed sync..sync hangs. Luckily this time

> a second terminal was still alive, so I could capture a trace for

> your enjoyment:

> 

> Feb  6 14:28:17 ragnarok kernel: io scheduler bfq registered

> Feb  6 14:28:20 ragnarok kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000030

> Feb  6 14:28:20 ragnarok kernel: IP: bfq_put_queue+0x10b/0x130 [bfq]

> Feb  6 14:28:20 ragnarok kernel: PGD 0 P4D 0 

> Feb  6 14:28:20 ragnarok kernel: Oops: 0000 [#1] SMP PTI

> Feb  6 14:28:20 ragnarok kernel: Modules linked in: bfq lz4 lz4_compress lz4_decompress nfs lockd grace sunrpc autofs4 sch_fq_codel it87 hwmon_vid x86_pkg_temp_thermal snd_hda_codec_realtek coretemp radeon crc32_pclmul snd_hda_codec_generic crc32c_intel pcbc snd_hda_codec_hdmi i2c_algo_bit aesni_intel drm_kms_helper aes_x86_64 uvcvideo syscopyarea crypto_simd snd_hda_intel sysfillrect cryptd snd_usb_audio sysimgblt videobuf2_vmalloc glue_helper fb_sys_fops snd_hda_codec snd_hwdep videobuf2_memops ttm videobuf2_v4l2 snd_usbmidi_lib videobuf2_core snd_rawmidi snd_hda_core drm snd_seq_device videodev snd_pcm i2c_i801 usbhid snd_timer i2c_core snd backlight soundcore r8169 parport_pc mii parport

> Feb  6 14:28:20 ragnarok kernel: CPU: 0 PID: 4 Comm: kworker/0:0H Not tainted 4.14.18 #1

> Feb  6 14:28:20 ragnarok kernel: Hardware name: Gigabyte Technology Co., Ltd. P67-DS3-B3/P67-DS3-B3, BIOS F1 05/06/2011

> Feb  6 14:28:20 ragnarok kernel: Workqueue: kblockd blk_mq_requeue_work

> Feb  6 14:28:20 ragnarok kernel: task: ffff88060395a1c0 task.stack: ffffc90000044000

> Feb  6 14:28:20 ragnarok kernel: RIP: 0010:bfq_put_queue+0x10b/0x130 [bfq]

> Feb  6 14:28:20 ragnarok kernel: RSP: 0018:ffffc90000047ca0 EFLAGS: 00010286

> Feb  6 14:28:20 ragnarok kernel: RAX: 0000000000000008 RBX: ffff8806023db690 RCX: 0000000000000000

> Feb  6 14:28:20 ragnarok kernel: RDX: 0000000000000000 RSI: ffff880601bb39b0 RDI: ffff880601a56400

> Feb  6 14:28:20 ragnarok kernel: RBP: 0000000001bb3980 R08: 0000000000000053 R09: ffff8806023db690

> Feb  6 14:28:20 ragnarok kernel: R10: 000000001dd0f11e R11: 00000000080a011b R12: ffff880601a56400

> Feb  6 14:28:20 ragnarok kernel: R13: ffff8806023dbed0 R14: 0000000000000053 R15: 0000000000000000

> Feb  6 14:28:20 ragnarok kernel: FS:  0000000000000000(0000) GS:ffff88061f400000(0000) knlGS:0000000000000000

> Feb  6 14:28:20 ragnarok kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> Feb  6 14:28:20 ragnarok kernel: CR2: 0000000000000030 CR3: 000000000200a002 CR4: 00000000000606f0

> Feb  6 14:28:20 ragnarok kernel: Call Trace:

> Feb  6 14:28:20 ragnarok kernel:  bfq_finish_requeue_request+0x4b/0x370 [bfq]

> Feb  6 14:28:20 ragnarok kernel:  __blk_mq_requeue_request+0x57/0x130

> Feb  6 14:28:20 ragnarok kernel:  blk_mq_dispatch_rq_list+0x1b3/0x510

> Feb  6 14:28:20 ragnarok kernel:  ? __bfq_bfqd_reset_in_service+0x20/0x70 [bfq]

> Feb  6 14:28:20 ragnarok kernel:  ? bfq_bfqq_expire+0x212/0x740 [bfq]

> Feb  6 14:28:20 ragnarok kernel:  blk_mq_sched_dispatch_requests+0xf0/0x170

> Feb  6 14:28:20 ragnarok kernel:  __blk_mq_run_hw_queue+0x4e/0x90

> Feb  6 14:28:20 ragnarok kernel:  __blk_mq_delay_run_hw_queue+0x73/0x80

> Feb  6 14:28:20 ragnarok kernel:  blk_mq_run_hw_queue+0x53/0x150

> Feb  6 14:28:20 ragnarok kernel:  blk_mq_run_hw_queues+0x3a/0x50

> Feb  6 14:28:20 ragnarok kernel:  blk_mq_requeue_work+0x104/0x110

> Feb  6 14:28:20 ragnarok kernel:  process_one_work+0x1d4/0x3d0

> Feb  6 14:28:20 ragnarok kernel:  worker_thread+0x2b/0x3c0

> Feb  6 14:28:20 ragnarok kernel:  ? process_one_work+0x3d0/0x3d0

> Feb  6 14:28:20 ragnarok kernel:  kthread+0x117/0x130

> Feb  6 14:28:20 ragnarok kernel:  ? kthread_create_on_node+0x40/0x40

> Feb  6 14:28:20 ragnarok kernel:  ret_from_fork+0x1f/0x30

> Feb  6 14:28:20 ragnarok kernel: Code: c1 e8 06 83 e0 01 48 83 f8 01 45 19 f6 e8 ce 3a 00 00 41 83 e6 ee 48 89 c7 41 83 c6 53 e8 9e 3a 00 00 49 89 d9 45 89 f0 44 89 f9 <48> 8b 70 28 48 c7 c2 d8 00 25 a0 55 4c 89 ef e8 11 ba ea e0 8b 

> Feb  6 14:28:20 ragnarok kernel: RIP: bfq_put_queue+0x10b/0x130 [bfq] RSP: ffffc90000047ca0

> Feb  6 14:28:20 ragnarok kernel: CR2: 0000000000000030

> Feb  6 14:28:20 ragnarok kernel: ---[ end trace 8b782ace30a4e7d8 ]---

> 


Same request: please
gdb <buildir>/block/bfq-iosched.o
list *(bfq_finish_requeue_request+0x4b)
list *(bfq_put_queue+0x10b)

Thanks,
Paolo


> Yes, this is 4.14.x but with most-of block/4.16, rock-solid otherwise (in daily use).

> Looks like there is something wrong with this patch after all..

> 

> cheers

> Holger

>

Oleksandr Natalenko Feb. 6, 2018, 2:59 p.m. UTC | #19

06.02.2018 15:50, Paolo Valente wrote:
> Could you please do a

> gdb <buildir>/block/bfq-iosched.o # or vmlinux.o if bfq is builtin

> list *(bfq_finish_requeue_request+0x54)

> list *(bfq_put_queue+0x10b)

> for me?

Yes. Just give me some time to recompile the kernel with minimal debug 
info enabled. I'll post then list/disasm and new stacktraces.

Holger Hoffstätte Feb. 6, 2018, 3:34 p.m. UTC | #20

On 02/06/18 15:55, Paolo Valente wrote:
> 

> 

>> Il giorno 06 feb 2018, alle ore 14:40, Holger Hoffstätte <holger@applied-asynchrony.com> ha scritto:

>>

>>

>> The plot thickens!

>>

> 

> Yep, the culprit seems clearer, though ...

> 

>> Just as I was about to post that I didn't have any problems - because

>> I didn't have any - I decided to do a second test, activated bfq on my

>> workstation, on a hunch typed "sync" and .. the machine locked up, hard.

>>

>> Rebooted, activated bfq, typed sync..sync hangs. Luckily this time

>> a second terminal was still alive, so I could capture a trace for

>> your enjoyment:

>>

>> Feb  6 14:28:17 ragnarok kernel: io scheduler bfq registered

>> Feb  6 14:28:20 ragnarok kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000030

>> Feb  6 14:28:20 ragnarok kernel: IP: bfq_put_queue+0x10b/0x130 [bfq]

>> Feb  6 14:28:20 ragnarok kernel: PGD 0 P4D 0 

>> Feb  6 14:28:20 ragnarok kernel: Oops: 0000 [#1] SMP PTI

>> Feb  6 14:28:20 ragnarok kernel: Modules linked in: bfq lz4 lz4_compress lz4_decompress nfs lockd grace sunrpc autofs4 sch_fq_codel it87 hwmon_vid x86_pkg_temp_thermal snd_hda_codec_realtek coretemp radeon crc32_pclmul snd_hda_codec_generic crc32c_intel pcbc snd_hda_codec_hdmi i2c_algo_bit aesni_intel drm_kms_helper aes_x86_64 uvcvideo syscopyarea crypto_simd snd_hda_intel sysfillrect cryptd snd_usb_audio sysimgblt videobuf2_vmalloc glue_helper fb_sys_fops snd_hda_codec snd_hwdep videobuf2_memops ttm videobuf2_v4l2 snd_usbmidi_lib videobuf2_core snd_rawmidi snd_hda_core drm snd_seq_device videodev snd_pcm i2c_i801 usbhid snd_timer i2c_core snd backlight soundcore r8169 parport_pc mii parport

>> Feb  6 14:28:20 ragnarok kernel: CPU: 0 PID: 4 Comm: kworker/0:0H Not tainted 4.14.18 #1

>> Feb  6 14:28:20 ragnarok kernel: Hardware name: Gigabyte Technology Co., Ltd. P67-DS3-B3/P67-DS3-B3, BIOS F1 05/06/2011

>> Feb  6 14:28:20 ragnarok kernel: Workqueue: kblockd blk_mq_requeue_work

>> Feb  6 14:28:20 ragnarok kernel: task: ffff88060395a1c0 task.stack: ffffc90000044000

>> Feb  6 14:28:20 ragnarok kernel: RIP: 0010:bfq_put_queue+0x10b/0x130 [bfq]

>> Feb  6 14:28:20 ragnarok kernel: RSP: 0018:ffffc90000047ca0 EFLAGS: 00010286

>> Feb  6 14:28:20 ragnarok kernel: RAX: 0000000000000008 RBX: ffff8806023db690 RCX: 0000000000000000

>> Feb  6 14:28:20 ragnarok kernel: RDX: 0000000000000000 RSI: ffff880601bb39b0 RDI: ffff880601a56400

>> Feb  6 14:28:20 ragnarok kernel: RBP: 0000000001bb3980 R08: 0000000000000053 R09: ffff8806023db690

>> Feb  6 14:28:20 ragnarok kernel: R10: 000000001dd0f11e R11: 00000000080a011b R12: ffff880601a56400

>> Feb  6 14:28:20 ragnarok kernel: R13: ffff8806023dbed0 R14: 0000000000000053 R15: 0000000000000000

>> Feb  6 14:28:20 ragnarok kernel: FS:  0000000000000000(0000) GS:ffff88061f400000(0000) knlGS:0000000000000000

>> Feb  6 14:28:20 ragnarok kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

>> Feb  6 14:28:20 ragnarok kernel: CR2: 0000000000000030 CR3: 000000000200a002 CR4: 00000000000606f0

>> Feb  6 14:28:20 ragnarok kernel: Call Trace:

>> Feb  6 14:28:20 ragnarok kernel:  bfq_finish_requeue_request+0x4b/0x370 [bfq]

>> Feb  6 14:28:20 ragnarok kernel:  __blk_mq_requeue_request+0x57/0x130

>> Feb  6 14:28:20 ragnarok kernel:  blk_mq_dispatch_rq_list+0x1b3/0x510

>> Feb  6 14:28:20 ragnarok kernel:  ? __bfq_bfqd_reset_in_service+0x20/0x70 [bfq]

>> Feb  6 14:28:20 ragnarok kernel:  ? bfq_bfqq_expire+0x212/0x740 [bfq]

>> Feb  6 14:28:20 ragnarok kernel:  blk_mq_sched_dispatch_requests+0xf0/0x170

>> Feb  6 14:28:20 ragnarok kernel:  __blk_mq_run_hw_queue+0x4e/0x90

>> Feb  6 14:28:20 ragnarok kernel:  __blk_mq_delay_run_hw_queue+0x73/0x80

>> Feb  6 14:28:20 ragnarok kernel:  blk_mq_run_hw_queue+0x53/0x150

>> Feb  6 14:28:20 ragnarok kernel:  blk_mq_run_hw_queues+0x3a/0x50

>> Feb  6 14:28:20 ragnarok kernel:  blk_mq_requeue_work+0x104/0x110

>> Feb  6 14:28:20 ragnarok kernel:  process_one_work+0x1d4/0x3d0

>> Feb  6 14:28:20 ragnarok kernel:  worker_thread+0x2b/0x3c0

>> Feb  6 14:28:20 ragnarok kernel:  ? process_one_work+0x3d0/0x3d0

>> Feb  6 14:28:20 ragnarok kernel:  kthread+0x117/0x130

>> Feb  6 14:28:20 ragnarok kernel:  ? kthread_create_on_node+0x40/0x40

>> Feb  6 14:28:20 ragnarok kernel:  ret_from_fork+0x1f/0x30

>> Feb  6 14:28:20 ragnarok kernel: Code: c1 e8 06 83 e0 01 48 83 f8 01 45 19 f6 e8 ce 3a 00 00 41 83 e6 ee 48 89 c7 41 83 c6 53 e8 9e 3a 00 00 49 89 d9 45 89 f0 44 89 f9 <48> 8b 70 28 48 c7 c2 d8 00 25 a0 55 4c 89 ef e8 11 ba ea e0 8b 

>> Feb  6 14:28:20 ragnarok kernel: RIP: bfq_put_queue+0x10b/0x130 [bfq] RSP: ffffc90000047ca0

>> Feb  6 14:28:20 ragnarok kernel: CR2: 0000000000000030

>> Feb  6 14:28:20 ragnarok kernel: ---[ end trace 8b782ace30a4e7d8 ]---

>>

> 

> Same request: please

> gdb <buildir>/block/bfq-iosched.o

> list *(bfq_finish_requeue_request+0x4b)

> list *(bfq_put_queue+0x10b)


(gdb) list *(bfq_finish_requeue_request+0x4b)
0x46cb is in bfq_finish_requeue_request (block/bfq-iosched.c:4804).
4799		 * that re-insertions of requeued requests, without
4800		 * re-preparation, can happen only for pass_through or at_head
4801		 * requests (which are not re-inserted into bfq internal
4802		 * queues).
4803		 */
4804		rq->elv.priv[0] = NULL;
4805		rq->elv.priv[1] = NULL;
4806	}
4807	
4808	/*

(gdb) list *(bfq_put_queue+0x10b)
0x415b is in bfq_put_queue (block/bfq-iosched.c:3978).
3973	#ifdef CONFIG_BFQ_GROUP_IOSCHED
3974		struct bfq_group *bfqg = bfqq_group(bfqq);
3975	#endif
3976	
3977		if (bfqq->bfqd)
3978			bfq_log_bfqq(bfqq->bfqd, bfqq, "put_queue: %p %d",
3979				     bfqq, bfqq->ref);
3980	
3981		bfqq->ref--;
3982		if (bfqq->ref)

Hope this helps!

Holger

Oleksandr Natalenko Feb. 6, 2018, 6:35 p.m. UTC | #21

Hi.

06.02.2018 15:50, Paolo Valente wrote:
> Could you please do a

> gdb <buildir>/block/bfq-iosched.o # or vmlinux.o if bfq is builtin

> list *(bfq_finish_requeue_request+0x54)

> list *(bfq_put_queue+0x10b)

> for me?


Fresh crashes and gdb output are given below. A side note: it is harder 
to trigger things on a slower machine, so clearly some timing-bounded 
race condition there.

[  134.276548] BUG: unable to handle kernel NULL pointer dereference at  
          (null)
[  134.283699] IP: blk_flush_complete_seq+0x20a/0x300
[  134.288163] PGD 0 P4D 0
[  134.291284] Oops: 0002 [#1] PREEMPT SMP PTI
[  134.293842] Modules linked in: bochs_drm ttm nls_iso8859_1 kvm_intel 
nls_cp437 vfat fat drm_kms_helper kvm drm irqbypass psmouse iTCO_wdt 
ppdev iTCO_vendor_support input_leds led_class i2c_i801 parport_pc 
joydev intel_agp parport intel_gtt mousedev lpc_ich rtc_cmos syscopyarea 
evdev sysfillrect agpgart qemu_fw_cfg mac_hid sysimgblt fb_sys_fops 
sch_fq_codel ip_tables x_tables xfs dm_thin_pool dm_persistent_data 
dm_bio_prison dm_bufio libcrc32c crc32c_generic dm_crypt algif_skcipher 
af_alg dm_mod hid_generic usbhid raid10 hid md_mod sr_mod sd_mod cdrom 
uhci_hcd ehci_pci serio_raw crct10dif_pclmul crc32_pclmul atkbd 
crc32c_intel libps2 ghash_clmulni_intel pcbc xhci_pci xhci_hcd ehci_hcd 
aesni_intel aes_x86_64 crypto_simd glue_helper cryptd ahci libahci 
libata usbcore usb_common i8042 serio virtio_scsi
[  134.340606]  scsi_mod virtio_blk virtio_net virtio_pci virtio_ring 
virtio
[  134.345803] CPU: 0 PID: 178 Comm: kworker/0:1H Not tainted 4.15.0-pf2 
#1
[  134.350309] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 
0.0.0 02/06/2015
[  134.355106] Workqueue: kblockd blk_mq_run_work_fn
[  134.359034] RIP: 0010:blk_flush_complete_seq+0x20a/0x300
[  134.367647] RSP: 0000:ffff88000f803ce8 EFLAGS: 00010082
[  134.371632] RAX: ffff88000d9755c0 RBX: ffff88000d9755a0 RCX: 
ffff88000c9b39a8
[  134.375675] RDX: 0000000000000000 RSI: ffff88000d9755d0 RDI: 
ffff88000c9b3900
[  134.381068] RBP: ffff88000d21a990 R08: ffff88000d9755b0 R09: 
0000000000000000
[  134.386302] R10: ffff8800058ff100 R11: 000000000002000b R12: 
0000000000000000
[  134.396915] R13: ffff88000d9755f0 R14: 0000000000000046 R15: 
ffff88000d9755a0
[  134.401140] FS:  0000000000000000(0000) GS:ffff88000f800000(0000) 
knlGS:0000000000000000
[  134.407361] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  134.412384] CR2: 0000000000000000 CR3: 0000000004008006 CR4: 
00000000001606f0
[  134.416913] Call Trace:
[  134.420251]  <IRQ>
[  134.427731]  mq_flush_data_end_io+0xb3/0xf0
[  134.431848]  scsi_end_request+0x90/0x1e0 [scsi_mod]
[  134.436424]  scsi_io_completion+0x237/0x650 [scsi_mod]
[  134.440109]  __blk_mq_complete_request+0xc4/0x150
[  134.444517]  ? scsi_mq_get_budget+0x110/0x110 [scsi_mod]
[  134.449603]  ata_scsi_qc_complete+0x8d/0x430 [libata]
[  134.458487]  ata_qc_complete_multiple+0x8d/0xe0 [libata]
[  134.461726]  ahci_handle_port_interrupt+0xc9/0x5b0 [libahci]
[  134.466420]  ahci_handle_port_intr+0x54/0xb0 [libahci]
[  134.470128]  ahci_single_level_irq_intr+0x3b/0x60 [libahci]
[  134.473327]  __handle_irq_event_percpu+0x44/0x1e0
[  134.476700]  handle_irq_event_percpu+0x30/0x70
[  134.480227]  handle_irq_event+0x37/0x60
[  134.490341]  handle_edge_irq+0x107/0x1c0
[  134.492876]  handle_irq+0x1f/0x30
[  134.495497]  do_IRQ+0x4d/0xe0
[  134.497963]  common_interrupt+0xa2/0xa2
[  134.500877]  </IRQ>
[  134.503129] RIP: 0010:_raw_spin_unlock_irqrestore+0x11/0x40
[  134.506782] RSP: 0000:ffffc90000307d30 EFLAGS: 00000293 ORIG_RAX: 
ffffffffffffffdb
[  134.511845] RAX: 0000000000000001 RBX: ffff88000db04000 RCX: 
0000000000000008
[  134.523019] RDX: 0000000000000100 RSI: 0000000000000293 RDI: 
0000000000000293
[  134.527968] RBP: 0000000000000293 R08: ffffffffffffffff R09: 
0000000000000040
[  134.532289] R10: 00000000008e66bf R11: 000000000002000b R12: 
0000000000000000
[  134.536376] R13: ffff88000d26a000 R14: ffff88000b99ac48 R15: 
ffff88000d26a000
[  134.541046]  ata_scsi_queuecmd+0xa0/0x210 [libata]
[  134.544363]  scsi_dispatch_cmd+0xe8/0x260 [scsi_mod]
[  134.552883]  scsi_queue_rq+0x4cf/0x560 [scsi_mod]
[  134.556811]  blk_mq_dispatch_rq_list+0x8f/0x4c0
[  134.559741]  blk_mq_sched_dispatch_requests+0x105/0x190
[  134.563253]  __blk_mq_run_hw_queue+0x80/0x90
[  134.565540]  process_one_work+0x1df/0x420
[  134.568041]  worker_thread+0x2b/0x3d0
[  134.571032]  ? process_one_work+0x420/0x420
[  134.573964]  kthread+0x113/0x130
[  134.584370]  ? kthread_create_on_node+0x70/0x70
[  134.587355]  ret_from_fork+0x35/0x40
[  134.589796] Code: 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 00 00 49 c1 
e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 00 00 48 89 
56 08 <48> 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00 00 48 89 97
[  134.598881] RIP: blk_flush_complete_seq+0x20a/0x300 RSP: 
ffff88000f803ce8
[  134.601812] CR2: 0000000000000000
[  134.603728] ---[ end trace fc6d0cdf33d29717 ]---
[  134.612349] Kernel panic - not syncing: Fatal exception in interrupt
[  134.615630] Kernel Offset: disabled
[  134.617712] ---[ end Kernel panic - not syncing: Fatal exception in 
interrupt

(gdb) list *(blk_flush_complete_seq+0x20a)
0xffffffff813056ca is in blk_flush_complete_seq 
(./include/linux/compiler.h:212).
207     {
208             switch (size) {
209             case 1: *(volatile __u8 *)p = *(__u8 *)res; break;
210             case 2: *(volatile __u16 *)p = *(__u16 *)res; break;
211             case 4: *(volatile __u32 *)p = *(__u32 *)res; break;
212             case 8: *(volatile __u64 *)p = *(__u64 *)res; break;
213             default:
214                     barrier();
215                     __builtin_memcpy((void *)p, (const void *)res, 
size);
216                     barrier();

[  231.545605] BUG: unable to handle kernel paging request at 
0000001000000028
[  231.551962] IP: bfq_put_queue+0x10b/0x130
[  231.556307] PGD 0 P4D 0
[  231.558939] Oops: 0000 [#1] PREEMPT SMP PTI
[  231.562149] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat 
kvm_intel kvm bochs_drm irqbypass ttm iTCO_wdt ppdev drm_kms_helper 
iTCO_vendor_support psmouse input_leds drm led_class joydev parport_pc 
mousedev intel_agp syscopyarea parport intel_gtt sysfillrect i2c_i801 
evdev sysimgblt agpgart rtc_cmos qemu_fw_cfg mac_hid fb_sys_fops lpc_ich 
sch_fq_codel ip_tables x_tables xfs dm_thin_pool dm_persistent_data 
dm_bio_prison dm_bufio libcrc32c crc32c_generic dm_crypt algif_skcipher 
af_alg dm_mod hid_generic usbhid hid raid10 md_mod sr_mod cdrom sd_mod 
serio_raw atkbd libps2 uhci_hcd crct10dif_pclmul crc32_pclmul 
crc32c_intel ghash_clmulni_intel pcbc xhci_pci aesni_intel aes_x86_64 
ehci_pci xhci_hcd ehci_hcd ahci crypto_simd glue_helper libahci cryptd 
usbcore libata usb_common i8042 serio virtio_scsi
[  231.608289]  scsi_mod virtio_blk virtio_net virtio_pci virtio_ring 
virtio
[  231.613610] CPU: 0 PID: 187 Comm: kworker/0:1H Not tainted 4.15.0-pf2 
#1
[  231.619675] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 
0.0.0 02/06/2015
[  231.624477] Workqueue: kblockd blk_mq_requeue_work
[  231.628532] RIP: 0010:bfq_put_queue+0x10b/0x130
[  231.635453] RSP: 0000:ffffc90000377c98 EFLAGS: 00010282
[  231.638621] RAX: 0000001000000000 RBX: ffff88000cdf20f0 RCX: 
0000000000000000
[  231.642332] RDX: 0000000000000000 RSI: ffff88000d4926d8 RDI: 
ffff88000cdf2120
[  231.647000] RBP: 000000000d4926a8 R08: 0000000000000041 R09: 
ffff88000cdf20f0
[  231.652682] R10: 0000000000105a7f R11: 000000000002000b R12: 
ffff88000cdf2120
[  231.657102] R13: ffff88000e152188 R14: 0000000000000041 R15: 
0000000000000000
[  231.661213] FS:  0000000000000000(0000) GS:ffff88000f800000(0000) 
knlGS:0000000000000000
[  231.664746] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  231.667647] CR2: 0000001000000028 CR3: 0000000004008002 CR4: 
00000000001606f0
[  231.671475] Call Trace:
[  231.673873]  bfq_finish_requeue_request+0x54/0x380
[  231.676823]  __blk_mq_requeue_request+0x5c/0x140
[  231.679465]  blk_mq_dispatch_rq_list+0x1b4/0x4c0
[  231.681798]  blk_mq_sched_dispatch_requests+0x105/0x190
[  231.685059]  __blk_mq_run_hw_queue+0x80/0x90
[  231.687750]  __blk_mq_delay_run_hw_queue+0x92/0xe0
[  231.691510]  blk_mq_run_hw_queue+0x25/0x90
[  231.694759]  blk_mq_run_hw_queues+0x3a/0x50
[  231.696706]  blk_mq_requeue_work+0x116/0x140
[  231.699340]  process_one_work+0x1df/0x420
[  231.703147]  worker_thread+0x2b/0x3d0
[  231.705322]  ? process_one_work+0x420/0x420
[  231.707002]  kthread+0x113/0x130
[  231.708494]  ? kthread_create_on_node+0x70/0x70
[  231.710209]  ? kthread_create_on_node+0x70/0x70
[  231.712754]  ret_from_fork+0x35/0x40
[  231.715068] Code: c1 e8 06 83 e0 01 48 83 f8 01 45 19 f6 e8 be 3b 00 
00 41 83 e6 ee 48 89 c7 41 83 c6 53 e8 8e 3b 00 00 49 89 d9 45 89 f0 44 
89 f9 <48> 8b 70 28 48 c7 c2 3a 9a e5 81 55 4c 89 ef e8 11 1c e0 ff 8b
[  231.725379] RIP: bfq_put_queue+0x10b/0x130 RSP: ffffc90000377c98
[  231.728391] CR2: 0000001000000028
[  231.730840] ---[ end trace 03bd81aa0d2b1434 ]---
[  231.733269] note: kworker/0:1H[187] exited with preempt_count 1

(gdb) l *(bfq_put_queue+0x10b)
0xffffffff81334d1b is in bfq_put_queue (block/bfq-iosched.c:3978).
3973    #ifdef CONFIG_BFQ_GROUP_IOSCHED
3974            struct bfq_group *bfqg = bfqq_group(bfqq);
3975    #endif
3976
3977            if (bfqq->bfqd)
3978                    bfq_log_bfqq(bfqq->bfqd, bfqq, "put_queue: %p 
%d",
3979                                 bfqq, bfqq->ref);
3980
3981            bfqq->ref--;
3982            if (bfqq->ref)

(gdb) l *(bfq_finish_requeue_request+0x54)
0xffffffff81335294 is in bfq_finish_requeue_request 
(block/bfq-iosched.c:4804).
4799             * that re-insertions of requeued requests, without
4800             * re-preparation, can happen only for pass_through or 
at_head
4801             * requests (which are not re-inserted into bfq internal
4802             * queues).
4803             */
4804            rq->elv.priv[0] = NULL;
4805            rq->elv.priv[1] = NULL;
4806    }
4807
4808    /*

[  322.939697] BUG: unable to handle kernel NULL pointer dereference at 
0000000000000008
[  322.944283] IP: blk_flush_complete_seq+0x206/0x300
[  322.947463] PGD 0 P4D 0
[  322.950266] Oops: 0002 [#2] PREEMPT SMP PTI
[  322.958898] Modules linked in: kvm_intel bochs_drm nls_iso8859_1 
nls_cp437 vfat fat ttm kvm drm_kms_helper drm iTCO_wdt irqbypass psmouse 
ppdev iTCO_vendor_support input_leds led_class i2c_i801 intel_agp 
parport_pc intel_gtt joydev lpc_ich rtc_cmos agpgart evdev parport 
syscopyarea mousedev qemu_fw_cfg sysfillrect mac_hid sysimgblt 
fb_sys_fops sch_fq_codel ip_tables x_tables xfs dm_thin_pool 
dm_persistent_data dm_bio_prison dm_bufio libcrc32c crc32c_generic 
dm_crypt algif_skcipher af_alg dm_mod hid_generic usbhid hid 
crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel raid10 
pcbc md_mod sr_mod cdrom sd_mod serio_raw atkbd libps2 uhci_hcd xhci_pci 
xhci_hcd ahci ehci_pci libahci aesni_intel aes_x86_64 crypto_simd 
glue_helper ehci_hcd cryptd libata usbcore usb_common i8042 serio 
virtio_scsi
[  323.001668]  scsi_mod virtio_blk virtio_net virtio_pci virtio_ring 
virtio
[  323.006121] CPU: 0 PID: 215 Comm: kworker/u5:1 Tainted: G      D      
     4.15.0-pf2 #1
[  323.010263] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 
0.0.0 02/06/2015
[  323.021225] Workqueue: kcryptd kcryptd_crypt [dm_crypt]
[  323.024947] RIP: 0010:blk_flush_complete_seq+0x206/0x300
[  323.028405] RSP: 0018:ffff88000f803ed0 EFLAGS: 00010086
[  323.032491] RAX: ffff88000cfe78b0 RBX: ffff88000cfe78a0 RCX: 
ffff88000d4d85a8
[  323.036262] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 
ffff88000d4d8500
[  323.041032] RBP: ffff88000d6510a0 R08: ffff88000cfe78a0 R09: 
0000000000000000
[  323.051518] R10: ffff88000dab4d00 R11: ffffffffc01aafb0 R12: 
0000000000000000
[  323.055818] R13: ffff88000cfe78f0 R14: 0000000000000046 R15: 
ffff88000cfe78a0
[  323.060965] FS:  0000000000000000(0000) GS:ffff88000f800000(0000) 
knlGS:0000000000000000
[  323.065902] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  323.070571] CR2: 0000000000000008 CR3: 0000000004008001 CR4: 
00000000001606f0
[  323.076591] Call Trace:
[  323.081685]  <IRQ>
[  323.084025]  mq_flush_data_end_io+0xb3/0xf0
[  323.087155]  scsi_end_request+0x90/0x1e0 [scsi_mod]
[  323.095768]  scsi_io_completion+0x237/0x650 [scsi_mod]
[  323.099928]  flush_smp_call_function_queue+0x7c/0xf0
[  323.104028]  smp_call_function_single_interrupt+0x32/0xf0
[  323.114170]  call_function_single_interrupt+0xa2/0xb0
[  323.118208]  </IRQ>
[  323.121040] RIP: 0010:_aesni_enc4+0x178/0x190 [aesni_intel]
[  323.124658] RSP: 0018:ffffc900004a7c40 EFLAGS: 00000293 ORIG_RAX: 
ffffffffffffff04
[  323.128777] RAX: ffffffffc01ab208 RBX: 0000000000000180 RCX: 
0000000000000000
[  323.133003] RDX: ffff88000daf9c80 RSI: ffff88000a2b3c80 RDI: 
ffff88000cd24260
[  323.139211] RBP: ffffc900004a7d40 R08: ffff8800089f7718 R09: 
0000000000000010
[  323.146930] R10: ffff88000cd24290 R11: ffffffffc01aafb0 R12: 
0000000000000080
[  323.151758] R13: ffffffffc01c90c8 R14: ffff88000a2b3d00 R15: 
ffff88000daf9d00
[  323.156507]  ? _aesni_enc1+0xac/0xac [aesni_intel]
[  323.160419]  ? _aesni_dec1+0xac/0xac [aesni_intel]
[  323.164204]  ? aesni_xts_crypt8+0x21e/0x260 [aesni_intel]
[  323.167322]  ? glue_xts_req_128bit+0x125/0x1d0 [glue_helper]
[  323.178383]  ? crypt_convert+0x961/0xef0 [dm_crypt]
[  323.182089]  ? xts_decrypt+0x40/0x40 [aesni_intel]
[  323.185825]  ? crypt_convert+0x961/0xef0 [dm_crypt]
[  323.189438]  ? bio_alloc_bioset+0x132/0x1e0
[  323.191926]  ? kcryptd_crypt+0x1ff/0x360 [dm_crypt]
[  323.194998]  ? process_one_work+0x1df/0x420
[  323.197475]  ? worker_thread+0x2b/0x3d0
[  323.206991]  ? process_one_work+0x420/0x420
[  323.210387]  ? kthread+0x113/0x130
[  323.213396]  ? kthread_create_on_node+0x70/0x70
[  323.216751]  ? ret_from_fork+0x35/0x40
[  323.220815] Code: 48 8b 10 48 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 
00 00 49 c1 e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 
00 00 <48> 89 56 08 48 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00
[  323.233543] RIP: blk_flush_complete_seq+0x206/0x300 RSP: 
ffff88000f803ed0
[  323.238885] CR2: 0000000000000008
[  323.241673] ---[ end trace 2ec7b63c3a4a4a02 ]---
[  323.245006] Kernel panic - not syncing: Fatal exception in interrupt
[  323.248858] Kernel Offset: disabled
[  323.250753] ---[ end Kernel panic - not syncing: Fatal exception in 
interrupt

(gdb) l *(blk_flush_complete_seq+0x206)
0xffffffff813056c6 is in blk_flush_complete_seq 
(./include/linux/list.h:105).
100      * This is only for internal list manipulation where we know
101      * the prev/next entries already!
102      */
103     static inline void __list_del(struct list_head * prev, struct 
list_head * next)
104     {
105             next->prev = prev;
106             WRITE_ONCE(prev->next, next);
107     }
108
109     /**

Paolo Valente Feb. 7, 2018, 9:08 a.m. UTC | #22

> Il giorno 06 feb 2018, alle ore 19:35, Oleksandr Natalenko <oleksandr@natalenko.name> ha scritto:

> 

> Hi.

> 

> 06.02.2018 15:50, Paolo Valente wrote:

>> Could you please do a

>> gdb <buildir>/block/bfq-iosched.o # or vmlinux.o if bfq is builtin

>> list *(bfq_finish_requeue_request+0x54)

>> list *(bfq_put_queue+0x10b)

>> for me?

> 

> Fresh crashes and gdb output are given below. A side note: it is harder to trigger things on a slower machine, so clearly some timing-bounded race condition there.

> 

> [  134.276548] BUG: unable to handle kernel NULL pointer dereference at           (null)

> [  134.283699] IP: blk_flush_complete_seq+0x20a/0x300

> [  134.288163] PGD 0 P4D 0

> [  134.291284] Oops: 0002 [#1] PREEMPT SMP PTI

> [  134.293842] Modules linked in: bochs_drm ttm nls_iso8859_1 kvm_intel nls_cp437 vfat fat drm_kms_helper kvm drm irqbypass psmouse iTCO_wdt ppdev iTCO_vendor_support input_leds led_class i2c_i801 parport_pc joydev intel_agp parport intel_gtt mousedev lpc_ich rtc_cmos syscopyarea evdev sysfillrect agpgart qemu_fw_cfg mac_hid sysimgblt fb_sys_fops sch_fq_codel ip_tables x_tables xfs dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio libcrc32c crc32c_generic dm_crypt algif_skcipher af_alg dm_mod hid_generic usbhid raid10 hid md_mod sr_mod sd_mod cdrom uhci_hcd ehci_pci serio_raw crct10dif_pclmul crc32_pclmul atkbd crc32c_intel libps2 ghash_clmulni_intel pcbc xhci_pci xhci_hcd ehci_hcd aesni_intel aes_x86_64 crypto_simd glue_helper cryptd ahci libahci libata usbcore usb_common i8042 serio virtio_scsi

> [  134.340606]  scsi_mod virtio_blk virtio_net virtio_pci virtio_ring virtio

> [  134.345803] CPU: 0 PID: 178 Comm: kworker/0:1H Not tainted 4.15.0-pf2 #1

> [  134.350309] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015

> [  134.355106] Workqueue: kblockd blk_mq_run_work_fn

> [  134.359034] RIP: 0010:blk_flush_complete_seq+0x20a/0x300

> [  134.367647] RSP: 0000:ffff88000f803ce8 EFLAGS: 00010082

> [  134.371632] RAX: ffff88000d9755c0 RBX: ffff88000d9755a0 RCX: ffff88000c9b39a8

> [  134.375675] RDX: 0000000000000000 RSI: ffff88000d9755d0 RDI: ffff88000c9b3900

> [  134.381068] RBP: ffff88000d21a990 R08: ffff88000d9755b0 R09: 0000000000000000

> [  134.386302] R10: ffff8800058ff100 R11: 000000000002000b R12: 0000000000000000

> [  134.396915] R13: ffff88000d9755f0 R14: 0000000000000046 R15: ffff88000d9755a0

> [  134.401140] FS:  0000000000000000(0000) GS:ffff88000f800000(0000) knlGS:0000000000000000

> [  134.407361] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> [  134.412384] CR2: 0000000000000000 CR3: 0000000004008006 CR4: 00000000001606f0

> [  134.416913] Call Trace:

> [  134.420251]  <IRQ>

> [  134.427731]  mq_flush_data_end_io+0xb3/0xf0

> [  134.431848]  scsi_end_request+0x90/0x1e0 [scsi_mod]

> [  134.436424]  scsi_io_completion+0x237/0x650 [scsi_mod]

> [  134.440109]  __blk_mq_complete_request+0xc4/0x150

> [  134.444517]  ? scsi_mq_get_budget+0x110/0x110 [scsi_mod]

> [  134.449603]  ata_scsi_qc_complete+0x8d/0x430 [libata]

> [  134.458487]  ata_qc_complete_multiple+0x8d/0xe0 [libata]

> [  134.461726]  ahci_handle_port_interrupt+0xc9/0x5b0 [libahci]

> [  134.466420]  ahci_handle_port_intr+0x54/0xb0 [libahci]

> [  134.470128]  ahci_single_level_irq_intr+0x3b/0x60 [libahci]

> [  134.473327]  __handle_irq_event_percpu+0x44/0x1e0

> [  134.476700]  handle_irq_event_percpu+0x30/0x70

> [  134.480227]  handle_irq_event+0x37/0x60

> [  134.490341]  handle_edge_irq+0x107/0x1c0

> [  134.492876]  handle_irq+0x1f/0x30

> [  134.495497]  do_IRQ+0x4d/0xe0

> [  134.497963]  common_interrupt+0xa2/0xa2

> [  134.500877]  </IRQ>

> [  134.503129] RIP: 0010:_raw_spin_unlock_irqrestore+0x11/0x40

> [  134.506782] RSP: 0000:ffffc90000307d30 EFLAGS: 00000293 ORIG_RAX: ffffffffffffffdb

> [  134.511845] RAX: 0000000000000001 RBX: ffff88000db04000 RCX: 0000000000000008

> [  134.523019] RDX: 0000000000000100 RSI: 0000000000000293 RDI: 0000000000000293

> [  134.527968] RBP: 0000000000000293 R08: ffffffffffffffff R09: 0000000000000040

> [  134.532289] R10: 00000000008e66bf R11: 000000000002000b R12: 0000000000000000

> [  134.536376] R13: ffff88000d26a000 R14: ffff88000b99ac48 R15: ffff88000d26a000

> [  134.541046]  ata_scsi_queuecmd+0xa0/0x210 [libata]

> [  134.544363]  scsi_dispatch_cmd+0xe8/0x260 [scsi_mod]

> [  134.552883]  scsi_queue_rq+0x4cf/0x560 [scsi_mod]

> [  134.556811]  blk_mq_dispatch_rq_list+0x8f/0x4c0

> [  134.559741]  blk_mq_sched_dispatch_requests+0x105/0x190

> [  134.563253]  __blk_mq_run_hw_queue+0x80/0x90

> [  134.565540]  process_one_work+0x1df/0x420

> [  134.568041]  worker_thread+0x2b/0x3d0

> [  134.571032]  ? process_one_work+0x420/0x420

> [  134.573964]  kthread+0x113/0x130

> [  134.584370]  ? kthread_create_on_node+0x70/0x70

> [  134.587355]  ret_from_fork+0x35/0x40

> [  134.589796] Code: 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 00 00 49 c1 e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 00 00 48 89 56 08 <48> 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00 00 48 89 97

> [  134.598881] RIP: blk_flush_complete_seq+0x20a/0x300 RSP: ffff88000f803ce8

> [  134.601812] CR2: 0000000000000000

> [  134.603728] ---[ end trace fc6d0cdf33d29717 ]---

> [  134.612349] Kernel panic - not syncing: Fatal exception in interrupt

> [  134.615630] Kernel Offset: disabled

> [  134.617712] ---[ end Kernel panic - not syncing: Fatal exception in interrupt

> 

> (gdb) list *(blk_flush_complete_seq+0x20a)

> 0xffffffff813056ca is in blk_flush_complete_seq (./include/linux/compiler.h:212).

> 207     {

> 208             switch (size) {

> 209             case 1: *(volatile __u8 *)p = *(__u8 *)res; break;

> 210             case 2: *(volatile __u16 *)p = *(__u16 *)res; break;

> 211             case 4: *(volatile __u32 *)p = *(__u32 *)res; break;

> 212             case 8: *(volatile __u64 *)p = *(__u64 *)res; break;

> 213             default:

> 214                     barrier();

> 215                     __builtin_memcpy((void *)p, (const void *)res, size);

> 216                     barrier();

> 

> [  231.545605] BUG: unable to handle kernel paging request at 0000001000000028

> [  231.551962] IP: bfq_put_queue+0x10b/0x130

> [  231.556307] PGD 0 P4D 0

> [  231.558939] Oops: 0000 [#1] PREEMPT SMP PTI

> [  231.562149] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat kvm_intel kvm bochs_drm irqbypass ttm iTCO_wdt ppdev drm_kms_helper iTCO_vendor_support psmouse input_leds drm led_class joydev parport_pc mousedev intel_agp syscopyarea parport intel_gtt sysfillrect i2c_i801 evdev sysimgblt agpgart rtc_cmos qemu_fw_cfg mac_hid fb_sys_fops lpc_ich sch_fq_codel ip_tables x_tables xfs dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio libcrc32c crc32c_generic dm_crypt algif_skcipher af_alg dm_mod hid_generic usbhid hid raid10 md_mod sr_mod cdrom sd_mod serio_raw atkbd libps2 uhci_hcd crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel pcbc xhci_pci aesni_intel aes_x86_64 ehci_pci xhci_hcd ehci_hcd ahci crypto_simd glue_helper libahci cryptd usbcore libata usb_common i8042 serio virtio_scsi

> [  231.608289]  scsi_mod virtio_blk virtio_net virtio_pci virtio_ring virtio

> [  231.613610] CPU: 0 PID: 187 Comm: kworker/0:1H Not tainted 4.15.0-pf2 #1

> [  231.619675] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015

> [  231.624477] Workqueue: kblockd blk_mq_requeue_work

> [  231.628532] RIP: 0010:bfq_put_queue+0x10b/0x130

> [  231.635453] RSP: 0000:ffffc90000377c98 EFLAGS: 00010282

> [  231.638621] RAX: 0000001000000000 RBX: ffff88000cdf20f0 RCX: 0000000000000000

> [  231.642332] RDX: 0000000000000000 RSI: ffff88000d4926d8 RDI: ffff88000cdf2120

> [  231.647000] RBP: 000000000d4926a8 R08: 0000000000000041 R09: ffff88000cdf20f0

> [  231.652682] R10: 0000000000105a7f R11: 000000000002000b R12: ffff88000cdf2120

> [  231.657102] R13: ffff88000e152188 R14: 0000000000000041 R15: 0000000000000000

> [  231.661213] FS:  0000000000000000(0000) GS:ffff88000f800000(0000) knlGS:0000000000000000

> [  231.664746] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> [  231.667647] CR2: 0000001000000028 CR3: 0000000004008002 CR4: 00000000001606f0

> [  231.671475] Call Trace:

> [  231.673873]  bfq_finish_requeue_request+0x54/0x380

> [  231.676823]  __blk_mq_requeue_request+0x5c/0x140

> [  231.679465]  blk_mq_dispatch_rq_list+0x1b4/0x4c0

> [  231.681798]  blk_mq_sched_dispatch_requests+0x105/0x190

> [  231.685059]  __blk_mq_run_hw_queue+0x80/0x90

> [  231.687750]  __blk_mq_delay_run_hw_queue+0x92/0xe0

> [  231.691510]  blk_mq_run_hw_queue+0x25/0x90

> [  231.694759]  blk_mq_run_hw_queues+0x3a/0x50

> [  231.696706]  blk_mq_requeue_work+0x116/0x140

> [  231.699340]  process_one_work+0x1df/0x420

> [  231.703147]  worker_thread+0x2b/0x3d0

> [  231.705322]  ? process_one_work+0x420/0x420

> [  231.707002]  kthread+0x113/0x130

> [  231.708494]  ? kthread_create_on_node+0x70/0x70

> [  231.710209]  ? kthread_create_on_node+0x70/0x70

> [  231.712754]  ret_from_fork+0x35/0x40

> [  231.715068] Code: c1 e8 06 83 e0 01 48 83 f8 01 45 19 f6 e8 be 3b 00 00 41 83 e6 ee 48 89 c7 41 83 c6 53 e8 8e 3b 00 00 49 89 d9 45 89 f0 44 89 f9 <48> 8b 70 28 48 c7 c2 3a 9a e5 81 55 4c 89 ef e8 11 1c e0 ff 8b

> [  231.725379] RIP: bfq_put_queue+0x10b/0x130 RSP: ffffc90000377c98

> [  231.728391] CR2: 0000001000000028

> [  231.730840] ---[ end trace 03bd81aa0d2b1434 ]---

> [  231.733269] note: kworker/0:1H[187] exited with preempt_count 1

> 

> (gdb) l *(bfq_put_queue+0x10b)

> 0xffffffff81334d1b is in bfq_put_queue (block/bfq-iosched.c:3978).

> 3973    #ifdef CONFIG_BFQ_GROUP_IOSCHED

> 3974            struct bfq_group *bfqg = bfqq_group(bfqq);

> 3975    #endif

> 3976

> 3977            if (bfqq->bfqd)

> 3978                    bfq_log_bfqq(bfqq->bfqd, bfqq, "put_queue: %p %d",

> 3979                                 bfqq, bfqq->ref);

> 3980

> 3981            bfqq->ref--;

> 3982            if (bfqq->ref)

> 

> (gdb) l *(bfq_finish_requeue_request+0x54)

> 0xffffffff81335294 is in bfq_finish_requeue_request (block/bfq-iosched.c:4804).

> 4799             * that re-insertions of requeued requests, without

> 4800             * re-preparation, can happen only for pass_through or at_head

> 4801             * requests (which are not re-inserted into bfq internal

> 4802             * queues).

> 4803             */

> 4804            rq->elv.priv[0] = NULL;

> 4805            rq->elv.priv[1] = NULL;

> 4806    }

> 4807

> 4808    /*

> 

> [  322.939697] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008

> [  322.944283] IP: blk_flush_complete_seq+0x206/0x300

> [  322.947463] PGD 0 P4D 0

> [  322.950266] Oops: 0002 [#2] PREEMPT SMP PTI

> [  322.958898] Modules linked in: kvm_intel bochs_drm nls_iso8859_1 nls_cp437 vfat fat ttm kvm drm_kms_helper drm iTCO_wdt irqbypass psmouse ppdev iTCO_vendor_support input_leds led_class i2c_i801 intel_agp parport_pc intel_gtt joydev lpc_ich rtc_cmos agpgart evdev parport syscopyarea mousedev qemu_fw_cfg sysfillrect mac_hid sysimgblt fb_sys_fops sch_fq_codel ip_tables x_tables xfs dm_thin_pool dm_persistent_data dm_bio_prison dm_bufio libcrc32c crc32c_generic dm_crypt algif_skcipher af_alg dm_mod hid_generic usbhid hid crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel raid10 pcbc md_mod sr_mod cdrom sd_mod serio_raw atkbd libps2 uhci_hcd xhci_pci xhci_hcd ahci ehci_pci libahci aesni_intel aes_x86_64 crypto_simd glue_helper ehci_hcd cryptd libata usbcore usb_common i8042 serio virtio_scsi

> [  323.001668]  scsi_mod virtio_blk virtio_net virtio_pci virtio_ring virtio

> [  323.006121] CPU: 0 PID: 215 Comm: kworker/u5:1 Tainted: G      D          4.15.0-pf2 #1

> [  323.010263] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015

> [  323.021225] Workqueue: kcryptd kcryptd_crypt [dm_crypt]

> [  323.024947] RIP: 0010:blk_flush_complete_seq+0x206/0x300

> [  323.028405] RSP: 0018:ffff88000f803ed0 EFLAGS: 00010086

> [  323.032491] RAX: ffff88000cfe78b0 RBX: ffff88000cfe78a0 RCX: ffff88000d4d85a8

> [  323.036262] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88000d4d8500

> [  323.041032] RBP: ffff88000d6510a0 R08: ffff88000cfe78a0 R09: 0000000000000000

> [  323.051518] R10: ffff88000dab4d00 R11: ffffffffc01aafb0 R12: 0000000000000000

> [  323.055818] R13: ffff88000cfe78f0 R14: 0000000000000046 R15: ffff88000cfe78a0

> [  323.060965] FS:  0000000000000000(0000) GS:ffff88000f800000(0000) knlGS:0000000000000000

> [  323.065902] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033

> [  323.070571] CR2: 0000000000000008 CR3: 0000000004008001 CR4: 00000000001606f0

> [  323.076591] Call Trace:

> [  323.081685]  <IRQ>

> [  323.084025]  mq_flush_data_end_io+0xb3/0xf0

> [  323.087155]  scsi_end_request+0x90/0x1e0 [scsi_mod]

> [  323.095768]  scsi_io_completion+0x237/0x650 [scsi_mod]

> [  323.099928]  flush_smp_call_function_queue+0x7c/0xf0

> [  323.104028]  smp_call_function_single_interrupt+0x32/0xf0

> [  323.114170]  call_function_single_interrupt+0xa2/0xb0

> [  323.118208]  </IRQ>

> [  323.121040] RIP: 0010:_aesni_enc4+0x178/0x190 [aesni_intel]

> [  323.124658] RSP: 0018:ffffc900004a7c40 EFLAGS: 00000293 ORIG_RAX: ffffffffffffff04

> [  323.128777] RAX: ffffffffc01ab208 RBX: 0000000000000180 RCX: 0000000000000000

> [  323.133003] RDX: ffff88000daf9c80 RSI: ffff88000a2b3c80 RDI: ffff88000cd24260

> [  323.139211] RBP: ffffc900004a7d40 R08: ffff8800089f7718 R09: 0000000000000010

> [  323.146930] R10: ffff88000cd24290 R11: ffffffffc01aafb0 R12: 0000000000000080

> [  323.151758] R13: ffffffffc01c90c8 R14: ffff88000a2b3d00 R15: ffff88000daf9d00

> [  323.156507]  ? _aesni_enc1+0xac/0xac [aesni_intel]

> [  323.160419]  ? _aesni_dec1+0xac/0xac [aesni_intel]

> [  323.164204]  ? aesni_xts_crypt8+0x21e/0x260 [aesni_intel]

> [  323.167322]  ? glue_xts_req_128bit+0x125/0x1d0 [glue_helper]

> [  323.178383]  ? crypt_convert+0x961/0xef0 [dm_crypt]

> [  323.182089]  ? xts_decrypt+0x40/0x40 [aesni_intel]

> [  323.185825]  ? crypt_convert+0x961/0xef0 [dm_crypt]

> [  323.189438]  ? bio_alloc_bioset+0x132/0x1e0

> [  323.191926]  ? kcryptd_crypt+0x1ff/0x360 [dm_crypt]

> [  323.194998]  ? process_one_work+0x1df/0x420

> [  323.197475]  ? worker_thread+0x2b/0x3d0

> [  323.206991]  ? process_one_work+0x420/0x420

> [  323.210387]  ? kthread+0x113/0x130

> [  323.213396]  ? kthread_create_on_node+0x70/0x70

> [  323.216751]  ? ret_from_fork+0x35/0x40

> [  323.220815] Code: 48 8b 10 48 39 d0 0f 84 8f 00 00 00 48 8b 97 b0 00 00 00 49 c1 e0 04 45 31 e4 48 8b b7 a8 00 00 00 49 01 d8 48 8d 8f a8 00 00 00 <48> 89 56 08 48 89 32 49 8b 50 18 49 89 48 18 48 89 87 a8 00 00

> [  323.233543] RIP: blk_flush_complete_seq+0x206/0x300 RSP: ffff88000f803ed0

> [  323.238885] CR2: 0000000000000008

> [  323.241673] ---[ end trace 2ec7b63c3a4a4a02 ]---

> [  323.245006] Kernel panic - not syncing: Fatal exception in interrupt

> [  323.248858] Kernel Offset: disabled

> [  323.250753] ---[ end Kernel panic - not syncing: Fatal exception in interrupt

> 

> (gdb) l *(blk_flush_complete_seq+0x206)

> 0xffffffff813056c6 is in blk_flush_complete_seq (./include/linux/list.h:105).

> 100      * This is only for internal list manipulation where we know

> 101      * the prev/next entries already!

> 102      */

> 103     static inline void __list_del(struct list_head * prev, struct list_head * next)

> 104     {

> 105             next->prev = prev;

> 106             WRITE_ONCE(prev->next, next);

> 107     }

> 108

> 109     /**



Thank you very much Oleksandr, and Holger, for your listings,
I've managed to make a crash happen, unfortunately only after a lot of
time and I/O.  Unfortunately, the crash happened for one of the call
chains not including bfq.  If you guys have found a way to get these
crashes more or less easily, then I think I'll need your help here.
The first piece of information I need is whether this failure happens
even without "BFQ hierarchical scheduling support".  If it does, then
the area of investigation narrows a little.  So, could you please
retry after disabling hierarchical support?

Thanks,
Paolo

Mike Galbraith Feb. 7, 2018, 9:23 a.m. UTC | #23

On Wed, 2018-02-07 at 10:08 +0100, Paolo Valente wrote:
> 

> The first piece of information I need is whether this failure happens

> even without "BFQ hierarchical scheduling support".


I presume you mean BFQ_GROUP_IOSCHED, which I do not have enabled.

	-Mike

Paolo Valente Feb. 7, 2018, 9:45 a.m. UTC | #24

> Il giorno 07 feb 2018, alle ore 10:23, Mike Galbraith <efault@gmx.de> ha scritto:

> 

> On Wed, 2018-02-07 at 10:08 +0100, Paolo Valente wrote:

>> 

>> The first piece of information I need is whether this failure happens

>> even without "BFQ hierarchical scheduling support".

> 

> I presume you mean BFQ_GROUP_IOSCHED, which I do not have enabled.

> 

Great (so to speak), this saves us one step.

So, here's my next request for help: please apply the attached patch (compressed to preserve it from my email client) and retry. It adds several anomaly checks. I hope I have not added any false-positive check.

Thanks,
Paolo
> 	-Mike

Mike Galbraith Feb. 7, 2018, 10:15 a.m. UTC | #25

On Wed, 2018-02-07 at 10:45 +0100, Paolo Valente wrote:
> 

> > Il giorno 07 feb 2018, alle ore 10:23, Mike Galbraith <efault@gmx.de> ha scritto:

> > 

> > On Wed, 2018-02-07 at 10:08 +0100, Paolo Valente wrote:

> >> 

> >> The first piece of information I need is whether this failure happens

> >> even without "BFQ hierarchical scheduling support".

> > 

> > I presume you mean BFQ_GROUP_IOSCHED, which I do not have enabled.

> > 

> 

> Great (so to speak), this saves us one step.

> 

> So, here's my next request for help: please apply the attached patch

> (compressed to preserve it from my email client) and retry. It adds

> several anomaly checks. I hope I have not added any false-positive

> check.


kernel BUG at block/bfq-iosched.c:4742!

4742         BUG_ON(!(rq->rq_flags & RQF_ELVPRIV));

Paolo Valente Feb. 7, 2018, 10:27 a.m. UTC | #26

> Il giorno 07 feb 2018, alle ore 11:15, Mike Galbraith <efault@gmx.de> ha scritto:

> 

> On Wed, 2018-02-07 at 10:45 +0100, Paolo Valente wrote:

>> 

>>> Il giorno 07 feb 2018, alle ore 10:23, Mike Galbraith <efault@gmx.de> ha scritto:

>>> 

>>> On Wed, 2018-02-07 at 10:08 +0100, Paolo Valente wrote:

>>>> 

>>>> The first piece of information I need is whether this failure happens

>>>> even without "BFQ hierarchical scheduling support".

>>> 

>>> I presume you mean BFQ_GROUP_IOSCHED, which I do not have enabled.

>>> 

>> 

>> Great (so to speak), this saves us one step.

>> 

>> So, here's my next request for help: please apply the attached patch

>> (compressed to preserve it from my email client) and retry. It adds

>> several anomaly checks. I hope I have not added any false-positive

>> check.

> 

> kernel BUG at block/bfq-iosched.c:4742!

> 

> 4742         BUG_ON(!(rq->rq_flags & RQF_ELVPRIV));


Oh my, this is as crazy as, fortunately, easy to fix.  The problem is
that this is easy to fix in bfq, but increases the doubts I have
expressed in my cover letter: is it ok that, in blk-mq, the functions
of an elevator may get invoked, without control, on requests that do
not belong to that elevator?

Anyway, two requests, Mike, if you haven't had enough already:

1. Could you paste a stack trace for this OOPS, just to understand how we
get there?

2. Could you please turn that BUG_ON into:
if (!(rq->rq_flags & RQF_ELVPRIV))
	return;
and see what happens?

Thanks a lot,
Paolo

Mike Galbraith Feb. 7, 2018, 10:31 a.m. UTC | #27

On Wed, 2018-02-07 at 11:27 +0100, Paolo Valente wrote:
> 

> 1. Could you paste a stack trace for this OOPS, just to understand how we

> get there?


[  442.421058] kernel BUG at block/bfq-iosched.c:4742!
[  442.421762] invalid opcode: 0000 [#1] SMP PTI
[  442.422436] Dumping ftrace buffer:
[  442.423116]    (ftrace buffer empty)
[  442.423785] Modules linked in: fuse(E) ebtable_filter(E) ebtables(E) af_packet(E) bridge(E) stp(E) llc(E) iscsi_ibft(E) iscsi_boot_sysfs(E) nf_conntrack_ipv6(E) nf_defrag_ipv6(E) ipt_REJECT(E) xt_tcpudp(E) iptable_filter(E) ip6table_>
[  442.426685]  pcbc(E) iTCO_wdt(E) aesni_intel(E) aes_x86_64(E) iTCO_vendor_support(E) crypto_simd(E) glue_helper(E) mei_me(E) i2c_i801(E) r8169(E) cryptd(E) lpc_ich(E) mfd_core(E) mii(E) mei(E) soundcore(E) pcspkr(E) shpchp(E) thermal>
[  442.429634]  dm_multipath(E) dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) efivarfs(E) autofs4(E)
[  442.430166] CPU: 2 PID: 489 Comm: kworker/2:1H Tainted: G            E    4.15.0.ga2e5790-master #612
[  442.430675] Hardware name: MEDION MS-7848/MS-7848, BIOS M7848W08.20C 09/23/2013
[  442.431195] Workqueue: kblockd blk_mq_requeue_work
[  442.431706] RIP: 0010:bfq_only_requeue_request+0xd1/0xe0
[  442.432221] RSP: 0018:ffff8803f7b8fcc0 EFLAGS: 00010246
[  442.432733] RAX: 0000000000002090 RBX: ffff8803dbda2580 RCX: 0000000000000000
[  442.433250] RDX: ffff8803fa3c8000 RSI: 0000000000000004 RDI: ffff8803dbda2580
[  442.433778] RBP: ffff8803f9ec85d0 R08: ffff8803fa3c81c0 R09: 0000000000000000
[  442.434296] R10: ffff8803fa3c81d0 R11: 0000000000001000 R12: ffff8803dbda2600
[  442.434815] R13: 000000000000000d R14: 0000000000000000 R15: ffff8803f7b8fd88
[  442.435334] FS:  0000000000000000(0000) GS:ffff88041ec80000(0000) knlGS:0000000000000000
[  442.435863] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  442.436381] CR2: 00007f00e001e198 CR3: 0000000001e0a002 CR4: 00000000001606e0
[  442.436909] Call Trace:
[  442.437445]  __blk_mq_requeue_request+0x8f/0x120
[  442.437980]  blk_mq_dispatch_rq_list+0x342/0x550
[  442.438506]  ? kyber_dispatch_request+0xd0/0xd0
[  442.439041]  blk_mq_sched_dispatch_requests+0xf7/0x180
[  442.439568]  __blk_mq_run_hw_queue+0x58/0xd0
[  442.440103]  __blk_mq_delay_run_hw_queue+0x99/0xa0
[  442.440628]  blk_mq_run_hw_queue+0x54/0xf0
[  442.441157]  blk_mq_run_hw_queues+0x4b/0x60
[  442.441822]  blk_mq_requeue_work+0x13a/0x150
[  442.442518]  process_one_work+0x147/0x350
[  442.443205]  worker_thread+0x47/0x3e0
[  442.443887]  kthread+0xf8/0x130
[  442.444579]  ? rescuer_thread+0x360/0x360
[  442.445264]  ? kthread_stop+0x120/0x120
[  442.445965]  ? do_syscall_64+0x75/0x1a0
[  442.446651]  ? SyS_exit_group+0x10/0x10
[  442.447340]  ret_from_fork+0x35/0x40
[  442.448023] Code: ff 4c 89 f6 4c 89 ef e8 be ec 2e 00 48 c7 83 80 00 00 00 00 00 00 00 48 c7 83 88 00 00 00 00 00 00 00 5b 5d 41 5c 41 5d 41 5e c3 <0f> 0b 0f 0b 0f 0b 0f 0b 0f 1f 80 00 00 00 00 0f 1f 44 00 00 41
[  442.448668] RIP: bfq_only_requeue_request+0xd1/0xe0 RSP: ffff8803f7b8fcc0

Mike Galbraith Feb. 7, 2018, 11:03 a.m. UTC | #28

On Wed, 2018-02-07 at 11:27 +0100, Paolo Valente wrote:
> 

> 2. Could you please turn that BUG_ON into:

> if (!(rq->rq_flags & RQF_ELVPRIV))

> 	return;

> and see what happens?


That seems to make it forgets how to make boom.

	-Mike

Paolo Valente Feb. 7, 2018, 11:12 a.m. UTC | #29

> Il giorno 07 feb 2018, alle ore 12:03, Mike Galbraith <efault@gmx.de> ha scritto:

> 

> On Wed, 2018-02-07 at 11:27 +0100, Paolo Valente wrote:

>> 

>> 2. Could you please turn that BUG_ON into:

>> if (!(rq->rq_flags & RQF_ELVPRIV))

>> 	return;

>> and see what happens?

> 

> That seems to make it forgets how to make boom.

> 

Great! This deserves to be celebrated with a packet of Ikea chips.

Just to be certain, before submitting a new patch: you changed *only*
the BUG_ON at line 4742, on top of my instrumentation patch.

Thanks,
Paolo

> 	-Mike

Mike Galbraith Feb. 7, 2018, 11:22 a.m. UTC | #30

On Wed, 2018-02-07 at 12:12 +0100, Paolo Valente wrote:

> Just to be certain, before submitting a new patch: you changed *only*

> the BUG_ON at line 4742, on top of my instrumentation patch.

Nah, I completely rewrite it with only a little help from an ouija
board to compensate for missing (all) knowledge wrt BFQ internals.

(iow yeah, I did exactly and only what I was asked to do:)

Paolo Valente Feb. 7, 2018, 11:27 a.m. UTC | #31

> Il giorno 07 feb 2018, alle ore 11:27, Paolo Valente <paolo.valente@linaro.org> ha scritto:

> 

> 

> 

>> Il giorno 07 feb 2018, alle ore 11:15, Mike Galbraith <efault@gmx.de> ha scritto:

>> 

>> On Wed, 2018-02-07 at 10:45 +0100, Paolo Valente wrote:

>>> 

>>>> Il giorno 07 feb 2018, alle ore 10:23, Mike Galbraith <efault@gmx.de> ha scritto:

>>>> 

>>>> On Wed, 2018-02-07 at 10:08 +0100, Paolo Valente wrote:

>>>>> 

>>>>> The first piece of information I need is whether this failure happens

>>>>> even without "BFQ hierarchical scheduling support".

>>>> 

>>>> I presume you mean BFQ_GROUP_IOSCHED, which I do not have enabled.

>>>> 

>>> 

>>> Great (so to speak), this saves us one step.

>>> 

>>> So, here's my next request for help: please apply the attached patch

>>> (compressed to preserve it from my email client) and retry. It adds

>>> several anomaly checks. I hope I have not added any false-positive

>>> check.

>> 

>> kernel BUG at block/bfq-iosched.c:4742!

>> 

>> 4742         BUG_ON(!(rq->rq_flags & RQF_ELVPRIV));

> 

> Oh my, this is as crazy as, fortunately, easy to fix.  The problem is

> that this is easy to fix in bfq, but increases the doubts I have

> expressed in my cover letter: is it ok that, in blk-mq, the functions

> of an elevator may get invoked, without control, on requests that do

> not belong to that elevator?

> 

> Anyway, two requests, Mike, if you haven't had enough already:

> 

> 1. Could you paste a stack trace for this OOPS, just to understand how we

> get there?

> 

> 2. Could you please turn that BUG_ON into:

> if (!(rq->rq_flags & RQF_ELVPRIV))

> 	return;

> and see what happens?

> 


Hi Oleksandr, Holger,
before I prepare a V2 candidate patch, could you please test my
instrumentation patch too, with the above change made.  For your
convenience, I have attached a compressed archive with both the
instrumentation patch and a patch making the above change.

Crossing my fingers,
Paolo
> Thanks a lot,

> Paolo

Oleksandr Natalenko Feb. 7, 2018, 3:50 p.m. UTC | #32

Hi.

07.02.2018 12:27, Paolo Valente wrote:
> Hi Oleksandr, Holger,

> before I prepare a V2 candidate patch, could you please test my

> instrumentation patch too, with the above change made.  For your

> convenience, I have attached a compressed archive with both the

> instrumentation patch and a patch making the above change.

> 

> Crossing my fingers,

> Paolo


With all three patches applied I cannot reproduce neither cfdisk hang 
nor some kind of boom.

Thank you.

Oleksandr

Paolo Valente Feb. 7, 2018, 5:33 p.m. UTC | #33

> Il giorno 07 feb 2018, alle ore 16:50, Oleksandr Natalenko <oleksandr@natalenko.name> ha scritto:

> 

> Hi.

> 

> 07.02.2018 12:27, Paolo Valente wrote:

>> Hi Oleksandr, Holger,

>> before I prepare a V2 candidate patch, could you please test my

>> instrumentation patch too, with the above change made.  For your

>> convenience, I have attached a compressed archive with both the

>> instrumentation patch and a patch making the above change.

>> Crossing my fingers,

>> Paolo

> 

> With all three patches applied I cannot reproduce neither cfdisk hang nor some kind of boom.

> 

> Thank you.

> 


Thank you, Oleksandr. I'm now ready to prepare a new version of this patch.

Paolo

> Oleksandr

[BUGFIX,1/1] block, bfq: add requeue-request hook

Commit Message

Comments

Patch