mkfs.ext4 over /dev/bcache0 hangs

Bug #1784665 reported by Ryan Harper on 2018-07-31
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
linux (Ubuntu)
High
Unassigned
Bionic
High
Unassigned
Cosmic
High
Unassigned

Bug Description

$ cat /proc/version_signature
Ubuntu 4.15.0-29.31-generic 4.15.18

$ lsb_release -rd
Description: Ubuntu Cosmic Cuttlefish (development branch)
Release: 18.10

$ apt-cache policy linux-image-`uname -r`
linux-image-4.15.0-29-generic:
  Installed: 4.15.0-29.31
  Candidate: 4.15.0-29.31
  Version table:
 *** 4.15.0-29.31 500
        500 http://archive.ubuntu.com/ubuntu cosmic/main amd64 Packages
        100 /var/lib/dpkg/status

3) mkfs.ext4 /dev/bcache0 returns successful creating an ext4 filesystem on top of a bcache device

4) mkfs.ext4 doesn't return and kernel prints hung process info

[ 58.018099] cloud-init[920]: Running command ['mkfs.ext4', '-F', '-L', 'root-fs', '-U', 'f01aec97-9457-11e8-b8d6-525400123401', '/dev/bcache0'] with allowed return codes [0] (capture=True)
[ 242.652018] INFO: task kworker/u4:0:5 blocked for more than 120 seconds.
[ 242.653767] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 242.655391] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.657397] INFO: task kworker/0:2:410 blocked for more than 120 seconds.
[ 242.659126] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 242.660980] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.663000] INFO: task bcache_allocato:2326 blocked for more than 120 seconds.
[ 242.664807] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 242.666516] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.668503] INFO: task bcache_writebac:2345 blocked for more than 120 seconds.
[ 242.670301] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 242.671936] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.673909] INFO: task mkfs.ext4:2803 blocked for more than 120 seconds.
[ 242.675414] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 242.677038] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 363.483998] INFO: task kworker/u4:0:5 blocked for more than 120 seconds.
[ 363.488441] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 363.489598] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 363.491043] INFO: task kworker/0:2:410 blocked for more than 120 seconds.
[ 363.492252] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 363.494085] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 363.495659] INFO: task bcache_allocato:2326 blocked for more than 120 seconds.
[ 363.496957] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 363.498454] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 363.499866] INFO: task bcache_writebac:2345 blocked for more than 120 seconds.
[ 363.501156] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 363.502597] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 363.504048] INFO: task mkfs.ext4:2803 blocked for more than 120 seconds.
[ 363.505505] Tainted: P O 4.15.0-29-generic #31-Ubuntu
[ 363.506677] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

System has two virtio block devices. bcache was created like so:

make-bcache -C /dev/vdb
make-bcache -B /dev/vda2

resulting in /dev/bcache0

ProblemType: Bug
DistroRelease: Ubuntu 18.10
Package: linux-image-4.15.0-29-generic 4.15.0-29.31
ProcVersionSignature: User Name 4.15.0-29.31-generic 4.15.18
Uname: Linux 4.15.0-29-generic x86_64
AlsaDevices:
 total 0
 crw-rw---- 1 root audio 116, 1 Jul 31 15:52 seq
 crw-rw---- 1 root audio 116, 33 Jul 31 15:52 timer
AplayDevices: Error: [Errno 2] No such file or directory: 'aplay': 'aplay'
ApportVersion: 2.20.10-0ubuntu7
Architecture: amd64
ArecordDevices: Error: [Errno 2] No such file or directory: 'arecord': 'arecord'
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
CRDA: N/A
Date: Tue Jul 31 15:53:56 2018
IwConfig: Error: [Errno 2] No such file or directory: 'iwconfig': 'iwconfig'
Lsusb: Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
MachineType: QEMU Standard PC (i440FX + PIIX, 1996)
PciMultimedia:

ProcEnviron:
 TERM=xterm
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=C.UTF-8
 SHELL=/bin/bash
ProcFB:

ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.15.0-29-generic root=LABEL=cloudimg-rootfs ro console=tty1 console=ttyS0
RelatedPackageVersions:
 linux-restricted-modules-4.15.0-29-generic N/A
 linux-backports-modules-4.15.0-29-generic N/A
 linux-firmware N/A
RfKill: Error: [Errno 2] No such file or directory: 'rfkill': 'rfkill'
SourcePackage: linux
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 04/01/2014
dmi.bios.vendor: SeaBIOS
dmi.bios.version: 1.11.1-1
dmi.chassis.type: 1
dmi.chassis.vendor: QEMU
dmi.chassis.version: pc-i440fx-bionic
dmi.modalias: dmi:bvnSeaBIOS:bvr1.11.1-1:bd04/01/2014:svnQEMU:pnStandardPC(i440FX+PIIX,1996):pvrpc-i440fx-bionic:cvnQEMU:ct1:cvrpc-i440fx-bionic:
dmi.product.name: Standard PC (i440FX + PIIX, 1996)
dmi.product.version: pc-i440fx-bionic
dmi.sys.vendor: QEMU

