Re: mmc: dw_mmc: log spamming

Re: mmc: dw_mmc: log spamming

[Jaehoon Chung]

Hi Tobias,

CC'd mmc mailing.

On 09/19/2016 10:03 AM, Seung-Woo Kim wrote:
> Hello Jaehoon,
> 
> On 2016년 09월 19일 09:32, Jaehoon Chung wrote:
>> Hi Tobias,
>>
>> On 09/16/2016 02:29 AM, Tobias Jakobi wrote:
>>> Hello everyone,
>>>
>>> I'm experiencing massive kernel log spamming by dw_mmc, the commit that
>>> causes this is the following one.
>>>
>>> 65257a0deed5aee66b4e3708944f0be62a64cabc
>>>
>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=65257a0deed5aee66b4e3708944f0be62a64cabc
>>>
>>> I've briefly checked the commit and I think the rationale behind
>>> removing the check is incorrect. While MMC_CLKGATE was certainly
>>> removed, runtime PM has "replaced" it (the commit
>>> 9eadcc0581a8ccaf4c2378aa1c193fb164304f1d even mentions this).
>>>
>>> This is on an Exynos4412 board, kernel is 4.8-rc6. Nothing is connected
>>> to the eMMC connector.
>>
>> Thanks for reporting this.
>>
>> Seung-Woo, Could you check your patch? I will also check this.

Did you test after reverting this commit? or previous version is working fine?
Which exynos4412 board do you use? I think it's related with "broken-cd".
(If you can share which board and dts you are using, we can check in more detail.)

As you mentioned, you didn't insert the eMMC card on board.
Then it should be polling whether card is inserted/removed. (If broken-cd is set...)

I think it's not related with runtime PM.

Best Regards,
Jaehoon Chung

> 
> Ok, I will check on Exynos4412 SpC boards.
> 
> By the way, to check no condition case, when I posted after v2[1], I
> checked with Exynos5422 and Exynos5433 SoC boards and they didn't show
> duplicated log, so I agreed not to check condition for logging.
> 
> [1] https://patchwork.kernel.org/patch/9182469/
> 
> Best Regards,
> - Seung-Woo Kim
> 
>>
>> Best Regards,
>> Jaehoon Chung
>>
>>>
>>> With best wishes,
>>> Tobias
>>>
>>>
>>>
>>
>>
>>
> 

Re: mmc: dw_mmc: log spamming

[Tobias Jakobi]

Hello Jaehoon,


Jaehoon Chung wrote:
> Hi Tobias,
> 
> CC'd mmc mailing.
> 
> On 09/19/2016 10:03 AM, Seung-Woo Kim wrote:
>> Hello Jaehoon,
>>
>> On 2016년 09월 19일 09:32, Jaehoon Chung wrote:
>>> Hi Tobias,
>>>
>>> On 09/16/2016 02:29 AM, Tobias Jakobi wrote:
>>>> Hello everyone,
>>>>
>>>> I'm experiencing massive kernel log spamming by dw_mmc, the commit that
>>>> causes this is the following one.
>>>>
>>>> 65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>
>>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>
>>>> I've briefly checked the commit and I think the rationale behind
>>>> removing the check is incorrect. While MMC_CLKGATE was certainly
>>>> removed, runtime PM has "replaced" it (the commit
>>>> 9eadcc0581a8ccaf4c2378aa1c193fb164304f1d even mentions this).
>>>>
>>>> This is on an Exynos4412 board, kernel is 4.8-rc6. Nothing is connected
>>>> to the eMMC connector.
>>>
>>> Thanks for reporting this.
>>>
>>> Seung-Woo, Could you check your patch? I will also check this.
> 
> Did you test after reverting this commit? or previous version is working fine?
yes, reverting the commit fixes the log spamming. I'm aware though that
the check is more of less broken (undefined behaviour because of
bit-shifting with large values), so I have also tried the following
thing: Just checking against 'div' instead of 'clock << div'. Anyway,
this also works for me.


> Which exynos4412 board do you use? I think it's related with "broken-cd".
> (If you can share which board and dts you are using, we can check in more detail.)
This is an Odroid-X2 board.


> As you mentioned, you didn't insert the eMMC card on board.
> Then it should be polling whether card is inserted/removed. (If broken-cd is set...)
I can check the callstack leading to dw_mci_setup_bus() I guess. Would
that should make it easier for you guys to understand where the issue
originates from?


> I think it's not related with runtime PM.
> 
> Best Regards,
> Jaehoon Chung

WIth best wishes,
Tobias




>> Ok, I will check on Exynos4412 SpC boards.
>>
>> By the way, to check no condition case, when I posted after v2[1], I
>> checked with Exynos5422 and Exynos5433 SoC boards and they didn't show
>> duplicated log, so I agreed not to check condition for logging.
>>
>> [1] https://patchwork.kernel.org/patch/9182469/
>>
>> Best Regards,
>> - Seung-Woo Kim
>>
>>>
>>> Best Regards,
>>> Jaehoon Chung
>>>
>>>>
>>>> With best wishes,
>>>> Tobias
>>>>
>>>>
>>>>
>>>
>>>
>>>
>>
> 

