sdhci: fix the fake timeout bug

From b893df3a1a937bd5fe22d39ceae93454a2e5e0e4 Mon Sep 17 00:00:00 2001

From the clock control register dump, we are pretty sure the clock was

Quoted 1 line

From b893df3a1a937bd5fe22d39ceae93454a2e5e0e4 Mon Sep 17 00:00:00 2001

From: Alek Du <[email protected]>
Date: Fri, 30 Nov 2018 14:02:28 +0800
Subject: [PATCH] sdhci: fix the fake timeout bug

We observed some fake timeouts on some devices, the log is like this:

[ 7586.290201] mmc1: Timeout waiting for hardware cmd interrupt.
[ 7586.290420] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
...
[ 7586.291774] mmc1: sdhci: Wake-up:   0x00000000 | Clock:    0x00000203

Quoted 1 line

From the clock control register dump, we are pretty sure the clock was

stabilized.

In other cases, we also observed:

[ 7596.530171] mmc1: Timeout waiting for hardware cmd interrupt.

and

[ 1956.534634] mmc1: Reset 0x2 never completed.

But we are pretty sure the mmc controller is working perfectly under low system load.

After checking the sdhci code, we found the timeout check actually has a little window that the CPU can be scheduled out and when it comes back, the original time set or check is not valid.

Signed-off-by Alek Du <[email protected]>

---
 drivers/mmc/host/sdhci.c | 19 ++++++++++++++++---
 1 file changed, 16 insertions(+), 3 deletions(-)

drivers/mmc/host/sdhci.c +16 -3

index 99bdae53fa2e..f88c49fc574e 100644
@@ -218,12 +218,17 @@ void sdhci_reset(struct sdhci_host *host, u8 mask)
 	/* hw clears the bit when it's done */
 	while (sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask) {
 		if (ktime_after(ktime_get(), timeout)) {
+			/* check it again, since there is a window between
+			   bit check and time check */
+			if (!(sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask))
+				break;
 			pr_err("%s: Reset 0x%x never completed.\n",
 				mmc_hostname(host->mmc), (int)mask);
 			sdhci_dumpregs(host);
 			return;
+		} else {
+			udelay(10);
 		}
-		udelay(10);
 	}
 }
 EXPORT_SYMBOL_GPL(sdhci_reset);

@@ -1395,9 +1400,10 @@ void sdhci_send_command(struct sdhci_host *host, struct mmc_command *cmd)
 		timeout += DIV_ROUND_UP(cmd->busy_timeout, 1000) * HZ + HZ;
 	else
 		timeout += 10 * HZ;
-	sdhci_mod_timer(host, cmd->mrq, timeout);
 
 	sdhci_writew(host, SDHCI_MAKE_CMD(cmd->opcode, flags), SDHCI_COMMAND);
+	/* setup timer after command to avoid fake timeout */
+	sdhci_mod_timer(host, cmd->mrq, timeout);
 }
 EXPORT_SYMBOL_GPL(sdhci_send_command);
 

@@ -1611,12 +1617,19 @@ void sdhci_enable_clk(struct sdhci_host *host, u16 clk)
 	while (!((clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL))
 		& SDHCI_CLOCK_INT_STABLE)) {
 		if (ktime_after(ktime_get(), timeout)) {
+			/* check it again since there is a window between
+			   status check and time check */
+			if ((clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL))
+					& SDHCI_CLOCK_INT_STABLE)
+				break;
 			pr_err("%s: Internal clock never stabilised.\n",
 			       mmc_hostname(host->mmc));
 			sdhci_dumpregs(host);
 			return;
 		}
-		udelay(10);
+		else {
+			udelay(10);
+		}
 	}
 
 	clk |= SDHCI_CLOCK_CARD_EN;

Commands and resets are under spin lock, so no possibility for preemption, and certainly a few microseconds isn't going to make any difference to these timeouts, so I don't see how this patch could help.

I recently sent a patch for GLK laptops that had BIOS issues:

	https://marc.info/?l=linux-mmc&m=154270005901609

And also some improvements to error handling:

	https://marc.info/?l=linux-mmc&m=154229013900437

If those don't help, please share more details of the actual problem.

Quoted 69 lines

Signed-off-by Alek Du <[email protected]>