Ryan Harper (raharper) wrote :

This change was made by a bot.

Changed in linux (Ubuntu):
status: New → Confirmed
Joseph Salisbury (jsalisbury) wrote :

Did this issue start happening after an update/upgrade? Was there a prior kernel version where you were not having this particular problem?

Would it be possible for you to test the latest upstream kernel? Refer to https://wiki.ubuntu.com/KernelMainlineBuilds . Please test the latest v4.18 kernel[0].

If this bug is fixed in the mainline kernel, please add the following tag 'kernel-fixed-upstream'.

If the mainline kernel does not fix this bug, please add the tag: 'kernel-bug-exists-upstream'.

Once testing of the upstream kernel is complete, please mark this bug as "Confirmed".

Thanks in advance.

[0] http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.18-rc7

Changed in linux (Ubuntu):
importance: Undecided → High
tags: added: kernel-key
Changed in linux (Ubuntu Cosmic):
status: Confirmed → Triaged
Ryan Harper (raharper) wrote :

> Did this issue start happening after an update/upgrade? Was there a prior kernel version where you were not having this particular problem?

We've had plenty of successful runs on this kernel. I suspect io load or something else may trigger this. We've only seen it once out of tens of not hundreds of runs on Cosmic 4.15.0-29-generic.

We don't currently have an easy way to test upstream kernels in the automation runs. If we see this again, I'll poke a bit more on running mkfs.ext4 over bcache devices on Cosmic to see if we can recreate outside of the automation.

Ryan Harper (raharper) wrote :

We've just had a second occurrence of this, same kernel, but with Xenial. (Xenial HWE Edge kernel 4.15.0-29) with the same scenario, mkfs.ext4 a /dev/bcache0.

I'll see if I can recreate by stressing things.

Joseph Salisbury (jsalisbury) wrote :

It would be great if we can identify a reproducer. It would make it much easier to track down.

Ryan Harper (raharper) wrote :

I think I've got one. It doesn't always hang the mkfs, but it does wedge bcache in a few ways.

[ 484.322546] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 484.326230] INFO: task bcache_allocato:32503 blocked for more than 120 seconds.

1) when it occurs, a backing device never get's released from the kernel, such that a blockdev --rereadpt on the device says the device is busy, but examining /sys/class/block/<dev>/holders shows nothing

2) attempts to open the device exclusively fail (so things like mkfs or make-bcache -B).

The reproducer has two virtio disks, vda, vdb; size doesn't really matter, but they are 10G and 2G respectively. /dev/vdb is a cache set (make-bcache -C /dev/vdb), /dev/vda2 is the backing device (make-bcache -B /dev/vda2) and then they are joined (echo $CSET_UUID > /sys/class/block/vda/vda2/bcache/attach), which results in a /dev/bcache0. Then we mkfs.ext4 it.

Then we tear it down, wipe the partitions, the disks and repeat.

I'll attach the script.

Ryan Harper (raharper) wrote :
Ryan Harper (raharper) wrote :

I'll see if I can reproduce on the mainline kernel.

Ryan Harper (raharper) wrote :

I can recreate on upstream:

# uname -r; dmesg | tail -n 16
4.18.0-041800rc7-generic
[ 967.657492] INFO: task bcache_allocato:14240 blocked for more than 120 seconds.
[ 967.664138] Not tainted 4.18.0-041800rc7-generic #201807292230
[ 967.669641] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 967.673503] bcache_allocato D 0 14240 2 0x80000000
[ 967.673512] Call Trace:
[ 967.673529] __schedule+0x29e/0x840
[ 967.673535] ? reschedule_interrupt+0xa/0x20
[ 967.673539] schedule+0x2c/0x80
[ 967.673555] bch_bucket_alloc+0x19d/0x380 [bcache]
[ 967.673561] ? wait_woken+0x80/0x80
[ 967.673574] bch_prio_write+0x186/0x330 [bcache]
[ 967.673583] bch_allocator_thread+0x482/0xd10 [bcache]
[ 967.673589] kthread+0x120/0x140
[ 967.673598] ? bch_invalidate_one_bucket+0x80/0x80 [bcache]
[ 967.673601] ? kthread_bind+0x40/0x40
[ 967.673605] ret_from_fork+0x35/0x40

tags: added: kernel-bug-exists-upstream
Changed in linux (Ubuntu Cosmic):
status: Triaged → Confirmed
Joseph Salisbury (jsalisbury) wrote :