Re: mmc: dw_mmc: log spamming

[Jaehoon Chung]

Hi Tobias,

On 09/19/2016 04:41 PM, Tobias Jakobi wrote:
> Hello Jaehoon,
> 
> 
> Jaehoon Chung wrote:
>> Hi Tobias,
>>
>> CC'd mmc mailing.
>>
>> On 09/19/2016 10:03 AM, Seung-Woo Kim wrote:
>>> Hello Jaehoon,
>>>
>>> On 2016년 09월 19일 09:32, Jaehoon Chung wrote:
>>>> Hi Tobias,
>>>>
>>>> On 09/16/2016 02:29 AM, Tobias Jakobi wrote:
>>>>> Hello everyone,
>>>>>
>>>>> I'm experiencing massive kernel log spamming by dw_mmc, the commit that
>>>>> causes this is the following one.
>>>>>
>>>>> 65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>
>>>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>
>>>>> I've briefly checked the commit and I think the rationale behind
>>>>> removing the check is incorrect. While MMC_CLKGATE was certainly
>>>>> removed, runtime PM has "replaced" it (the commit
>>>>> 9eadcc0581a8ccaf4c2378aa1c193fb164304f1d even mentions this).
>>>>>
>>>>> This is on an Exynos4412 board, kernel is 4.8-rc6. Nothing is connected
>>>>> to the eMMC connector.
>>>>
>>>> Thanks for reporting this.
>>>>
>>>> Seung-Woo, Could you check your patch? I will also check this.
>>
>> Did you test after reverting this commit? or previous version is working fine?
> yes, reverting the commit fixes the log spamming. I'm aware though that
> the check is more of less broken (undefined behaviour because of
> bit-shifting with large values), so I have also tried the following
> thing: Just checking against 'div' instead of 'clock << div'. Anyway,
> this also works for me.
> 
> 
>> Which exynos4412 board do you use? I think it's related with "broken-cd".
>> (If you can share which board and dts you are using, we can check in more detail.)
> This is an Odroid-X2 board.
> 

When i have checked on odroid-u3, it's reproduced very easy.

> 
>> As you mentioned, you didn't insert the eMMC card on board.
>> Then it should be polling whether card is inserted/removed. (If broken-cd is set...)
> I can check the callstack leading to dw_mci_setup_bus() I guess. Would
> that should make it easier for you guys to understand where the issue
> originates from?

Not need to share the callstack. Because i understood what is problem.
But checking 'div' instead of 'clock << div' should also have the unexpected behavior.

If needs to fix, i want to go ahead the correct way at this time.
Anyway, thanks for reporting this!

Best Regards,
Jaehoon Chung

> 
> 
>> I think it's not related with runtime PM.
>>
>> Best Regards,
>> Jaehoon Chung
> 
> WIth best wishes,
> Tobias
> 
> 
> 
> 
>>> Ok, I will check on Exynos4412 SpC boards.
>>>
>>> By the way, to check no condition case, when I posted after v2[1], I
>>> checked with Exynos5422 and Exynos5433 SoC boards and they didn't show
>>> duplicated log, so I agreed not to check condition for logging.
>>>
>>> [1] https://patchwork.kernel.org/patch/9182469/
>>>
>>> Best Regards,
>>> - Seung-Woo Kim
>>>
>>>>
>>>> Best Regards,
>>>> Jaehoon Chung
>>>>
>>>>>
>>>>> With best wishes,
>>>>> Tobias
>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>>
>>>
>>
> 
> 
> 
> 

Re: mmc: dw_mmc: log spamming

[Tobias Jakobi]

Hey Jaehoon,


Jaehoon Chung wrote:
> Hi Tobias,
> 
> On 09/19/2016 04:41 PM, Tobias Jakobi wrote:
>> Hello Jaehoon,
>>
>>
>> Jaehoon Chung wrote:
>>> Hi Tobias,
>>>
>>> CC'd mmc mailing.
>>>
>>> On 09/19/2016 10:03 AM, Seung-Woo Kim wrote:
>>>> Hello Jaehoon,
>>>>
>>>> On 2016년 09월 19일 09:32, Jaehoon Chung wrote:
>>>>> Hi Tobias,
>>>>>
>>>>> On 09/16/2016 02:29 AM, Tobias Jakobi wrote:
>>>>>> Hello everyone,
>>>>>>
>>>>>> I'm experiencing massive kernel log spamming by dw_mmc, the commit that
>>>>>> causes this is the following one.
>>>>>>
>>>>>> 65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>
>>>>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>
>>>>>> I've briefly checked the commit and I think the rationale behind
>>>>>> removing the check is incorrect. While MMC_CLKGATE was certainly
>>>>>> removed, runtime PM has "replaced" it (the commit
>>>>>> 9eadcc0581a8ccaf4c2378aa1c193fb164304f1d even mentions this).
>>>>>>
>>>>>> This is on an Exynos4412 board, kernel is 4.8-rc6. Nothing is connected
>>>>>> to the eMMC connector.
>>>>>
>>>>> Thanks for reporting this.
>>>>>
>>>>> Seung-Woo, Could you check your patch? I will also check this.
>>>
>>> Did you test after reverting this commit? or previous version is working fine?
>> yes, reverting the commit fixes the log spamming. I'm aware though that
>> the check is more of less broken (undefined behaviour because of
>> bit-shifting with large values), so I have also tried the following
>> thing: Just checking against 'div' instead of 'clock << div'. Anyway,
>> this also works for me.
>>
>>
>>> Which exynos4412 board do you use? I think it's related with "broken-cd".
>>> (If you can share which board and dts you are using, we can check in more detail.)
>> This is an Odroid-X2 board.
>>
> 
> When i have checked on odroid-u3, it's reproduced very easy.
good to hear! I also worry that I'm the only one with these issues on
the X2. :)