---
 drivers/mmc/host/sdhci.c | 19 ++++++++++++++++---
 1 file changed, 16 insertions(+), 3 deletions(-)

drivers/mmc/host/sdhci.c +0 -0

index 99bdae53fa2e..f88c49fc574e 100644
@@ -218,12 +218,17 @@ void sdhci_reset(struct sdhci_host *host, u8

mask) /* hw clears the bit when it's done */

drivers/mmc/host/sdhci.c +1 -0

 	while (sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask) {
 		if (ktime_after(ktime_get(), timeout)) {
+			/* check it again, since there is a window

between

drivers/mmc/host/sdhci.c +2 -0

+			   bit check and time check */
+			if (!(sdhci_readb(host,

SDHCI_SOFTWARE_RESET) & mask))

drivers/mmc/host/sdhci.c +1 -0

+				break;
 			pr_err("%s: Reset 0x%x never completed.\n",
 				mmc_hostname(host->mmc),

(int)mask); sdhci_dumpregs(host);

drivers/mmc/host/sdhci.c +2 -1

 			return;
+		} else {
+			udelay(10);
 		}
-		udelay(10);
 	}
 }
 EXPORT_SYMBOL_GPL(sdhci_reset);

@@ -1395,9 +1400,10 @@ void sdhci_send_command(struct sdhci_host
 *host, struct mmc_command *cmd) timeout +=

DIV_ROUND_UP(cmd->busy_timeout, 1000) * HZ + HZ; else

drivers/mmc/host/sdhci.c +0 -1

 		timeout += 10 * HZ;
-	sdhci_mod_timer(host, cmd->mrq, timeout);
 
 	sdhci_writew(host, SDHCI_MAKE_CMD(cmd->opcode, flags),

SDHCI_COMMAND);

drivers/mmc/host/sdhci.c +3 -0

+	/* setup timer after command to avoid fake timeout */
+	sdhci_mod_timer(host, cmd->mrq, timeout);
 }
 EXPORT_SYMBOL_GPL(sdhci_send_command);

@@ -1611,12 +1617,19 @@ void sdhci_enable_clk(struct sdhci_host
 *host, u16 clk) while (!((clk = sdhci_readw(host,
 SDHCI_CLOCK_CONTROL)) & SDHCI_CLOCK_INT_STABLE)) {
 		if (ktime_after(ktime_get(), timeout)) {
+			/* check it again since there is a window

between

drivers/mmc/host/sdhci.c +2 -0

+			   status check and time check */
+			if ((clk = sdhci_readw(host,

SDHCI_CLOCK_CONTROL))

drivers/mmc/host/sdhci.c +2 -0

+					& SDHCI_CLOCK_INT_STABLE)
+				break;
 			pr_err("%s: Internal clock never

stabilised.\n", mmc_hostname(host->mmc));

drivers/mmc/host/sdhci.c +3 -1

 			sdhci_dumpregs(host);
 			return;
 		}
-		udelay(10);
+		else {
+			udelay(10);
+		}
 	}
 
 	clk |= SDHCI_CLOCK_CARD_EN;

Quoted 4 lines · On Fri, 30 Nov 2018 11:19:03 +0200 Adrian Hunter <[email protected]>…

Commands and resets are under spin lock, so no possibility for preemption, and certainly a few microseconds isn't going to make any difference to these timeouts, so I don't see how this patch could help.

Thanks for your review.

I believe my case the scheduling out delay sometime can reach 10~20 milliseconds... This may be due to the hypervisor...

Please look at the sdhci_enable_clk() below, there is a window in clock stabilization check. The first check is to check status register, the second check is to check if time passed. That's why I can capture a case that after time passed, the actually clock control register indicated that clock is stable. So the error handling is wrong...

Also the sdhci_send_command commands is not in spin lock There is a windows between mod_timer and real command send...

Thanks,
Alek

Quoted 10 lines

I recently sent a patch for GLK laptops that had BIOS issues:

	https://marc.info/?l=linux-mmc&m=154270005901609

And also some improvements to error handling:

	https://marc.info/?l=linux-mmc&m=154229013900437

If those don't help, please share more details of the actual problem.

Sorry, I can't see how this patches could fix my problem.

Quoted 70 lines

Quoted 69 lines

Signed-off-by Alek Du <[email protected]>

---
 drivers/mmc/host/sdhci.c | 19 ++++++++++++++++---
 1 file changed, 16 insertions(+), 3 deletions(-)

drivers/mmc/host/sdhci.c +0 -0

index 99bdae53fa2e..f88c49fc574e 100644
@@ -218,12 +218,17 @@ void sdhci_reset(struct sdhci_host *host, u8

mask) /* hw clears the bit when it's done */

drivers/mmc/host/sdhci.c +1 -0

 	while (sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask) {
 		if (ktime_after(ktime_get(), timeout)) {
+			/* check it again, since there is a window

between

drivers/mmc/host/sdhci.c +2 -0

+			   bit check and time check */
+			if (!(sdhci_readb(host,

SDHCI_SOFTWARE_RESET) & mask))

drivers/mmc/host/sdhci.c +1 -0

+				break;
 			pr_err("%s: Reset 0x%x never completed.\n",
 				mmc_hostname(host->mmc),

(int)mask); sdhci_dumpregs(host);

drivers/mmc/host/sdhci.c +2 -1

 			return;
+		} else {
+			udelay(10);
 		}
-		udelay(10);
 	}
 }
 EXPORT_SYMBOL_GPL(sdhci_reset);

