| Message ID | 20210514155318.16812-1-uli+renesas@fpond.eu (mailing list archive) |
|---|---|
| State | Under Review |
| Delegated to: | Geert Uytterhoeven |
| Headers | show |
| Series | mmc: renesas_sdhi: increase suspend/resume latency limit | expand |
Hi Uli, On Fri, May 14, 2021 at 05:53:18PM +0200, Ulrich Hecht wrote: > The TMIO core sets a very low latency limit (100 us), but when using R-Car > SDHI hosts with SD cards, I have observed typical latencies of around 20-30 > ms. This prevents runtime PM from working properly, and the devices remain > on continuously. > > This patch sets the default latency limit to 100 ms to avoid that. > > Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> Well, yes, I can confirm that this helps wrt the "always-enabled" clock. However, when removing UHS cards, I now see this regression: [ 8.659916] mmcblk2: mmc2:0001 00000 29.8 GiB [ 8.677304] mmcblk2: p1 [ 9.622918] mmc2: tuning execution failed: -5 [ 9.627385] mmc2: card 0001 removed It is interesting to see the "execution failed" error when *removing* the card. Before removing, access to the card seems fine. I haven't checked further, so I can't say yet if this is a related or seperate but now undiscovered issue. Thanks for the work so far! Wolfram
> On 05/19/2021 4:25 PM Wolfram Sang <wsa@kernel.org> wrote: > On Fri, May 14, 2021 at 05:53:18PM +0200, Ulrich Hecht wrote: > > The TMIO core sets a very low latency limit (100 us), but when using R-Car > > SDHI hosts with SD cards, I have observed typical latencies of around 20-30 > > ms. This prevents runtime PM from working properly, and the devices remain > > on continuously. > > > > This patch sets the default latency limit to 100 ms to avoid that. > > > > Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> > > Well, yes, I can confirm that this helps wrt the "always-enabled" clock. > However, when removing UHS cards, I now see this regression: > > [ 8.659916] mmcblk2: mmc2:0001 00000 29.8 GiB > [ 8.677304] mmcblk2: p1 > [ 9.622918] mmc2: tuning execution failed: -5 > [ 9.627385] mmc2: card 0001 removed > > It is interesting to see the "execution failed" error when *removing* > the card. Before removing, access to the card seems fine. I haven't > checked further, so I can't say yet if this is a related or seperate but > now undiscovered issue. I have traced this, and it seems to be triggered by mmc_sd_detect(), which is called by mmc_rescan() and does this: [...] /* * Just check if our card has been removed. */ err = _mmc_detect_card_removed(host); mmc_put_card(host->card, NULL); if (err) { mmc_sd_remove(host); [...] _mmc_detect_card_removed() calls mmc_sd_alive(), which tries to send a command to the SD card to see if it's still there, which in turn triggers the retune. IOW, this is expected to fail, and the error message is misleading. CU Uli
Hi Uli, > _mmc_detect_card_removed() calls mmc_sd_alive(), which tries to send a > command to the SD card to see if it's still there, which in turn > triggers the retune. IOW, this is expected to fail, and the error > message is misleading. This makes perfect sense to me. I disabled tuning in _mmc_detect_card_removed() and the message is gone, of course. I'll send a patch right away. With that sorted out, the patch works for me nicely and we have *finally* RPM kicking in for SDHI. Looks good to me. Reviewed-by: Wolfram Sang <wsa+renesas@sang-engineering.com> However, I'd appreciate if Shimoda-san could also test this against his test-suite to make sure there are no other issues unearthed now that RPM is finally suspending the device. I will also add do additional suspend/resume tests before I say Tested-by. Good work so far, thanks!
> is finally suspending the device. I will also add do additional > suspend/resume tests before I say Tested-by. So, I could not find a regression. I checked that RPM disables the clock between reads and reenables them properly when needed. Also, suspend/resume works, even when the resume happens in the middle of a transfer. No issues with bus width etc. Looks good. Tested-by: Wolfram Sang <wsa+renesas@sang-engineering.com>
On Fri, May 14, 2021 at 05:53:18PM +0200, Ulrich Hecht wrote: > The TMIO core sets a very low latency limit (100 us), but when using R-Car > SDHI hosts with SD cards, I have observed typical latencies of around 20-30 > ms. This prevents runtime PM from working properly, and the devices remain > on continuously. > > This patch sets the default latency limit to 100 ms to avoid that. > > Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> Ulrich is right that the tuning error is just a cosmetic problem revealed by this patch and not really a regression. We are working on fixing this cosmetic problem. However, this patch is good as is and we finally have RPM working for SDHI with it. I tested RPM and suspend/resume and all worked nicely: Reviewed-by: Wolfram Sang <wsa+renesas@sang-engineering.com> Tested-by: Wolfram Sang <wsa+renesas@sang-engineering.com>
On Fri, May 14, 2021 at 05:53:18PM +0200, Ulrich Hecht wrote: > The TMIO core sets a very low latency limit (100 us), but when using R-Car > SDHI hosts with SD cards, I have observed typical latencies of around 20-30 > ms. This prevents runtime PM from working properly, and the devices remain > on continuously. > > This patch sets the default latency limit to 100 ms to avoid that. > > Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> Adding Shimoda-san to CC. Shimoda-san: can you kindly run your SDHI tests with this patch applied? That would be very kind, thank you! > --- > drivers/mmc/host/renesas_sdhi_core.c | 4 ++++ > 1 file changed, 4 insertions(+) > > diff --git a/drivers/mmc/host/renesas_sdhi_core.c b/drivers/mmc/host/renesas_sdhi_core.c > index 635bf31a6735..4f41616cc6bb 100644 > --- a/drivers/mmc/host/renesas_sdhi_core.c > +++ b/drivers/mmc/host/renesas_sdhi_core.c > @@ -32,6 +32,7 @@ > #include <linux/pinctrl/pinctrl-state.h> > #include <linux/platform_device.h> > #include <linux/pm_domain.h> > +#include <linux/pm_qos.h> > #include <linux/regulator/consumer.h> > #include <linux/reset.h> > #include <linux/sh_dma.h> > @@ -1147,6 +1148,9 @@ int renesas_sdhi_probe(struct platform_device *pdev, > host->ops.hs400_complete = renesas_sdhi_hs400_complete; > } > > + /* keep tmio_mmc_host_probe() from setting latency limit too low */ > + dev_pm_qos_expose_latency_limit(&pdev->dev, 100000); > + > ret = tmio_mmc_host_probe(host); > if (ret < 0) > goto edisclk; > -- > 2.20.1 >
Hi Wolfram-san, Ulrich-san, > From: Wolfram Sang, Sent: Saturday, July 31, 2021 12:28 AM > > On Fri, May 14, 2021 at 05:53:18PM +0200, Ulrich Hecht wrote: > > The TMIO core sets a very low latency limit (100 us), but when using R-Car > > SDHI hosts with SD cards, I have observed typical latencies of around 20-30 > > ms. This prevents runtime PM from working properly, and the devices remain > > on continuously. > > > > This patch sets the default latency limit to 100 ms to avoid that. > > > > Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> > > Adding Shimoda-san to CC. > > Shimoda-san: can you kindly run your SDHI tests with this patch applied? Sure! However, I have a question about this patch. Would you know how to measure the latencies? I enabled function trace of rpm and checked the log, but I could not observe any behavior changes with and without applying this patch. --- echo 1 > /sys/kernel/debug/tracing/events/rpm/enable dd if=/dev/mmcblk1 of=/dev/null bs=4k count=1 cat /sys/kernel/debug/tracing/trace # /root/trace/read.sh # tracer: nop # # entries-in-buffer/entries-written: 36/36 #P:8 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | kworker/4:1H-307 [004] d..1 125.845356: rpm_resume: mmc0:0001 flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.845401: rpm_resume: ee140000.mmc flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.867766: rpm_idle: ee140000.mmc flags-1 cnt-1 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.867774: rpm_return_int: rpm_idle+0x40/0x3d0:ee140000.mmc ret=-11 kworker/4:1H-307 [004] d..1 125.867785: rpm_idle: soc flags-5 cnt-0 dep-1 auto-1 p-0 irq-0 child-27 kworker/4:1H-307 [004] d..1 125.867788: rpm_return_int: rpm_idle+0x40/0x3d0:soc ret=-13 kworker/4:1H-307 [004] d..1 125.867796: rpm_return_int: rpm_resume+0x124/0x6d8:ee140000.mmc ret=0 kworker/4:1H-307 [004] d..1 125.867819: rpm_suspend: ee140000.mmc flags-d cnt-0 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.867948: rpm_return_int: rpm_suspend+0x150/0x620:ee140000.mmc ret=0 kworker/4:1H-307 [004] d..1 125.867962: rpm_idle: mmc0:0001 flags-1 cnt-1 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.867965: rpm_return_int: rpm_idle+0x40/0x3d0:mmc0:0001 ret=-11 kworker/4:1H-307 [004] d..1 125.867974: rpm_idle: mmc0 flags-5 cnt-0 dep-1 auto-1 p-0 irq-0 child-1 kworker/4:1H-307 [004] d..1 125.867978: rpm_return_int: rpm_idle+0x40/0x3d0:mmc0 ret=-13 kworker/4:1H-307 [004] d..1 125.867985: rpm_return_int: rpm_resume+0x124/0x6d8:mmc0:0001 ret=0 kworker/4:1H-307 [004] d..1 125.868009: rpm_resume: ee140000.mmc flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.868013: rpm_return_int: rpm_resume+0x124/0x6d8:ee140000.mmc ret=1 kworker/0:1H-295 [000] d..1 125.879823: rpm_suspend: ee140000.mmc flags-d cnt-0 dep-0 auto-1 p-0 irq-0 child-0 kworker/0:1H-295 [000] d..1 125.879833: rpm_return_int: rpm_suspend+0x150/0x620:ee140000.mmc ret=0 kworker/0:1H-295 [000] d..1 125.879843: rpm_suspend: mmc0:0001 flags-d cnt-0 dep-0 auto-1 p-0 irq-0 child-0 kworker/0:1H-295 [000] d..1 125.879856: rpm_return_int: rpm_suspend+0x150/0x620:mmc0:0001 ret=0 kworker/4:1H-307 [004] d..1 125.880562: rpm_resume: mmc0:0001 flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.880569: rpm_return_int: rpm_resume+0x124/0x6d8:mmc0:0001 ret=1 kworker/4:1H-307 [004] d..1 125.880591: rpm_resume: ee140000.mmc flags-4 cnt-1 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:1H-307 [004] d..1 125.880594: rpm_return_int: rpm_resume+0x124/0x6d8:ee140000.mmc ret=1 kworker/0:1H-295 [000] d..1 125.883242: rpm_suspend: ee140000.mmc flags-d cnt-0 dep-0 auto-1 p-0 irq-0 child-0 kworker/0:1H-295 [000] d..1 125.883249: rpm_return_int: rpm_suspend+0x150/0x620:ee140000.mmc ret=0 kworker/0:1H-295 [000] d..1 125.883258: rpm_suspend: mmc0:0001 flags-d cnt-0 dep-0 auto-1 p-0 irq-0 child-0 kworker/0:1H-295 [000] d..1 125.883262: rpm_return_int: rpm_suspend+0x150/0x620:mmc0:0001 ret=0 <idle>-0 [004] d.h2 125.928997: rpm_suspend: ee140000.mmc flags-9 cnt-0 dep-0 auto-1 p-0 irq-0 child-0 <idle>-0 [004] d.h2 125.929015: rpm_return_int: rpm_suspend+0x150/0x620:ee140000.mmc ret=0 <idle>-0 [004] d.h2 125.945766: rpm_suspend: ee140000.mmc flags-9 cnt-0 dep-0 auto-1 p-0 irq-0 child-0 <idle>-0 [004] dNh2 125.945808: rpm_return_int: rpm_suspend+0x150/0x620:ee140000.mmc ret=0 kworker/4:2-361 [004] d..1 125.945872: rpm_suspend: ee140000.mmc flags-a cnt-0 dep-0 auto-1 p-0 irq-0 child-0 kworker/4:2-361 [004] d..1 125.945956: rpm_idle: soc flags-1 cnt-0 dep-1 auto-1 p-0 irq-0 child-26 kworker/4:2-361 [004] d..1 125.945960: rpm_return_int: rpm_idle+0x40/0x3d0:soc ret=-13 kworker/4:2-361 [004] d..1 125.945966: rpm_return_int: rpm_suspend+0x150/0x620:ee140000.mmc ret=0 --- Best regards, Yoshihiro Shimoda > That would be very kind, thank you! > > > --- > > drivers/mmc/host/renesas_sdhi_core.c | 4 ++++ > > 1 file changed, 4 insertions(+) > > > > diff --git a/drivers/mmc/host/renesas_sdhi_core.c b/drivers/mmc/host/renesas_sdhi_core.c > > index 635bf31a6735..4f41616cc6bb 100644 > > --- a/drivers/mmc/host/renesas_sdhi_core.c > > +++ b/drivers/mmc/host/renesas_sdhi_core.c > > @@ -32,6 +32,7 @@ > > #include <linux/pinctrl/pinctrl-state.h> > > #include <linux/platform_device.h> > > #include <linux/pm_domain.h> > > +#include <linux/pm_qos.h> > > #include <linux/regulator/consumer.h> > > #include <linux/reset.h> > > #include <linux/sh_dma.h> > > @@ -1147,6 +1148,9 @@ int renesas_sdhi_probe(struct platform_device *pdev, > > host->ops.hs400_complete = renesas_sdhi_hs400_complete; > > } > > > > + /* keep tmio_mmc_host_probe() from setting latency limit too low */ > > + dev_pm_qos_expose_latency_limit(&pdev->dev, 100000); > > + > > ret = tmio_mmc_host_probe(host); > > if (ret < 0) > > goto edisclk; > > -- > > 2.20.1 > >
> On 08/02/2021 7:34 AM Yoshihiro Shimoda <yoshihiro.shimoda.uh@renesas.com> wrote: > > > Hi Wolfram-san, Ulrich-san, > > > From: Wolfram Sang, Sent: Saturday, July 31, 2021 12:28 AM > > > > On Fri, May 14, 2021 at 05:53:18PM +0200, Ulrich Hecht wrote: > > > The TMIO core sets a very low latency limit (100 us), but when using R-Car > > > SDHI hosts with SD cards, I have observed typical latencies of around 20-30 > > > ms. This prevents runtime PM from working properly, and the devices remain > > > on continuously. > > > > > > This patch sets the default latency limit to 100 ms to avoid that. > > > > > > Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> > > > > Adding Shimoda-san to CC. > > > > Shimoda-san: can you kindly run your SDHI tests with this patch applied? > > Sure! > > However, I have a question about this patch. > Would you know how to measure the latencies? IIRC I simply put a printk() in default_suspend_ok() that dumps td->suspend_latency_ns and td->resume_latency_ns. > I enabled function trace of rpm and checked the log, but I could not observe > any behavior changes with and without applying this patch. So you are saying that for you, the clock is suspended as expected when removing the card, even without this patch? If so, I wonder if there are variations between boards... CU Uli
> Would you know how to measure the latencies?
I didn't measure the latencies itself. I just checked 'clk_summary' in
debugfs and verified that finally clocks are disabled by RPM. Because
only with this patch, clk_enable-cnt goes to zero when SD card is
removed or eMMC has no activity.
Hi Wolfram-san, > From: Wolfram Sang, Sent: Monday, August 2, 2021 9:53 PM > > > Would you know how to measure the latencies? > > I didn't measure the latencies itself. I just checked 'clk_summary' in > debugfs and verified that finally clocks are disabled by RPM. Because > only with this patch, clk_enable-cnt goes to zero when SD card is > removed or eMMC has no activity. Thank you for your comment! Now I understood :) So, I'll test this patch with my test environment tomorrow. Best regards, Yoshihiro Shimoda
Hi Ulrich-san, Thank you for your comments! > From: Ulrich Hecht, Sent: Monday, August 2, 2021 8:18 PM > > > On 08/02/2021 7:34 AM Yoshihiro Shimoda <yoshihiro.shimoda.uh@renesas.com> wrote: > > > > > > Hi Wolfram-san, Ulrich-san, > > > > > From: Wolfram Sang, Sent: Saturday, July 31, 2021 12:28 AM > > > > > > On Fri, May 14, 2021 at 05:53:18PM +0200, Ulrich Hecht wrote: > > > > The TMIO core sets a very low latency limit (100 us), but when using R-Car > > > > SDHI hosts with SD cards, I have observed typical latencies of around 20-30 > > > > ms. This prevents runtime PM from working properly, and the devices remain > > > > on continuously. > > > > > > > > This patch sets the default latency limit to 100 ms to avoid that. > > > > > > > > Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> > > > > > > Adding Shimoda-san to CC. > > > > > > Shimoda-san: can you kindly run your SDHI tests with this patch applied? > > > > Sure! > > > > However, I have a question about this patch. > > Would you know how to measure the latencies? > > IIRC I simply put a printk() in default_suspend_ok() that dumps td->suspend_latency_ns and td->resume_latency_ns. Thanks! I could get the latencies. > > I enabled function trace of rpm and checked the log, but I could not observe > > any behavior changes with and without applying this patch. > > So you are saying that for you, the clock is suspended as expected when removing the card, even without this patch? > If so, I wonder if there are variations between boards... I'm sorry, I only observed the trace log. As Wolfram-san mentioned on other email thread, I should check the clk_summary whether the clock is enabled or not. So, I'll test this patch with my test environment tomorrow. > CU > Uli
Hi Ulrich-san again, > From: Yoshihiro Shimoda, Sent: Tuesday, August 3, 2021 8:17 PM > > So, I'll test this patch with my test environment tomorrow. Unfortunately, this patch failed on mmc_test driver. I'm not sure, but perhaps we have a potential issue on runtime PM with SDHI driver? < My environment > - H3 ES3.0 Salvator-XS - kernel v5.14-rc2 - buildroot v2020.02.10 < How to test > # mount -t debugfs none /sys/kernel/debug # ./bind.sh mmc0:0001 # ./test.sh mmc0 mmc0;0001 38 38 # ./test.sh mmc0 mmc0;0001 38 38 CAUTION: The mmc_test driver will overwrite any data of the device.. < Results > - When I tested on an eMMC, the issue happened. -- But, when I tested on a sd card, the issue didn't happen. - The mmc_test failed after test case 38. -- After that, I could not recover the device even if I issued test case 45(Reset). -- Once the test case 38 was OK, but after that, any test case failed. - When I changed the latency value via sysfs as 100, the issue didn't happen. # echo 100 > /sys/devices/platform/soc/ee140000.mmc/power/pm_qos_resume_latency_us < Issue > # ./test.sh mmc0 mmc0:0001 38 38 [ 90.688971] mmc0: Starting tests of card mmc0:0001... [ 90.718703] mmc0: Test case 38. Write performance with non-blocking req 4k to 4MB... [ 90.762127] [mmc_test_rw_multiple] error [ 90.770964] mmc0: Result: ERROR (-84) [ 90.779551] mmc0: Tests completed. < My scripts > --- bind.sh --- #!/bin/sh if [ $# -ne 2 ]; then echo "[dev] [bind or unbind]" echo "dev list (for bind)" ls -la /sys/bus/mmc/drivers/mmcblk echo "dev list (for unbind)" ls -la /sys/bus/mmc/drivers/mmc_test exit fi if [ $2 = "bind" ]; then echo $1 > /sys/bus/mmc/drivers/mmcblk/unbind echo $1 > /sys/bus/mmc/drivers/mmc_test/bind elif [ $2 = "unbind" ]; then echo $1 > /sys/bus/mmc/drivers/mmc_test/unbind echo $1 > /sys/bus/mmc/drivers/mmcblk/bind fi --------------- --- test.sh --- #!/bin/sh if [ $# -ne 4 ]; then echo "[dev base] [dev] [start] [end]" if [ $# -eq 2 ]; then echo "testlist" cat /sys/kernel/debug/$1/$2/testlist fi exit fi dev_base=$1 dev=$2 start=$3 end=$4 i=$start while [ $i -le $end ] ; do echo $i > /sys/kernel/debug/$dev_base/$dev/test sleep 1 i=`expr $i + 1` done --------------- Best regards, Yoshihiro Shimoda
> On 08/04/2021 7:29 AM Yoshihiro Shimoda <yoshihiro.shimoda.uh@renesas.com> wrote: > > From: Yoshihiro Shimoda, Sent: Tuesday, August 3, 2021 8:17 PM > > > > So, I'll test this patch with my test environment tomorrow. > > Unfortunately, this patch failed on mmc_test driver. Confirmed on Salvator-XS M3-N. :/ > I'm not sure, but perhaps we have a potential issue on runtime PM with SDHI driver? It sure feels like it. CU Uli
diff --git a/drivers/mmc/host/renesas_sdhi_core.c b/drivers/mmc/host/renesas_sdhi_core.c index 635bf31a6735..4f41616cc6bb 100644 --- a/drivers/mmc/host/renesas_sdhi_core.c +++ b/drivers/mmc/host/renesas_sdhi_core.c @@ -32,6 +32,7 @@ #include <linux/pinctrl/pinctrl-state.h> #include <linux/platform_device.h> #include <linux/pm_domain.h> +#include <linux/pm_qos.h> #include <linux/regulator/consumer.h> #include <linux/reset.h> #include <linux/sh_dma.h> @@ -1147,6 +1148,9 @@ int renesas_sdhi_probe(struct platform_device *pdev, host->ops.hs400_complete = renesas_sdhi_hs400_complete; } + /* keep tmio_mmc_host_probe() from setting latency limit too low */ + dev_pm_qos_expose_latency_limit(&pdev->dev, 100000); + ret = tmio_mmc_host_probe(host); if (ret < 0) goto edisclk;
The TMIO core sets a very low latency limit (100 us), but when using R-Car SDHI hosts with SD cards, I have observed typical latencies of around 20-30 ms. This prevents runtime PM from working properly, and the devices remain on continuously. This patch sets the default latency limit to 100 ms to avoid that. Signed-off-by: Ulrich Hecht <uli+renesas@fpond.eu> --- drivers/mmc/host/renesas_sdhi_core.c | 4 ++++ 1 file changed, 4 insertions(+)