Anyway, do you seen any other message on the U3 that are related to the
eMMC. I'm asking because I have also experience some warning/error from
the regulator subsystem:
> Sep 15 17:19:56 chidori kernel: [    4.976690] vddf_emmc_2.85V: voltage operation not allowed
> Sep 15 17:19:56 chidori kernel: [    4.995417] mmc_host mmc1: Bus speed (slot 0) = 50000000Hz (slot req 400000Hz, actual 396825HZ div = 63)

I'm sending you a patch shortly which fixes the warning, but I'm not
sure if this is the right approach. Maybe you can take a look?


>>> As you mentioned, you didn't insert the eMMC card on board.
>>> Then it should be polling whether card is inserted/removed. (If broken-cd is set...)
>> I can check the callstack leading to dw_mci_setup_bus() I guess. Would
>> that should make it easier for you guys to understand where the issue
>> originates from?
> 
> Not need to share the callstack. Because i understood what is problem.
> But checking 'div' instead of 'clock << div' should also have the unexpected behavior.
Why is that? If I understood the initial problem correctly, then
shifting with 'div' produces undefined behaviour since we don't know an
upper bound for it. That's not the case if we just compare old and new
divisor.


> If needs to fix, i want to go ahead the correct way at this time.
> Anyway, thanks for reporting this!

Also thanks, and let me know if I can test anything else.

With best wishes,
Tobias


> Best Regards,
> Jaehoon Chung
> 
>>
>>
>>> I think it's not related with runtime PM.
>>>
>>> Best Regards,
>>> Jaehoon Chung
>>
>> WIth best wishes,
>> Tobias
>>
>>
>>
>>
>>>> Ok, I will check on Exynos4412 SpC boards.
>>>>
>>>> By the way, to check no condition case, when I posted after v2[1], I
>>>> checked with Exynos5422 and Exynos5433 SoC boards and they didn't show
>>>> duplicated log, so I agreed not to check condition for logging.
>>>>
>>>> [1] https://patchwork.kernel.org/patch/9182469/
>>>>
>>>> Best Regards,
>>>> - Seung-Woo Kim
>>>>
>>>>>
>>>>> Best Regards,
>>>>> Jaehoon Chung
>>>>>
>>>>>>
>>>>>> With best wishes,
>>>>>> Tobias
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>>
>>>>
>>>
>>
>>
>>
>>
> 

Re: mmc: dw_mmc: log spamming

[Jaehoon Chung]

Hi Tobias,

On 09/19/2016 07:00 PM, Tobias Jakobi wrote:
> Hey Jaehoon,
> 
> 
> Jaehoon Chung wrote:
>> Hi Tobias,
>>
>> On 09/19/2016 04:41 PM, Tobias Jakobi wrote:
>>> Hello Jaehoon,
>>>
>>>
>>> Jaehoon Chung wrote:
>>>> Hi Tobias,
>>>>
>>>> CC'd mmc mailing.
>>>>
>>>> On 09/19/2016 10:03 AM, Seung-Woo Kim wrote:
>>>>> Hello Jaehoon,
>>>>>
>>>>> On 2016년 09월 19일 09:32, Jaehoon Chung wrote:
>>>>>> Hi Tobias,
>>>>>>
>>>>>> On 09/16/2016 02:29 AM, Tobias Jakobi wrote:
>>>>>>> Hello everyone,
>>>>>>>
>>>>>>> I'm experiencing massive kernel log spamming by dw_mmc, the commit that
>>>>>>> causes this is the following one.
>>>>>>>
>>>>>>> 65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>>
>>>>>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>>
>>>>>>> I've briefly checked the commit and I think the rationale behind
>>>>>>> removing the check is incorrect. While MMC_CLKGATE was certainly
>>>>>>> removed, runtime PM has "replaced" it (the commit
>>>>>>> 9eadcc0581a8ccaf4c2378aa1c193fb164304f1d even mentions this).
>>>>>>>
>>>>>>> This is on an Exynos4412 board, kernel is 4.8-rc6. Nothing is connected
>>>>>>> to the eMMC connector.
>>>>>>
>>>>>> Thanks for reporting this.
>>>>>>
>>>>>> Seung-Woo, Could you check your patch? I will also check this.
>>>>
>>>> Did you test after reverting this commit? or previous version is working fine?
>>> yes, reverting the commit fixes the log spamming. I'm aware though that
>>> the check is more of less broken (undefined behaviour because of
>>> bit-shifting with large values), so I have also tried the following
>>> thing: Just checking against 'div' instead of 'clock << div'. Anyway,
>>> this also works for me.
>>>
>>>
>>>> Which exynos4412 board do you use? I think it's related with "broken-cd".
>>>> (If you can share which board and dts you are using, we can check in more detail.)
>>> This is an Odroid-X2 board.
>>>
>>
>> When i have checked on odroid-u3, it's reproduced very easy.
> good to hear! I also worry that I'm the only one with these issues on
> the X2. :)
> 
> Anyway, do you seen any other message on the U3 that are related to the
> eMMC. I'm asking because I have also experience some warning/error from
> the regulator subsystem:
>> Sep 15 17:19:56 chidori kernel: [    4.976690] vddf_emmc_2.85V: voltage operation not allowed
>> Sep 15 17:19:56 chidori kernel: [    4.995417] mmc_host mmc1: Bus speed (slot 0) = 50000000Hz (slot req 400000Hz, actual 396825HZ div = 63)
> 
> I'm sending you a patch shortly which fixes the warning, but I'm not
> sure if this is the right approach. Maybe you can take a look?