@@ -1395,9 +1400,10 @@ void sdhci_send_command(struct sdhci_host
 *host, struct mmc_command *cmd) timeout +=

DIV_ROUND_UP(cmd->busy_timeout, 1000) * HZ + HZ; else

drivers/mmc/host/sdhci.c +0 -1

 		timeout += 10 * HZ;
-	sdhci_mod_timer(host, cmd->mrq, timeout);
 
 	sdhci_writew(host, SDHCI_MAKE_CMD(cmd->opcode, flags),

SDHCI_COMMAND);

drivers/mmc/host/sdhci.c +3 -0

+	/* setup timer after command to avoid fake timeout */
+	sdhci_mod_timer(host, cmd->mrq, timeout);
 }
 EXPORT_SYMBOL_GPL(sdhci_send_command);

@@ -1611,12 +1617,19 @@ void sdhci_enable_clk(struct sdhci_host
 *host, u16 clk) while (!((clk = sdhci_readw(host,
 SDHCI_CLOCK_CONTROL)) & SDHCI_CLOCK_INT_STABLE)) {
 		if (ktime_after(ktime_get(), timeout)) {
+			/* check it again since there is a window

between

drivers/mmc/host/sdhci.c +2 -0

+			   status check and time check */
+			if ((clk = sdhci_readw(host,

SDHCI_CLOCK_CONTROL))

drivers/mmc/host/sdhci.c +2 -0

+					& SDHCI_CLOCK_INT_STABLE)
+				break;
 			pr_err("%s: Internal clock never

stabilised.\n", mmc_hostname(host->mmc));

drivers/mmc/host/sdhci.c +3 -1

 			sdhci_dumpregs(host);
 			return;
 		}
-		udelay(10);
+		else {
+			udelay(10);
+		}
 	}
 
 	clk |= SDHCI_CLOCK_CARD_EN;

So you are saying this only happens under virtualization?

Quoted 7 lines

Please look at the sdhci_enable_clk() below, there is a window in clock stabilization check. The first check is to check status register, the second check is to check if time passed. That's why I can capture a case that after time passed, the actually clock control register indicated that clock is stable. So the error handling is wrong...

Sure, but "Internal clock never stabilised." is not one of the errors you listed.

Quoted 4 lines

Also the sdhci_send_command commands is not in spin lock There is a windows between mod_timer and real command send...

What code path does not have a spin lock?

From 87692fc090978bde8fe872f02d0023a57af6b492 Mon Sep 17 00:00:00 2001

From the clock control register dump, we are pretty sure the clock was

Quoted 1 line

From 87692fc090978bde8fe872f02d0023a57af6b492 Mon Sep 17 00:00:00 2001

From: Alek Du <[email protected]>
Date: Fri, 30 Nov 2018 14:02:28 +0800
Subject: [PATCH] sdhci: fix the timeout check window for clock and reset

We observed some fake timeouts on some devices, the log is like this:

case 1:

[159525.255629] mmc1: Internal clock never stabilised.
[159525.255818] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[159525.256049] mmc1: sdhci: Sys addr:  0x00000000 | Version:  0x00001002
[159525.256277] mmc1: sdhci: Blk size:  0x00000000 | Blk cnt:  0x00000000
[159525.256523] mmc1: sdhci: Argument:  0x00000000 | Trn mode: 0x00000000
[159525.256752] mmc1: sdhci: Present:   0x1fff0000 | Host ctl: 0x00000000
[159525.256979] mmc1: sdhci: Power:     0x0000000b | Blk gap:  0x00000080
[159525.257205] mmc1: sdhci: Wake-up:   0x00000000 | Clock:    0x0000fa03

Quoted 1 line

From the clock control register dump, we are pretty sure the clock was

stablized.

case 2:

[  914.550127] mmc1: Reset 0x2 never completed.
[  914.550321] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[  914.550608] mmc1: sdhci: Sys addr:  0x00000010 | Version:  0x00001002

After checking the sdhci code, we found the timeout check actually has a little window that the CPU can be scheduled out and when it comes back, the original time set or check is not valid.

Signed-off-by Alek Du <[email protected]>

---
 drivers/mmc/host/sdhci.c | 16 ++++++++++++++--
 1 file changed, 14 insertions(+), 2 deletions(-)

drivers/mmc/host/sdhci.c +0 -0

index 99bdae53fa2e..af01f7d16eae 100644

drivers/mmc/host/sdhci.c +1 -1

+			udelay(10);
 		}
