Logs flooded with block_rq_complete events

[mchehab]

Logs flooded with block_rq_complete events

[kylemanna]

I see the identical error on Arch Linux kernel 5.7.2 with a Kingwin KWCR-801U3 Memory Card Reader.

The errors are reported every 2 seconds for each memory card slot that is empty. The device has 5 memory card slots. If I populate one or two slots (only cards I have) the errors drop from 5x -> 3x errors every 2 seconds.

Gist logs @ 3a90eda6565ed64ff2627ccb7f24a1d2 with

• rasdaemon logs
• bpftrace bioerr script and output
• standalone perf record and log

Seems something is polling the device every 2 seconds and it fails and returns -5.

Question I have:

• Is this the kernel polling on its own?
• Is there something in Gnome polling the device?
• Is the firmware/controller on the memory card to blame? (seems not since it works fine with real cards).
• Can these filtered or ignored if this is expected for a block device such as a memory card reader without media?

[BStrauss3]

I'm seeing them also, Arch Linux running 0.6.5-2 from AUR.

May 24 13:13:51 tock rasdaemon[25367]: rasdaemon: diskerror_eventstore: 0x559839dacf00
May 24 13:13:51 tock rasdaemon[25367]: rasdaemon: register inserted at db
May 24 13:13:51 tock rasdaemon[25367]: <...>-21 [001] 0.007774: block_rq_complete: 2020-05-24 13:13:51 -0500
May 24 13:13:53 tock rasdaemon[25367]: rasdaemon: diskerror_eventstore: 0x559839dacf00
May 24 13:13:53 tock rasdaemon[25367]: rasdaemon: register inserted at db
May 24 13:13:53 tock rasdaemon[25367]: <...>-21 [001] 0.007775: block_rq_complete: 2020-05-24 13:13:53 -0500
May 24 13:13:55 tock rasdaemon[25367]: rasdaemon: diskerror_eventstore: 0x559839dacf00
May 24 13:13:55 tock rasdaemon[25367]: rasdaemon: register inserted at db
May 24 13:13:55 tock rasdaemon[25367]: -0 [003] 0.007775: block_rq_complete: 2020-05-24 13:13:55 -0500
May 24 13:13:57 tock rasdaemon[25367]: rasdaemon: diskerror_eventstore: 0x559839dacf00
May 24 13:13:57 tock rasdaemon[25367]: rasdaemon: register inserted at db
May 24 13:13:57 tock rasdaemon[25367]: <...>-21 [001] 0.007775: block_rq_complete: 2020-05-24 13:13:57 -0500

[mchouque]

Similar thing happens on Fedora 32...

[kylemanna]

The same issues are exhibited on an old USB 2.0 IOGear GFR209 Memory Card reader, so I don't suspect that this is the device controller or firmware at this point.

[stintel]

@kylemanna great find! I have 2 Dell U2410 monitors, each with an SD card reader. Plugging in a card in one of them reduces the block_rq_complete events to one per 2 seconds. The other reader is not accessible as it is blocked by the other monitor so can't use it as a workaround. I will look into disabling the reader as a workaround until this can be filtered in rasdaemon.

[stintel]

That was easy:

echo 1 > /sys/block/sdi/device/delete

The above command inhibits the block_rq_complete event for the inaccessible card reader. So by doing this and having a card inserted in the other reader, my logs are no longer flooded. Not ideal, but good enough as a workaround.

Thanks again for pointing to card readers!

[kylemanna]