I didn't see this..what is vddf_emmc_2.85V? I can't find this anywhere.

> 
> 
>>>> As you mentioned, you didn't insert the eMMC card on board.
>>>> Then it should be polling whether card is inserted/removed. (If broken-cd is set...)
>>> I can check the callstack leading to dw_mci_setup_bus() I guess. Would
>>> that should make it easier for you guys to understand where the issue
>>> originates from?
>>
>> Not need to share the callstack. Because i understood what is problem.
>> But checking 'div' instead of 'clock << div' should also have the unexpected behavior.
> Why is that? If I understood the initial problem correctly, then
> shifting with 'div' produces undefined behaviour since we don't know an
> upper bound for it. That's not the case if we just compare old and new
> divisor.

This problem is because of "polling" method. ("broken-cd" property in device-tree)
If can't find the eMMC card, mmc_rescan_try_freq() is running four times.
Because it's looping with freqs array size in mmc_rescan().
At that time, clock and current_speed is 400KHz..and if didn't find any cards, clock is set to 0.
After HZ, mmc_rescan is running again..and repeat above behavior.

I didn't consider about this case. (removable case and polling method.)

I think we can fix the below code..Could you check the below?
I have tested with exynos4412/exynos5422 boards.
If there is no issue, i will send the patch. Or if there is a problem, let me know, plz.


diff --git a/drivers/mmc/host/dw_mmc.c b/drivers/mmc/host/dw_mmc.c
index 22dacae..41306d1 100644
--- a/drivers/mmc/host/dw_mmc.c
+++ b/drivers/mmc/host/dw_mmc.c
@@ -1112,11 +1112,12 @@ static void dw_mci_setup_bus(struct dw_mci_slot *slot, bool force_clkinit)

                div = (host->bus_hz != clock) ? DIV_ROUND_UP(div, 2) : 0;

-               dev_info(&slot->mmc->class_dev,
-                        "Bus speed (slot %d) = %dHz (slot req %dHz, actual %dHZ div = %d)\n",
-                        slot->id, host->bus_hz, clock,
-                        div ? ((host->bus_hz / div) >> 1) :
-                        host->bus_hz, div);
+               if (clock != slot->__clk_old || force_clkinit)
+                       dev_info(&slot->mmc->class_dev,
+                                "Bus speed (slot %d) = %dHz (slot req %dHz, actual %dHZ div = %d)\n",
+                                slot->id, host->bus_hz, clock,
+                                div ? ((host->bus_hz / div) >> 1) :
+                                host->bus_hz, div);

                /* disable clock */
                mci_writel(host, CLKENA, 0);
@@ -1139,6 +1140,9 @@ static void dw_mci_setup_bus(struct dw_mci_slot *slot, bool force_clkinit)

                /* inform CIU */
                mci_send_cmd(slot, sdmmc_cmd_bits, 0);
+
+               /* keep the last clock value that requested from core */
+               slot->__clk_old = clock;
        }

        host->current_speed = clock;
diff --git a/drivers/mmc/host/dw_mmc.h b/drivers/mmc/host/dw_mmc.h
index 9e740bc..0f12e15 100644
--- a/drivers/mmc/host/dw_mmc.h
+++ b/drivers/mmc/host/dw_mmc.h
@@ -249,6 +249,8 @@ extern int dw_mci_resume(struct dw_mci *host);
  * @queue_node: List node for placing this node in the @queue list of
  *     &struct dw_mci.
  * @clock: Clock rate configured by set_ios(). Protected by host->lock.
+ * @__clk_old: The last clock value that requested from core.
+ *     Keeping track of this helps us to avoid spamming the console.
  * @flags: Random state bits associated with the slot.
  * @id: Number of this slot.
  * @sdio_id: Number of this slot in the SDIO interrupt registers.
