Linux: Network driver on RPi3 B Plus causing hung tasks when working on an NFS mount
Platform/Distro: RPi 3B+ running Arch ARM (armv7h).
Kernel version: 4.14.31 (https://github.com/raspberrypi/linux/commit/b36f4e9e198477803d29861e02d3ea00fe5e09ab)
Firmware version: latest as I write this (https://github.com/raspberrypi/firmware/commit/c14a90333c13f507ab219d583b74a998ec11a6e7)
Bug: Frequent kernel oops due to blocked tasks when writing files to NFS mount.
Details: When compiling, dmesg is full of kernel oops like the below when doing so on an NFS mount. Compiling to the micro SD card is fine. I believe that the software (disto) on the micro SD card is NOT to blame... if I put the same micro SD card into a RPi3 or RPi2, I can compile without error.
Again, I am using an NFS mounted partition (/scratch) on which to compile, so I'm hypothesizing that these problems are related to the network driver.
% dmesg
...
[ 2455.534291] INFO: task ld:24879 blocked for more than 120 seconds.
[ 2455.538489] Tainted: G C 4.14.31-1-ARCH #1
[ 2455.542688] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2455.550990] ld D 0 24879 24804 0x00000000
[ 2455.555379] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 2455.559662] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 2455.563990] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 2455.572326] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 2455.580865] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 2455.589272] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 2455.597837] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 2455.606295] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 2455.610675] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 2455.614999] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 2547.695051] nfs: server ease not responding, still trying
[ 2548.735626] nfs: server ease not responding, still trying
[ 2548.768826] nfs: server ease OK
[ 2548.796748] nfs: server ease OK
[ 2701.296329] INFO: task ld:24879 blocked for more than 120 seconds.
[ 2701.300214] Tainted: G C 4.14.31-1-ARCH #1
[ 2701.304061] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2701.311642] ld D 0 24879 24804 0x00000000
[ 2701.315536] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 2701.319458] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 2701.323355] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 2701.330878] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 2701.338447] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 2701.345916] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 2701.353469] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 2701.360953] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 2701.364740] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 2701.368593] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 2772.976750] nfs: server ease not responding, still trying
[ 2774.331264] nfs: server ease OK
[ 2947.057892] INFO: task ld:24879 blocked for more than 120 seconds.
[ 2947.061907] Tainted: G C 4.14.31-1-ARCH #1
[ 2947.066031] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 2947.074107] ld D 0 24879 24804 0x00000000
[ 2947.078244] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 2947.081483] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 2947.084348] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 2947.090033] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 2947.095898] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 2947.101751] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 2947.107513] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 2947.113352] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 2947.116350] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 2947.119289] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 2998.258064] nfs: server ease not responding, still trying
[ 2999.352463] nfs: server ease OK
[ 3192.819075] INFO: task ld:24879 blocked for more than 120 seconds.
[ 3192.823185] Tainted: G C 4.14.31-1-ARCH #1
[ 3192.827330] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3192.835447] ld D 0 24879 24804 0x00000000
[ 3192.839604] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 3192.842832] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 3192.845750] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 3192.851476] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 3192.857318] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 3192.863126] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 3192.868837] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 3192.874594] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 3192.877558] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 3192.880466] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 3223.539141] nfs: server ease not responding, still trying
[ 3224.579687] nfs: server ease not responding, still trying
[ 3224.612015] nfs: server ease OK
[ 3224.626000] nfs: server ease OK
[ 3438.580109] INFO: task objcopy:24916 blocked for more than 120 seconds.
[ 3438.583905] Tainted: G C 4.14.31-1-ARCH #1
[ 3438.587697] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3438.595231] objcopy D 0 24916 24912 0x00000000
[ 3438.599109] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 3438.603019] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 3438.606896] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 3438.614435] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 3438.622018] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 3438.629666] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 3438.637259] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 3438.644894] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 3438.648704] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 3438.652599] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 3448.820081] nfs: server ease not responding, still trying
[ 3450.148878] nfs: server ease OK
[ 3674.100906] nfs: server ease not responding, still trying
[ 3675.141506] nfs: server ease not responding, still trying
[ 3675.174279] nfs: server ease OK
[ 3675.202048] nfs: server ease OK
[ 3807.221430] INFO: task objcopy:24916 blocked for more than 120 seconds.
[ 3807.225253] Tainted: G C 4.14.31-1-ARCH #1
[ 3807.229007] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3807.236459] objcopy D 0 24916 24912 0x00000000
[ 3807.240428] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 3807.244393] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 3807.248202] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 3807.255540] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 3807.263030] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 3807.270494] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 3807.277992] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 3807.285364] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 3807.289292] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 3807.293169] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 3899.381659] nfs: server ease not responding, still trying
[ 3900.422241] nfs: server ease not responding, still trying
[ 3900.461112] nfs: server ease OK
[ 3900.474540] nfs: server ease OK
[ 4011.372575] nf_conntrack: default automatic helper assignment has been turned off for security reasons and CT-based firewall rule not found. Use the iptables CT target to attach helpers instead.
[ 4052.982250] INFO: task as:25088 blocked for more than 120 seconds.
[ 4052.986324] Tainted: G C 4.14.31-1-ARCH #1
[ 4052.990389] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4052.998504] as D 0 25088 25086 0x00000000
[ 4053.002785] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4053.006065] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4053.008960] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4053.014564] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4053.020330] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 4053.026110] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 4053.031705] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 4053.037527] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 4053.040507] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 4053.043431] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4134.902727] nfs: server ease not responding, still trying
[ 4135.997194] nfs: server ease OK
[ 4529.145918] nfs: server ease not responding, still trying
[ 4529.145923] nfs: server ease not responding, still trying
[ 4529.145940] nfs: server ease not responding, still trying
[ 4529.145978] nfs: server ease not responding, still trying
[ 4529.146011] nfs: server ease not responding, still trying
[ 4529.146028] nfs: server ease not responding, still trying
[ 4529.146044] nfs: server ease not responding, still trying
[ 4538.105971] nfs: server ease not responding, still trying
[ 4538.109131] nfs: server ease not responding, still trying
[ 4544.506128] INFO: task gcc:2854 blocked for more than 120 seconds.
[ 4544.509193] Tainted: G C 4.14.31-1-ARCH #1
[ 4544.512157] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4544.517957] gcc D 0 2854 2852 0x00000000
[ 4544.520871] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4544.523830] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4544.526762] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4544.530980] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4544.534883] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 4544.538880] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 4544.542873] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 4544.546949] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 4544.549173] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 4544.551445] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4571.406855] nfs: server ease OK
[ 4571.406996] nfs: server ease OK
[ 4571.407031] nfs: server ease OK
[ 4571.407691] nfs: server ease OK
[ 4571.407701] nfs: server ease OK
[ 4571.410844] nfs: server ease OK
[ 4571.410877] nfs: server ease OK
[ 4571.411761] nfs: server ease OK
[ 4571.411810] nfs: server ease OK
[ 4790.267644] INFO: task ld:7630 blocked for more than 120 seconds.
[ 4790.270597] Tainted: G C 4.14.31-1-ARCH #1
[ 4790.273588] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4790.279563] ld D 0 7630 7628 0x00000000
[ 4790.282558] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4790.285531] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4790.288488] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4790.294136] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4790.299855] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 4790.305556] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 4790.311366] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 4790.317112] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 4790.320380] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 4790.323699] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4790.330500] INFO: task ld:7636 blocked for more than 120 seconds.
[ 4790.334181] Tainted: G C 4.14.31-1-ARCH #1
[ 4790.338097] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4790.346223] ld D 0 7636 7633 0x00000000
[ 4790.350304] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4790.354463] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4790.358593] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4790.366494] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4790.374744] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 4790.383021] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 4790.391236] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 4790.399371] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 4790.403607] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 4790.407831] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
graysky2
All 113 comments
An easy way to trigger this bug (if you don't want to try compiling the kernel package) is to simply use dd to write out from /dev/zero to the NFS mount. For example on my RPi3 B+:
# mount ease:/scratch /scratch-nfs
% dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=1000 status=progress
964689920 bytes (965 MB, 920 MiB) copied, 149 s, 6.5 MB/s
<<< it froze up after about 965 MB written >>>
<<< In dmesg I get another server not responding error >>>
[ 5112.824818] nfs: server ease not responding, still trying
[ 5149.707808] nfs: server ease OK
Now, if I swap out the micro SD and boot into a RPi 2 I have lying around, same network cable, same power supply, and repeat the commands, everything works as expected. I think that helps to rule out the NFS server, network hardware etc. as potentially to blame.
# mount ease:/scratch /scratch-nfs
% dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=1000 status=progress
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 346 s, 12.1 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 357.595 s, 11.7 MB/s
dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=1000 status=progress 0.00s user 24.47s system 5% cpu 8:03.99 total
Does disabling Energy Efficient Ethernet make a difference? Add dtparam=eee=off to config.txt and reboot.
But before trying that you can confirm whether EEE is active using ethtool --show-eee eth0.
pelwell
on 30 Mar 2018
Great suggestion, @pelwell. I got some very encouraging results using the dd test which floods the I/O with a steady stream of data. It "passed" meaning no timeouts writing and no server not responding messages via dmesg. I am compiling the same package that consistently gives the errors now and will post back with those results.
Before:
# ethtool --show-eee eth0
EEE Settings for eth0:
EEE status: enabled - active
...
After:
# ethtool --show-eee eth0
EEE Settings for eth0:
EEE status: disabled
...
The test with dd:
# mount ease:/scratch /scratch-nfs
% dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=1000 status=progress && rm fill
4169138176 bytes (4.2 GB, 3.9 GiB) copied, 97 s, 42.9 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 100.665 s, 41.7 MB/s
dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=1000 status=progress 0.00s user 13.79s system 13% cpu 1:40.68 total
% dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=2000 status=progress && rm fill
8380219392 bytes (8.4 GB, 7.8 GiB) copied, 198 s, 42.3 MB/s
2000+0 records in
2000+0 records out
8388608000 bytes (8.4 GB, 7.8 GiB) copied, 201.245 s, 41.7 MB/s
dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=2000 status=progress 0.00s user 27.98s system 13% cpu 3:21.25 total
% dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=2000 status=progress && rm fill
8380219392 bytes (8.4 GB, 7.8 GiB) copied, 198 s, 42.3 MB/s
2000+0 records in
2000+0 records out
8388608000 bytes (8.4 GB, 7.8 GiB) copied, 201.052 s, 41.7 MB/s
dd if=/dev/zero of=/scratch-nfs/fill bs=4M count=2000 status=progress 0.00s user 28.23s system 13% cpu 3:22.19 total
Unfortunately, when compiling which as you can reconize, writes out data must less frequently than dd does, I am experiencing the same errors:
[ 3315.685473] INFO: task gzip:29769 blocked for more than 120 seconds.
[ 3315.685636] Tainted: G C 4.14.31-1-ARCH #1
[ 3315.685767] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3315.685955] gzip D 0 29769 29767 0x00000000
[ 3315.686127] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 3315.686299] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 3315.686473] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 3315.686663] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 3315.686875] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 3315.687121] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 3315.687349] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 3315.687529] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 3315.691478] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 3315.695540] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 3402.725251] nfs: server ease not responding, still trying
[ 3403.765783] nfs: server ease not responding, still trying
[ 3404.089089] nfs: server ease OK
[ 3404.089297] nfs: server ease OK
[ 3899.364008] nfs: server ease not responding, still trying
[ 3899.364013] nfs: server ease not responding, still trying
[ 3899.364028] nfs: server ease not responding, still trying
[ 3899.364060] nfs: server ease not responding, still trying
[ 3899.364071] nfs: server ease not responding, still trying
[ 3899.364076] nfs: server ease not responding, still trying
[ 3930.084023] INFO: task ld:13616 blocked for more than 120 seconds.
[ 3930.087086] Tainted: G C 4.14.31-1-ARCH #1
[ 3930.090229] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3930.096312] ld D 0 13616 13612 0x00000000
[ 3930.099422] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 3930.102523] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 3930.105566] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 3930.111351] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 3930.117264] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 3930.123049] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 3930.129036] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 3930.135044] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 3930.138283] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 3930.141618] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 3941.625186] nfs: server ease OK
[ 3941.625295] nfs: server ease OK
[ 3941.625441] nfs: server ease OK
[ 3941.625829] nfs: server ease OK
[ 3941.635332] nfs: server ease OK
[ 3941.635549] nfs: server ease OK
[ 4170.727338] nfs: server ease not responding, still trying
[ 4170.727343] nfs: server ease not responding, still trying
[ 4170.727356] nfs: server ease not responding, still trying
[ 4170.727395] nfs: server ease not responding, still trying
[ 4170.727413] nfs: server ease not responding, still trying
[ 4170.727428] nfs: server ease not responding, still trying
[ 4170.727441] nfs: server ease not responding, still trying
[ 4170.727455] nfs: server ease not responding, still trying
[ 4170.727461] nfs: server ease not responding, still trying
[ 4170.727467] nfs: server ease not responding, still trying
[ 4175.847588] INFO: task gzip:22430 blocked for more than 120 seconds.
[ 4175.849590] Tainted: G C 4.14.31-1-ARCH #1
[ 4175.851594] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4175.855516] gzip D 0 22430 22391 0x00000000
[ 4175.857549] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4175.859576] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4175.861543] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4175.865280] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4175.869533] [<80230d0c>] (__filemap_fdatawait_range) from [<80230d70>] (filemap_fdatawait_range+0x18/0x28)
[ 4175.874352] [<80230d70>] (filemap_fdatawait_range) from [<802330f4>] (filemap_write_and_wait+0x58/0x7c)
[ 4175.879764] [<802330f4>] (filemap_write_and_wait) from [<803ea028>] (nfs_wb_all+0x14/0x15c)
[ 4175.885618] [<803ea028>] (nfs_wb_all) from [<803dd96c>] (nfs_setattr+0x280/0x2a4)
[ 4175.892223] [<803dd96c>] (nfs_setattr) from [<802bf8d4>] (notify_change+0x17c/0x410)
[ 4175.899511] [<802bf8d4>] (notify_change) from [<802d62fc>] (utimes_common+0xbc/0x188)
[ 4175.907605] [<802d62fc>] (utimes_common) from [<802d64c8>] (do_utimes+0x100/0x144)
[ 4175.916359] [<802d64c8>] (do_utimes) from [<802d6548>] (SyS_utimensat+0x3c/0xb0)
[ 4175.925462] [<802d6548>] (SyS_utimensat) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4175.934598] INFO: task cp:22444 blocked for more than 120 seconds.
[ 4175.939378] Tainted: G C 4.14.31-1-ARCH #1
[ 4175.944179] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4175.953867] cp D 0 22444 22422 0x00000000
[ 4175.958731] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4175.963485] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4175.968194] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4175.977469] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4175.986837] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[ 4175.996147] [<80233190>] (filemap_write_and_wait_range) from [<803db1c4>] (nfs_file_fsync+0x30/0x280)
[ 4176.005282] [<803db1c4>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[ 4176.014199] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[ 4176.018723] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[ 4176.023212] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4176.031736] INFO: task gzip:22446 blocked for more than 120 seconds.
[ 4176.036150] Tainted: G C 4.14.31-1-ARCH #1
[ 4176.040488] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4176.048923] gzip D 0 22446 22413 0x00000000
[ 4176.053120] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4176.057319] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4176.061492] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4176.069486] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4176.077824] [<80230d0c>] (__filemap_fdatawait_range) from [<80230d70>] (filemap_fdatawait_range+0x18/0x28)
[ 4176.086158] [<80230d70>] (filemap_fdatawait_range) from [<802330f4>] (filemap_write_and_wait+0x58/0x7c)
[ 4176.094434] [<802330f4>] (filemap_write_and_wait) from [<803ea028>] (nfs_wb_all+0x14/0x15c)
[ 4176.102722] [<803ea028>] (nfs_wb_all) from [<803dd96c>] (nfs_setattr+0x280/0x2a4)
[ 4176.111286] [<803dd96c>] (nfs_setattr) from [<802bf8d4>] (notify_change+0x17c/0x410)
[ 4176.119906] [<802bf8d4>] (notify_change) from [<802d62fc>] (utimes_common+0xbc/0x188)
[ 4176.128677] [<802d62fc>] (utimes_common) from [<802d64c8>] (do_utimes+0x100/0x144)
[ 4176.137604] [<802d64c8>] (do_utimes) from [<802d6548>] (SyS_utimensat+0x3c/0xb0)
[ 4176.146598] [<802d6548>] (SyS_utimensat) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4176.155652] INFO: task gzip:22448 blocked for more than 120 seconds.
[ 4176.160374] Tainted: G C 4.14.31-1-ARCH #1
[ 4176.165034] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4176.174526] gzip D 0 22448 22399 0x00000000
[ 4176.179330] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4176.183995] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4176.188703] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4176.197969] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4176.207204] [<80230d0c>] (__filemap_fdatawait_range) from [<80230d70>] (filemap_fdatawait_range+0x18/0x28)
[ 4176.216304] [<80230d70>] (filemap_fdatawait_range) from [<802330f4>] (filemap_write_and_wait+0x58/0x7c)
[ 4176.225376] [<802330f4>] (filemap_write_and_wait) from [<803ea028>] (nfs_wb_all+0x14/0x15c)
[ 4176.234297] [<803ea028>] (nfs_wb_all) from [<803dd96c>] (nfs_setattr+0x280/0x2a4)
[ 4176.243314] [<803dd96c>] (nfs_setattr) from [<802bf8d4>] (notify_change+0x17c/0x410)
[ 4176.252319] [<802bf8d4>] (notify_change) from [<802d62fc>] (utimes_common+0xbc/0x188)
[ 4176.261418] [<802d62fc>] (utimes_common) from [<802d64c8>] (do_utimes+0x100/0x144)
[ 4176.270386] [<802d64c8>] (do_utimes) from [<802d6548>] (SyS_utimensat+0x3c/0xb0)
[ 4176.279426] [<802d6548>] (SyS_utimensat) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4176.288484] INFO: task gzip:22449 blocked for more than 120 seconds.
[ 4176.293202] Tainted: G C 4.14.31-1-ARCH #1
[ 4176.297913] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4176.307420] gzip D 0 22449 22402 0x00000000
[ 4176.312234] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4176.316976] [<80a88018>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 4176.321712] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[ 4176.330930] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[ 4176.340209] [<80230d0c>] (__filemap_fdatawait_range) from [<80230d70>] (filemap_fdatawait_range+0x18/0x28)
[ 4176.349341] [<80230d70>] (filemap_fdatawait_range) from [<802330f4>] (filemap_write_and_wait+0x58/0x7c)
[ 4176.358392] [<802330f4>] (filemap_write_and_wait) from [<803ea028>] (nfs_wb_all+0x14/0x15c)
[ 4176.367284] [<803ea028>] (nfs_wb_all) from [<803dd96c>] (nfs_setattr+0x280/0x2a4)
[ 4176.376299] [<803dd96c>] (nfs_setattr) from [<802bf8d4>] (notify_change+0x17c/0x410)
[ 4176.385274] [<802bf8d4>] (notify_change) from [<802d62fc>] (utimes_common+0xbc/0x188)
[ 4176.394337] [<802d62fc>] (utimes_common) from [<802d64c8>] (do_utimes+0x100/0x144)
[ 4176.403276] [<802d64c8>] (do_utimes) from [<802d6548>] (SyS_utimensat+0x3c/0xb0)
[ 4176.412262] [<802d6548>] (SyS_utimensat) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4176.421295] INFO: task gzip:22452 blocked for more than 120 seconds.
[ 4176.425993] Tainted: G C 4.14.31-1-ARCH #1
[ 4176.430693] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4176.440149] gzip D 0 22452 22418 0x00000000
[ 4176.444909] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4176.449585] [<80a88018>] (schedule) from [<80a8b3d4>] (rwsem_down_write_failed+0x12c/0x278)
[ 4176.458924] [<80a8b3d4>] (rwsem_down_write_failed) from [<80a8a6f0>] (down_write+0x58/0x60)
[ 4176.468288] [<80a8a6f0>] (down_write) from [<802afc48>] (path_openat+0x3b0/0x1150)
[ 4176.477766] [<802afc48>] (path_openat) from [<802b1954>] (do_filp_open+0x6c/0xdc)
[ 4176.487122] [<802b1954>] (do_filp_open) from [<8029edc4>] (do_sys_open+0x168/0x20c)
[ 4176.496594] [<8029edc4>] (do_sys_open) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4176.505990] INFO: task mkdir:22457 blocked for more than 120 seconds.
[ 4176.510857] Tainted: G C 4.14.31-1-ARCH #1
[ 4176.515599] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4176.525022] mkdir D 0 22457 22453 0x00000000
[ 4176.529774] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4176.534358] [<80a88018>] (schedule) from [<80a8b3d4>] (rwsem_down_write_failed+0x12c/0x278)
[ 4176.543475] [<80a8b3d4>] (rwsem_down_write_failed) from [<80a8a6f0>] (down_write+0x58/0x60)
[ 4176.552568] [<80a8a6f0>] (down_write) from [<802b1118>] (filename_create+0x70/0x14c)
[ 4176.561851] [<802b1118>] (filename_create) from [<802b1d30>] (SyS_mkdirat+0x4c/0xec)
[ 4176.571295] [<802b1d30>] (SyS_mkdirat) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4176.580876] INFO: task mkdir:22458 blocked for more than 120 seconds.
[ 4176.585741] Tainted: G C 4.14.31-1-ARCH #1
[ 4176.590628] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 4176.600118] mkdir D 0 22458 22450 0x00000000
[ 4176.604882] [<80a87848>] (__schedule) from [<80a88018>] (schedule+0x3c/0xa0)
[ 4176.609664] [<80a88018>] (schedule) from [<80a8b3d4>] (rwsem_down_write_failed+0x12c/0x278)
[ 4176.618855] [<80a8b3d4>] (rwsem_down_write_failed) from [<80a8a6f0>] (down_write+0x58/0x60)
[ 4176.628053] [<80a8a6f0>] (down_write) from [<802b1118>] (filename_create+0x70/0x14c)
[ 4176.637238] [<802b1118>] (filename_create) from [<802b1d30>] (SyS_mkdirat+0x4c/0xec)
[ 4176.646634] [<802b1d30>] (SyS_mkdirat) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[ 4211.688544] nfs: server ease not responding, still trying
[ 4212.989190] nfs: server ease OK
[ 4212.989336] nfs: server ease OK
[ 4212.989372] nfs: server ease OK
[ 4212.992652] nfs: server ease OK
[ 4213.002084] nfs: server ease OK
[ 4213.002311] nfs: server ease OK
[ 4213.002416] nfs: server ease OK
[ 4213.017966] nfs: server ease OK
[ 4213.018012] nfs: server ease OK
[ 4213.018632] nfs: server ease OK
[ 4213.020006] nfs: server ease OK
[ 4401.133010] nfs: server ease not responding, still trying
[ 4401.133014] nfs: server ease not responding, still trying
[ 4401.133030] nfs: server ease not responding, still trying
[ 4401.133067] nfs: server ease not responding, still trying
[ 4401.133110] nfs: server ease not responding, still trying
[ 4401.133120] nfs: server ease not responding, still trying
[ 4401.133124] nfs: server ease not responding, still trying
[ 4401.133139] nfs: server ease not responding, still trying
[ 4401.133156] nfs: server ease not responding, still trying
[ 4401.133171] nfs: server ease not responding, still trying
[ 4401.133187] nfs: server ease not responding, still trying
[ 4401.133202] nfs: server ease not responding, still trying
[ 4401.133233] nfs: server ease not responding, still trying
[ 4401.133245] nfs: server ease not responding, still trying
[ 4401.133251] nfs: server ease not responding, still trying
[ 4443.397196] nfs: server ease OK
[ 4443.397213] nfs: server ease OK
[ 4443.397291] nfs: server ease OK
[ 4443.397316] nfs: server ease OK
[ 4443.397343] nfs: server ease OK
[ 4443.397410] nfs: server ease OK
[ 4443.397505] nfs: server ease OK
[ 4443.397580] nfs: server ease OK
[ 4443.397605] nfs: server ease OK
[ 4443.397714] nfs: server ease OK
[ 4443.399097] nfs: server ease OK
[ 4443.405096] nfs: server ease OK
[ 4443.405772] nfs: server ease OK
[ 4443.406117] nfs: server ease OK
[ 4443.406398] nfs: server ease OK
[ 4667.377155] nfs: server ease not responding, still trying
[ 4668.417708] nfs: server ease not responding, still trying
[ 4668.700017] nfs: server ease OK
[ 4668.700524] nfs: server ease OK
[ 4856.819062] nfs: server ease not responding, still trying
[ 4856.819067] nfs: server ease not responding, still trying
[ 4856.819082] nfs: server ease not responding, still trying
[ 4856.819130] nfs: server ease not responding, still trying
[ 4856.819135] nfs: server ease not responding, still trying
[ 4856.819142] nfs: server ease not responding, still trying
[ 4856.819154] nfs: server ease not responding, still trying
[ 4856.819174] nfs: server ease not responding, still trying
[ 4856.819188] nfs: server ease not responding, still trying
[ 4856.819209] nfs: server ease not responding, still trying
[ 4856.819216] nfs: server ease not responding, still trying
[ 4893.959982] nfs: server ease OK
[ 4893.960172] nfs: server ease OK
[ 4893.960210] nfs: server ease OK
[ 4893.960311] nfs: server ease OK
[ 4893.960640] nfs: server ease OK
[ 4893.960770] nfs: server ease OK
[ 4893.960780] nfs: server ease OK
[ 4893.961280] nfs: server ease OK
[ 4893.966452] nfs: server ease OK
[ 4893.967131] nfs: server ease OK
[ 4893.969369] nfs: server ease OK
[ 5123.060914] nfs: server ease not responding, still trying
[ 5124.101425] nfs: server ease not responding, still trying
[ 5124.376882] nfs: server ease OK
[ 5124.381100] nfs: server ease OK
[ 5353.461931] nfs: server ease not responding, still trying
[ 5354.784753] nfs: server ease OK
[ 5588.982673] nfs: server ease not responding, still trying
[ 5590.077559] nfs: server ease OK
[ 5814.263180] nfs: server ease not responding, still trying
[ 5815.303698] nfs: server ease not responding, still trying
[ 5815.334003] nfs: server ease OK
[ 5815.360538] nfs: server ease OK
[ 6044.663615] nfs: server ease not responding, still trying
[ 6045.721789] nfs: server ease OK
[ 6285.305546] nfs: server ease not responding, still trying
[ 6286.346054] nfs: server ease not responding, still trying
[ 6286.376999] nfs: server ease OK
[ 6286.403761] nfs: server ease OK
[ 6510.587277] nfs: server ease not responding, still trying
[ 6511.627865] nfs: server ease not responding, still trying
[ 6511.674761] nfs: server ease OK
[ 6511.686188] nfs: server ease OK
[ 6735.868562] nfs: server ease not responding, still trying
[ 6736.909076] nfs: server ease not responding, still trying
[ 6736.940771] nfs: server ease OK
[ 6736.967038] nfs: server ease OK
[ 6940.669438] nfs: server ease not responding, still trying
[ 6977.551872] nfs: server ease OK
I combined a few replies into one (above) and tried to make it it bit more concise. TL;DR version is that disabling EEE does not help.
graysky2
on 31 Mar 2018
If possible, and if it isn't already on, can you enable flow control on the switch port connected to the Pi?
pelwell
on 31 Mar 2018
@pelwell - All the wired connections go through an unmanaged switch. No settings to tweak :/
graysky2
on 31 Mar 2018
Bug: Frequent kernel oops due to blocked tasks when writing files to NFS mount.
I had similar issues on SAMBA mount. But currently I can not run tests again, because I sent back my Pi3B+.
IMO current revision of Pi3B+ has serious hardware issues and I don't believe that they can be solved via software (Finally, I never was able to play a video longer than 15mins without a Kodi crash, kernel Oops, or freeze)
@pelwell and co:
Which Pi3B+ (revision) are you currently using? Parts of 0-series or parts from current production line, which customers are using now.
I still can't believe that you guys never had such issues before
mkreisl
on 31 Mar 2018
Current production I believe. Although I don't think there have been
many/any changes since the prototypes.
It appears that the issues are erratic, and depend on the capabilities of
the network the device is attached to. We are trying to figure out the
exact circumstances. I suspect there are a number of issues being seen, as
often happens when a previously working driver suddenly because used by
250k extra people over a weekend, in all sorts of new and unpredictable
ways. I have high hopes there is a software solution to this, we've always
been able to find them in the past.
On 31 March 2018 at 19:29, Manfred Kreisl notifications@github.com wrote:
Bug: Frequent kernel oops due to blocked tasks when writing files to NFS
mount.I had similar issues on SAMBA mount. But currently I can not run tests
again, because I sent back my Pi3B+.IMO current revision of Pi3B+ has serious hardware issues and I don't
believe that they can be solved via software (Finally, I never was able to
play a video longer than 15mins without a Kodi crash, kernel Oops, or
freeze)@pelwell https://github.com/pelwell and co:
Which Pi3B+ (revision) are you currently using? Parts of 0-series or parts
from current production line, which customers are using now.I still can't believe that you guys never had such issues before
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/raspberrypi/linux/issues/2482#issuecomment-377713477,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ADqrHV52f7xwHg74CUm3wYPAGFDuyvYZks5tj8sFgaJpZM4TB_lw
.
--
James Hughes
Principal Software Engineer,
Raspberry Pi (Trading) Ltd
JamesH65
on 31 Mar 2018
Perso I back on pi 2b ...
(He boot faster with the same SD card...)
@mkreisl when your pi is back if work normally I send my pi too
Knoppix1
on 1 Apr 2018
+1 I am noticing this issue as well when reading off samba mount. Brand new RPI 3B+.
zmartell
on 4 Apr 2018
@pelwell - From @popcornmix's advice in https://github.com/raspberrypi/linux/issues/2442, I built:
- raspberrypi-firmware from https://github.com/raspberrypi/firmware/commit/0dff9ecc00d8114164bb9a73799793dad24d8593
- linux-raspberrypi from https://github.com/raspberrypi/linux/commit/b5b6bb9bdb5e62bc7dfc64b40bd833bffd971693
I automated that dd test I described above in a simple script that repeats the writing out of 1G worth of zero filled file over an NFS share 32 times. I then used histogram.py to compute the stats.
With the dtparam=eee=off parameter set in /boot/config.txt I got some consistent results:
% histogram.py -p < results_no_eee.csv
# NumSamples = 32; Min = 25.46; Max = 25.75
# Mean = 25.687864; Variance = 0.002705; SD = 0.052009; Median 25.693114
When I removed that line (reverting to the default state of it being on, 1 of the 32 runs was really long:
% histogram.py -p < results.csv
# NumSamples = 36; Min = 25.34; Max = 139.44
# Mean = 28.763650; Variance = 350.005030; SD = 18.708421; Median 25.599488
Since using dd is going to max out the bus, I will try compiling the kernel which is much more gentle to the network IO and much more prone to errors in my experience. Thoughts?
graysky2
on 5 Apr 2018
OK... still experiencing the timeouts when compiling to the NFS share with eee enabled despite the successful replicates of using dd above. I am currently building https://github.com/raspberrypi/linux/commit/c2eb30683b43b13b931bd9cfef6a2a09ac7b7c1e and will test it by compiling the kernel to NFS with eee enabled and with it disabled.
For reference, here is the script to automate the replicate compile jobs.
graysky2
on 5 Apr 2018
@pelwell - I am still getting network timeouts... below is with dtparam=eee=off set booted into the latest kernel.
[11786.758187] nfs: server ease not responding, still trying
[11786.758192] nfs: server ease not responding, still trying
[11786.758206] nfs: server ease not responding, still trying
[11786.758225] nfs: server ease not responding, still trying
[11794.438353] INFO: task ld:25967 blocked for more than 120 seconds.
[11794.441599] Tainted: G C 4.14.32-2-ARCH #1
[11794.444867] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[11794.451496] ld D 0 25967 25966 0x00000000
[11794.454918] [<80a87c48>] (__schedule) from [<80a88418>] (schedule+0x3c/0xa0)
[11794.458408] [<80a88418>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[11794.461670] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[11794.468043] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[11794.474533] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[11794.481165] [<80233190>] (filemap_write_and_wait_range) from [<803db254>] (nfs_file_fsync+0x30/0x280)
[11794.487571] [<803db254>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[11794.494001] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[11794.497339] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[11794.500698] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[11831.579322] nfs: server ease OK
[11831.579326] nfs: server ease OK
[11831.583067] nfs: server ease OK
[11831.583118] nfs: server ease OK
[12040.199240] INFO: task ld:27693 blocked for more than 120 seconds.
[12040.202836] Tainted: G C 4.14.32-2-ARCH #1
[12040.206449] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[12040.213627] ld D 0 27693 27692 0x00000000
[12040.217311] [<80a87c48>] (__schedule) from [<80a88418>] (schedule+0x3c/0xa0)
[12040.220971] [<80a88418>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[12040.223568] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[12040.228677] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[12040.233740] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[12040.238903] [<80233190>] (filemap_write_and_wait_range) from [<803db254>] (nfs_file_fsync+0x30/0x280)
[12040.244189] [<803db254>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[12040.249445] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[12040.252070] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[12040.254713] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
[12101.639302] nfs: server ease not responding, still trying
[12101.639311] nfs: server ease not responding, still trying
[12101.639328] nfs: server ease not responding, still trying
[12142.599536] nfs: server ease not responding, still trying
[12143.639966] nfs: server ease not responding, still trying
[12143.900616] nfs: server ease OK
[12143.900633] nfs: server ease OK
[12143.909707] nfs: server ease OK
[12143.917548] nfs: server ease OK
[12143.917848] nfs: server ease OK
[12408.840196] nfs: server ease not responding, still trying
[12408.840200] nfs: server ease not responding, still trying
[12408.840228] nfs: server ease not responding, still trying
[12408.840248] nfs: server ease not responding, still trying
[12408.840274] nfs: server ease not responding, still trying
[12408.840412] INFO: task ld:29538 blocked for more than 120 seconds.
[12408.840421] Tainted: G C 4.14.32-2-ARCH #1
[12408.840424] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[12408.840430] ld D 0 29538 29537 0x00000000
[12408.840493] [<80a87c48>] (__schedule) from [<80a88418>] (schedule+0x3c/0xa0)
[12408.840514] [<80a88418>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[12408.840541] [<8015c138>] (io_schedule) from [<80230be4>] (wait_on_page_bit+0x110/0x15c)
[12408.840559] [<80230be4>] (wait_on_page_bit) from [<80230d0c>] (__filemap_fdatawait_range+0xdc/0x128)
[12408.840574] [<80230d0c>] (__filemap_fdatawait_range) from [<80233190>] (filemap_write_and_wait_range+0x54/0x88)
[12408.840596] [<80233190>] (filemap_write_and_wait_range) from [<803db254>] (nfs_file_fsync+0x30/0x280)
[12408.840618] [<803db254>] (nfs_file_fsync) from [<802d5dcc>] (vfs_fsync+0x24/0x2c)
[12408.840635] [<802d5dcc>] (vfs_fsync) from [<8029d758>] (filp_close+0x2c/0x80)
[12408.840648] [<8029d758>] (filp_close) from [<8029d7cc>] (SyS_close+0x20/0x48)
[12408.840665] [<8029d7cc>] (SyS_close) from [<80107ce0>] (ret_fast_syscall+0x0/0x4c)
Same here, nothing changed. Still absolutely unstable, unreliable and completely unusable, the Pi3B+
mkreisl
on 6 Apr 2018
Odd, got one on my desk that is working fine. I think you forget to add "In the circumstances I am using it".
Anyway, issues still being looked at both here and at Microchip. There was a patch on the linux netdev list today for this chips driver (lan78xxx) for EEE which may well help, that will need to be tried. It's not like we are just sitting here twiddling our thumbs.
JamesH65
on 6 Apr 2018
Anyway, issues still being looked at both here and at Microchip. There was a patch on the linux netdev list today for this chips driver (lan78xxx) for EEE which may well help, that will need to be tried. It's not like we are just sitting here twiddling our thumbs.
Seems you're getting fire under your a.. now :smile:
IMO you're looking at the wrong place. LAN issues are only the top of the iceberg
I was already reporting, that system is still unstable after that dump microchip is powered off and all traffic is going over wlan device. System still freezing randomly. So, before I'm better informed, I would say the hole Pi3B+ design is a huge issue
mkreisl
on 6 Apr 2018
Some users who reported problems (and there honestly haven't been that many, but they are shouting loudly) have had success with adding sdram_freq=450 to config.txt. I would recommend anybody with stability problems (anything not obviously network related) to do the same.
pelwell
on 6 Apr 2018
Some users who reported problems (and there honestly haven't been that many, but they are shouting loudly) have had success with adding sdram_freq=450 to config.txt. I would recommend anybody with stability problems (anything not obviously network related) to do the same.
What's the default for Pi3B+. Cant find it here
mkreisl
on 6 Apr 2018
500 turbo, 400 normal
pelwell
on 6 Apr 2018
For reference, here is the script to automate the replicate compile jobs.
@pelwell - I have some hard data now. I ran the make benchmark writing out to the NFS share under 2 conditions, once with eee disabled and once with it enabled. There is a clear trend: eee is causing problems.
Running make zImage
Here are 9 or 10 replicates running make zImage with all times reported in minutes.
% histogram.py < eee_on_zimage
# NumSamples = 9; Min = 9.77; Max = 29.07
# Mean = 18.573025; Variance = 86.102905; SD = 9.279165; Median 10.764777
vs
% histogram.py < eee_off_zimage
# NumSamples = 10; Min = 9.91; Max = 10.87
# Mean = 10.178291; Variance = 0.067048; SD = 0.258936; Median 10.166035
Several trends from these data:
- Average time to compile is nearly double with eee enabled.
- Standard deviation and variance is much worse with eee enabled (more unpredictable compile times).
- Of the replicates, the longest compile time was observed with eee enabled and was nearly tripled.
Running make modules
Here are 9 or 10 replicates running make modules with all times reported in minutes.
% histogram.py < eee_on_modules
# NumSamples = 9; Min = 25.21; Max = 67.19
# Mean = 51.765753; Variance = 218.212739; SD = 14.772026; Median 46.494882
vs
% histogram.py < eee_off_modules
# NumSamples = 9; Min = 26.33; Max = 49.60
# Mean = 33.328529; Variance = 42.429103; SD = 6.513763; Median 32.126122
The same trends from these data:
- Average time to compile is about 1.5x longer with eee enabled.
- Standard deviation and variance is much worse with eee enabled (more unpredictable compile times).
- Of the replicates, the longest compile time was observed with eee enabled and was about 33% longer.
I am happy to test future patches/firmware, whatever to help optimize this. I think the make zImage benchmark will be sufficient for this since it's way faster than make modules and gives similar results. Just let me know.
EDIT: I see @popcornmix pushed https://github.com/raspberrypi/firmware/commit/3aa806091dc57b757790b026c01754883cee2abc a few hours ago... time to retest?
graysky2
on 6 Apr 2018
@mkreisl - Please keep this issue on task... it's scoped for network writes not for general stability. Open a new task for that.
graysky2
on 6 Apr 2018
@graysky2 Oops, sorry for tainting your thread
mkreisl
on 6 Apr 2018
A potential work-around: don't totally disable EEE, but set dtparam=tx_lpi_timer=10000 in /boot/config.txt which I did and found nearly identical results in the make zImage benchmark to having EEE totally disabled.
Again, values reported are compile times in minutes.
dtparam=tx_lpi_timer=10000
# NumSamples = 12; Min = 9.90; Max = 10.19
# Mean = 10.089245; Variance = 0.007412; SD = 0.086094; Median 10.119596
dtparam=eee=off
# NumSamples = 10; Min = 9.91; Max = 10.87
# Mean = 10.178291; Variance = 0.067048; SD = 0.258936; Median 10.166035
EDIT: see https://github.com/raspberrypi/linux/issues/2482#issuecomment-379551481 which demonstrates that the problem is still present.
graysky2
on 6 Apr 2018
All those EEE settings doesn't help for me, because my router/switch does not support EEE (most router with integrated switch does not support it) and I'm still getting nfs timeouts even if EEE is completely disabled, or I'm getting
Apr 6 16:11:14 kmxbilr2 kernel: [ 837.345227] CIFS VFS: sends on sock aa2921c0 stuck for 15 seconds
Apr 6 16:11:14 kmxbilr2 kernel: [ 837.345261] CIFS VFS: Error -11 sending data on socket to server
Apr 6 16:11:30 kmxbilr2 kernel: [ 852.705497] CIFS VFS: sends on sock aa2921c0 stuck for 15 seconds
Apr 6 16:11:30 kmxbilr2 kernel: [ 852.705532] CIFS VFS: Error -11 sending data on socket to server
Apr 6 16:11:30 kmxbilr2 kernel: [ 852.833704] CIFS VFS: Free previous auth_key.response = 99685c00
Apr 6 16:11:55 kmxbilr2 kernel: [ 878.305932] CIFS VFS: sends on sock aa29c380 stuck for 15 seconds
Apr 6 16:11:55 kmxbilr2 kernel: [ 878.305972] CIFS VFS: Error -11 sending data on socket to server
Apr 6 16:12:11 kmxbilr2 kernel: [ 893.666123] CIFS VFS: sends on sock aa29c380 stuck for 15 seconds
Apr 6 16:12:11 kmxbilr2 kernel: [ 893.666156] CIFS VFS: Error -11 sending data on socket to server
Apr 6 16:12:26 kmxbilr2 kernel: [ 909.026351] CIFS VFS: sends on sock aa29c380 stuck for 15 seconds
Apr 6 16:12:26 kmxbilr2 kernel: [ 909.026382] CIFS VFS: Error -11 sending data on socket to server
Apr 6 16:12:41 kmxbilr2 kernel: [ 924.386541] CIFS VFS: sends on sock aa29c380 stuck for 15 seconds
Apr 6 16:12:41 kmxbilr2 kernel: [ 924.386573] CIFS VFS: Error -11 sending data on socket to server
Apr 6 16:12:41 kmxbilr2 kernel: [ 924.484318] CIFS VFS: Free previous auth_key.response = a7910f00
if using SAMBA mount instead of NFS mount and after some time process that writes to share stucks and becomes uninterruptable 'D' state forever
mkreisl
on 6 Apr 2018
@mkreisl - Are you booted into the same kernel and are you using the same firmware commit that I am?
Kernel: https://github.com/raspberrypi/linux/commit/c2eb30683b43b13b931bd9cfef6a2a09ac7b7c1e
Firmware: https://github.com/raspberrypi/firmware/commit/0dff9ecc00d8114164bb9a73799793dad24d8593
graysky2
on 6 Apr 2018
@graysky2
Kernel: yes (XBian built based on bcm2709_defconfig)
Firmware: yes, excatly the same version
mkreisl
on 6 Apr 2018
@mkreisl - not sure what to say then.... perhaps you have a different issue. As a control, have you tried the same stuff with another older RPi? Like a 2 or 3?
graysky2
on 7 Apr 2018
@graysky2 Sure, I'm running same procedure on Pi1, 2 and 3 (without +) since years without any problem.
mkreisl
on 7 Apr 2018
@graysky2 In short words, I can explain what it does
1) mount network share (sshfs, nfs or samba)
2) create image on this share, big enough to backup data from root/boot fs into it
3) create partition in image (vfat for boot, btrfs for root)
4) copy boot partition into mounted image (loop device)
5) copy all subvolumes into mounted image (using btrfs send/receive or tar, both tested)
6) close everything and umount share
From 1 to 4 it always works, and within 5 it stucks always, but not on the same subvolume
And, it does not matter if source fs is on sd, usb disk or iSCSI target
mkreisl
on 7 Apr 2018
What is your NFS or samba server? How are these configured? I can complete these steps on mine without error except I don't do much with BTRFS. Can you complete the steps with ext4? I can:
# mount nfs share
mount -t nfs4 ease:/scratch /opt/armv7h/scratch
mount | grep opt
ease:/scratch on /opt/armv7/scratch type nfs4
(rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=10.9.8.108,local_lock=none,addr=10.9.8.128)
# make image and format it
cd /opt/armv7h/scratch
truncate -s 5G image.img
mkfs.ext4 -F image.img
mkdir mp
# mount it
mount -o loop image.img mp
chown facade:users mp
# add 1.0 GB of data to image
dd if=/dev/zero of=/opt/armv7/scratch/mp/zerofill bs=4M count=250 status=progress
ls -l mp
total 1024020
drwx------ 2 facade users 16384 Apr 7 12:30 lost+found
-rw-r--r-- 1 facade users 1048576000 Apr 7 12:32 zerofill
umount mp
What is your NFS or samba server? How are these configured? I can complete these steps on mine without error except I don't do much with BTRFS. Can you complete the steps with ext4?
Running Debian Stretch as NFS and SAMBA server. Nothing special configured AFAIR
Currently it's not possible to run tests with ext4, don't have any configuation based on ext4. Will do more testing next days, actually I'm testing wlan only configuration.
mkreisl
on 7 Apr 2018
You haven't said if you have changed sdram_freq or arm_freq yet.
pelwell
on 7 Apr 2018
@pelwell
You haven't said if you have changed sdram_freq or arm_freq yet.
Ehm @graysky2 told me that I should not post such topics here :disappointed:
Yes, changing sdram clock to 450 did it, setting arm clock to 1200 I tested 2 weeks ago without success
But, reducing sdram clock did not solve ethernet network issues discussed here
mkreisl
on 7 Apr 2018
Ehm @graysky2 told me that I should not post such topics here disappointed
No, just reminded you that this task is about network write issues, if one of the developers asks you to try something, do it, just don't add a bunch of unrelated issues on top of this one.
graysky2
on 7 Apr 2018
Exactly. There appear to be two classes of errors - network problems and memory corruption. I'm satisfied this is purely a networking problem.
EEE does seem to worsen network throughout, enabling flow control improves it, and we haven't ruled out further driver problems.
pelwell
on 7 Apr 2018
Based on @mkreisl's observation about samba shares, I did the same make zImage benchmark on a samba share (samba version 4.7.6) and found inconsistent performance (nothing in dmesg) though. This is with dtparam=tx_lpi_timer=10000 set:
# NumSamples = 4; Min = 462.65; Max = 1251.20
# Mean = 895.113710; Variance = 124647.496919; SD = 353.054524; Median 933.305226
1,zImage,631.770020346
2,zImage,462.645222405
3,zImage,1251.199164634
4,zImage,1234.840431102
After I got this result, I switched over the NFS and found highly consistent runs as before. Not sure what to make of it.
@mkreisl - You game to try the benchmark on your system? You just need a kernel source that contains some .config ready to go. See here.
graysky2
on 7 Apr 2018
@graysky2 modified your script as follows and let it run
#!/bin/bash
cd /srv/backup
mount | grep /srv/backup
truncate -s 8G image.img
mkfs.ext4 -F image.img
mkdir -p img
mount -o loop image.img img
to='--warning=none --acls --xattrs'
tar c --one-file-system $to -C / . | tar x $to -v -C /srv/backup/img
ls -l img
umount img && rmdir img && rm -f image.img
Destination is ext4, but source is still BTRFS
It ends up always with nfs: server kmcubie not responding, timed out
[ 1692.649145] INFO: task loop0:9479 blocked for more than 120 seconds.
[ 1692.649159] Tainted: G C 4.14.32+ #1
[ 1692.649167] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1692.649175] loop0 D 0 9479 2 0x00000000
[ 1692.649219] [<808c4124>] (__schedule) from [<808c47d4>] (schedule+0x58/0xb8)
[ 1692.649240] [<808c47d4>] (schedule) from [<8014be98>] (io_schedule+0x20/0x40)
[ 1692.649262] [<8014be98>] (io_schedule) from [<80221fb8>] (wait_on_page_bit+0x108/0x128)
[ 1692.649279] [<80221fb8>] (wait_on_page_bit) from [<802220bc>] (__filemap_fdatawait_range+0xe4/0x114)
[ 1692.649297] [<802220bc>] (__filemap_fdatawait_range) from [<80224614>] (filemap_write_and_wait_range+0x68/0xa4)
[ 1692.649316] [<80224614>] (filemap_write_and_wait_range) from [<803a0184>] (nfs_file_fsync+0x3c/0x308)
[ 1692.649335] [<803a0184>] (nfs_file_fsync) from [<802c7644>] (vfs_fsync_range+0x68/0xbc)
[ 1692.649356] [<802c7644>] (vfs_fsync_range) from [<802c76cc>] (vfs_fsync+0x34/0x3c)
[ 1692.649383] [<802c76cc>] (vfs_fsync) from [<7f007e80>] (loop_queue_work+0x574/0xb98 [loop])
[ 1692.649438] [<7f007e80>] (loop_queue_work [loop]) from [<8013dff4>] (kthread_worker_fn+0xbc/0x1e0)
[ 1692.649459] [<8013dff4>] (kthread_worker_fn) from [<7f005738>] (loop_kthread_worker_fn+0x34/0x194 [loop])
[ 1692.649480] [<7f005738>] (loop_kthread_worker_fn [loop]) from [<8013dec4>] (kthread+0x13c/0x16c)
[ 1692.649502] [<8013dec4>] (kthread) from [<8010834c>] (ret_from_fork+0x14/0x28)
[ 1784.809482] nfs: server kmcubie not responding, timed out
[ 1784.809540] nfs: server kmcubie not responding, timed out
[ 1784.809563] nfs: server kmcubie not responding, timed out
[ 1813.481779] INFO: task kworker/u8:2:7543 blocked for more than 120 seconds.
[ 1813.481794] Tainted: G C 4.14.32+ #1
[ 1813.481801] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1813.481810] kworker/u8:2 D 0 7543 2 0x00000000
[ 1813.481844] Workqueue: writeback wb_workfn (flush-7:0)
[ 1813.481885] [<808c4124>] (__schedule) from [<808c47d4>] (schedule+0x58/0xb8)
[ 1813.481903] [<808c47d4>] (schedule) from [<8014be98>] (io_schedule+0x20/0x40)
[ 1813.481923] [<8014be98>] (io_schedule) from [<805688c8>] (blk_mq_get_tag+0x1a4/0x2fc)
[ 1813.481944] [<805688c8>] (blk_mq_get_tag) from [<805634e8>] (blk_mq_get_request+0x134/0x43c)
[ 1813.481961] [<805634e8>] (blk_mq_get_request) from [<805661a8>] (blk_mq_make_request+0xec/0x758)
[ 1813.481980] [<805661a8>] (blk_mq_make_request) from [<80558d50>] (generic_make_request+0xe8/0x260)
[ 1813.481999] [<80558d50>] (generic_make_request) from [<80558f80>] (submit_bio+0xb8/0x1a8)
[ 1813.482018] [<80558f80>] (submit_bio) from [<8035dec8>] (ext4_io_submit+0x58/0x64)
[ 1813.482038] [<8035dec8>] (ext4_io_submit) from [<80342b6c>] (ext4_writepages+0x718/0x998)
[ 1813.482056] [<80342b6c>] (ext4_writepages) from [<80234668>] (do_writepages+0x30/0x9c)
[ 1813.482074] [<80234668>] (do_writepages) from [<802c20d8>] (__writeback_single_inode+0x44/0x554)
[ 1813.482092] [<802c20d8>] (__writeback_single_inode) from [<802c2b74>] (writeback_sb_inodes+0x238/0x4c0)
[ 1813.482111] [<802c2b74>] (writeback_sb_inodes) from [<802c2e8c>] (__writeback_inodes_wb+0x90/0xd0)
[ 1813.482128] [<802c2e8c>] (__writeback_inodes_wb) from [<802c31b8>] (wb_writeback+0x2ec/0x3bc)
[ 1813.482144] [<802c31b8>] (wb_writeback) from [<802c3c24>] (wb_workfn+0x1d4/0x570)
[ 1813.482167] [<802c3c24>] (wb_workfn) from [<80137b18>] (process_one_work+0x140/0x4c4)
[ 1813.482187] [<80137b18>] (process_one_work) from [<80137ef8>] (worker_thread+0x5c/0x568)
[ 1813.482206] [<80137ef8>] (worker_thread) from [<8013dec4>] (kthread+0x13c/0x16c)
[ 1813.482226] [<8013dec4>] (kthread) from [<8010834c>] (ret_from_fork+0x14/0x28)
[ 1813.482258] INFO: task jbd2/loop0-8:9482 blocked for more than 120 seconds.
[ 1813.482266] Tainted: G C 4.14.32+ #1
[ 1813.482272] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1813.482278] jbd2/loop0-8 D 0 9482 2 0x00000000
[ 1813.482303] [<808c4124>] (__schedule) from [<808c47d4>] (schedule+0x58/0xb8)
[ 1813.482318] [<808c47d4>] (schedule) from [<8014be98>] (io_schedule+0x20/0x40)
[ 1813.482333] [<8014be98>] (io_schedule) from [<808c525c>] (bit_wait_io+0x1c/0x70)
[ 1813.482350] [<808c525c>] (bit_wait_io) from [<808c4ee8>] (__wait_on_bit+0x94/0xd4)
[ 1813.482368] [<808c4ee8>] (__wait_on_bit) from [<808c4fb0>] (out_of_line_wait_on_bit+0x88/0x90)
[ 1813.482385] [<808c4fb0>] (out_of_line_wait_on_bit) from [<802c988c>] (__wait_on_buffer+0x34/0x38)
[ 1813.482404] [<802c988c>] (__wait_on_buffer) from [<803838a0>] (jbd2_journal_commit_transaction+0x145c/0x191c)
[ 1813.482428] [<803838a0>] (jbd2_journal_commit_transaction) from [<80388e40>] (kjournald2+0x110/0x2a0)
[ 1813.482446] [<80388e40>] (kjournald2) from [<8013dec4>] (kthread+0x13c/0x16c)
[ 1813.482464] [<8013dec4>] (kthread) from [<8010834c>] (ret_from_fork+0x14/0x28)
[ 1813.482477] INFO: task tar:9486 blocked for more than 120 seconds.
[ 1813.482487] Tainted: G C 4.14.32+ #1
[ 1813.482493] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1813.482500] tar D 0 9486 9454 0x00000000
[ 1813.482523] [<808c4124>] (__schedule) from [<808c47d4>] (schedule+0x58/0xb8)
[ 1813.482538] [<808c47d4>] (schedule) from [<8014be98>] (io_schedule+0x20/0x40)
[ 1813.482553] [<8014be98>] (io_schedule) from [<805688c8>] (blk_mq_get_tag+0x1a4/0x2fc)
[ 1813.482570] [<805688c8>] (blk_mq_get_tag) from [<805634e8>] (blk_mq_get_request+0x134/0x43c)
[ 1813.482586] [<805634e8>] (blk_mq_get_request) from [<805661a8>] (blk_mq_make_request+0xec/0x758)
[ 1813.482602] [<805661a8>] (blk_mq_make_request) from [<80558d50>] (generic_make_request+0xe8/0x260)
[ 1813.482619] [<80558d50>] (generic_make_request) from [<80558f80>] (submit_bio+0xb8/0x1a8)
[ 1813.482635] [<80558f80>] (submit_bio) from [<802cca70>] (submit_bh_wbc+0x190/0x1c0)
[ 1813.482653] [<802cca70>] (submit_bh_wbc) from [<802cd268>] (submit_bh+0x24/0x2c)
[ 1813.482672] [<802cd268>] (submit_bh) from [<8031fe1c>] (ext4_read_block_bitmap_nowait+0x354/0x80c)
[ 1813.482691] [<8031fe1c>] (ext4_read_block_bitmap_nowait) from [<8034b544>] (ext4_mb_init_cache+0x128/0x750)
[ 1813.482709] [<8034b544>] (ext4_mb_init_cache) from [<8034bd2c>] (ext4_mb_init_group+0x1c0/0x2b0)
[ 1813.482725] [<8034bd2c>] (ext4_mb_init_group) from [<8034bfb4>] (ext4_mb_good_group+0x198/0x1a8)
[ 1813.482744] [<8034bfb4>] (ext4_mb_good_group) from [<8034ee20>] (ext4_mb_regular_allocator+0x2b8/0x408)
[ 1813.482761] [<8034ee20>] (ext4_mb_regular_allocator) from [<80351124>] (ext4_mb_new_blocks+0x854/0xe8c)
[ 1813.482781] [<80351124>] (ext4_mb_new_blocks) from [<803299b0>] (ext4_ext_map_blocks+0xccc/0x13b8)
[ 1813.482799] [<803299b0>] (ext4_ext_map_blocks) from [<8033e0e0>] (ext4_map_blocks+0x114/0x600)
[ 1813.482814] [<8033e0e0>] (ext4_map_blocks) from [<8033f0e8>] (ext4_getblk+0x4c/0x184)
[ 1813.482829] [<8033f0e8>] (ext4_getblk) from [<8033f23c>] (ext4_bread+0x1c/0xac)
[ 1813.482845] [<8033f23c>] (ext4_bread) from [<80356cf4>] (ext4_append+0x68/0x10c)
[ 1813.482863] [<80356cf4>] (ext4_append) from [<8035b050>] (ext4_mkdir+0x210/0x414)
[ 1813.482883] [<8035b050>] (ext4_mkdir) from [<8029e14c>] (vfs_mkdir+0x100/0x154)
[ 1813.482908] [<8029e14c>] (vfs_mkdir) from [<802a261c>] (SyS_mkdirat+0x74/0xc0)
[ 1813.482927] [<802a261c>] (SyS_mkdirat) from [<801082a0>] (ret_fast_syscall+0x0/0x28)
But it does not always block everything infinitely bc mounted loop device will randomly become ro (after a looong time doing nothing) and tar does not continue copying, just throws a lot of error messages to the screen or tar continues copying until nfs is blocked again or third case is blocking infinitely
root@kmxbilr2 ~/bin # ps ax | grep tar\
13829 pts/3 S+ 0:18 tar c --one-file-system --warning=none --acls --xattrs -C / .
13830 pts/3 D+ 0:20 tar x --warning=none --acls --xattrs -C /srv/backup/img
15679 pts/1 S+ 0:00 grep --color=auto tar
root@kmxbilr2 ~/bin #
This is my eee setting:
root@kmxbilr2 ~/bin # ethtool --show-eee eth0
EEE Settings for eth0:
EEE status: disabled
Tx LPI: disabled
Supported EEE link modes: 100baseT/Full
1000baseT/Full
Advertised EEE link modes: Not reported
Link partner advertised EEE link modes: Not reported
root@kmxbilr2 ~/bin #
So, I run above test three times:
1st run: loop device becomes r/o
2nd run: test finished
3rd run: test blocked infinitely
but getting always messages like this: NFO: task loop0:9479 blocked for more than 120 seconds.
Ah, forgot, destination folder is mouted as follows
kmcubie:/media/system/backup/kmxbilr2 on /srv/backup type nfs4 (rw,nosuid,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,soft,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.1.24,local_lock=none,addr=192.168.1.6)
Mounted via autofs
EDIT:
After 45min of blocking loop fs becomes r/o in 3rd run and script finished
mkreisl
on 7 Apr 2018
Destination is ext4, but source is still BTRFS
It ends up always with nfs: server kmcubie not responding, timed out
I don't use BTRFS nor do I have access to your specific filesystem, so let's come up with a standard script anyone can use provided that they have an NFS server and can mount to it.
Here is a such a script.
Experiment
Run this script on the RPi3B+ and _using the identical micro SD card_, on known-good board which in my case is a RPi2.
Details
- Distro: Arch ARM (armv7h)
- I have
dtparam=eee=offset in/etc/boot.txt - Kernel version (4.14.32-git): https://github.com/raspberrypi/linux/commit/c2eb30683b43b13b931bd9cfef6a2a09ac7b7c1e
- Firmware version: https://github.com/raspberrypi/firmware/commit/3aa806091dc57b757790b026c01754883cee2abc
Conclusion
@pelwell
- When I run it on my 3B+, I see that the original bug I for which I opened this ticket is STILL present.
- Running on the RPi2 resulting in 4 successful completions in very similar run times. A page allocation failure occurred on the 2nd run (see output below/dmesg timestamp 759.7). Related? Unrelated?
Details: RPi3B+
% mount | grep nfs
ease:/scratch on /scratch type nfs4 (rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=10.9.8.108,local_lock=none,addr=10.9.8.128)
Output of the script:
# /root/bin/nfstest
Writting round 1
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 605 s, 6.9 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 605.129 s, 6.9 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 8 12:54 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 8 13:04 rnd.1
Round 1 done
Writting round 2
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 930 s, 4.5 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 929.514 s, 4.5 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 8 13:05 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 8 13:20 rnd.2
Round 2 done
Writting round 3
2990538752 bytes (3.0 GB, 2.8 GiB) copied, 679 s, 4.4 MB/s
It is currently stuck on round 3. System is still up but not very responsive.
From dmsg:
[ 90.991309] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[ 699.983054] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[ 858.079796] INFO: task jbd2/loop0-8:633 blocked for more than 120 seconds.
[ 858.079980] Tainted: G C 4.14.32-2-ARCH #1
[ 858.080112] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 858.080290] jbd2/loop0-8 D 0 633 2 0x00000000
[ 858.080451] [<80a87c48>] (__schedule) from [<80a88418>] (schedule+0x3c/0xa0)
[ 858.080627] [<80a88418>] (schedule) from [<8015c138>] (io_schedule+0x14/0x3c)
[ 858.080801] [<8015c138>] (io_schedule) from [<80a88d28>] (bit_wait_io+0xc/0x60)
[ 858.080975] [<80a88d28>] (bit_wait_io) from [<80a8899c>] (__wait_on_bit+0x60/0xb8)
[ 858.081158] [<80a8899c>] (__wait_on_bit) from [<80a88a68>] (out_of_line_wait_on_bit+0x74/0xa0)
[ 858.085451] [<80a88a68>] (out_of_line_wait_on_bit) from [<803be5b4>] (jbd2_journal_commit_transaction+0xf6c/0x17d8)
[ 858.094108] [<803be5b4>] (jbd2_journal_commit_transaction) from [<803c3ea4>] (kjournald2+0xe0/0x2e4)
[ 858.102800] [<803c3ea4>] (kjournald2) from [<8014e708>] (kthread+0x138/0x150)
[ 858.107318] [<8014e708>] (kthread) from [<80107db8>] (ret_from_fork+0x14/0x3c)
[ 1633.827852] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
Details: RPi2
Output of the script:
# /root/bin/nfstest
Writting round 1
4185915392 bytes (4.2 GB, 3.9 GiB) copied, 373 s, 11.2 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 373.4 s, 11.2 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 8 09:44 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 8 09:51 rnd.1
Round 1 done
Writting round 2
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 373 s, 11.3 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 372.777 s, 11.3 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 8 09:51 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 8 09:57 rnd.2
Round 2 done
Writting round 3
4190109696 bytes (4.2 GB, 3.9 GiB) copied, 369 s, 11.3 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 369.738 s, 11.3 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 8 09:57 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 8 10:03 rnd.3
Round 3 done
Writting round 4
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 368 s, 11.4 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 367.684 s, 11.4 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 8 10:04 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 8 10:10 rnd.4
Round 4 done
nfstest 0.64s user 157.45s system 10% cpu 25:36.18 total
From dmesg:
[ 26.240546] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[ 411.226606] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[ 759.730166] kworker/0:1H: page allocation failure: order:0, mode:0x1080020(GFP_ATOMIC), nodemask=(null)
[ 759.739788] kworker/0:1H cpuset=/ mems_allowed=0
[ 759.744512] CPU: 0 PID: 196 Comm: kworker/0:1H Tainted: G C 4.14.32-2-ARCH #1
[ 759.752917] Hardware name: BCM2835
[ 759.756391] Workqueue: xprtiod xs_tcp_data_receive_workfn
[ 759.761905] [<8010ef14>] (unwind_backtrace) from [<8010bbc0>] (show_stack+0x10/0x14)
[ 759.769790] [<8010bbc0>] (show_stack) from [<80a71e3c>] (dump_stack+0x9c/0xc8)
[ 759.777144] [<80a71e3c>] (dump_stack) from [<8023bea4>] (warn_alloc+0xd0/0x194)
[ 759.784584] [<8023bea4>] (warn_alloc) from [<8023cf98>] (__alloc_pages_nodemask+0xf98/0x10ec)
[ 759.817701] [<8023cf98>] (__alloc_pages_nodemask) from [<8023d2f0>] (page_frag_alloc+0x168/0x198)
[ 759.877932] [<8023d2f0>] (page_frag_alloc) from [<8096695c>] (__netdev_alloc_skb+0x90/0x10c)
[ 759.938928] [<8096695c>] (__netdev_alloc_skb) from [<8080d36c>] (rx_submit+0x34/0x214)
[ 760.001476] [<8080d36c>] (rx_submit) from [<8080d8fc>] (rx_complete+0x138/0x220)
[ 760.065467] [<8080d8fc>] (rx_complete) from [<80819888>] (__usb_hcd_giveback_urb+0x98/0x154)
[ 760.131215] [<80819888>] (__usb_hcd_giveback_urb) from [<808424f0>] (completion_tasklet_func+0x78/0xbc)
[ 760.198174] [<808424f0>] (completion_tasklet_func) from [<80134f44>] (tasklet_hi_action+0x64/0xf8)
[ 760.264776] [<80134f44>] (tasklet_hi_action) from [<80101574>] (__do_softirq+0xc4/0x328)
[ 760.331823] [<80101574>] (__do_softirq) from [<801349e8>] (do_softirq.part.4+0x48/0x50)
[ 760.400468] [<801349e8>] (do_softirq.part.4) from [<80134aa8>] (__local_bh_enable_ip+0xb8/0xd8)
[ 760.471671] [<80134aa8>] (__local_bh_enable_ip) from [<80a47024>] (xs_tcp_data_receive_workfn+0x88/0x194)
[ 760.543912] [<80a47024>] (xs_tcp_data_receive_workfn) from [<801487f0>] (process_one_work+0x210/0x4fc)
[ 760.617849] [<801487f0>] (process_one_work) from [<80149718>] (worker_thread+0x34/0x5d0)
[ 760.691146] [<80149718>] (worker_thread) from [<8014e708>] (kthread+0x138/0x150)
[ 760.763687] [<8014e708>] (kthread) from [<80107db8>] (ret_from_fork+0x14/0x3c)
[ 760.803499] Mem-Info:
[ 760.838097] active_anon:2032 inactive_anon:2748 isolated_anon:0
active_file:8207 inactive_file:204480 isolated_file:0
unevictable:0 dirty:8517 writeback:28663 unstable:2
slab_reclaimable:6216 slab_unreclaimable:3548
mapped:4648 shmem:56 pagetables:200 bounce:0
free:4508 free_pcp:242 free_cma:1299
[ 761.056841] Node 0 active_anon:8128kB inactive_anon:10992kB active_file:32828kB inactive_file:817920kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:18592kB dirty:34068kB writeback:114652kB shmem:224kB writeback_tmp:0kB unstable:8kB all_unreclaimable? no
[ 761.198936] Normal free:18032kB min:3884kB low:4852kB high:5820kB active_anon:8128kB inactive_anon:10992kB active_file:32828kB inactive_file:817948kB unevictable:0kB writepending:148628kB present:983040kB managed:958392kB mlocked:0kB kernel_stack:896kB pagetables:800kB bounce:0kB free_pcp:968kB local_pcp:108kB free_cma:5196kB
[ 761.376256] lowmem_reserve[]: 0 0
[ 761.408452] Normal: 95*4kB (UMEC) 155*8kB (UMEHC) 152*16kB (UME) 218*32kB (MEH) 15*64kB (UMC) 2*128kB (MH) 0*256kB 1*512kB (H) 1*1024kB (C) 0*2048kB 1*4096kB (C) = 17876kB
[ 761.509861] 212750 total pagecache pages
[ 761.541672] 0 pages in swap cache
[ 761.572101] Swap cache stats: add 0, delete 0, find 0/0
[ 761.603884] Free swap = 1191420kB
[ 761.633321] Total swap = 1191420kB
[ 761.661755] 245760 pages RAM
[ 761.688868] 0 pages HighMem/MovableOnly
[ 761.716659] 6162 pages reserved
[ 761.743400] 2048 pages cma reserved
[ 796.738005] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[ 1180.359713] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
@graysky2
When I run it on my 3B+, I see that the original bug I for which I opened this ticket is STILL presen
Can confirm this ...
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 605 s, 6.9 MB/s
... and your network performance is ridiculous slow
btw, I'm getting better results if I turn off flow control completely
ethtool -A eth0 tx off rx off autoneg off && ethtool -r eth0
Infinite locks are gone, but of course, those annoying locks are still there
mkreisl
on 8 Apr 2018
Well, the important thing is that you are independently able to reproduce this bug.
... and your network performance is ridiculous slow
Just on the 3B+ and I believe it is due to the locks ... the network is all cat6 going through an SG100-16. Here is an x86_64 box doing the same 4G write:
% dd if=/dev/zero of=/mnt/media/test/fill bs=4M count=1000 status=progress
4177526784 bytes (4.2 GB, 3.9 GiB) copied, 31 s, 135 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 35.8983 s, 117 MB/s
@graysky2 In order to identify a locking issue you could try to recompile your kernel with the following options:
Kernel hacking --->
Lock Debugging (spinlocks, mutexes, etc...) --->
Lock debugging: prove locking correctness (CONFIG_PROVE_LOCKING=y)
Sleep inside atomic section checking (CONFIG_DEBUG_ATOMIC_SLEEP=y)
lategoodbye
on 9 Apr 2018
You bet. Building now. For reference, the config I am using.
graysky2
on 9 Apr 2018
@lategoodbye @pelwell - I never thought to see what what going on the nfs server's side of things. My NFS server is running on a i7-4790K machine. The dmesg log there gets spammed with hundreds of lines like this the below that coincide with freeze ups on the RPi3BPlus:
[ 3624.508074] nfsd4_validate_stateid: 119 callbacks suppressed
[ 3624.508074] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.508938] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.509754] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.510577] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.511396] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.512229] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.513059] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.513872] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.514688] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3624.515514] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 3767.535787] nfsd4_validate_stateid: 119 callbacks suppressed
[ 3767.535788] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.423284] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.423887] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.424487] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.425385] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.425979] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.426585] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.427501] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.428322] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4105.429125] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4218.046249] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
[ 4218.047093] NFSD: client 10.9.8.108 testing state ID with incorrect client ID
@lategoodbye - I don't think the kernel has what you need... I booted into it but get this on lock up:
[ 532.399675] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[ 858.099808] INFO: task jbd2/loop0-8:859 blocked for more than 120 seconds.
[ 858.100037] Tainted: G WC 4.14.32-3-ARCH #1
[ 858.100215] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 858.100453] jbd2/loop0-8 D 0 859 2 0x00000000
[ 858.100665] [<80baebf0>] (__schedule) from [<80baf72c>] (schedule+0x50/0xc0)
[ 858.100892] [<80baf72c>] (schedule) from [<80168230>] (io_schedule+0x14/0x3c)
[ 858.101124] [<80168230>] (io_schedule) from [<80bb00f4>] (bit_wait_io+0xc/0x60)
[ 858.101354] [<80bb00f4>] (bit_wait_io) from [<80bafd68>] (__wait_on_bit+0x60/0xb8)
[ 858.101594] [<80bafd68>] (__wait_on_bit) from [<80bafe34>] (out_of_line_wait_on_bit+0x74/0xa0)
[ 858.101868] [<80bafe34>] (out_of_line_wait_on_bit) from [<80420fe0>] (jbd2_journal_commit_transaction+0x1470/0x1ef8)
[ 858.102191] [<80420fe0>] (jbd2_journal_commit_transaction) from [<80426e70>] (kjournald2+0xdc/0x2d0)
[ 858.102472] [<80426e70>] (kjournald2) from [<80157430>] (kthread+0x148/0x164)
[ 858.102697] [<80157430>] (kthread) from [<8010824c>] (ret_from_fork+0x14/0x28)
[ 858.102923] INFO: lockdep is turned off.
@graysky2 This means you build the kernel with these options, but it didn't trigger any warning except of the hung? I tought it would be worth to try it.
lategoodbye
on 9 Apr 2018
@lategoodbye -
[ 858.102923] INFO: lockdep is turned off.
Perhaps I didn't compile with enough of these options enabled? Here is the nconfig... more?
.config - Linux/arm 4.14.32-3 Kernel Configuration
┌── Lock Debugging (spinlocks, mutexes, etc...) ────────────────────────────────┐
│ │
│ -*- RT Mutex debugging, deadlock detection │
│ -*- Spinlock and rw-lock debugging: basic checks │
│ -*- Mutex debugging: basic checks │
│ [ ] Wait/wound mutex debugging: Slowpath testing │
│ -*- Lock debugging: detect incorrect freeing of live locks │
│ [*] Lock debugging: prove locking correctness │
│ [ ] Lock usage statistics │
│ [ ] Lock dependency engine debugging (NEW) │
│ [*] Sleep inside atomic section checking │
│ [ ] Locking API boot-time self-tests │
│ < > torture tests for locking │
│ < > Wait/wound mutex selftests │
│ │
@graysky2 If you want to doublecheck it, search for "Lock dependency validator" within dmesg. The default RPI kernel doesn't have it.
Edit: The config above looks good.
Edit2: lockdep is disabled because of the hung.
lategoodbye
on 9 Apr 2018
If you want to doublecheck it, search for "Lock dependency validator" within dmesg. The default RPI kernel doesn't have it.
It's there:
% dmesg | grep -i validator
[ 0.004391] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
Edit: The config above looks good.
Edit2: lockdep is disabled because of the hung.
OK... so no need to recompile... and we are back to square 1 :(
graysky2
on 9 Apr 2018
@graysky2 I plan to submit RPi 3+ support to Linux Mainline soon. Any chance for you to give it a try?
lategoodbye
on 10 Apr 2018
@lategoodbye - Longterm, I need the vendor libraries supplied by the raspberrypi-firmware package which I believe are tied to the 4.14.x kernel. I might have some time over the weekend to compile/use a mainline version of the kernel. I believe that would be aarch64 in Arch ARM.
graysky2
on 10 Apr 2018
@graysky2 Sure. It would help to narrow down, if this is a downstream specific issue. It would be the best to use the same rootfs, which currently causes this issue and only the replace the kernel and device tree BLOB. Mainline kernel support both 32 and 64 bit.
Thanks in advance
Stefan
lategoodbye
on 10 Apr 2018
@graysky2 I've created a branch based on Linus' tree (pre 4.17) which includes the necessary changes for RPi 3B+
https://github.com/lategoodbye/rpi-zero/tree/bcm2837-rpi3-plus-4.17
lategoodbye
on 12 Apr 2018
Here is a such a script.
@pelwell @mkreisl - More evidences that the bug we are seeking is in the wired LAN driver: if I use the on board Wi-Fi, I am able to successfully complete this without kernel oops or lockup.
5 GHz connection:
% cat /proc/net/wireless
Inter-| sta-| Quality | Discarded packets | Missed | WE
face | tus | link level noise | nwid crypt frag retry misc | beacon | 22
wlan0: 0000 56. -54. -256 0 0 0 19 0 0
Running the script:
# /root/bin/nfstest
Writting round 1
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 358 s, 11.7 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 358.232 s, 11.7 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 12 15:03 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 12 15:09 rnd.1
Round 1 done
Writting round 2
4185915392 bytes (4.2 GB, 3.9 GiB) copied, 358 s, 11.7 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 357.618 s, 11.7 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 12 15:09 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 12 15:15 rnd.2
Round 2 done
Writting round 3
4181721088 bytes (4.2 GB, 3.9 GiB) copied, 357 s, 11.7 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 357.173 s, 11.7 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 12 15:15 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 12 15:21 rnd.3
Round 3 done
Writting round 4
4181721088 bytes (4.2 GB, 3.9 GiB) copied, 357 s, 11.7 MB/s
1000+0 records in
1000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 357.512 s, 11.7 MB/s
total 4096020
drwx------ 2 root root 16384 Apr 12 15:21 lost+found
-rw-r--r-- 1 root root 4194304000 Apr 12 15:27 rnd.4
Round 4 done
/root/bin/nfstest 0.35s user 105.39s system 7% cpu 24:31.40 total
And dmesg:
[ +2.033113] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Feb 27 2018 03:15:32 version 7.45.154 (r684107 CY) FWID 01-4fbe0b04
[ +0.001800] brcmfmac: brcmf_c_preinit_dcmds: CLM version = API: 12.2 Data: 9.10.105 Compiler: 1.29.4 ClmImport: 1.36.3 Creation: 2018-03-09 18:56:28
[ +0.081575] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ +0.000902] brcmfmac: power management disabled
[ +3.238507] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[Apr12 15:03] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[Apr12 15:08] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000132] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000100] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000093] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0xfb
[ +0.000117] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000106] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000090] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000090] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000089] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.000086] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[Apr12 15:09] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[Apr12 15:10] net_ratelimit: 73 callbacks suppressed
[ +0.000008] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.013994] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0xfb
[ +0.009320] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0xff
[ +0.010984] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.009323] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008868] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008751] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008961] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[Apr12 15:14] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.009775] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008504] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008744] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008674] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008638] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0x0
[ +0.008662] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0xfb
[ +0.008604] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0xfb
[ +0.008401] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0xfb
[ +0.008542] brcmfmac: brcmf_proto_bcdc_hdrpull: wlan0: non-BCDC packet received, flags 0xfb
@graysky2 Thanks for confirming that wlan is ok
I was posting this multiple times already :smile:
mkreisl
on 12 Apr 2018
No news about this annoying issue. Hmmm, seems that you guys from Raspberry Pi foundation having absolutely no idea how to fix it :angry:
Extremely disappointing
mkreisl
on 15 Apr 2018
You do know it's the weekend, right? Even RPF(T) employees have the weekend off. We have multiple engineers working on this. I'm sure there will be progress in the near future. Meanwhile, perhaps laying off the sarcasm might help.
JamesH65
on 15 Apr 2018
Really? I find it highly motivating.
pelwell
on 15 Apr 2018
@mkreisl - No idea why you would piss all over the very people who are helping you...
@pelwell - I noticed that the hung task seems to be dependent on the amount of data one tries to write and am wondering if that helps clue you into the cause?
For example, see this script. I start writing out 10 MB (a total of 10x), then step up in 1/4-log increments (ie 10, 18, 32, 56, 100, 178, 316, 563, 1000) until the hung task occurs. In my testing, all sizes under 563 were fine; the error occurred on the 5th iteration of writing out 563 megs.. Significant?
graysky2
on 17 Apr 2018
For example, see this script. I start writing out 10 MB (a total of 10x), then step up in 1/4-log increments (ie 10, 18, 32, 56, 100, 178, 316, 563, 1000) until the hung task occurs. In my testing, all sizes under 563 were fine; the error occurred on the 5th iteration of writing out 563 megs.. Significant?
Looks for me it's ok as long as the data completely fit into the (write-)cache
mkreisl
on 17 Apr 2018
In my testing, all sizes under 563 were fine; the error occurred on the 5th iteration of writing out 563 megs..
I ran it again with 30 iterations per size and found errors on the 316 MB writes... maybe it speaks to the unpredictable nature of the bug?
EDIT: When the bug manifests itself, the code I use to keep track of the time between runs also freezes thus recording an untrue time to complete. Does that imply that the internal clock on the RPi also
freezes?
start=$(date +%s.%N)
dd if=/dev/zero of="$MP/rnd.$x" bs=1M count=$size status=progress
finish=$(date +%s.%N)
diff=$(echo "scale=6; $finish - $start" | bc)
Microchip pointed us at a patch that should prevent link drops when using EEE with long cables. Testing here has shown that it completely fixes the EEE-related throughput issues (caused by link drops) I have observed (the cable in question is about 40 metres long). Since the patch tweaks a lot of PHY registers it may also make a difference with shorter cables. The patch (and a few pre-requisites) is in the rpi-4.14.y branch and will be picked up by the next firmware build.
pelwell
on 4 May 2018
@pelwell - That's great to hear! My cable is no where near 40 m long but I am happy to test it. To be clear, if I build the following two commits, will I have the patch in question?
graysky2
on 4 May 2018
Yes, that's correct - the kernel commit you reference is the significant one.
pelwell
on 4 May 2018
@pelwell - Great, building now. Will let you know.
graysky2
on 4 May 2018
@pelwell - The bug is still present...
/root/bin/nfstest
==> Writting round 1 for 500 MB
349175808 bytes (349 MB, 333 MiB) copied, 7 s, 49.8 MB/s^C^C^C
The terminal is locked at this point :/
Link to script.
graysky2
on 4 May 2018
@graysky2
Sure, this bug still exists, but another (not reported? [1]) bug seems to be fixed (never seen it today)
It's just fishing in the dull :disappointed:
[1] unmotivated link reset
mkreisl
on 4 May 2018
The EEE issue was found internally when we first started testing for ethernet/Wireless issues after release and reports started coming in. It was fixed by a Cypress and posted to the linux-net mailing list, and we have taken it and backported to 4.14. Because of its nature, its possible it may have an effect outside the EEE issue the patch specifically fixes, hence we have suggested people try it just in case. we haven't stopped looking at other issues.
JamesH65
on 5 May 2018
@JamesH65 - Thanks for the continued diligence.
graysky2
on 5 May 2018
@graysky2 I want to mention that the Raspberry Pi 3 B+ support is now in linux-next. So it would be helpful if anyone who can reproduce this issue, also try upstream linux-next. This might give us the chance to exclude possible issues in combination with dwc_otg driver (upstream uses dwc2).
lategoodbye
on 5 May 2018
@lategoodbye
I'm using dwc2 with 4.14 kernel tree from here, just set
# CONFIG_USB_DWCOTG is not set
CONFIG_USB_DWC2=y
CONFIG_USB_DWC2_HOST=y
and enabled dwc2 in /boot/config.txt
dtoverlay=dwc2,dr_mode=host
Seems this driver is working a bit better [1] but does not solve this issue
[1] intr status -5 error messages produced here are gone. But have to test a bit more because they do not occur very often
EDIT: No, still there, happened immediate after posting
So, dwc2 does not make any difference
mkreisl
on 5 May 2018
Just wondering if there has been any new thoughts around the cause of this bug. Still present in 4.14.44.
graysky2
on 7 Jun 2018
I believe its the same issue as #2449, possibly some others as well. Actively looking in to it, but having trouble replicating.
JamesH65
on 8 Jun 2018
@JamesH65 - Thanks for the continued diligence with it. I recommend using this script which triggers the error for me very reproducibly.
graysky2
on 8 Jun 2018
@graysky2 Could you please provide the output of lsusb -t of your RPI 3B+ ?
lategoodbye
on 8 Jun 2018
Apparently I have the same problem using Pi 3 B+ (reported as #2576 ) . It is a headless box just running transmission daemon and monquitto. Torrents are downloaded on a NAS using CIFS v3. The exact same SD card worked perfectly on Raspberry Pi 2 and Raspberry Pi 3 but hangs after one hour of work on the Raspberry Pi 3 B+ requiring restart.
This are examples of the hangs:
Jun 8 15:49:59 raspberrypi kernel: [58120.469383] INFO: task transmission-da:799 blocked for more than 120 seconds.
Jun 8 15:49:59 raspberrypi kernel: [58120.471927] Tainted: G C 4.14.44-v7+ #1117
Jun 8 15:49:59 raspberrypi kernel: [58120.474426] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 8 15:49:59 raspberrypi kernel: [58120.479425] transmission-da D 0 799 1 0x00000000
Jun 8 15:50:00 raspberrypi kernel: [58120.482071] [<8079b418>] (__schedule) from [<8079ba90>] (schedule+0x50/0xa8)
Jun 8 15:50:00 raspberrypi kernel: [58120.484626] [<8079ba90>] (schedule) from [<8014b148>] (io_schedule+0x20/0x40)
Jun 8 15:50:00 raspberrypi kernel: [58120.487156] [<8014b148>] (io_schedule) from [<8021cb74>] (wait_on_page_bit+0x110/0x130)
Jun 8 15:50:00 raspberrypi kernel: [58120.492127] [<8021cb74>] (wait_on_page_bit) from [<8021cc74>] (__filemap_fdatawait_range+0xe0/0x114)
Jun 8 15:50:00 raspberrypi kernel: [58120.497281] [<8021cc74>] (__filemap_fdatawait_range) from [<8021ccd0>] (filemap_fdatawait_range+0x28/0x38)
Jun 8 15:50:00 raspberrypi kernel: [58120.502536] [<8021ccd0>] (filemap_fdatawait_range) from [<8021f084>] (filemap_write_and_wait+0x68/0x9c)
Jun 8 15:50:00 raspberrypi kernel: [58120.508125] [<8021f084>] (filemap_write_and_wait) from [<7f545028>] (cifs_reopen_file+0x364/0x430 [cifs])
Jun 8 15:50:00 raspberrypi kernel: [58120.514027] [<7f545028>] (cifs_reopen_file [cifs]) from [<7f54a3b4>] (cifs_readpages+0x408/0x6d0 [cifs])
Jun 8 15:50:00 raspberrypi kernel: [58120.519917] [<7f54a3b4>] (cifs_readpages [cifs]) from [<8022f63c>] (__do_page_cache_readahead+0x17c/0x284)
Jun 8 15:50:00 raspberrypi kernel: [58120.525833] [<8022f63c>] (__do_page_cache_readahead) from [<8022fb34>] (force_page_cache_readahead+0xb8/0x12c)
Jun 8 15:50:00 raspberrypi kernel: [58120.531787] [<8022fb34>] (force_page_cache_readahead) from [<80267934>] (SyS_fadvise64_64+0x2d4/0x314)
Jun 8 15:50:00 raspberrypi kernel: [58120.537790] [<80267934>] (SyS_fadvise64_64) from [<8010be18>] (sys_arm_fadvise64_64+0x28/0x30)
Jun 8 15:50:00 raspberrypi kernel: [58120.543911] [<8010be18>] (sys_arm_fadvise64_64) from [<80108060>] (ret_fast_syscall+0x0/0x28)
Jun 6 22:58:38 raspberrypi kernel: [ 980.956292] INFO: task transmission-da:696 blocked for more than 120 seconds.
Jun 6 22:58:38 raspberrypi kernel: [ 980.959486] Tainted: G C 4.14.44-v7+ #1117
Jun 6 22:58:38 raspberrypi kernel: [ 980.962627] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 6 22:58:38 raspberrypi kernel: [ 980.968999] transmission-da D 0 696 1 0x00000000
Jun 6 22:58:38 raspberrypi kernel: [ 980.972262] [<8079b418>] (__schedule) from [<8079ba90>] (schedule+0x50/0xa8)
Jun 6 22:58:38 raspberrypi kernel: [ 980.975402] [<8079ba90>] (schedule) from [<8014b148>] (io_schedule+0x20/0x40)
Jun 6 22:58:38 raspberrypi kernel: [ 980.978538] [<8014b148>] (io_schedule) from [<8021cb74>] (wait_on_page_bit+0x110/0x130)
Jun 6 22:58:38 raspberrypi kernel: [ 980.984608] [<8021cb74>] (wait_on_page_bit) from [<8021cc74>] (__filemap_fdatawait_range+0xe0/0x114)
Jun 6 22:58:38 raspberrypi kernel: [ 980.990671] [<8021cc74>] (__filemap_fdatawait_range) from [<8021ccd0>] (filemap_fdatawait_range+0x28/0x38)
Jun 6 22:58:38 raspberrypi kernel: [ 980.996670] [<8021ccd0>] (filemap_fdatawait_range) from [<8021f084>] (filemap_write_and_wait+0x68/0x9c)
Jun 6 22:58:38 raspberrypi kernel: [ 981.002760] [<8021f084>] (filemap_write_and_wait) from [<7f4ed028>] (cifs_reopen_file+0x364/0x430 [cifs])
Jun 6 22:58:38 raspberrypi kernel: [ 981.008991] [<7f4ed028>] (cifs_reopen_file [cifs]) from [<7f4f23b4>] (cifs_readpages+0x408/0x6d0 [cifs])
Jun 6 22:58:38 raspberrypi kernel: [ 981.015576] [<7f4f23b4>] (cifs_readpages [cifs]) from [<8022f63c>] (__do_page_cache_readahead+0x17c/0x284)
Jun 6 22:58:38 raspberrypi kernel: [ 981.022136] [<8022f63c>] (__do_page_cache_readahead) from [<8022fb34>] (force_page_cache_readahead+0xb8/0x12c)
Jun 6 22:58:38 raspberrypi kernel: [ 981.029398] [<8022fb34>] (force_page_cache_readahead) from [<80267934>] (SyS_fadvise64_64+0x2d4/0x314)
Jun 6 22:58:38 raspberrypi kernel: [ 981.036036] [<80267934>] (SyS_fadvise64_64) from [<8010be18>] (sys_arm_fadvise64_64+0x28/0x30)
Jun 6 22:58:38 raspberrypi kernel: [ 981.042513] [<8010be18>] (sys_arm_fadvise64_64) from [<80108060>] (ret_fast_syscall+0x0/0x28)
May 31 23:45:25 raspberrypi kernel: [91052.516033] INFO: task kworker/u8:0:4705 blocked for more than 120 seconds.
May 31 23:45:25 raspberrypi kernel: [91052.518051] Tainted: G C 4.14.34-v7+ #1110
May 31 23:45:25 raspberrypi kernel: [91052.519995] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 31 23:45:25 raspberrypi kernel: [91052.523674] kworker/u8:0 D 0 4705 2 0x00000000
May 31 23:45:25 raspberrypi kernel: [91052.525645] Workqueue: writeback wb_workfn (flush-cifs-27)
May 31 23:45:25 raspberrypi kernel: [91052.527692] [<8079a0b8>] (__schedule) from [<8079a730>] (schedule+0x50/0xa8)
May 31 23:45:25 raspberrypi kernel: [91052.529785] [<8079a730>] (schedule) from [<8079aba8>] (schedule_preempt_disabled+0x18/0x1c)
May 31 23:45:25 raspberrypi kernel: [91052.533927] [<8079aba8>] (schedule_preempt_disabled) from [<8079c4b0>] (__mutex_lock.constprop.3+0x190/0x58c)
May 31 23:45:25 raspberrypi kernel: [91052.538273] [<8079c4b0>] (__mutex_lock.constprop.3) from [<8079c9c8>] (__mutex_lock_slowpath+0x1c/0x20)
May 31 23:45:25 raspberrypi kernel: [91052.542856] [<8079c9c8>] (__mutex_lock_slowpath) from [<8079ca28>] (mutex_lock+0x5c/0x60)
May 31 23:45:25 raspberrypi kernel: [91052.548351] [<8079ca28>] (mutex_lock) from [<7f521ce4>] (cifs_reopen_file+0x34/0x430 [cifs])
May 31 23:45:25 raspberrypi kernel: [91052.554206] [<7f521ce4>] (cifs_reopen_file [cifs]) from [<7f525904>] (find_writable_file+0x188/0x28c [cifs])
May 31 23:45:25 raspberrypi kernel: [91052.560495] [<7f525904>] (find_writable_file [cifs]) from [<7f526128>] (cifs_writepages+0x720/0xa40 [cifs])
May 31 23:45:25 raspberrypi kernel: [91052.566693] [<7f526128>] (cifs_writepages [cifs]) from [<8022ea5c>] (do_writepages+0x30/0x8c)
May 31 23:45:25 raspberrypi kernel: [91052.572661] [<8022ea5c>] (do_writepages) from [<802bb198>] (__writeback_single_inode+0x44/0x430)
May 31 23:45:25 raspberrypi kernel: [91052.578850] [<802bb198>] (__writeback_single_inode) from [<802bba8c>] (writeback_sb_inodes+0x20c/0x4c4)
May 31 23:45:25 raspberrypi kernel: [91052.585180] [<802bba8c>] (writeback_sb_inodes) from [<802bbdd4>] (__writeback_inodes_wb+0x90/0xd0)
May 31 23:45:25 raspberrypi kernel: [91052.591646] [<802bbdd4>] (__writeback_inodes_wb) from [<802bc058>] (wb_writeback+0x244/0x358)
May 31 23:45:25 raspberrypi kernel: [91052.598297] [<802bc058>] (wb_writeback) from [<802bca58>] (wb_workfn+0x1d4/0x4d8)
May 31 23:45:25 raspberrypi kernel: [91052.605143] [<802bca58>] (wb_workfn) from [<80137490>] (process_one_work+0x158/0x454)
May 31 23:45:25 raspberrypi kernel: [91052.612071] [<80137490>] (process_one_work) from [<801377f0>] (worker_thread+0x64/0x5b8)
May 31 23:45:25 raspberrypi kernel: [91052.619175] [<801377f0>] (worker_thread) from [<8013d860>] (kthread+0x13c/0x16c)
May 31 23:45:25 raspberrypi kernel: [91052.626322] [<8013d860>] (kthread) from [<8010810c>] (ret_from_fork+0x14/0x28)
Many of the suggestions in this thread are a bit too technical for me, is there any suggested reconfiguration I could perform?
gourry
on 8 Jun 2018
Exactly same situation here. Brand new 3B+ headless, running transmission daemon and pi-hole. After a period of time, network transfers start to hang. Using Samba and SFTP, both fail.
rfpaiva
on 9 Jun 2018
@lategoodbye -
Could you please provide the output of lsusb -t of your RPI 3B+ ?
# lsusb -t
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc_otg/1p, 480M
|__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
|__ Port 1: Dev 3, If 0, Class=Hub, Driver=hub/3p, 480M
|__ Port 1: Dev 4, If 0, Class=Vendor Specific Class, Driver=lan78xx, 480M
Same here, got already 3 RPi's 3B+ each one of them lookups during night when i mount my network share. Right now it is unusable for me..,
The RPi3 B+ was released almost 3 months and the issue is still there, why it is not fixed yet?
merdok
on 10 Jun 2018
@merdok
This is my opinion to that problem
mkreisl
on 10 Jun 2018
Please run sudo ethtool -K eth0 tx off after booting and see if that makes any difference.
pelwell
on 10 Jun 2018
@pelwell -
I should mention that my /etc/config.txt hasn't touched the eee settings:
# See /boot/overlays/README for all available options
gpu_mem=64
initramfs initramfs-linux.img followkernel
#dtparam=eee=off
#dtparam=tx_lpi_timer=10000
Disabling TX checksuming fixes the issue at least as measured by this script on my test system. 30 iterations using the 1500 MB size test and and another 30 iterations using 5000 MB ran without issue :+1:
# ethtool -K eth0 tx off
Actual changes:
tx-checksumming: off
tx-checksum-ip-generic: off
tcp-segmentation-offload: off
tx-tcp-segmentation: off [requested on]
tx-tcp6-segmentation: off [requested on]
# nfstest
==> Writting round 1 for 1500 MB
1551892480 bytes (1.6 GB, 1.4 GiB) copied, 43 s, 36.1 MB/s
1500+0 records in
1500+0 records out
1572864000 bytes (1.6 GB, 1.5 GiB) copied, 43.5239 s, 36.1 MB/s
==> Run 1/30 took 43.549705810 seconds. ETA: 04:10:42 PM or about 21.04 min from now.
==> Writting round 2 for 1500 MB
1558183936 bytes (1.6 GB, 1.5 GiB) copied, 43 s, 36.2 MB/s
1500+0 records in
1500+0 records out
1572864000 bytes (1.6 GB, 1.5 GiB) copied, 43.6105 s, 36.1 MB/s
==> Run 2/30 took 43.623449720 seconds. ETA: 04:10:49 PM or about 20.35 min from now.
==> Writting round 3 for 1500 MB
...
==> Run 29/30 took 43.844378789 seconds. ETA: 04:13:00 PM or about .73 min from now.
==> Writting round 30 for 1500 MB
1566572544 bytes (1.6 GB, 1.5 GiB) copied, 43 s, 36.4 MB/s
1500+0 records in
1500+0 records out
1572864000 bytes (1.6 GB, 1.5 GiB) copied, 43.6139 s, 36.1 MB/s
==> Run 30/30 took 43.620949933 seconds. ETA: 04:13:04 PM or about 0 min from now.
nfstest 3.00s user 240.57s system 16% cpu 24:13.16 total
EDIT: The 5G test passed 30 times.
# ethtool -K eth0 tx off
Actual changes:
tx-checksumming: off
tx-checksum-ip-generic: off
tcp-segmentation-offload: off
tx-tcp-segmentation: off [requested on]
tx-tcp6-segmentation: off [requested on]
# nfstest
==> Writting round 1 for 5000 MB
5225054208 bytes (5.2 GB, 4.9 GiB) copied, 155 s, 33.7 MB/s
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 155.543 s, 33.7 MB/s
==> Run 1/30 took 155.561819965 seconds. ETA: 05:41:58 PM or about 75.18 min from now.
==> Writting round 2 for 5000 MB
5215617024 bytes (5.2 GB, 4.9 GiB) copied, 156 s, 33.4 MB/s
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 156.407 s, 33.5 MB/s
==> Run 2/30 took 156.433706123 seconds. ETA: 05:42:29 PM or about 73.00 min from now.
...
==> Run 29/30 took 154.356966099 seconds. ETA: 05:44:22 PM or about 2.57 min from now.
==> Writting round 30 for 5000 MB
5220859904 bytes (5.2 GB, 4.9 GiB) copied, 155 s, 33.7 MB/s
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 155.943 s, 33.6 MB/s
==> Run 30/30 took 155.953668009 seconds. ETA: 05:44:29 PM or about 0 min from now.
nfstest 4.49s user 790.78s system 16% cpu 1:20:23.19 total
@graysky2 I'll try your script in a moment, but can you also try with ethtool -K eth0 tx-tcp-segmentation off rather than tx off? (please reboot first to ensure a clean system)
tx off (to disable TCP checksum offload) has the side effect of disabling tcp segmentation offload too - it has to as the CPU can't compute the checksums for each of the segments that the LAN adapter is going to produce. The current understanding is that there is a failure mechanism in the segmentation, but checksumming is OK.
6by9
on 12 Jun 2018
The other thing to say is that current belief is that it only affects TCP sessions, not UDP.
It depends on the version of of NFS in use as to whether it defaults to using UDP (<=NFSv2) or TCP (>=NFSv3).
6by9
on 12 Jun 2018
Both commands give an improvement here building images on an IPv4 NFS (TCP) filesystem with Raspbian (4.14.44-v7+).
3b takes around 80 minutes
3b+ without takes around 8 hours
3b+ "tx off" 60 mins
3b+ "tx-tcp-segmentation off" 60 mins
Edit: These are times taken to build the images and when I said "without" I mean without running "ethtool" to change anything.
burtyb
on 12 Jun 2018
@burtyb Not sure what your times represent? Times before failure or overall times to build? Something else?
JamesH65
on 12 Jun 2018
Two runs of @graysky2 's script on 1500, and one at 5000 all worked fine with offloading enabled.
This is the main problem in this issue - we have no reliable way to reproduce it.
6by9
on 12 Jun 2018
I'd like to add that I can reliably cause my ethernet ssh sessions to fail or hang on fully updated Raspbian or Fedora 28 installs. My simplest way to cause the failure is to create a shared ssh connection and fire off a couple of rsync's:
ssh -o serveraliveinterval=300 -o visualhostkey=yes -i ~/.ssh/id_rsa -M -S /tmp/control user@
rsync --progress --stats --inplace --delete -nave 'ssh -o controlpath=/tmp/control' user@host:/usr /tmp/usr
So long as the rsync is sufficiently stressful, my connections will hang. rsync's -n flag included.
That said, I am happy to report that after running "ethtool -K eth0 tx off" on Raspbian, my stressful ssh/rsync sessions have not yet failed.
gbugs
on 12 Jun 2018
@gbugs What storage is that accessing on the Pi?
pelwell
on 12 Jun 2018
@pelwell my prior post referenced files on usb storage, specifically self-powered hard drives. I'm unable to replicate the bug as easily without using external storage, but I'll give it a shot.
Editing this post to keep the bug tidy. I tried pulling files after issuing "ethtool -K eth0 tx on" and results are inconsistent. I'm not at liberty to reboot but wish to do so and to re-test.
gbugs
on 12 Jun 2018
I think the test will work as expected, but it will still be an interesting datapoint.
pelwell
on 12 Jun 2018
@6by9 - I am using an NFSv4 mount:
# mount | grep nfs
192.168.1.128:/scratch on /scratch type nfs4 (rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.1.108,local_lock=none,addr=192.168.1.128)
Two runs of @graysky2 's script on 1500, and one at 5000 all worked fine with offloading enabled.
This is the main problem in this issue - we have no reliable way to reproduce it.
When I run the script with 30 iterations I consistently get errors. Sometimes on the 1st one, some times it takes more than 3. Please try it using all 30 iterations using the 1500 value which deadlocks the terminal for me. Are you using an NFSv4 mount?
I'll try your script in a moment, but can you also try with ethtool -K eth0 tx-tcp-segmentation off rather than tx off? (please reboot first to ensure a clean system)
I will try 30 iterations using 1500 and another 30 using 5000 with the setting of ethtool -K eth0 tx-tcp-segmentation off now. Will take a few hours.
EDIT: both assed without error with this setting! :+1:
# ethtool -K eth0 tx-tcp-segmentation off
# nfstest
==> Writting round 1 for 1500 MB
1524629504 bytes (1.5 GB, 1.4 GiB) copied, 42 s, 36.3 MB/s
1500+0 records in
1500+0 records out
1572864000 bytes (1.6 GB, 1.5 GiB) copied, 42.8219 s, 36.7 MB/s
==> Run 1/30 took 42.840001143 seconds. ETA: 03:42:11 PM or about 20.70 min from now.
==> Writting round 2 for 1500 MB
1560281088 bytes (1.6 GB, 1.5 GiB) copied, 43 s, 36.3 MB/s
1500+0 records in
1500+0 records out
1572864000 bytes (1.6 GB, 1.5 GiB) copied, 43.2013 s, 36.4 MB/s
==> Run 2/30 took 43.222090384 seconds. ETA: 03:42:27 PM or about 20.17 min from now.
==> Writting round 3 for 1500 MB
1569718272 bytes (1.6 GB, 1.5 GiB) copied, 44 s, 35.7 MB/s
1500+0 records in
1500+0 records out
...
And 30 iterations of 5000 MB passed as well.
# nfstest
==> Writting round 1 for 5000 MB
5239734272 bytes (5.2 GB, 4.9 GiB) copied, 162 s, 32.3 MB/s
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 162.287 s, 32.3 MB/s
==> Run 1/30 took 162.309989933 seconds. ETA: 07:41:08 PM or about 78.44 min from now.
==> Writting round 2 for 5000 MB
5226102784 bytes (5.2 GB, 4.9 GiB) copied, 158 s, 33.1 MB/s
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 158.736 s, 33.0 MB/s
==> Run 2/30 took 158.746751304 seconds. ETA: 07:39:30 PM or about 74.08 min from now.
...
==> Writting round 30 for 5000 MB
5233442816 bytes (5.2 GB, 4.9 GiB) copied, 157 s, 33.3 MB/s
5000+0 records in
5000+0 records out
5242880000 bytes (5.2 GB, 4.9 GiB) copied, 157.288 s, 33.3 MB/s
==> Run 30/30 took 157.298323510 seconds. ETA: 07:41:37 PM or about 0 min from now.
nfstest 3.86s user 858.38s system 17% cpu 1:21:44.14 total
md5-5c9c6133e89234f9218051b458107b9b
# nfstest
==> Writting round 1 for 15000 MB
15726542848 bytes (16 GB, 15 GiB) copied, 465 s, 33.8 MB/s
15000+0 records in
15000+0 records out
15728640000 bytes (16 GB, 15 GiB) copied, 465.009 s, 33.8 MB/s
==> Run 1/30 took 465.043177736 seconds. ETA: 10:29:22 AM or about 224.77 min from now.
==> Writting round 2 for 15000 MB
15715008512 bytes (16 GB, 15 GiB) copied, 465 s, 33.8 MB/s
15000+0 records in
15000+0 records out
15728640000 bytes (16 GB, 15 GiB) copied, 465.723 s, 33.8 MB/s
==> Run 2/30 took 465.736173930 seconds. ETA: 10:29:47 AM or about 217.34 min from now.
...
==> Writting round 26 for 15000 MB
15713959936 bytes (16 GB, 15 GiB) copied, 478 s, 32.9 MB/s
15000+0 records in
15000+0 records out
15728640000 bytes (16 GB, 15 GiB) copied, 478.64 s, 32.9 MB/s
==> Run 26/30 took 478.648041431 seconds. ETA: 10:36:30 AM or about 31.90 min from now.
^C
nfstest 6.89s user 2014.35s system 16% cpu 3:27:52.89 total
Using an IPv6 TCP NFS mount I'm also no longer seeing the stalls/timeouts after running sudo ethtool -K eth0 tx-tcp6-segmentation off.
burtyb
on 12 Jun 2018
@burtyb Thank you - that's the first confirmation I've seen of issues on IPv6, but it sounds like it's a very similar issue with segmentation offload.
6by9
on 13 Jun 2018
More details into investigations are on #2449.
It appears that TCP's selective acknowledge (SACK) mechanism isn't behaving as expected, so if any packets get dropped (for whatever reason) they never get retried.
Internal discussions have concluded we'll disable TCP segmentation offload (both IPv4 and IPv6) for now. The performance overhead isn't measurable using standard tools, so it's not that big a loss.
Investigations will continue to try and understand why SACK is going wrong for us, but it'll workaround the issue for now.
6by9
on 13 Jun 2018
@6by9 - Thanks for the time on this one. Can you ping this issue when with the commit of the disabling the TCP segmentation you mentioned when it is implemented? I am glad to compile the kernel with it and verify functionality.
graysky2
on 13 Jun 2018
By mentioning this issue in the commit text, Github automatically adds the link :-) I don't believe it notifies all watchers though.
I'm rebuilding now to ensure it does disable it.
A minor niggle: due to the way network devices work it isn't possible to disable TSO and yet leave it available to be enabled via ethtool. The change has to disable it totally, so there is a module parameter to make it available again.
6by9
on 13 Jun 2018
I see it... building https://github.com/raspberrypi/linux/commit/5762758699e1ddab22bf4c14eb225941761c52c8 now and will report back.
graysky2
on 13 Jun 2018
Booting the commit I referenced above indeed solves the issue. I was able to complete 30 iterations of 1500 MB and 30 iterations of 5000 MB without issue. Thanks all!
graysky2
on 13 Jun 2018
Latest rpi-update kernel includes @6by9's workaround
popcornmix
on 14 Jun 2018
@pelwell for completeness, I caused a network freeze today using a few rsyncs to pull files from the sdcard. As before, these were shared from the same ssh connection. After running "sudo ethtool -K eth0 tx-tcp-segmentation off" I haven't frozen the connection with the same conditions.
gbugs
on 15 Jun 2018
@gbugs Thanks for the report. Good to know we are getting to the bottom of this one.
JamesH65
on 15 Jun 2018
Are we happy we have solved this? If so we should close it (and crack a bottle of champagne, this was a tough one - nice work @6by9)
JamesH65
on 26 Jun 2018
Worked around, not fixed.
I've got a draft email to send to netdev, so a fix depends on what they say.
Unless anyone can still reproduce this then close this one, but keep #2449 open as it has the debugging info on.
6by9
on 26 Jun 2018
The issue is still NOT fixed! All my 3B+ crashing overnight when using Ethernet and mounting a network share.
merdok
on 27 Jun 2018
The issue is still NOT fixed! All my 3B+ crashing overnight when using Ethernet and mounting a network share.
Details about network share, protocol, method used to mount (fstab, systemd, etc.) would be helpful.
graysky2
on 27 Jun 2018
Used distribution, kernel version and the panic output is also necessary ...
lategoodbye
on 27 Jun 2018
Raspbian stretch with latest firmware. Using fstab with the following command for years now:
//ip/USB_Storage/ /home/pi/network_drive cifs vers=3.0,defaults,guest,uid=1000,iocharset=utf8,x-systemd.automount 0 0
Since 3B+ it just freezes always overnight whenever the network drive is mounted and ethernet is connected. When the network drive is not mounted or using WiFi then the Pi runs fine.
3B with the the same sd card and using ethernet doesn't crash overnight.
I suppose kernel has nothing to do with it, i have the issue since release of the 3B+ and there was already some kernel updates in that time. I got multiple 3B+ in and every one suffering the same issue.
merdok
on 27 Jun 2018
No crash visible in /var/log/messages?
Otherwise any chance to connect a display or serial connection to the RPi 3B+?
lategoodbye
on 27 Jun 2018
There is no crash log, the 3B+ is just dead and the network controller chip is burning hot. I am already scared that my house will burn down one night because of this...
Unfortunately i cannot connect a display or serial connection. Pi is running headless all the time.
merdok
on 27 Jun 2018
You haven't told us the kernel version you are running. Output of uname -a please. AFAIK the patch hasn't been released via Raspbian as yet, therefore what do you consider to be "the latest firmware"?
A full lock up and hot ethernet chip is not the same as NFS tasks hanging, therefore it does not appear to be the same issue.
Please open a new issue if you have some diagnostics that we can work with. "It randomly lockups up" is not sufficient as there is zero chance of reproducing that. What router/switch? What link speed/duplex is the ethernet actually connecting at? What have you tried? Does it work if the Pi is connected on ethernet but without a network share mounted? What else do you have connected to the Pi? All of the above on that new issue please.
6by9
on 27 Jun 2018
Kernel version 4.14.50. With latest firmware i consider "rpi-update".
I didn't say that "It randomly lockups". It lockups ALWAYS when i connect it to ethernet and mount a network share.
Like i already wrote in my previous post, yes it works over ethernet without a network share mounted. As soon as i mount a share the 3B+ is dead overnight. I have nothing else connected to the Pi, just a LAN cable.
merdok
on 27 Jun 2018
New issue please. This reported issue was that the Pi was responsive via SSH etc, but the CIFS or NFS mount died.
And I'll add the question of "what OS is exporting the share?" to the list of information required.
6by9
on 27 Jun 2018
Related issues
fivdi
·
9Comments
mi-hol
·
8Comments
pssc
·
9Comments
dkerr64
·
7Comments
Joulinar
·
5Comments