Hi,
As per the info from kernelnewbies IRC, I'm sending this also to the PCI
list.
There seems to be a bug in the power saving functions of the drivers
forthe RTS5260 PCIe Card Reader. 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 revsions of the chip.
I tested this on Kernel 5.3.0, 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, most of the time (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 command always succeeds and data transfer from and
to the card is resumed and works correctly, until the next
rtsx_pic_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.
If I modify the rtsx_comm_pm_full_on() function 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. It
looks like something needs a little more time to wake up before issuing
a new DMA access.
If I can help further in any way in debugging this issue, let me know.
Attached are the changed function in rtsx_pcr.c, and kernel logs with
and without the modification:
--------------------------------------------------------------------------
Changed funcion in rtsx_pcr.c (lines 139 - 151)
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