Thanks for testing mainline. We should be able to bisect this down if we confirm it's a regression.

Can you test the following kernels and report back? We are looking for the first kernel version that exhibits this bug:

4.10 Final: http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.10/
4.13 Final: http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.13/
4.15 Final: http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.15/

You don't have to test every kernel, just up until the kernel that first has this bug. If 4.10 final exhibits the bug, we'll have to test even earlier versions.

Thanks in advance!

Ryan Harper (raharper) wrote :

4.10:
  Status: OK
  Comment: Survived 30 minute loop over recreating with no issues.
4.13:
  Status: OK
  Comment: Survived 30 minute loop over recreating with no issues.
4.15:
  Status: FAIL
  Comment: triggered within less than a minute of the loop.
  Kernel Trace:

[ 122.500943] Oops: 0000 [#24] SMP PTI
[ 122.501612] Modules linked in: bcache nls_utf8 isofs nls_iso8859_1 ppdev kvm_intel kvm irqbypass parport_pc input_leds parport joydev mac_hid serio_raw sch_fq_codel ib_iser rdma_cm iw_cm ib_cm ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi virtio_rng ip_tables x_tables autofs4 btrfs zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear psmouse virtio_net virtio_blk virtio_scsi i2c_piix4 pata_acpi floppy
[ 122.508306] CPU: 3 PID: 2212 Comm: kworker/3:249 Tainted: G D 4.15.0-041500-generic #201802011154
[ 122.510459] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 122.512541] Workqueue: bcache bch_data_insert_keys [bcache]
[ 122.513779] RIP: 0010:__bch_bset_search+0x80/0x470 [bcache]
[ 122.515015] RSP: 0018:ffffb49141a83c10 EFLAGS: 00010286
[ 122.516127] RAX: fffffffffff6cacc RBX: fffffffffff6cacc RCX: 0000000000000000
[ 122.516947] RDX: ffffb49141a83e18 RSI: 0000000000000069 RDI: ffff8f6a7ad64cc8
[ 122.517768] RBP: ffffb49141a83c70 R08: 0000000000000001 R09: ffff8f6a7ad64ce0
[ 122.518586] R10: ffff8f6a6735ab80 R11: 0000000000027ec0 R12: ffffb49141a83e18
[ 122.519858] R13: 0000000400656369 R14: 0000000066643165 R15: ffff8f6a7ad64ce0
[ 122.521302] FS: 0000000000000000(0000) GS:ffff8f6a7fd80000(0000) knlGS:0000000000000000
[ 122.522272] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 122.522969] CR2: 0000000400656389 CR3: 0000000038fc2000 CR4: 00000000000006e0
[ 122.524521] Call Trace:
[ 122.525153] ? ttwu_do_activate+0x7a/0x90
[ 122.526147] __bch_btree_iter_init+0x5d/0xc0 [bcache]
[ 122.527411] bch_btree_iter_init+0x12/0x20 [bcache]
[ 122.528578] bch_btree_map_nodes_recurse+0x93/0x190 [bcache]
[ 122.529904] ? __slab_free+0x14d/0x2c0
[ 122.530814] ? bch_btree_insert_check_key+0x1f0/0x1f0 [bcache]
[ 122.532331] __bch_btree_map_nodes+0x142/0x1a0 [bcache]
[ 122.533685] ? bch_btree_insert_check_key+0x1f0/0x1f0 [bcache]
[ 122.534994] bch_btree_insert+0xf9/0x170 [bcache]
[ 122.536059] ? wait_woken+0x80/0x80
[ 122.536876] bch_data_insert_keys+0x36/0x130 [bcache]
[ 122.538004] process_one_work+0x1ef/0x410
[ 122.538928] worker_thread+0x32/0x410
[ 122.539779] kthread+0x121/0x140
[ 122.540538] ? process_one_work+0x410/0x410
[ 122.541487] ? kthread_create_worker_on_cpu+0x70/0x70
[ 122.542619] ret_from_fork+0x35/0x40
[ 122.543547] Code: 41 08 81 e3 ff ff 0f 00 25 ff ff 0f 00 48 39 d8 48 89 5d d0 0f 85 b6 03 00 00 48 8b 42 08 49 2b 41 10 48 85 c0 0f 89 7c 03 00 00 <49> 8b 45 20 25 ff ff 0f 00 48 39 45 d0 0f 85 c0 03 00 00 48 8b
[ 122.546019] RIP: __bch_bset_search+0x80/0x470 [bcache] RSP: ffffb49141a83c10
[ 122.546836] CR2: 0000000400656389
[ 122.547567] ---[ end trace c539406c76c0edd2 ]---