@@ -263,6 +265,7 @@ struct dw_mci_slot {
        struct list_head        queue_node;

        unsigned int            clock;
+       unsigned int            __clk_old;

        unsigned long           flags;
 #define DW_MMC_CARD_PRESENT    0


Best Regards,
Jaehoon Chung

> 
> 
>> If needs to fix, i want to go ahead the correct way at this time.
>> Anyway, thanks for reporting this!
> 
> Also thanks, and let me know if I can test anything else.
> 
> With best wishes,
> Tobias
> 
> 
>> Best Regards,
>> Jaehoon Chung
>>
>>>
>>>
>>>> I think it's not related with runtime PM.
>>>>
>>>> Best Regards,
>>>> Jaehoon Chung
>>>
>>> WIth best wishes,
>>> Tobias
>>>
>>>
>>>
>>>
>>>>> Ok, I will check on Exynos4412 SpC boards.
>>>>>
>>>>> By the way, to check no condition case, when I posted after v2[1], I
>>>>> checked with Exynos5422 and Exynos5433 SoC boards and they didn't show
>>>>> duplicated log, so I agreed not to check condition for logging.
>>>>>
>>>>> [1] https://patchwork.kernel.org/patch/9182469/
>>>>>
>>>>> Best Regards,
>>>>> - Seung-Woo Kim
>>>>>
>>>>>>
>>>>>> Best Regards,
>>>>>> Jaehoon Chung
>>>>>>
>>>>>>>
>>>>>>> With best wishes,
>>>>>>> Tobias
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>>
>>>
>>>
>>
> 
> 
> 
> 

Re: mmc: dw_mmc: log spamming

[Tobias Jakobi]

Hey Jaehoon,


Jaehoon Chung wrote:
> Hi Tobias,
> 
> On 09/19/2016 07:00 PM, Tobias Jakobi wrote:
>> Hey Jaehoon,
>>
>>
>> Jaehoon Chung wrote:
>>> Hi Tobias,
>>>
>>> On 09/19/2016 04:41 PM, Tobias Jakobi wrote:
>>>> Hello Jaehoon,
>>>>
>>>>
>>>> Jaehoon Chung wrote:
>>>>> Hi Tobias,
>>>>>
>>>>> CC'd mmc mailing.
>>>>>
>>>>> On 09/19/2016 10:03 AM, Seung-Woo Kim wrote:
>>>>>> Hello Jaehoon,
>>>>>>
>>>>>> On 2016년 09월 19일 09:32, Jaehoon Chung wrote:
>>>>>>> Hi Tobias,
>>>>>>>
>>>>>>> On 09/16/2016 02:29 AM, Tobias Jakobi wrote:
>>>>>>>> Hello everyone,
>>>>>>>>
>>>>>>>> I'm experiencing massive kernel log spamming by dw_mmc, the commit that
>>>>>>>> causes this is the following one.
>>>>>>>>
>>>>>>>> 65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>>>
>>>>>>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>>>
>>>>>>>> I've briefly checked the commit and I think the rationale behind
>>>>>>>> removing the check is incorrect. While MMC_CLKGATE was certainly
>>>>>>>> removed, runtime PM has "replaced" it (the commit
>>>>>>>> 9eadcc0581a8ccaf4c2378aa1c193fb164304f1d even mentions this).
>>>>>>>>
>>>>>>>> This is on an Exynos4412 board, kernel is 4.8-rc6. Nothing is connected
>>>>>>>> to the eMMC connector.
>>>>>>>
>>>>>>> Thanks for reporting this.
>>>>>>>
>>>>>>> Seung-Woo, Could you check your patch? I will also check this.
>>>>>
>>>>> Did you test after reverting this commit? or previous version is working fine?
>>>> yes, reverting the commit fixes the log spamming. I'm aware though that
>>>> the check is more of less broken (undefined behaviour because of
>>>> bit-shifting with large values), so I have also tried the following
>>>> thing: Just checking against 'div' instead of 'clock << div'. Anyway,
>>>> this also works for me.
>>>>
>>>>
>>>>> Which exynos4412 board do you use? I think it's related with "broken-cd".
>>>>> (If you can share which board and dts you are using, we can check in more detail.)
>>>> This is an Odroid-X2 board.
>>>>
>>>
>>> When i have checked on odroid-u3, it's reproduced very easy.
>> good to hear! I also worry that I'm the only one with these issues on
>> the X2. :)
>>
>> Anyway, do you seen any other message on the U3 that are related to the
>> eMMC. I'm asking because I have also experience some warning/error from
>> the regulator subsystem:
>>> Sep 15 17:19:56 chidori kernel: [    4.976690] vddf_emmc_2.85V: voltage operation not allowed
>>> Sep 15 17:19:56 chidori kernel: [    4.995417] mmc_host mmc1: Bus speed (slot 0) = 50000000Hz (slot req 400000Hz, actual 396825HZ div = 63)
>>
>> I'm sending you a patch shortly which fixes the warning, but I'm not
>> sure if this is the right approach. Maybe you can take a look?
> 
> I didn't see this..what is vddf_emmc_2.85V? I can't find this anywhere.
sorry for the confusion, I have renamed some of the regulator labels in
my private tree.

vddf_emmc_2.85V is BUCK8, and called 'BUCK8_VDDQ_MMC4_2.8V' in the
vanilla kernel. It's the vqmmc regulator of the eMMC.


