There seems to be a bug in the power saving functions of the drivers for the RTS5260 PCIe Card Reader.
The affacted file is /drivers/misc/cardreader/rtsx_pcr.c, so it would be part of /drivers/misc, as the cardreader subfolder does not have any specified maintainers according to the MAINTAINERS file in the kernel source tree.
I tried contacting Arnd Bergmann and Greg Kroah-Hartman, as they are given as the maintainers of drivers/misc, however I got no reply from Arnd for several weeks, Gregs email bot keeps deleting my mails, and there is no mailing list given for drivers/misc
As the result of this bug is a not working SD card reader, in particular, the rtsx_pci_sdmmc module, I am hoping someone here has time and knowledge to look into it.
About the bug:
Reading a card basically works, however the first command issued to the card after the chip goes into power saving fails. Due to the command timeout of 10 seconds inside the code, every new access takes 10 seconds before it is processed.
It applies to at least PCI ID 10ec:5260 (rev 01), in case there are several revsisons of the chip.
I tested this on Kernel 5.3.0 and 5.6.2, on a default Ubuntu 19.10, and a custom Gentoo installation. Both versions, Ubuntu using 5.3.0 kernel, and Gentoo using Kernel 5.6.2 have the same issue on both several Dell Precision 7530 and 7540 laptops.
How to reproduce:
1) Insert SD-Card
2) Wait for one second or more where there is no access to the card
3) dd if=/dev/mmblk0p1 of=/dev/null
4) The dd command will hang for 10 seconds without transfering a single byte, and then resume. After resuming, full (correct) transfer speed is reached, until repeating from 2). The card can stay inserted for repeated reproduction of issue.
The issue in detail:
If the rtsx_pci_idle_work() function is called, in most cases (like 90% or more), the next call to rtsx_pci_dma_transfer (i.e. reading or writing to the card) runs into its timeout and fails.
After that, the next, and all further command always succeeds and data transfer from and to the card is resumed and works correctly, until the next rtsx_pci_idle_work() call is issued. After that the same timeout happens again.
It does not matter if reading or writing occurs using a file system or direct access to the block device using dd or similar.
After some testing it looks like something how the driver or the chip itself handle leaving the power saving mode is wrong. It seems it needs a bit more delay for waking up. I do however not have the datasheet to that chip to see, if you would have to wait for some bit in a register, or if you just need a generic delay.
If I modify the rtsx_comm_pm_full_on() function in /drivers/misc/cardreader/rtsx_pcr.c and add msleep(1); directly after the rtsx_disable_aspm(pcr); call, leaving power save always works, and the card does not fail on the first command after power saving mode.
This is likely not the proper solution to the issue, however I hope it might help the current developer in identifying the correct solution.
As this bug report was written beginning of april, I now had some time to test it. I did not find any case until now, where this fix did not help.
If I can help further in any way in debugging this issue, let me know.
Attached are the changed function in /drivers/misc/cardreader/rtsx_pcr.c, and kernel logs with and without the modification:
--------------------------------------------------------------------------
Changed function in /drivers/misc/cardreader/rtsx_pcr.c (lines 139 - 151)
Just the msleep(1) was added
static void rtsx_comm_pm_full_on(struct rtsx_pcr *pcr)
{
struct rtsx_cr_option *option = &pcr->option;
rtsx_disable_aspm(pcr);
+ msleep(1);
if (option->ltr_enabled)
rtsx_set_ltr_latency(pcr, option->ltr_active_latency);
if (rtsx_check_dev_flag(pcr, LTR_L1SS_PWR_GATE_EN))
rtsx_set_l1off_sub_cfg_d0(pcr, 1);
}
--------------------------------------------------------------------------
Kernel 5.6.2 without modification:
Apr 5 21:38:25 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: pre dma sg: 4
Apr 5 21:38:25 - kernel: rtsx_pci 0000:6f:00.0: Switch card clock to 50MHz
Apr 5 21:38:25 - kernel: rtsx_pci 0000:6f:00.0: Internal SSC clock: 100MHz (cur_clock = 100)
Apr 5 21:38:25 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_read_long_data: SD/MMC CMD 18, arg = 0x00002000
Apr 5 21:38:25 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff054000, Len: 0x1000
Apr 5 21:38:25 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff055000, Len: 0x1000
Apr 5 21:38:25 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff056000, Len: 0x1000
Apr 5 21:38:25 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff057000, Len: 0x1000
Apr 5 21:38:25 - kernel: rtsx_pci 0000:6f:00.0: --> rtsx_pci_idle_work
--- waiting for 10 seconds here
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: Timeout (rtsx_pci_dma_transfer 538)
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFDA0(8): 11 01 04 08 00 1f 00 08
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFDA8(8): 10 0c 00 00 0b 00 7f 00
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFDB0(4): 02 00 00 68 00 00 00 00
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFD52(8): 04 41 00 04 0f 00 f0 00
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFD5A(8): 94 1f 52 ff 94 bb 66 aa
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFD62(8): e9 aa aa aa 24 00 04 04
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_send_cmd_get_rsp: SD/MMC CMD 12, arg = 0x00000000
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: Timeout (rtsx_pci_send_cmd 401)
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFDA0(8): 11 01 04 08 00 1f 00 08
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFDA8(8): 10 ff ff ff ff ff 7f 00
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFDB0(4): 02 00 00 08 00 00 00 00
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFD52(8): 04 41 00 04 0f 00 f0 00
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFD5A(8): 94 1f 52 ff 94 bb 66 aa
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: 0xFD62(8): e9 aa aa aa 24 00 04 04
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: rtsx_pci_send_cmd error (err = -110)
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: CMD 18 0x00002000 error(-110)
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: Switch card clock to 50MHz
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: Internal SSC clock: 100MHz (cur_clock = 100)
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_send_cmd_get_rsp: SD/MMC CMD 13, arg = 0xe6240000
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: cmd->resp[0] = 0x00400900
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: pre dma sg: 4
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: Switch card clock to 50MHz
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: Internal SSC clock: 100MHz (cur_clock = 100)
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_read_long_data: SD/MMC CMD 18, arg = 0x00002000
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff050000, Len: 0x1000
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff051000, Len: 0x1000
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff052000, Len: 0x1000
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xff053000, Len: 0x1000
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_send_cmd_get_rsp: SD/MMC CMD 12, arg = 0x00000000
Apr 5 21:38:35 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: cmd->resp[0] = 0x00000b00
Apr 5 21:38:35 - kernel: rtsx_pci 0000:6f:00.0: --> rtsx_pci_idle_work
--------------------------------------------------------------------------
Kernel 5.6.2 with msleep(1); like described above:
For testing i tried to read some bytes from the SD card using DD. dd is
called every 2 seconds, and reads 10 bytes from the SD card. The delay
between the reads is inserted, to allow the driver to go into power
saving and issue a rtsx_pci_idle_work and trigger the issue.
The 2 seconds delay between rtsx_pci_idle_work and the next log entry
are therefore not from the issue itself, but from the way I read data.
Access in file system mode, dd and everything else does not experience
any noticeable delay anymore.
Apr 5 21:42:46 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: pre dma sg: 4
Apr 5 21:42:46 - kernel: rtsx_pci 0000:6f:00.0: Switch card clock to 50MHz
Apr 5 21:42:46 - kernel: rtsx_pci 0000:6f:00.0: Internal SSC clock: 100MHz (cur_clock = 100)
Apr 5 21:42:46 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_read_long_data: SD/MMC CMD 18, arg = 0x00002000
Apr 5 21:42:46 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffbbc000, Len: 0x1000
Apr 5 21:42:46 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffbbd000, Len: 0x1000
Apr 5 21:42:46 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffbbe000, Len: 0x1000
Apr 5 21:42:46 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffbbf000, Len: 0x1000
Apr 5 21:42:46 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_send_cmd_get_rsp: SD/MMC CMD 12, arg = 0x00000000
Apr 5 21:42:46 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: cmd->resp[0] = 0x00000b00
Apr 5 21:42:46 - kernel: rtsx_pci 0000:6f:00.0: --> rtsx_pci_idle_work
-- no delay anymore
Apr 5 21:42:48 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: pre dma sg: 4
Apr 5 21:42:48 - kernel: rtsx_pci 0000:6f:00.0: Switch card clock to 50MHz
Apr 5 21:42:48 - kernel: rtsx_pci 0000:6f:00.0: Internal SSC clock: 100MHz (cur_clock = 100)
Apr 5 21:42:48 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_read_long_data: SD/MMC CMD 18, arg = 0x00002000
Apr 5 21:42:48 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffc3c000, Len: 0x1000
Apr 5 21:42:48 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffc3d000, Len: 0x1000
Apr 5 21:42:48 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffc3e000, Len: 0x1000
Apr 5 21:42:48 - kernel: rtsx_pci 0000:6f:00.0: DMA addr: 0xffc3f000, Len: 0x1000
Apr 5 21:42:48 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: sd_send_cmd_get_rsp: SD/MMC CMD 12, arg = 0x00000000
Apr 5 21:42:48 - kernel: rtsx_pci_sdmmc rtsx_pci_sdmmc.0: cmd->resp[0] = 0x00000b00
Apr 5 21:42:48 - kernel: rtsx_pci 0000:6f:00.0: --> rtsx_pci_idle_work