Joseph Salisbury (jsalisbury) wrote :

To narrow it down further, can you test the following two kernels:

4.14 Final: http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.14/
4.15-rc1: http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.15-rc1/

Ryan Harper (raharper) wrote :

4.14 Final: OK
4.15-rc1: OK

I started a further bisect:

4.15-rc9: FAIL
4.15-rc5: OK
4.15-rc7: FAIL
4.15-rc6: OK

So, it appears something between rc6 (last known good) and rc7 (FAIL)

Changed in linux (Ubuntu Bionic):
status: New → In Progress
Changed in linux (Ubuntu Cosmic):
status: Confirmed → In Progress
Changed in linux (Ubuntu Bionic):
importance: Undecided → High
assignee: nobody → Joseph Salisbury (jsalisbury)
Changed in linux (Ubuntu Cosmic):
assignee: nobody → Joseph Salisbury (jsalisbury)
Joseph Salisbury (jsalisbury) wrote :

I started a kernel bisect between v4.15-rc6 and v4.15-rc7. The kernel bisect will require testing of about 7-10 test kernels.

I built the first test kernel, up to the following commit:
d8887f1c7289848e74c92bd4322789a9cd7de699

The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test that kernel and report back if it has the bug or not? I will build the next test kernel based on your test results.

Thanks in advance

Ryan Harper (raharper) wrote :

test kernel 4.15-rc6 up to d8887f1c7289848e74c92bd4322789a9cd7de699 FAILED

Attaching oops.

Ryan Harper (raharper) wrote :

test kernel 4.15-rc6 up to d8887f1c7289848e74c92bd4322789a9cd7de699 FAILED

Joseph Salisbury (jsalisbury) wrote :

I built the next test kernel, up to the following commit:
abb62c46d4949d44979fa647740feff3f7538799

The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test that kernel and report back if it has the bug or not? I will build the next test kernel based on your test results.

Thanks in advance

Ryan Harper (raharper) wrote :

test kernel 4.15-rc1 up to abb62c46d4949d44979fa647740feff3f7538799 FAILED

Joseph Salisbury (jsalisbury) wrote :

I built the next test kernel, up to the following commit:
f17b9e764dfcd838dab51572d620a371c05a8e60

The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test that kernel and report back if it has the bug or not? I will build the next test kernel based on your test results.

Thanks in advance

Ryan Harper (raharper) wrote :

FAILED: Kernel 4.15-rc1 up to f17b9e764dfcd838dab51572d620a371c05a8e60

Attached is the oops of the failure.

Joseph Salisbury (jsalisbury) wrote :

I built the next test kernel, up to the following commit:
f48f66a962a54c3d26d688c3df5441c9d1ba8730

The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test that kernel and report back if it has the bug or not? I will build the next test kernel based on your test results.

Thanks in advance

Ryan Harper (raharper) wrote :

FAILED: Kernel 4.15-rc1 up to f48f66a962a54c3d26d688c3df5441c9d1ba8730

Attached is the oops of the failure.

Joseph Salisbury (jsalisbury) wrote :

I built the next test kernel, up to the following commit:
6b457409169b7686d293b408da0b6446ccb57a76

The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test that kernel and report back if it has the bug or not? I will build the next test kernel based on your test results.

Thanks in advance

Ryan Harper (raharper) wrote :

PASS: Kernel 4.15-rc1 (bisect5) up to 6b457409169b7686d293b408da0b6446ccb57a76

I've 2600 seconds of uptime with over 800 loops in the test-case.

Joseph Salisbury (jsalisbury) wrote :

I built the next test kernel, up to the following commit:
87eba0716011e528f7841026f2cc65683219d0ad

The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test that kernel and report back if it has the bug or not? I will build the next test kernel based on your test results.

Thanks in advance

Ryan Harper (raharper) wrote :

PASS: Kernel 4.15-rc1 (bisect6) up to 87eba0716011e528f7841026f2cc65683219d0ad

Joseph Salisbury (jsalisbury) wrote :

I built the next test kernel, up to the following commit:
bc631943faba6fc3f755748091ada31798fb7d50

The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test that kernel and report back if it has the bug or not? I will build the next test kernel based on your test results.

Thanks in advance

Ryan Harper (raharper) wrote :

FAILED: Kernel 4.15-rc1 up to bc631943faba6fc3f755748091ada31798fb7d50

Attached is the oops of the failure.

Joseph Salisbury (jsalisbury) wrote :

The bisect reported the following commit as the first bad commit:

bc631943faba ("arm64: dts: rockchip: limit rk3328-rock64 gmac speed to 100MBit for now")

It's strange that this is an arm64 commit. I'll investigate a bit and see why the bisect came back with this result.