>>>>> As you mentioned, you didn't insert the eMMC card on board.
>>>>> Then it should be polling whether card is inserted/removed. (If broken-cd is set...)
>>>> I can check the callstack leading to dw_mci_setup_bus() I guess. Would
>>>> that should make it easier for you guys to understand where the issue
>>>> originates from?
>>>
>>> Not need to share the callstack. Because i understood what is problem.
>>> But checking 'div' instead of 'clock << div' should also have the unexpected behavior.
>> Why is that? If I understood the initial problem correctly, then
>> shifting with 'div' produces undefined behaviour since we don't know an
>> upper bound for it. That's not the case if we just compare old and new
>> divisor.
> 
> This problem is because of "polling" method. ("broken-cd" property in device-tree)
> If can't find the eMMC card, mmc_rescan_try_freq() is running four times.
> Because it's looping with freqs array size in mmc_rescan().
> At that time, clock and current_speed is 400KHz..and if didn't find any cards, clock is set to 0.
> After HZ, mmc_rescan is running again..and repeat above behavior.
> 
> I didn't consider about this case. (removable case and polling method.)
> 
> I think we can fix the below code..Could you check the below?
I'll try to do a test this evening. I'll let you know the results then!

And thanks for looking into this!

With best wishes,
Tobias


> I have tested with exynos4412/exynos5422 boards.
> If there is no issue, i will send the patch. Or if there is a problem, let me know, plz.
> 
> 
> diff --git a/drivers/mmc/host/dw_mmc.c b/drivers/mmc/host/dw_mmc.c
> index 22dacae..41306d1 100644
> --- a/drivers/mmc/host/dw_mmc.c
> +++ b/drivers/mmc/host/dw_mmc.c
> @@ -1112,11 +1112,12 @@ static void dw_mci_setup_bus(struct dw_mci_slot *slot, bool force_clkinit)
> 
>                 div = (host->bus_hz != clock) ? DIV_ROUND_UP(div, 2) : 0;
> 
> -               dev_info(&slot->mmc->class_dev,
> -                        "Bus speed (slot %d) = %dHz (slot req %dHz, actual %dHZ div = %d)\n",
> -                        slot->id, host->bus_hz, clock,
> -                        div ? ((host->bus_hz / div) >> 1) :
> -                        host->bus_hz, div);
> +               if (clock != slot->__clk_old || force_clkinit)
> +                       dev_info(&slot->mmc->class_dev,
> +                                "Bus speed (slot %d) = %dHz (slot req %dHz, actual %dHZ div = %d)\n",
> +                                slot->id, host->bus_hz, clock,
> +                                div ? ((host->bus_hz / div) >> 1) :
> +                                host->bus_hz, div);
> 
>                 /* disable clock */
>                 mci_writel(host, CLKENA, 0);
> @@ -1139,6 +1140,9 @@ static void dw_mci_setup_bus(struct dw_mci_slot *slot, bool force_clkinit)
> 
>                 /* inform CIU */
>                 mci_send_cmd(slot, sdmmc_cmd_bits, 0);
> +
> +               /* keep the last clock value that requested from core */
> +               slot->__clk_old = clock;
>         }
> 
>         host->current_speed = clock;
> diff --git a/drivers/mmc/host/dw_mmc.h b/drivers/mmc/host/dw_mmc.h
> index 9e740bc..0f12e15 100644
> --- a/drivers/mmc/host/dw_mmc.h
> +++ b/drivers/mmc/host/dw_mmc.h
> @@ -249,6 +249,8 @@ extern int dw_mci_resume(struct dw_mci *host);
>   * @queue_node: List node for placing this node in the @queue list of
>   *     &struct dw_mci.
>   * @clock: Clock rate configured by set_ios(). Protected by host->lock.
> + * @__clk_old: The last clock value that requested from core.
> + *     Keeping track of this helps us to avoid spamming the console.
>   * @flags: Random state bits associated with the slot.
>   * @id: Number of this slot.
>   * @sdio_id: Number of this slot in the SDIO interrupt registers.
> @@ -263,6 +265,7 @@ struct dw_mci_slot {
>         struct list_head        queue_node;
> 
>         unsigned int            clock;
> +       unsigned int            __clk_old;
> 
>         unsigned long           flags;
>  #define DW_MMC_CARD_PRESENT    0
> 
> 
> Best Regards,
> Jaehoon Chung
> 
>>
>>
>>> If needs to fix, i want to go ahead the correct way at this time.
>>> Anyway, thanks for reporting this!
>>
>> Also thanks, and let me know if I can test anything else.
>>
>> With best wishes,
>> Tobias
>>
>>
>>> Best Regards,
>>> Jaehoon Chung
>>>
>>>>
>>>>
>>>>> I think it's not related with runtime PM.
>>>>>
>>>>> Best Regards,
>>>>> Jaehoon Chung
>>>>
>>>> WIth best wishes,
>>>> Tobias
>>>>
>>>>
>>>>
>>>>
>>>>>> Ok, I will check on Exynos4412 SpC boards.
>>>>>>
>>>>>> By the way, to check no condition case, when I posted after v2[1], I
>>>>>> checked with Exynos5422 and Exynos5433 SoC boards and they didn't show
>>>>>> duplicated log, so I agreed not to check condition for logging.
>>>>>>
>>>>>> [1] https://patchwork.kernel.org/patch/9182469/
>>>>>>
>>>>>> Best Regards,
>>>>>> - Seung-Woo Kim
>>>>>>
>>>>>>>
>>>>>>> Best Regards,
>>>>>>> Jaehoon Chung
>>>>>>>
>>>>>>>>
>>>>>>>> With best wishes,
>>>>>>>> Tobias
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>>
>>>>
>>>>
>>>
>>
>>
>>
>>
> 

Re: mmc: dw_mmc: log spamming

[Tobias Jakobi]

Hello again,


Jaehoon Chung wrote:
> Hi Tobias,
> 
> On 09/19/2016 07:00 PM, Tobias Jakobi wrote:
>> Hey Jaehoon,
>>
>>
>> Jaehoon Chung wrote:
>>> Hi Tobias,
>>>
>>> On 09/19/2016 04:41 PM, Tobias Jakobi wrote:
>>>> Hello Jaehoon,
>>>>
>>>>
>>>> Jaehoon Chung wrote:
>>>>> Hi Tobias,
>>>>>
>>>>> CC'd mmc mailing.
>>>>>
>>>>> On 09/19/2016 10:03 AM, Seung-Woo Kim wrote:
>>>>>> Hello Jaehoon,
>>>>>>
>>>>>> On 2016년 09월 19일 09:32, Jaehoon Chung wrote:
>>>>>>> Hi Tobias,
>>>>>>>
>>>>>>> On 09/16/2016 02:29 AM, Tobias Jakobi wrote:
>>>>>>>> Hello everyone,
>>>>>>>>
>>>>>>>> I'm experiencing massive kernel log spamming by dw_mmc, the commit that
>>>>>>>> causes this is the following one.
>>>>>>>>
>>>>>>>> 65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>>>
>>>>>>>> https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=65257a0deed5aee66b4e3708944f0be62a64cabc
>>>>>>>>
>>>>>>>> I've briefly checked the commit and I think the rationale behind
>>>>>>>> removing the check is incorrect. While MMC_CLKGATE was certainly
>>>>>>>> removed, runtime PM has "replaced" it (the commit
>>>>>>>> 9eadcc0581a8ccaf4c2378aa1c193fb164304f1d even mentions this).
>>>>>>>>
>>>>>>>> This is on an Exynos4412 board, kernel is 4.8-rc6. Nothing is connected
>>>>>>>> to the eMMC connector.
>>>>>>>
>>>>>>> Thanks for reporting this.
>>>>>>>
>>>>>>> Seung-Woo, Could you check your patch? I will also check this.
>>>>>
>>>>> Did you test after reverting this commit? or previous version is working fine?
>>>> yes, reverting the commit fixes the log spamming. I'm aware though that
>>>> the check is more of less broken (undefined behaviour because of
>>>> bit-shifting with large values), so I have also tried the following
>>>> thing: Just checking against 'div' instead of 'clock << div'. Anyway,
>>>> this also works for me.
>>>>
>>>>
>>>>> Which exynos4412 board do you use? I think it's related with "broken-cd".
>>>>> (If you can share which board and dts you are using, we can check in more detail.)
>>>> This is an Odroid-X2 board.
>>>>
>>>
>>> When i have checked on odroid-u3, it's reproduced very easy.
>> good to hear! I also worry that I'm the only one with these issues on
>> the X2. :)
>>
>> Anyway, do you seen any other message on the U3 that are related to the
>> eMMC. I'm asking because I have also experience some warning/error from
>> the regulator subsystem:
>>> Sep 15 17:19:56 chidori kernel: [    4.976690] vddf_emmc_2.85V: voltage operation not allowed
>>> Sep 15 17:19:56 chidori kernel: [    4.995417] mmc_host mmc1: Bus speed (slot 0) = 50000000Hz (slot req 400000Hz, actual 396825HZ div = 63)
>>
>> I'm sending you a patch shortly which fixes the warning, but I'm not
>> sure if this is the right approach. Maybe you can take a look?
> 
> I didn't see this..what is vddf_emmc_2.85V? I can't find this anywhere.
> 
>>
>>
>>>>> As you mentioned, you didn't insert the eMMC card on board.
>>>>> Then it should be polling whether card is inserted/removed. (If broken-cd is set...)
>>>> I can check the callstack leading to dw_mci_setup_bus() I guess. Would
>>>> that should make it easier for you guys to understand where the issue
>>>> originates from?
>>>
>>> Not need to share the callstack. Because i understood what is problem.
>>> But checking 'div' instead of 'clock << div' should also have the unexpected behavior.
>> Why is that? If I understood the initial problem correctly, then
>> shifting with 'div' produces undefined behaviour since we don't know an
>> upper bound for it. That's not the case if we just compare old and new
>> divisor.
> 
> This problem is because of "polling" method. ("broken-cd" property in device-tree)
> If can't find the eMMC card, mmc_rescan_try_freq() is running four times.
> Because it's looping with freqs array size in mmc_rescan().
> At that time, clock and current_speed is 400KHz..and if didn't find any cards, clock is set to 0.
> After HZ, mmc_rescan is running again..and repeat above behavior.
> 
> I didn't consider about this case. (removable case and polling method.)
> 
> I think we can fix the below code..Could you check the below?
> I have tested with exynos4412/exynos5422 boards.
> If there is no issue, i will send the patch. Or if there is a problem, let me know, plz.
caching the clock value (instead of just div) also seems to work, the
message is just shown once.