-		udelay(10);
 	}
 }
 EXPORT_SYMBOL_GPL(sdhci_reset);

drivers/mmc/host/sdhci.c +2 -0

+			udelay(10);
+		}
 	}
 
 	clk |= SDHCI_CLOCK_CARD_EN;

From bcb38577961823b4f8f2cc0aec7dd450a81b6ddc Mon Sep 17 00:00:00 2001

From the clock control register dump, we are pretty sure the clock was

Quoted 1 line

From bcb38577961823b4f8f2cc0aec7dd450a81b6ddc Mon Sep 17 00:00:00 2001

From: Alek Du <[email protected]>
Date: Fri, 30 Nov 2018 14:02:28 +0800
Subject: [PATCH] sdhci: fix the timeout check window for clock and reset

We observed some premature timeouts on a virtualization platform, the log is like this:

case 1:

[159525.255629] mmc1: Internal clock never stabilised.
[159525.255818] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[159525.256049] mmc1: sdhci: Sys addr:  0x00000000 | Version:  0x00001002
...
[159525.257205] mmc1: sdhci: Wake-up:   0x00000000 | Clock:    0x0000fa03

Quoted 1 line

From the clock control register dump, we are pretty sure the clock was

stablized.

case 2:

[  914.550127] mmc1: Reset 0x2 never completed.
[  914.550321] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[  914.550608] mmc1: sdhci: Sys addr:  0x00000010 | Version:  0x00001002

After checking the sdhci code, we found the timeout check actually has a little window that the CPU can be scheduled out and when it comes back, the original time set or check is not valid.

Fixes 5a436cc0af62 ("mmc: sdhci: Optimize delay loops")

Signed-off-by Alek Du <[email protected]>

Cc [email protected] # v4.12+

---
 drivers/mmc/host/sdhci.c | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

drivers/mmc/host/sdhci.c +13 -5

index 99bdae53fa2e..451b08a818a9 100644
@@ -216,8 +216,12 @@ void sdhci_reset(struct sdhci_host *host, u8 mask)
 	timeout = ktime_add_ms(ktime_get(), 100);
 
 	/* hw clears the bit when it's done */