https://patchwork.kernel.org/patch/10094201/

diff --git a/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
b/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
index d4f80786e7c2..3890468678ce 100644
--- a/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
+++ b/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
@@ -132,6 +132,8 @@
  assigned-clocks = <&cru SCLK_MAC2IO>, <&cru SCLK_MAC2IO_EXT>;
  assigned-clock-parents = <&gmac_clkin>, <&gmac_clkin>;
  clock_in_out = "input";
+ /* shows instability at 1GBit right now */
+ max-speed = <100>;
  phy-supply = <&vcc_io>;
  phy-mode = "rgmii";
  pinctrl-names = "default";

That can't be it, which means maybe some of the PASSED didn't pass; I
just didn't wait long enough?
On Tue, Aug 28, 2018 at 2:11 PM Joseph Salisbury
<email address hidden> wrote:
>
> The bisect reported the following commit as the first bad commit:
>
> bc631943faba ("arm64: dts: rockchip: limit rk3328-rock64 gmac speed to
> 100MBit for now")
>
> It's strange that this is an arm64 commit. I'll investigate a bit and
> see why the bisect came back with this result.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1784665
>
> Title:
> mkfs.ext4 over /dev/bcache0 hangs
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1784665/+subscriptions

Ryan Harper (raharper) wrote :

It's always been a locking issue, so either misuse (or missing) locks
in the bcache attach/detach path, or generic locking changes to block
layer path I'd think.

I'll see if I can find any hits on those oops tracebacks too

On Tue, Aug 28, 2018 at 2:29 PM Ryan Harper <email address hidden> wrote:
>
> https://patchwork.kernel.org/patch/10094201/
>
> diff --git a/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> b/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> index d4f80786e7c2..3890468678ce 100644
> --- a/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> +++ b/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> @@ -132,6 +132,8 @@
> assigned-clocks = <&cru SCLK_MAC2IO>, <&cru SCLK_MAC2IO_EXT>;
> assigned-clock-parents = <&gmac_clkin>, <&gmac_clkin>;
> clock_in_out = "input";
> + /* shows instability at 1GBit right now */
> + max-speed = <100>;
> phy-supply = <&vcc_io>;
> phy-mode = "rgmii";
> pinctrl-names = "default";
>
>
> That can't be it, which means maybe some of the PASSED didn't pass; I
> just didn't wait long enough?
> On Tue, Aug 28, 2018 at 2:11 PM Joseph Salisbury
> <email address hidden> wrote:
> >
> > The bisect reported the following commit as the first bad commit:
> >
> > bc631943faba ("arm64: dts: rockchip: limit rk3328-rock64 gmac speed to
> > 100MBit for now")
> >
> > It's strange that this is an arm64 commit. I'll investigate a bit and
> > see why the bisect came back with this result.
> >
> > --
> > You received this bug notification because you are subscribed to the bug
> > report.
> > https://bugs.launchpad.net/bugs/1784665
> >
> > Title:
> > mkfs.ext4 over /dev/bcache0 hangs
> >
> > To manage notifications about this bug go to:
> > https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1784665/+subscriptions

Ryan Harper (raharper) wrote :

https://www.spinics.net/lists/linux-bcache/msg04869.html

https://www.spinics.net/lists/linux-bcache/msg05774.html
On Tue, Aug 28, 2018 at 2:30 PM Ryan Harper <email address hidden> wrote:
>
> It's always been a locking issue, so either misuse (or missing) locks
> in the bcache attach/detach path, or generic locking changes to block
> layer path I'd think.
>
> I'll see if I can find any hits on those oops tracebacks too
>
> On Tue, Aug 28, 2018 at 2:29 PM Ryan Harper <email address hidden> wrote:
> >
> > https://patchwork.kernel.org/patch/10094201/
> >
> > diff --git a/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> > b/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> > index d4f80786e7c2..3890468678ce 100644
> > --- a/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> > +++ b/arch/arm64/boot/dts/rockchip/rk3328-rock64.dts
> > @@ -132,6 +132,8 @@
> > assigned-clocks = <&cru SCLK_MAC2IO>, <&cru SCLK_MAC2IO_EXT>;
> > assigned-clock-parents = <&gmac_clkin>, <&gmac_clkin>;
> > clock_in_out = "input";
> > + /* shows instability at 1GBit right now */
> > + max-speed = <100>;
> > phy-supply = <&vcc_io>;
> > phy-mode = "rgmii";
> > pinctrl-names = "default";
> >
> >
> > That can't be it, which means maybe some of the PASSED didn't pass; I
> > just didn't wait long enough?
> > On Tue, Aug 28, 2018 at 2:11 PM Joseph Salisbury
> > <email address hidden> wrote:
> > >
> > > The bisect reported the following commit as the first bad commit:
> > >
> > > bc631943faba ("arm64: dts: rockchip: limit rk3328-rock64 gmac speed to
> > > 100MBit for now")
> > >
> > > It's strange that this is an arm64 commit. I'll investigate a bit and
> > > see why the bisect came back with this result.
> > >
> > > --
> > > You received this bug notification because you are subscribed to the bug
> > > report.
> > > https://bugs.launchpad.net/bugs/1784665
> > >
> > > Title:
> > > mkfs.ext4 over /dev/bcache0 hangs
> > >
> > > To manage notifications about this bug go to:
> > > https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1784665/+subscriptions

Joseph Salisbury (jsalisbury) wrote :

Thanks for digging up this additional information. I'll investigate further. While I do that, the v4.19-rc1 kernel is now out. It might be worthwhile to give that one a go, and see if the fix was already committed to mainline:

http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.19-rc1/

Ryan Harper (raharper) wrote :

On Wed, Aug 29, 2018 at 12:01 PM Joseph Salisbury
<email address hidden> wrote:
>
> Thanks for digging up this additional information. I'll investigate
> further. While I do that, the v4.19-rc1 kernel is now out. It might be
> worthwhile to give that one a go, and see if the fix was already
> committed to mainline:
>
> http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.19-rc1/

v4.19 also hangs like 4.16+ does, but does not oops like 4.15.

Joseph Salisbury (jsalisbury) wrote :

Thanks for testing. I was hoping a fix would be in 4.19, but I'll dig some more.

tags: added: kernel-da-key
removed: kernel-key
Joseph Salisbury (jsalisbury) wrote :

The 4.20 kernel is now available. Can you give v4.20-rc3 a test:

http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.20-rc3

Ryan Harper (raharper) wrote :

4.20-rc3 also fails.

Successful runs: 95
root@ubuntu:~# [ 484.565298] INFO: task kworker/3:206:2091 blocked for more than 120 seconds.
[ 484.566976] Not tainted 4.20.0-042000rc3-generic #201811182231
[ 484.568069] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 484.569579] INFO: task bcache_allocato:16294 blocked for more than 120 seconds.
[ 484.571275] Not tainted 4.20.0-042000rc3-generic #201811182231
[ 484.572300] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Joseph Salisbury (jsalisbury) wrote :

I built a new Bionic test kernel. The test kernel can be downloaded from:
http://kernel.ubuntu.com/~jsalisbury/lp1784665

Can you test this kernel and see if it resolves this bug?

Note about installing test kernels:
• If the test kernel is prior to 4.15(Bionic) you need to install the linux-image and linux-image-extra .deb packages.
• If the test kernel is 4.15(Bionic) or newer, you need to install the linux-modules, linux-modules-extra and linux-image-unsigned .deb packages.

Thanks in advance!

Ryan Harper (raharper) wrote :

The 4.15.0-39 kernel FAILs:

+ make-bcache -C /dev/sdb
Can't open dev /dev/sdb: Device or resource busy
+ exit 1
Successful runs: 24
root@ubuntu:~# [ 242.655013] INFO: task kworker/3:103:2610 blocked for more than 120 seconds.
[ 242.665486] Not tainted 4.15.0-39-generic #43~lp1784665
[ 242.672393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.682480] INFO: task bcache_allocato:5864 blocked for more than 120 seconds.
[ 242.698149] Not tainted 4.15.0-39-generic #43~lp1784665
[ 242.705883] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Joseph Salisbury (jsalisbury) wrote :

Can you confirm that v4.15-rc6 does not exhibit the bug? That will ensure I'm reviewing the correct commits:

http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.15-rc6/

Ryan Harper (raharper) wrote :
Download full text (3.3 KiB)

It took a while, but v4.15-rc6 fails; so we need to move back a bit.

[ 2541.139904] bcache: bcache_device_free() bcache0 stopped
[ 2541.141848] BUG: unable to handle kernel NULL pointer dereference
at 0000000000000d38
[ 2541.143813] IP: search_free+0ex01-b6435-e1/5f0x40 [bcache]
[ 2541.145676] PGD 0 P4D 0
[ 2541.146493] Oops: 0000 [#58] SMP
[ 2541.147509] Modules linked in: bcache nls_utf8 isofs nls_iso8859_1
ppdev kvm_intel kvm irqbypass joydev input_leds parport_pc parport
mac_hid serio_raw sch_fq_codel ib_iser rdma_cm iw_cm ib_cm ib_core
iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi virtio_rng
ip_tables x_tables autofs4 btrfs zstd_compress raid10 raid456
async_raid6_recov async_memcpy async_pq async_xor async_tx xor
raid6_pq libcrc32c raid1 raid0 multipath linear psmouse virtio_net
virtio_scsi virtio_blk i2c_piix4 pata_acpi floppy
[ 2541.154248] CPU: 3 PID: 13332 Comm: kworker/3:200 Tainted: G D
         4.15.0-041500rc6-generic #201712312330
[ 2541.156921] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 2541.159381] Workqueue: bcache bch_data_insert_keys [bcache]
[ 2541.160566] RIP: 0010:search_free+0x31/0x40 [bcache]
[ 2541.161300] RSP: 0018:ffffb04e45b6bdf8 EFLAGS: 00010282
[ 2541.162098] RAX: 0000000000000000 RBX: ffff942c22b3b390 RCX: 0000000180100006
[ 2541.163791] RDX: 0000000180100007 RSI: ffffded4c086a7c0 RDI: ffff942c22b3b390
[ 2541.165486] RBP: ffffb04e45b6be00 R08: ffff942c21a9fc00 R09: 0000000180100006
[ 2541.167191] R10: ffffb04e45b6bd70 R11: ffff942c3ffb4000 R12: ffff942c39610010
[ 2541.168897] R13: ffff942c22b3b518 R14: ffff942c3fda3080 R15: ffff942c26b526c0
[ 2541.170637] FS: 0000000000000000(0000) GS:ffff942c3fd80000(0000)
knlGS:0000000000000000
[ 2541.172574] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2541.174043] CR2: 0000000000000d38 CR3: 0000000011409000 CR4: 00000000000006e0
[ 2541.175847] Call Trace:
[ 2541.176349] cached_dev_cache_miss_done+0x38/0x80 [bcache]
[ 2541.177131] closure_put+0x8b/0xc0 [bcache]
[ 2541.177791] closure_sub+0x6f/0xc0 [bcache]
[ 2541.178924] bch_data_insert_keys+0xd8/0x130 [bcache]
[ 2541.180107] process_one_work+0x1ea/0x410
[ 2541.181176] worker_thread+0x32/0x410
[ 2541.182157] kthread+0x11e/0x140
[ 2541.183043] ? process_one_work+0x410/0x410
[ 2541.184154] ? kthread_create_worker_on_cpu+0x70/0x70
[ 2541.185460] ret_from_fork+0x1f/0x30
[ 2541.186397] Code: 48 89 e5 53 48 89 fb e8 0e ff ff ff 48 8b bb 68
01 00 00 48 85 ff 74 05 e8 cd 0b d0 f5 48 8b 83 e8 00 00 00 48 89 df
48 8b 40 70 <48> 8b b0 38 0d 00 00 e8 c3 18 a9 f5 5b 5d c3 0f 1f 44 00
00 55
[ 2541.189920] RIP: search_free+0x31/0x40 [bcache] RSP: ffffb04e45b6bdf8
[ 2541.191636] CR2: 0000000000000d38
[ 2541.192503] ---[ end trace e2b7818e7472ac25 ]---
On Mon, Nov 26, 2018 at 8:26 PM Joseph Salisbury
<email address hidden> wrote:

>
> Can you confirm that v4.15-rc6 does not exhibit the bug? That will
> ensure I'm reviewing the correct commits:
>
> http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.15-rc6/
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1784665
>
> Title:
> ...

Read more...

Ryan Harper (raharper) wrote :
Download full text (3.7 KiB)

I also tested v4.15-rc5, which failed with the same stack trace. Then I returned to 4.14 mainline, and got this one:

[ 953.659489] BUG: unable to handle kernel NULL pointer dereference at
0000000000000d40
[ 953.668707] IP: search_free+0x31/0x40 [bcache]
[ 953.674872] PGD 0 P4D 0
[ 953.677680] Oops: 0000 [#34] SMP
[ 953.678796] Modules linked in: nls_utf8 isofs nls_iso8859_1 ppdev kvm_intel
kvm irqbypass parport_pc joydev input_leds parport serio_raw mac_hid
sch_fq_codel ib_iser rdma_cm iw_cm ib_cm ib_core iscsi_tcp libiscsi_tcp libiscsi
scsi_transport_iscsi virtio_rng ip_tables x_tables autofs4 btrfs zstd_compress
raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor
raid6_pq libcrc32c raid1 raid0 multipath linear bcache psmouse virtio_scsi
virtio_blk virtio_net i2c_piix4 floppy pata_acpi
[ 953.700549] CPU: 1 PID: 3132 Comm: kworker/1:229 Tainted: G D
4.14.0-041400-generic #201711122031
[ 953.704522] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 953.707128] Workqueue: bcache bch_data_insert_keys [bcache]
[ 953.708986] task: ffff985fe6050000 task.stack: ffffc01402c4c000
[ 953.711147] RIP: 0010:search_free+0x31/0x40 [bcache]
[ 953.712997] RSP: 0018:ffffc01402c4fdf8 EFLAGS: 00010282
[ 953.714287] RAX: 0000000000000000 RBX: ffff985ffb385e78 RCX: ffffe83580d58e00
[ 953.716883] RDX: 0000000000000007 RSI: 000000000001f540 RDI: ffff985ffb385e78
[ 953.718731] RBP: ffffc01402c4fe00 R08: ffff985ff8121800 R09: 000000018010000f
[ 953.720269] R10: ffffc01402c4fd70 R11: 0000000000000001 R12: ffff985fe3670010
[ 953.721583] R13: ffff985ffb386000 R14: ffff985fffc9bb40 R15: ffff985ff83eab40
[ 953.723315] FS: 0000000000000000(0000) GS:ffff985fffc80000(0000)
knlGS:0000000000000000
[ 953.725738] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 953.727401] CR2: 0000000000000d40 CR3: 0000000028c09000 CR4: 00000000000006e0
[ 953.729737] Call Trace:
[ 953.730687] cached_dev_cache_miss_done+0x38/0x80 [bcache]
[ 953.732939] closure_put+0x8b/0xc0 [bcache]
[ 953.734647] closure_sub+0x6f/0xc0 [bcache]
[ 953.736104] bch_data_insert_keys+0xd8/0x130 [bcache]
[ 953.737311] process_one_work+0x1e7/0x410
[ 953.738233] worker_thread+0x32/0x410
[ 953.739246] kthread+0x125/0x140
[ 953.740231] ? process_one_work+0x410/0x410
[ 953.741407] ? kthread_create_on_node+0x70/0x70
[ 953.742631] ...