Some comments below.


> diff --git a/drivers/mmc/host/dw_mmc.c b/drivers/mmc/host/dw_mmc.c
> index 22dacae..41306d1 100644
> --- a/drivers/mmc/host/dw_mmc.c
> +++ b/drivers/mmc/host/dw_mmc.c
> @@ -1112,11 +1112,12 @@ static void dw_mci_setup_bus(struct dw_mci_slot *slot, bool force_clkinit)
> 
>                 div = (host->bus_hz != clock) ? DIV_ROUND_UP(div, 2) : 0;
> 
> -               dev_info(&slot->mmc->class_dev,
> -                        "Bus speed (slot %d) = %dHz (slot req %dHz, actual %dHZ div = %d)\n",
> -                        slot->id, host->bus_hz, clock,
> -                        div ? ((host->bus_hz / div) >> 1) :
> -                        host->bus_hz, div);
> +               if (clock != slot->__clk_old || force_clkinit)
> +                       dev_info(&slot->mmc->class_dev,
> +                                "Bus speed (slot %d) = %dHz (slot req %dHz, actual %dHZ div = %d)\n",
Put the missing comma before "div" here, i.e. "slot req %dHz, actual
%dHZ, div = %d)".


> +                                slot->id, host->bus_hz, clock,
> +                                div ? ((host->bus_hz / div) >> 1) :
> +                                host->bus_hz, div);
> 
>                 /* disable clock */
>                 mci_writel(host, CLKENA, 0);
> @@ -1139,6 +1140,9 @@ static void dw_mci_setup_bus(struct dw_mci_slot *slot, bool force_clkinit)
> 
>                 /* inform CIU */
>                 mci_send_cmd(slot, sdmmc_cmd_bits, 0);
> +
> +               /* keep the last clock value that requested from core */
"...that was requested from..."


