Dear Linux folks,
On an IBM S822LC with Ubuntu 21.10, only when shutting down the system
there are I/O errors hanging the system. I was able to capture some
messages from the end:
```
[XXXXXXXXXXXX3] I/O error, dev sda, sector 1198060800 op 0x1:(WRITE)
flags 0x100000 phys_seg 1 prio class 0
[223109.260842] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 3, rd
0, flush 0, corrupt 0, gen 0
[223109.260878] sd 0:0:0:0: [sda] tag#15 timing out command, waited 180s
[223109.261026] I/O error, dev sda, sector 1198829952 op 0x1:(WRITE)
flags 0x104000 phys_seg 20 prio class 0
[223109.360562] sd 0:0:0:0: [sda] tag#28 timing out command, waited 180s
[223109.360615] I/O error, dev sda, sector 1198835072 op 0x1:(WRITE)
flags 0x100000 phys_seg 17 prio class 0
[223109.360757] sd 0:0:0:0: [sda] tag#29 timing out command, waited 180s
[223109.360778] I/O error, dev sda, sector 1198832512 op 0x1:(WRITE)
flags 0x104000 phys_seg 20 prio class 0
[223109.360798] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 4, rd
0, flush 0, corrupt 0, gen 0
[223179.108402] INFO: task kworker/0:2:651024 blocked for more than 120
seconds.
[223179.108481] Not tainted 5.17.0-rc3+ #1
[223179.108580] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[223179.109311] INFO: task kworker/u321:7:652803 blocked for more than
120 seconds.
[223179.109357] Not tainted 5.17.0-rc3+ #1
[223179.109370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[223289.259960] sd 0:0:0:0: [sda] tag#24 timing out command, waited 180s
[223289.260169] I/O error, dev sda, sector 1197961728 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[223289.260192] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 4, rd
1, flush 0, corrupt 0, gen 0
[223289.363952] sd 0:0:0:0: [sda] tag#13 timing out command, waited 180s
[223289.363958] sd 0:0:0:0: [sda] tag#16 timing out command, waited 180s
[223289.364152] I/O error, dev sda, sector 1064447232 op 0x1:(WRITE)
flags 0x4800 phys_seg 20 prio class 0
[223289.364176] I/O error, dev sda, sector 1198837504 op 0x1:(WRITE)
flags 0x100000 phys_seg 7 prio class 0
[223289.364182] sd 0:0:0:0: [sda] tag#14 timing out command, waited 180s
[223289.364198] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 5, rd
1, flush 0, corrupt 0, gen 0
[223289.364364] I/O error, dev sda, sector 1064444672 op 0x1:(WRITE)
flags 0x4800 phys_seg 20 prio class 0
[223289.364377] sd 0:0:0:0: [sda] tag#17 timing out command, waited 180s
[223289.364388] sd 0:0:0:0: [sda] tag#15 timing out command,
[228549.050771442,5] IPMI: Soft shutdown requested
waited 180s
[223289.364417] I/O error, dev sda, sector 1198838528 op 0x1:(WRITE)
flags 0x100000 phys_seg 2 prio class 0
[223289.364421] I/O error, dev sda, sector 1064452352 op 0x1:(WRITE)
flags 0x800 phys_seg 4 prio class 0
[223289.364438] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 6, rd
1, flush 0, corrupt 0, gen 0
[223289.364466] sd 0:0:0:0: [sda] tag#19 timing out command, waited 180s
[223289.364498] I/O error, dev sda, sector 1064449792 op 0x1:(WRITE)
flags 0x4800 phys_seg 20 prio class 0
[223289.364520] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 7, rd
1, flush 0, corrupt 0, gen 0
[223299.944147] INFO: task kworker/0:2:651024 blocked for more than 241
seconds.
[223299.944197] Not tainted 5.17.0-rc3+ #1
[223299.944327] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[223299.945059] INFO: task kworker/u321:7:652803 blocked for more than
241 seconds.
[223299.945105] Not tainted 5.17.0-rc3+ #1
[223299.945117] "echo 0 > /proc/sys/kernel/hun[228630.461459920,5] OPAL:
Shutdown request type 0x0...
g_task_timeout_secs" disables this message.
[223303.591904] sd 1:0:0:0: [sdb] tag#23 timing out command, waited 360s
[223303.592090] I/O error, dev sdb, sector 0 op 0x1:(WRITE) flags 0x800
phys_seg 0 prio class 0
[223420.771542] INFO: task kworker/35:2:1077 blocked for more than 120
seconds.
[223420.771680] Not tainted 5.17.0-rc3+ #1
[223420.771722] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[223469.263372] sd 0:0:0:0: [sda] tag#31 timing out command, waited 180s
[223469.263480] I/O error, dev sda, sector 1197961728 op 0x0:(READ)
flags 0x0 phys_seg 1 prio class 0
[223469.263600] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 7, rd
2, flush 0, corrupt 0, gen 0
[223469.367343] sd 0:0:0:0: [sda] tag#17 timing out command, waited 180s
[223469.367346] sd 0:0:0:0: [sda] tag#19 timing out command, waited 180s
[223469.367358] sd 0:0:0:0: [sda] tag#15 timing out command, waited 180s
[223469.367382] I/O error, dev sda, sector 1198836992 op 0x1:(WRITE)
flags 0x800 phys_seg 1 prio class 0
[223469.367390] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 8, rd
2, flush 0, corrupt 0, gen 0
[223469.367401] I/O error, dev sda, sector 1198839168 op 0x1:(WRITE)
flags 0x100000 phys_seg 1 prio class 0
[223469.367406] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 9, rd
2, flush 0, corrupt 0, gen 0
[223469.367433] sd 0:0:0:0: [sda] tag#18 timing out command, waited 180s
[223469.367442] I/O error, dev sda, sector 1198839424 op 0x1:(WRITE)
flags 0x100000 phys_seg 6 prio class 0
[223469.367445] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 10,
rd 2, flush 0, corrupt 0, gen 0
[223469.367585] sd 0:0:0:0: [sda] tag#16 timing out command, waited 180s
[223469.367637] I/O error, dev sda, sector 480640 op 0x1:(WRITE) flags
0x1800 phys_seg 1 prio class 0
[223469.367670] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 11,
rd 2, flush 0, corrupt 0, gen 0
[223469.367690] I/O error, dev sda, sector 1198834816 op 0x1:(WRITE)
flags 0x800 phys_seg 1 prio class 0
[223469.367798] sd 0:0:0:0: [sda] tag#20 timing out command, waited 180s
[223469.367845] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 12,
rd 2, flush 0, corrupt 0, gen 0
[223469.367888] sd 0:0:0:0: [sda] tag#21 timing out command, waited 180s
[223469.367929] I/O error, dev sda, sector 2577792 op 0x1:(WRITE) flags
0x1800 phys_seg 1 prio class 0
[223469.367949] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 13,
rd 2, flush 0, corrupt 0, gen 0
[223469.367949] I/O error, dev sda, sector 1198838272 op 0x1:(WRITE)
flags 0x800 phys_seg 1 prio class 0
[223469.367989] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 14,
rd 2, flush 0, corrupt 0, gen 0
[223469.368018] sd 0:0:0:0: [sda] tag#22 timing out command, waited 180s
[223469.368046] I/O error, dev sda, sector 1198831360 op 0x1:(WRITE)
flags 0x800 phys_seg 1 prio class 0
[223469.368069] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 15,
rd 2, flush 0, corrupt 0, gen 0
[223469.368105] sd 0:0:0:0: [sda] tag#23 timing out command, waited 180s
[223469.368132] I/O error, dev sda, sector 1198060800 op 0x1:(WRITE)
flags 0x800 phys_seg 1 prio class 0
[223469.368156] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 16,
rd 2, flush 0, corrupt 0, gen 0
[223469.380930] reboot: Power down
```
I had to power down the system manually. There are no messages when
booting (and mounting) the HDD, which is the system drive.
Checking the partition, checking the free space cache returns some failures:
```
$ btrfs version
btrfs-progs v5.10.1
$ sudo btrfs check --readonly --force /dev/sda2
Opening filesystem to check...
WARNING: filesystem mounted, continuing because of --force
Checking filesystem on /dev/sda2
UUID: 2c3dd738-785a-469b-843e-9f0ba8b47b0d
[1/7] checking root items
[2/7] checking extents
[3/7] checking free space cache
btrfs: space cache generation (4119788) does not match inode (4119782)
failed to load free space cache for block group 29360128
btrfs: space cache generation (4119788) does not match inode (4119775)
failed to load free space cache for block group 741448089600
btrfs: space cache generation (4119786) does not match inode (4119782)
failed to load free space cache for block group 751111766016
btrfs: space cache generation (4119788) does not match inode (4119782)
failed to load free space cache for block group 795135180800
btrfs: space cache generation (4119788) does not match inode (4119782)
failed to load free space cache for block group 796208922624
btrfs: space cache generation (4119788) does not match inode (4119782)
failed to load free space cache for block group 803725115392
btrfs: space cache generation (4119788) does not match inode (4119782)
failed to load free space cache for block group 804798857216
btrfs: space cache generation (4119788) does not match inode (4119782)
failed to load free space cache for block group 808020082688
btrfs: space cache generation (4119788) does not match inode (4119782)
failed to load free space cache for block group 811241308160
[4/7] checking fs roots
[5/7] checking only csums items (without verifying data)
[6/7] checking root refs
[7/7] checking quota groups skipped (not enabled on this FS)
found 604326461440 bytes used, no error found
total csum bytes: 35109100
total tree bytes: 7996112896
total fs tree bytes: 7701987328
total extent tree bytes: 231276544
btree space waste bytes: 1615676149
file data blocks allocated: 818525175808
referenced 724324974592
```
Is that related? Is there a way to fix the system partition during
runtime? (Otherwise I’d need to boot some live system or take the drive
out.)
Kind regards,
Paul
PS: No idea, if useful:
```
$ sudo btrfs filesystem usage /
Overall:
Device size: 931.50GiB
Device allocated: 565.02GiB
Device unallocated: 366.48GiB
Device missing: 0.00B
Used: 560.86GiB
Free (estimated): 368.39GiB (min: 185.15GiB)
Free (statfs, df): 368.39GiB
Data ratio: 1.00
Metadata ratio: 2.00
Global reserve: 275.81MiB (used: 0.00B)
Multiple profiles: no
Data,single: Size:548.01GiB, Used:546.10GiB (99.65%)
/dev/sda2 548.01GiB
Metadata,DUP: Size:8.50GiB, Used:7.38GiB (86.86%)
/dev/sda2 17.00GiB
System,DUP: Size:8.00MiB, Used:64.00KiB (0.78%)
/dev/sda2 16.00MiB
Unallocated:
/dev/sda2 366.48GiB
$ sudo btrfs filesystem df /
Data, single: total=548.01GiB, used=546.10GiB
System, DUP: total=8.00MiB, used=64.00KiB
Metadata, DUP: total=8.50GiB, used=7.38GiB
GlobalReserve, single: total=275.81MiB, used=0.00B
```
On Mon, Feb 14, 2022 at 10:11:18AM +0100, Paul Menzel wrote:
> Dear Linux folks,
>
>
> On an IBM S822LC with Ubuntu 21.10, only when shutting down the system there
> are I/O errors hanging the system. I was able to capture some messages from
> the end:
>
> ```
> [XXXXXXXXXXXX3] I/O error, dev sda, sector 1198060800 op 0x1:(WRITE) flags
> 0x100000 phys_seg 1 prio class 0
> [223109.260842] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 3, rd 0,
> flush 0, corrupt 0, gen 0
> [223109.260878] sd 0:0:0:0: [sda] tag#15 timing out command, waited 180s
> [223109.261026] I/O error, dev sda, sector 1198829952 op 0x1:(WRITE) flags
> 0x104000 phys_seg 20 prio class 0
> [223109.360562] sd 0:0:0:0: [sda] tag#28 timing out command, waited 180s
> [223109.360615] I/O error, dev sda, sector 1198835072 op 0x1:(WRITE) flags
> 0x100000 phys_seg 17 prio class 0
> [223109.360757] sd 0:0:0:0: [sda] tag#29 timing out command, waited 180s
> [223109.360778] I/O error, dev sda, sector 1198832512 op 0x1:(WRITE) flags
> 0x104000 phys_seg 20 prio class 0
> [223109.360798] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 4, rd 0,
> flush 0, corrupt 0, gen 0
> [223179.108402] INFO: task kworker/0:2:651024 blocked for more than 120
> seconds.
> [223179.108481] Not tainted 5.17.0-rc3+ #1
> [223179.108580] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [223179.109311] INFO: task kworker/u321:7:652803 blocked for more than 120
> seconds.
> [223179.109357] Not tainted 5.17.0-rc3+ #1
> [223179.109370] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [223289.259960] sd 0:0:0:0: [sda] tag#24 timing out command, waited 180s
> [223289.260169] I/O error, dev sda, sector 1197961728 op 0x0:(READ) flags
> 0x0 phys_seg 1 prio class 0
> [223289.260192] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 4, rd 1,
> flush 0, corrupt 0, gen 0
> [223289.363952] sd 0:0:0:0: [sda] tag#13 timing out command, waited 180s
> [223289.363958] sd 0:0:0:0: [sda] tag#16 timing out command, waited 180s
> [223289.364152] I/O error, dev sda, sector 1064447232 op 0x1:(WRITE) flags
> 0x4800 phys_seg 20 prio class 0
> [223289.364176] I/O error, dev sda, sector 1198837504 op 0x1:(WRITE) flags
> 0x100000 phys_seg 7 prio class 0
> [223289.364182] sd 0:0:0:0: [sda] tag#14 timing out command, waited 180s
> [223289.364198] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 5, rd 1,
> flush 0, corrupt 0, gen 0
> [223289.364364] I/O error, dev sda, sector 1064444672 op 0x1:(WRITE) flags
> 0x4800 phys_seg 20 prio class 0
> [223289.364377] sd 0:0:0:0: [sda] tag#17 timing out command, waited 180s
> [223289.364388] sd 0:0:0:0: [sda] tag#15 timing out command,
> [228549.050771442,5] IPMI: Soft shutdown requested
> waited 180s
> [223289.364417] I/O error, dev sda, sector 1198838528 op 0x1:(WRITE) flags
> 0x100000 phys_seg 2 prio class 0
> [223289.364421] I/O error, dev sda, sector 1064452352 op 0x1:(WRITE) flags
> 0x800 phys_seg 4 prio class 0
> [223289.364438] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 6, rd 1,
> flush 0, corrupt 0, gen 0
> [223289.364466] sd 0:0:0:0: [sda] tag#19 timing out command, waited 180s
> [223289.364498] I/O error, dev sda, sector 1064449792 op 0x1:(WRITE) flags
> 0x4800 phys_seg 20 prio class 0
> [223289.364520] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 7, rd 1,
> flush 0, corrupt 0, gen 0
> [223299.944147] INFO: task kworker/0:2:651024 blocked for more than 241
> seconds.
> [223299.944197] Not tainted 5.17.0-rc3+ #1
> [223299.944327] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [223299.945059] INFO: task kworker/u321:7:652803 blocked for more than 241
> seconds.
> [223299.945105] Not tainted 5.17.0-rc3+ #1
> [223299.945117] "echo 0 > /proc/sys/kernel/hun[228630.461459920,5] OPAL:
> Shutdown request type 0x0...
> g_task_timeout_secs" disables this message.
> [223303.591904] sd 1:0:0:0: [sdb] tag#23 timing out command, waited 360s
> [223303.592090] I/O error, dev sdb, sector 0 op 0x1:(WRITE) flags 0x800
> phys_seg 0 prio class 0
> [223420.771542] INFO: task kworker/35:2:1077 blocked for more than 120
> seconds.
> [223420.771680] Not tainted 5.17.0-rc3+ #1
> [223420.771722] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [223469.263372] sd 0:0:0:0: [sda] tag#31 timing out command, waited 180s
> [223469.263480] I/O error, dev sda, sector 1197961728 op 0x0:(READ) flags
> 0x0 phys_seg 1 prio class 0
> [223469.263600] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 7, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.367343] sd 0:0:0:0: [sda] tag#17 timing out command, waited 180s
> [223469.367346] sd 0:0:0:0: [sda] tag#19 timing out command, waited 180s
> [223469.367358] sd 0:0:0:0: [sda] tag#15 timing out command, waited 180s
> [223469.367382] I/O error, dev sda, sector 1198836992 op 0x1:(WRITE) flags
> 0x800 phys_seg 1 prio class 0
> [223469.367390] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 8, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.367401] I/O error, dev sda, sector 1198839168 op 0x1:(WRITE) flags
> 0x100000 phys_seg 1 prio class 0
> [223469.367406] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 9, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.367433] sd 0:0:0:0: [sda] tag#18 timing out command, waited 180s
> [223469.367442] I/O error, dev sda, sector 1198839424 op 0x1:(WRITE) flags
> 0x100000 phys_seg 6 prio class 0
> [223469.367445] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 10, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.367585] sd 0:0:0:0: [sda] tag#16 timing out command, waited 180s
> [223469.367637] I/O error, dev sda, sector 480640 op 0x1:(WRITE) flags
> 0x1800 phys_seg 1 prio class 0
> [223469.367670] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 11, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.367690] I/O error, dev sda, sector 1198834816 op 0x1:(WRITE) flags
> 0x800 phys_seg 1 prio class 0
> [223469.367798] sd 0:0:0:0: [sda] tag#20 timing out command, waited 180s
> [223469.367845] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 12, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.367888] sd 0:0:0:0: [sda] tag#21 timing out command, waited 180s
> [223469.367929] I/O error, dev sda, sector 2577792 op 0x1:(WRITE) flags
> 0x1800 phys_seg 1 prio class 0
> [223469.367949] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 13, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.367949] I/O error, dev sda, sector 1198838272 op 0x1:(WRITE) flags
> 0x800 phys_seg 1 prio class 0
> [223469.367989] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 14, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.368018] sd 0:0:0:0: [sda] tag#22 timing out command, waited 180s
> [223469.368046] I/O error, dev sda, sector 1198831360 op 0x1:(WRITE) flags
> 0x800 phys_seg 1 prio class 0
> [223469.368069] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 15, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.368105] sd 0:0:0:0: [sda] tag#23 timing out command, waited 180s
> [223469.368132] I/O error, dev sda, sector 1198060800 op 0x1:(WRITE) flags
> 0x800 phys_seg 1 prio class 0
> [223469.368156] BTRFS error (device sda2): bdev /dev/sda2 errs: wr 16, rd 2,
> flush 0, corrupt 0, gen 0
> [223469.380930] reboot: Power down
> ```
>
> I had to power down the system manually. There are no messages when booting
> (and mounting) the HDD, which is the system drive.
>
> Checking the partition, checking the free space cache returns some failures:
>
> ```
> $ btrfs version
> btrfs-progs v5.10.1
> $ sudo btrfs check --readonly --force /dev/sda2
> Opening filesystem to check...
> WARNING: filesystem mounted, continuing because of --force
> Checking filesystem on /dev/sda2
> UUID: 2c3dd738-785a-469b-843e-9f0ba8b47b0d
> [1/7] checking root items
> [2/7] checking extents
> [3/7] checking free space cache
> btrfs: space cache generation (4119788) does not match inode (4119782)
> failed to load free space cache for block group 29360128
> btrfs: space cache generation (4119788) does not match inode (4119775)
> failed to load free space cache for block group 741448089600
> btrfs: space cache generation (4119786) does not match inode (4119782)
> failed to load free space cache for block group 751111766016
> btrfs: space cache generation (4119788) does not match inode (4119782)
> failed to load free space cache for block group 795135180800
> btrfs: space cache generation (4119788) does not match inode (4119782)
> failed to load free space cache for block group 796208922624
> btrfs: space cache generation (4119788) does not match inode (4119782)
> failed to load free space cache for block group 803725115392
> btrfs: space cache generation (4119788) does not match inode (4119782)
> failed to load free space cache for block group 804798857216
> btrfs: space cache generation (4119788) does not match inode (4119782)
> failed to load free space cache for block group 808020082688
> btrfs: space cache generation (4119788) does not match inode (4119782)
> failed to load free space cache for block group 811241308160
> [4/7] checking fs roots
> [5/7] checking only csums items (without verifying data)
> [6/7] checking root refs
> [7/7] checking quota groups skipped (not enabled on this FS)
> found 604326461440 bytes used, no error found
> total csum bytes: 35109100
> total tree bytes: 7996112896
> total fs tree bytes: 7701987328
> total extent tree bytes: 231276544
> btree space waste bytes: 1615676149
> file data blocks allocated: 818525175808
> referenced 724324974592
> ```
>
> Is that related? Is there a way to fix the system partition during runtime?
> (Otherwise I’d need to boot some live system or take the drive out.)
>
These messages are just informational, so you know it's going to throw out the
free space cache and re-create it from the extent tree. These are common if
there's an unclean shutdown. Just as a general recommendation I'd suggest
switching to -o space_cache=v2, which is the new default and better for
performance in general.
That being said the disk is having trouble, I'd replace it. The fs is fine so
you should be good to get everything off of it. Thanks,
Josef