Read more...

Ryan Harper (raharper) wrote :

v4.13 shows the same search_free stack as 4.14, but doesn't appear to be fatal (it doesn't result in a hung process nor a block device that cannot be wiped.

I suspect we've got a new upstream issue since 4.20 didn't fix things. Re-running 4.20 to see if we had a stack trace, we don't NULL pointer oops, but there is a stuck worker queue:

[ 242.887966] kworker/0:47 D 0 2165 2 0x80000000
[ 242.888014] Workqueue: events cache_set_flush [bcache]
[ 242.888027] Call Trace:
[ 242.888084] __schedule+0x2a2/0x880
[ 242.888097] ? __switch_to+0xfc/0x4f0
[ 242.888105] schedule+0x2c/0x80
[ 242.888113] schedule_timeout+0x246/0x350
[ 242.888122] wait_for_completion+0xb7/0x140
[ 242.888141] ? wake_up_q+0x80/0x80
[ 242.888151] kthread_stop+0x49/0x110
[ 242.888176] cache_set_flush+0xdb/0x190 [bcache]
[ 242.888186] process_one_work+0x20f/0x410
[ 242.888194] worker_thread+0x34/0x400
[ 242.888202] kthread+0x120/0x140
[ 242.888209] ? process_one_work+0x410/0x410
[ 242.888216] ? kthread_park+0x90/0x90
[ 242.888236] ret_from_fork+0x35/0x40
[ 242.888435] INFO: task bcache_allocato:9015 blocked for more than 120 seconds.
[ 242.893786] Not tainted 4.20.0-042000rc3-generic #201811182231
[ 242.896669] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.900428] bcache_allocato D 0 9015 2 0x80000000
[ 242.900434] Call Trace:
[ 242.900448] __schedule+0x2a2/0x880
[ 242.900455] ? __schedule+0x2aa/0x880
[ 242.900462] schedule+0x2c/0x80
[ 242.900480] bch_bucket_alloc+0x19d/0x380 [bcache]
[ 242.900503] ? wait_woken+0x80/0x80
[ 242.900519] bch_prio_write+0x190/0x340 [bcache]
[ 242.900530] bch_allocator_thread+0x482/0xd10 [bcache]
[ 242.900535] kthread+0x120/0x140
[ 242.900546] ? bch_invalidate_one_bucket+0x80/0x80 [bcache]
[ 242.900549] ? kthread_park+0x90/0x90
[ 242.900554] ret_from_fork+0x35/0x40

Changed in linux (Ubuntu):
status: In Progress → Confirmed
Changed in linux (Ubuntu Bionic):
status: In Progress → Confirmed
Changed in linux (Ubuntu Cosmic):
status: In Progress → Confirmed
assignee: Joseph Salisbury (jsalisbury) → nobody
Changed in linux (Ubuntu Bionic):
assignee: Joseph Salisbury (jsalisbury) → nobody
Changed in linux (Ubuntu):
assignee: Joseph Salisbury (jsalisbury) → nobody
To post a comment you must log in.