> +               slot->__clk_old = clock;
>         }
> 
>         host->current_speed = clock;
> diff --git a/drivers/mmc/host/dw_mmc.h b/drivers/mmc/host/dw_mmc.h
> index 9e740bc..0f12e15 100644
> --- a/drivers/mmc/host/dw_mmc.h
> +++ b/drivers/mmc/host/dw_mmc.h
> @@ -249,6 +249,8 @@ extern int dw_mci_resume(struct dw_mci *host);
>   * @queue_node: List node for placing this node in the @queue list of
>   *     &struct dw_mci.
>   * @clock: Clock rate configured by set_ios(). Protected by host->lock.
> + * @__clk_old: The last clock value that requested from core.
Same here.


With best wishes,
Tobias


> + *     Keeping track of this helps us to avoid spamming the console.
>   * @flags: Random state bits associated with the slot.
>   * @id: Number of this slot.
>   * @sdio_id: Number of this slot in the SDIO interrupt registers.
> @@ -263,6 +265,7 @@ struct dw_mci_slot {
>         struct list_head        queue_node;
> 
>         unsigned int            clock;
> +       unsigned int            __clk_old;
> 
>         unsigned long           flags;
>  #define DW_MMC_CARD_PRESENT    0
> 
> 
> Best Regards,
> Jaehoon Chung
> 
>>
>>
>>> If needs to fix, i want to go ahead the correct way at this time.
>>> Anyway, thanks for reporting this!
>>
>> Also thanks, and let me know if I can test anything else.
>>
>> With best wishes,
>> Tobias
>>
>>
>>> Best Regards,
>>> Jaehoon Chung
>>>
>>>>
>>>>
>>>>> I think it's not related with runtime PM.
>>>>>
>>>>> Best Regards,
>>>>> Jaehoon Chung
>>>>
>>>> WIth best wishes,
>>>> Tobias
>>>>
>>>>
>>>>
>>>>
>>>>>> Ok, I will check on Exynos4412 SpC boards.
>>>>>>
>>>>>> By the way, to check no condition case, when I posted after v2[1], I
>>>>>> checked with Exynos5422 and Exynos5433 SoC boards and they didn't show
>>>>>> duplicated log, so I agreed not to check condition for logging.
>>>>>>
>>>>>> [1] https://patchwork.kernel.org/patch/9182469/
>>>>>>
>>>>>> Best Regards,
>>>>>> - Seung-Woo Kim
>>>>>>
>>>>>>>
>>>>>>> Best Regards,
>>>>>>> Jaehoon Chung
>>>>>>>
>>>>>>>>
>>>>>>>> With best wishes,
>>>>>>>> Tobias
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>>
>>>>
>>>>
>>>
>>
>>
>>
>>
>