Hi,
On Mon, Oct 16, 2017 at 5:54 PM, Shawn Lin <shawn.lin@xxxxxxxxxxxxxx> wrote:
> Hi Doug
>
>
> On 2017/10/13 12:20, Doug Anderson wrote:
>>
>> Shawn,
>>
>> On Thu, Oct 12, 2017 at 6:32 PM, Shawn Lin <shawn.lin@xxxxxxxxxxxxxx>
>> wrote:
>>>
>>>
>>> On 2017/10/13 4:11, Douglas Anderson wrote:
>>>>
>>>>
>>>> This attempts to instill a bit of paranoia to the code dealing with
>>>> the CTO timer. It's believed that this will make the CTO timer more
>>>> robust in the case that we're having very long interrupt latencies.
>>>>
>>>
>>> Ack. It could help fix some problems observed.
>>>
>>>
>>>> Note that I originally thought that perhaps this patch was being
>>>> overly paranoid and wasn't really needed, but then while I was running
>>>> mmc_test on an rk3399 board I saw one instance of the message:
>>>> dwmmc_rockchip fe320000.dwmmc: Unexpected interrupt latency
>>>>
>>>> I had debug prints in the CTO timer code and I found that it was
>>>> running CMD 13 at the time.
>>>>
>>>> ...so even though this patch seems like it might be overly paranoid,
>>>> maybe it really isn't?
>>>>
>>>> Presumably the bad interrupt latency experienced was due to the fact
>>>> that I had serial console enabled as serial console is typically where
>>>> I place blame when I see absurdly large interrupt latencies. In this
>>>> particular case there was an (unrelated) printout to the serial
>>>> console just before I saw the "Unexpected interrupt latency" printout.
>>>>
>>>> ...and actually, I managed to even reproduce the problems by running
>>>> "iw mlan0 scan > /dev/null" while mmc_test was running. That not only
>>>> does a bunch of PCIe traffic but it also (on my system) outputs some
>>>> SELinux log spam.
>>>>>
>>>>> Fixes: 03de19212ea3 ("mmc: dw_mmc: introduce timer for broken command
>>>
>>>
>>> transfer over scheme")
>>>>
>>>>
>>>> Tested-by: Emil Renner Berthing <kernel@xxxxxxxx>
>>>> Signed-off-by: Douglas Anderson <dianders@xxxxxxxxxxxx>
>>>> ---
>>>>
>>>> Changes in v2:
>>>> - Removed extra "int i"
>>>>
>>>> drivers/mmc/host/dw_mmc.c | 91
>>>> +++++++++++++++++++++++++++++++++++++++++------
>>>> 1 file changed, 81 insertions(+), 10 deletions(-)
>>>>
>>>> diff --git a/drivers/mmc/host/dw_mmc.c b/drivers/mmc/host/dw_mmc.c
>>>> index 16516c528a88..50148991f30e 100644
>>>> --- a/drivers/mmc/host/dw_mmc.c
>>>> +++ b/drivers/mmc/host/dw_mmc.c
>>>> @@ -403,6 +403,7 @@ static inline void dw_mci_set_cto(struct dw_mci
>>>> *host)
>>>> unsigned int cto_clks;
>>>> unsigned int cto_div;
>>>> unsigned int cto_ms;
>>>> + unsigned long irqflags;
>>>> cto_clks = mci_readl(host, TMOUT) & 0xff;
>>>> cto_div = (mci_readl(host, CLKDIV) & 0xff) * 2;
>>>> @@ -413,8 +414,24 @@ static inline void dw_mci_set_cto(struct dw_mci
>>>> *host)
>>>> /* add a bit spare time */
>>>> cto_ms += 10;
>>>> - mod_timer(&host->cto_timer,
>>>> - jiffies + msecs_to_jiffies(cto_ms) + 1);
>>>> + /*
>>>> + * The durations we're working with are fairly short so we have
>>>> to
>>>> be
>>>> + * extra careful about synchronization here. Specifically in
>>>> hardware a
>>>> + * command timeout is _at most_ 5.1 ms, so that means we expect
>>>> an
>>>> + * interrupt (either command done or timeout) to come rather
>>>> quickly
>>>> + * after the mci_writel. ...but just in case we have a long
>>>> interrupt
>>>> + * latency let's add a bit of paranoia.
>>>> + *
>>>> + * In general we'll assume that at least an interrupt will be
>>>> asserted
>>>> + * in hardware by the time the cto_timer runs. ...and if it
>>>> hasn't
>>>> + * been asserted in hardware by that time then we'll assume
>>>> it'll
>>>> never
>>>> + * come.
>>>> + */
>>>> + spin_lock_irqsave(&host->irq_lock, irqflags);
>>>> + if (!test_bit(EVENT_CMD_COMPLETE, &host->pending_events))
>>>> + mod_timer(&host->cto_timer,
>>>> + jiffies + msecs_to_jiffies(cto_ms) + 1);
>>>> + spin_unlock_irqrestore(&host->irq_lock, irqflags);
>>>
>>>
>>>
>>> IIUC, this change is beacuse you move
>>> mci_writel(host, CMD, cmd_flags | SDMMC_CMD_START) before
>>> setting up the timer, so there is a timing gap that the cmd_done
>>> already comes and handled by dw_mci_interrupt->dw_mci_cmd_interrupt.
>>> At this point, we don't need the cto timer at all.
>>
>>
>> As per below, if I don't move the mci_writel() before setting up the
>> timer then there's still a race. ...and actually that race was harder
>> for me to write code for, but I invite you to try to see if it's
>> somehow cleaner.
>>
>>
>>>> }
>>>> static void dw_mci_start_command(struct dw_mci *host,
>>>> @@ -429,11 +446,11 @@ static void dw_mci_start_command(struct dw_mci
>>>> *host,
>>>> wmb(); /* drain writebuffer */
>>>> dw_mci_wait_while_busy(host, cmd_flags);
>>>> + mci_writel(host, CMD, cmd_flags | SDMMC_CMD_START);
>>>> +
>>>> /* response expected command only */
>>>> if (cmd_flags & SDMMC_CMD_RESP_EXP)
>>>> dw_mci_set_cto(host);
>>>> -
>>>> - mci_writel(host, CMD, cmd_flags | SDMMC_CMD_START);
>>>
>>>
>>>
>>>
>>> But why? If we still keep the original logic, it's always correct
>>> that cmd_done comes after setting up the cto timer. So could you
>>> eleborate a bit more to help me understand the real intention here?
>>
>>
>> No matter which order you put things, there's a race one way or the
>> other. You need a lock.
>>
>> Let's think about the old code you wrote. You did this:
>> 1. Start the CTO timer.
>> 2. Start the command.
>>
>> Now if you (somehow) take 20 ms to handle the interrupt, then this
>> happens:
>>
>> 1. Start the CTO timer.
>> 2. Start the command.
>> 3. Interrupt is pending, but interrupt handler doesn't run yet.
>> 4. CTO timer fires and enqueues CTO timeout.
>> 5. Interrupt finally fires.
>
>
> OK, got it.
>
>
>>
>>
>> Now normally things are pretty bad if you've got an interrupt latency
>> of 20 ms. ...and, in fact, I originally wrote up a commit that simply
>> explained why the race didn't matter and was thinking of posting that
>> instead of this one. I wrote up:
>>
>> * Start a timer to detect missing cmd timeout if we expect a
>> response.
>> *
>> * Note that we need to be a little careful about race conditions
>> here
>> * since our timer will be racing with the actual hardware interrupt
>> * and things would get confused if both of them happened.
>> *
>> * We end up avoiding races here mostly because of our 10 ms "spare
>> * time" buffer above. That's probably reliable enough because:
>> * - There's "guaranteed" "very little" time between setting the
>> timer
>> * and starting the command. We're holding a spinlock (host->lock)
>> * in all calls to this function so we won't get preempted.
>> Possibly
>> * we could get interrupts still, but that shouldn't add up to
>> * anything like the 10 ms spare time.
>> * - We expect that when the actual interrupt fires that our
>> interrupt
>> * routine should get called "relatively quickly" (compared to the
>> * 10 ms buffer) and will be able to cancel this timer.
>>
>> ...but then I ran a whole bunch of tests and I found that, as far as I
>> could tell, we actually _were_ getting a super long interrupt latency.
>> Specifically I saw the printout "Unexpected interrupt latency" in my
>> patch. In order to see that printout in my patch (which even starts
>> the command _before_ the CTO timer), the only explanation is bad
>> interrupt latency, right? Also: based on my past experience I believe
>> it is possible to get upwards of 100 ms interrupt latency if you've
>> got serial console enabled. printk, especially printk from an
>> interrupt context, can do some funny things.
>>
>
> Right! It makes sense to me now.
>
>>
>> ...but this stuff is always hard to get right, so if I messed up the
>> above please let me know! I tried to think of all of the cases so it
>> would work no matter if delays happened in any random place but
>> concurrency is hard.
>
>
> Yes, it looks hard to get concurrency right. I have a comment for your
> DRTO case(patch 5). Let's do some brainstorm there.
Since your comments in this patch are positive and you've now added
your Reviewed-by to patch #5, I'm going to assume that you'd also like
your Reviewed-by on this patch?
Jaehoon: I think I have Shawn's review on all this series. It would
be great if you could review them yourself and/or pick them up in your
tree. Since they fix a regression on 4.14 we really don't want to
delay too long. If you're busy, please yell and we can figure out a
way to get these in (either through Ulf directly or we should find
someone else to make a git tree and send a pull request).
Thanks!
-Doug
--
To unsubscribe from this list: send the line "unsubscribe linux-mmc" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