-	while (sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask) {
-		if (ktime_after(ktime_get(), timeout)) {
+	while (1) {
+		bool timedout = ktime_after(ktime_get(), timeout);
+
+		if (!(sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask))
+			break;
+		if (timedout) {
 			pr_err("%s: Reset 0x%x never completed.\n",
 				mmc_hostname(host->mmc), (int)mask);
 			sdhci_dumpregs(host);

@@ -1608,9 +1612,13 @@ void sdhci_enable_clk(struct sdhci_host *host, u16 clk)
 
 	/* Wait max 20 ms */
 	timeout = ktime_add_ms(ktime_get(), 20);
-	while (!((clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL))
-		& SDHCI_CLOCK_INT_STABLE)) {
-		if (ktime_after(ktime_get(), timeout)) {
+	while (1) {
+		bool timedout = ktime_after(ktime_get(), timeout);
+
+		clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL);
+		if (clk & SDHCI_CLOCK_INT_STABLE)
+			break;
+		if (timedout) {
 			pr_err("%s: Internal clock never stabilised.\n",
 			       mmc_hostname(host->mmc));
 			sdhci_dumpregs(host);

From bcb38577961823b4f8f2cc0aec7dd450a81b6ddc Mon Sep 17 00:00:00 2001
From: Alek Du <[email protected]>
Date: Fri, 30 Nov 2018 14:02:28 +0800
Subject: [PATCH] sdhci: fix the timeout check window for clock and reset

We observed some premature timeouts on a virtualization platform, the log is like this:

case 1:

[159525.255629] mmc1: Internal clock never stabilised.
[159525.255818] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[159525.256049] mmc1: sdhci: Sys addr:  0x00000000 | Version:  0x00001002
...
[159525.257205] mmc1: sdhci: Wake-up:   0x00000000 | Clock:    0x0000fa03

From the clock control register dump, we are pretty sure the clock was stablized.

case 2:

[  914.550127] mmc1: Reset 0x2 never completed.
[  914.550321] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[  914.550608] mmc1: sdhci: Sys addr:  0x00000010 | Version:  0x00001002

After checking the sdhci code, we found the timeout check actually has a little window that the CPU can be scheduled out and when it comes back, the original time set or check is not valid.

Fixes 5a436cc0af62 ("mmc: sdhci: Optimize delay loops")

Signed-off-by Alek Du <[email protected]>

Cc [email protected] # v4.12+

---
 drivers/mmc/host/sdhci.c | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

drivers/mmc/host/sdhci.c +13 -6

index 99bdae53fa2e..451b08a818a9 100644
@@ -216,8 +216,12 @@ void sdhci_reset(struct sdhci_host *host, u8 mask)
        timeout = ktime_add_ms(ktime_get(), 100);
 
        /* hw clears the bit when it's done */
-       while (sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask) {
-               if (ktime_after(ktime_get(), timeout)) {
+       while (1) {
+               bool timedout = ktime_after(ktime_get(), timeout);
+
+               if (!(sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask))
+                       break;
+               if (timedout) {
                        pr_err("%s: Reset 0x%x never completed.\n",
                                mmc_hostname(host->mmc), (int)mask);
                        sdhci_dumpregs(host);

@@ -1608,9 +1612,13 @@ void sdhci_enable_clk(struct sdhci_host *host, u16 clk)
 
        /* Wait max 20 ms */
        timeout = ktime_add_ms(ktime_get(), 20);
-       while (!((clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL))
-               & SDHCI_CLOCK_INT_STABLE)) {
-               if (ktime_after(ktime_get(), timeout)) {
+       while (1) {
+               bool timedout = ktime_after(ktime_get(), timeout);
+
+               clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL);
+               if (clk & SDHCI_CLOCK_INT_STABLE)
+                       break;
+               if (timedout) {
                        pr_err("%s: Internal clock never stabilised.\n",
                               mmc_hostname(host->mmc));
                        sdhci_dumpregs(host);
--

2.17.1

From a081e783383adf1179c71bc37b4e199d087af643 Mon Sep 17 00:00:00 2001

From the clock control register dump, we are pretty sure the clock was

From a081e783383adf1179c71bc37b4e199d087af643 Mon Sep 17 00:00:00 2001
From: Alek Du <[email protected]>
Date: Fri, 30 Nov 2018 14:02:28 +0800
Subject: [PATCH] mmc: sdhci: fix the timeout check window for clock and reset

We observed some premature timeouts on a virtualization platform, the log is like this:

case 1:

[159525.255629] mmc1: Internal clock never stabilised.
[159525.255818] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[159525.256049] mmc1: sdhci: Sys addr:  0x00000000 | Version:  0x00001002
...
[159525.257205] mmc1: sdhci: Wake-up:   0x00000000 | Clock:    0x0000fa03

From the clock control register dump, we are pretty sure the clock was stablized.

case 2:

[  914.550127] mmc1: Reset 0x2 never completed.
[  914.550321] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[  914.550608] mmc1: sdhci: Sys addr:  0x00000010 | Version:  0x00001002

After checking the sdhci code, we found the timeout check actually has a little window that the CPU can be scheduled out and when it comes back, the original time set or check is not valid.

Fixes 5a436cc0af62 ("mmc: sdhci: Optimize delay loops")

Cc [email protected] # v4.12+

Signed-off-by Alek Du <[email protected]>

---
 drivers/mmc/host/sdhci.c | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

drivers/mmc/host/sdhci.c +13 -6

index 99bdae53fa2e..451b08a818a9 100644
@@ -216,8 +216,12 @@ void sdhci_reset(struct sdhci_host *host, u8 mask)
        timeout = ktime_add_ms(ktime_get(), 100);
 
        /* hw clears the bit when it's done */
-       while (sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask) {
-               if (ktime_after(ktime_get(), timeout)) {
+       while (1) {
+               bool timedout = ktime_after(ktime_get(), timeout);
+
+               if (!(sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask))
+                       break;
+               if (timedout) {
                        pr_err("%s: Reset 0x%x never completed.\n",
                                mmc_hostname(host->mmc), (int)mask);
                        sdhci_dumpregs(host);

@@ -1608,9 +1612,13 @@ void sdhci_enable_clk(struct sdhci_host *host, u16 clk)
 
        /* Wait max 20 ms */
        timeout = ktime_add_ms(ktime_get(), 20);
-       while (!((clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL))
-               & SDHCI_CLOCK_INT_STABLE)) {
-               if (ktime_after(ktime_get(), timeout)) {
+       while (1) {
+               bool timedout = ktime_after(ktime_get(), timeout);
+
+               clk = sdhci_readw(host, SDHCI_CLOCK_CONTROL);
+               if (clk & SDHCI_CLOCK_INT_STABLE)
+                       break;
+               if (timedout) {
                        pr_err("%s: Internal clock never stabilised.\n",
                               mmc_hostname(host->mmc));
                        sdhci_dumpregs(host);
--

2.17.1

Could you check at your side and see what can be wrong? If there is too much hazzle I can manually fixup the patch next week, as one time thing.

Kind regards
Uffe

Quoted 2 lines · On Fri, 30 Nov 2018 16:40:04 +0200 Adrian Hunter <[email protected]>…

So you are saying this only happens under virtualization?

Yes, I saw the issue under ACRN virtualization Service OS (4.19 kernel). But theoretically it can happen in other case when scheduling is not that good. (due to bad driver or other high priority task)

Quoted 10 lines

Quoted 7 lines

Please look at the sdhci_enable_clk() below, there is a window in clock stabilization check. The first check is to check status register, the second check is to check if time passed. That's why I can capture a case that after time passed, the actually clock control register indicated that clock is stable. So the error handling is wrong...

Sure, but "Internal clock never stabilised." is not one of the errors you listed.

Sorry my bad not listing all the error log:

Case 1. clock stabilization timeout: (the below clock control dump shows clock is good)

[159525.255629] mmc1: Internal clock never stabilised.
[159525.255818] mmc1: sdhci: ============ SDHCI REGISTER DUMP ===========
[159525.256049] mmc1: sdhci: Sys addr:  0x00000000 | Version:  0x00001002
[159525.256277] mmc1: sdhci: Blk size:  0x00000000 | Blk cnt:  0x00000000
[159525.256523] mmc1: sdhci: Argument:  0x00000000 | Trn mode: 0x00000000
[159525.256752] mmc1: sdhci: Present:   0x1fff0000 | Host ctl: 0x00000000
[159525.256979] mmc1: sdhci: Power:     0x0000000b | Blk gap:  0x00000080
[159525.257205] mmc1: sdhci: Wake-up:   0x00000000 | Clock:    0x0000fa03

Case 2. Reset timeout: (the same check window in sdhci_reset())

[ 7639.968613] mmc1: Reset 0x4 never completed.

Case 3. Hardware interrupt timeout

[ 1049.561728] mmc1: Timeout waiting for hardware interrupt.

Quoted 2 lines

Quoted 2 lines

Quoted 4 lines

Quoted 2 lines

Also the sdhci_send_command commands is not in spin lock There is a windows between mod_timer and real command send...

What code path does not have a spin lock?

Ouch my bad, the sdhci_send_command are called either from spinlock or IRQ handler, so this part is good ...

I'll send a new patch to cover case 1 and case 2 if you agree.