Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1293794

Re: SDHCI long sleep with interrupts off

From Lucas Stach <l.stach@pengutronix.de>
Newsgroups linux.kernel
Subject Re: SDHCI long sleep with interrupts off
Date 2015-12-17 12:30 +0100
Message-ID <qGEUV-79i-3@gated-at.bofh.it> (permalink)
References <qGEie-6Cx-19@gated-at.bofh.it> <qGEBA-70s-11@gated-at.bofh.it> <qGEUV-79i-5@gated-at.bofh.it>
Organization linux.* mail to news gateway

Show all headers | View raw

Am Donnerstag, den 17.12.2015, 12:20 +0100 schrieb David Jander:
> Hi Lucas,
> 
> Thanks for reacting.
> 
> On Thu, 17 Dec 2015 12:03:10 +0100
> Lucas Stach <l.stach@pengutronix.de> wrote:
> 
> > Am Donnerstag, den 17.12.2015, 11:28 +0100 schrieb David Jander:
> > > Hi all, 
> > > 
> > > I was investigating the source of abnormal irq-latency spikes on an i.MX6
> > > (ARM) board, and discovered this:
> > > 
> > > # tracer: preemptirqsoff
> > > #
> > > # preemptirqsoff latency trace v1.1.5 on 4.4.0-rc4+
> > > # --------------------------------------------------------------------
> > > # latency: 2068 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:1)
> > > #    -----------------
> > > #    | task: mmcqd/0-92 (uid:0 nice:0 policy:0 rt_prio:0)
> > > #    -----------------
> > > #  => started at: _raw_spin_lock_irqsave
> > > #  => ended at:   _raw_spin_unlock_irqrestore
> > > #
> > > #
> > > #                  _------=> CPU#            
> > > #                 / _-----=> irqs-off        
> > > #                | / _----=> need-resched    
> > > #                || / _---=> hardirq/softirq 
> > > #                ||| / _--=> preempt-depth   
> > > #                |||| /     delay            
> > > #  cmd     pid   ||||| time  |   caller      
> > > #     \   /      |||||  \    |   /         
> > >  mmcqd/0-92      0d...    1us#: _raw_spin_lock_irqsave
> > >  mmcqd/0-92      0.n.1 2066us : _raw_spin_unlock_irqrestore
> > >  mmcqd/0-92      0.n.1 2070us+: trace_preempt_on
> > > <-_raw_spin_unlock_irqrestore mmcqd/0-92      0.n.1 2107us : <stack trace>
> > >  => sdhci_runtime_resume_host
> > >  => __rpm_callback
> > >  => rpm_callback
> > >  => rpm_resume
> > >  => __pm_runtime_resume
> > >  => __mmc_claim_host
> > >  => mmc_blk_issue_rq
> > >  => mmc_queue_thread
> > >  => kthread
> > >  => ret_from_fork
> > > 
> > > 2 ms with interrupts disabled!!! To much dismay, I later discovered that
> > > this isn't even the worst case scenario. I also discovered that this has
> > > been in the kernel for a long time without a fix (I have tested from 3.17
> > > to 4.4-rc4). There has been an attempt by someone to address this back in
> > > 2010, but apparently it never hit mainline.
> > > Going through the code in sdhci.c, I found this troublesome code-path:
> > > 
> > > sdhci_do_set_ios() {
> > > 	spin_lock_irqsave(&host->lock, flags);
> > > 	...
> > > 	sdhci_reinit() --> sdhci_init() --> sdhci_do_reset() -->
> > > 		host->ops->reset() --> sdhci_reset()	
> > > 	...
> > > 	spin_unlock_irqrestore(&host->lock, flags);
> > > }
> > > 
> > > And in sdhci_reset(), which may be called with held spinlock:
> > > 
> > > 	...
> > > 	/* Wait max 100 ms */
> > > 	timeout = 100;
> > > 
> > > 	/* hw clears the bit when it's done */
> > > 	while (sdhci_readb(host, SDHCI_SOFTWARE_RESET) & mask) {
> > > 		if (timeout == 0) {
> > > 			pr_err("%s: Reset 0x%x never completed.\n",
> > > 				mmc_hostname(host->mmc), (int)mask);
> > > 			sdhci_dumpregs(host);
> > > 			return;
> > > 		}
> > > 		timeout--;
> > > 		mdelay(1);
> > > 	}
> > > 
> > > I am wondering: There either must be a reason this hasn't been fixed in
> > > such a long time, or I am not understanding this correctly, so please
> > > enlighten me. Before trying a cowboy attempt at "fixing" this, I'd really
> > > like to know why am I seeing this?
> > > I mean... how can such a problem get unnoticed and unfixed for so long?
> > > Will an attempt at fixing this issue even be accepted?
> > > 
> > I would like to see the sdhci spinlock killed and replaced by a mutex
> > for exactly this reason.
> > 
> > That said, your problem is card polling, when no card is present in the
> > slot. This is most probably caused by CD gpios having the wrong
> > polarity.
> 
> ... or not having a CD pin at all.
> I am using an embedded eMMC chip and a uSD card inserted into a slot. The card
> is present and also detected as such. If I never access the card, I see no
> spikes (filesystem is mounted but not accessed). If I try to read a file or
> directory I get the above trace.
> OTOH, if I disable PM functionality in the kernel, the spike is gone, and
> worst-case latency is in the 300us range, so I don't think this is related to
> card polling.
> 
You may be right. If the SDHCI host gets runtime suspended it needs a
reset after waking up, causing this latency.

Killing the sdhci spinlock may not be straight forward, as a lot of code
paths need to be audited for irq safety, but it's the only thing to fix
this properly.

Regards,
Lucas

-- 
Pengutronix e.K.             | Lucas Stach                 |
Industrial Linux Solutions   | http://www.pengutronix.de/  |

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Back to linux.kernel | Previous | Next — Previous in thread | Next in thread | Find similar | Unroll thread

Thread

SDHCI long sleep with interrupts off David Jander <david@protonic.nl> - 2015-12-17 11:50 +0100
  Re: SDHCI long sleep with interrupts off Lucas Stach <l.stach@pengutronix.de> - 2015-12-17 12:10 +0100
    Re: SDHCI long sleep with interrupts off David Jander <david@protonic.nl> - 2015-12-17 12:30 +0100
      Re: SDHCI long sleep with interrupts off Lucas Stach <l.stach@pengutronix.de> - 2015-12-17 12:30 +0100
        Re: SDHCI long sleep with interrupts off Ulf Hansson <ulf.hansson@linaro.org> - 2015-12-17 12:40 +0100
          Re: SDHCI long sleep with interrupts off David Jander <david@protonic.nl> - 2015-12-17 13:30 +0100
            Re: SDHCI long sleep with interrupts off Ulf Hansson <ulf.hansson@linaro.org> - 2015-12-17 16:00 +0100
              Re: SDHCI long sleep with interrupts off David Jander <david@protonic.nl> - 2015-12-17 16:10 +0100
                Re: SDHCI long sleep with interrupts off Russell King - ARM Linux <linux@arm.linux.org.uk> - 2015-12-18 21:10 +0100
            Re: SDHCI long sleep with interrupts off Russell King - ARM Linux <linux@arm.linux.org.uk> - 2015-12-18 19:40 +0100

csiph-web