As an additional data point, this seems to be triggered by the kernel itself (not sure though, didn't dig any deeper) and is displayed with btrace:

~ ❯❯❯ sudo btrace /dev/sd{j,k,l,m,n}
  8,208  4        1     0.000000000 1971106  D   N 0 [kworker/u16:0]
  8,160  4        1     0.000896029   351  D   N 0 [kworker/4:1H]
  8,160  2        1     0.001481716    28  C   N [65531]
  8,176  2        1     0.002215997    28  C   N [65531]
  8,192  2        1     0.002240982   189  D   N 0 [kworker/2:1H]
  8,176  5        1     0.001530792   192  D   N 0 [kworker/5:1H]
  8,144  5        1     0.003275401   192  D   N 0 [kworker/5:1H]
  8,208  3        1     0.000787045    35  C   N [65531]
  8,192  3        1     0.003163968    35  C   N [65531]
  8,144  3        1     0.003949268    35  C   N [65531]
  8,176  2        2     2.134056407    28  C   N [65531]
  8,144  2        1     2.134721766    28  C   N [65531]
  8,208  2        1     2.135613506    28  C   N [65531]
  8,160  4        2     2.135647276   351  D   N 0 [kworker/4:1H]
  8,160  2        2     2.136260911    28  C   N [65531]
  8,192  2        2     2.136294531   189  D   N 0 [kworker/2:1H]
  8,192  2        3     2.137180495    28  C   N [65531]
  8,176  3        1     2.133407440 2092023  D   N 0 [kworker/u16:2]
  8,144  3        2     2.134108724   190  D   N 0 [kworker/3:1H]
  8,208  0        1     2.134767357   191  D   N 0 [kworker/0:1H]
  8,176  6        1     4.269513561   324  D   N 0 [kworker/6:1H]
  8,160  4        3     4.266711553 1971106  D   N 0 [kworker/u16:0]
  8,192  4        1     4.267451333   351  D   N 0 [kworker/4:1H]
  8,144  4        1     4.268103277   351  D   N 0 [kworker/4:1H]
  8,144  2        2     4.268701934    28  C   N [65531]
  8,160  2        3     4.267347711    28  C   N [65531]
  8,192  2        4     4.268011237    28  C   N [65531]
  8,208  2        2     4.269472730    28  C   N [65531]
  8,208  3        2     4.268780240   190  D   N 0 [kworker/3:1H]
  8,176  3        2     4.270435353    35  C   N [65531]
  8,160  7        1     6.402437598   292  D   N 0 [kworker/7:1H]
  8,192  5        1     6.401618694   192  D   N 0 [kworker/5:1H]
  8,208  2        3     6.400015344 2099065  D   N 0 [kworker/u16:5]
  8,208  2        4     6.400746353    28  C   N [65531]
  8,176  2        3     6.400786333   189  D   N 0 [kworker/2:1H]
  8,144  4        2     6.403306835 2106419  D   N 0 [kworker/u16:8]
  8,176  6        2     6.401546412    56  C   N [65531]
  8,192  6        1     6.402379568    56  C   N [65531]
  8,160  6        1     6.403024128    56  C   N [65531]
  8,144  6        1     6.403950697    56  C   N [65531]
  8,192  6        2     8.535625476   324  D   N 0 [kworker/6:1H]
  8,144  1        1     8.533310599 2106419  D   N 0 [kworker/u16:8]
  8,160  1        1     8.534111119   294  D   N 0 [kworker/1:1H]
  8,208  7        1     8.536296498   292  D   N 0 [kworker/7:1H]
  8,144  2        3     8.534055160    28  C   N [65531]
  8,160  2        4     8.534901067    28  C   N [65531]
  8,176  2        4     8.535580824    28  C   N [65531]
  8,192  2        5     8.536218365    28  C   N [65531]
  8,208  2        5     8.537182627    28  C   N [65531]
  8,176  4        1     8.534957975   351  D   N 0 [kworker/4:1H]
  8,208  6        1    10.667369536    56  C   N [65531]
  8,192  6        3    10.671544493   324  D   N 0 [kworker/6:1H]
  8,192  6        4    10.672275125    56  C   N [65531]
  8,208  1        1    10.666689562 1971106  D   N 0 [kworker/u16:0]
  8,176  1        1    10.667442261   294  D   N 0 [kworker/1:1H]
  8,176  2        5    10.668204709    28  C   N [65531]
  8,160  2        5    10.670772221    28  C   N [65531]
  8,144  2        4    10.671500585    28  C   N [65531]
  8,160  4        4    10.670013979 2055637  D   N 0 [kworker/u16:1]
  8,144  4        3    10.670856289   351  D   N 0 [kworker/4:1H]

[WildPenquin]

Just ejecting and re-inserting an optical disc into a drive will cause a flood of these messages.

Is there a workaround? Echoing 1 to /sys/block/sdi/[DEVICE]/delete gets rid of these messages but also the block device ;-).

[stintel]

Still happens on 0.6.8. I no longer have the monitors with built-in SD card readers, but as soon as I plug in an USB SD card reader, there's again a journal entry appearing every 2 seconds.

[mchehab]

Version 0.7.0 uses a new event to monitor disk errors. It requires Kernel 5.18 or upper. Hopefully this should help with the issue.