LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
From: Simon Huggins <huggie@earth.li>
To: Ingo Molnar <mingo@elte.hu>
Cc: linux-kernel@vger.kernel.org, Thomas Gleixner <tglx@linutronix.de>
Subject: Re: Scheduler broken? sdhci issues with scheduling
Date: Fri, 29 Feb 2008 19:39:51 +0000	[thread overview]
Message-ID: <20080229193951.GI24533@paranoidfreak.co.uk> (raw)
In-Reply-To: <20080229140024.GA26342@elte.hu> <20080229133433.GA15532@elte.hu>

[-- Attachment #1: Type: text/plain, Size: 3892 bytes --]

Hi Ingo,

(please cc me again)

On Fri, Feb 29, 2008 at 02:34:33PM +0100, Ingo Molnar wrote:
> * Simon Huggins <huggie@earth.li> wrote:
> > [ Please Cc me on replies ]
> > I had a bug with sdhci which Pierre Ossman looked at for me.
> > In the end essentially the fix was to use HZ=1000 and nothing else. 
> > Pierre seemed to think that this was a bug in the scheduler.
> does the patch below help, even if you keep HZ=100? This doesnt look 
> like a scheduler issue, it's more of a timer/timing issue. Different HZ 
> means different msleep() results - and the mmc code does a loop of small 
> msleep delays.

Thanks for looking at it.

I did tests with 2.6.24.3 with HZ=1000 and HZ=100 and as expected the
latter didn't work.

> -------------->
> ---
>  drivers/mmc/core/core.h |    7 +------
>  1 file changed, 1 insertion(+), 6 deletions(-)

> Index: linux/drivers/mmc/core/core.h
> ===================================================================
> --- linux.orig/drivers/mmc/core/core.h
> +++ linux/drivers/mmc/core/core.h
> @@ -36,12 +36,7 @@ void mmc_set_timing(struct mmc_host *hos

>  static inline void mmc_delay(unsigned int ms)
>  {
> -	if (ms < 1000 / HZ) {
> -		cond_resched();
> -		mdelay(ms);
> -	} else {
> -		msleep(ms);
> -	}
> +	mdelay(ms);
>  }

>  void mmc_rescan(struct work_struct *work);

That doesn't work.  I did a test with HZ=100 and this patch.  I've
attached the log as patch1-log.

On Fri, Feb 29, 2008 at 03:00:24PM +0100, Ingo Molnar wrote:

> * Ingo Molnar <mingo@elte.hu> wrote:

> > alternatively, instead of applying the first patch, could you apply 
> > the patch below instead? This makes "msleep()" much more precise. Does 
> > this help in the HZ != 1000 case?

> ok, this had a build failure - use the one below instead.

That doesn't work either.  Again I did a test with HZ=100 and this
patch.  I've attached the log as patch2-log.

It had some fuzz but no rejects with 2.6.24.3.

> -------------->
> Subject: hrtimers: use hrtimers so that msleep() sleeps for the requested time
> From: Jonathan Corbet <corbet@lwn.net>

> The problem being addressed here is that the current msleep() will stop
> for a minimum of two jiffies, meaning that, on a HZ=100 system,
> msleep(1) delays for for about 20ms.  In a driver with one such delay
> for each of 150 or so register setting operations, the extra time adds
> up to a few seconds.

> This patch addresses the situation by using hrtimers.  On tickless
> systems with working timers, msleep(1) now sleeps for 1ms, even with
> HZ=100.

> Most comments last time were favorable.  The one dissenter was Roman,
> who worries about the overhead of using hrtimers for this operation; my
> understanding is that he would rather see a really_msleep() function for
> those who actually want millisecond resolution.  I'm not sure how to
> characterize what the cost could be, but it can only be buried by the
> fact that every call sleeps for some number of milliseconds.  On my
> system, the several hundred total msleep() calls can't cause any real
> overhead, and almost all happen at initialization time.

> I still think it would be useful for msleep() to do what it says it does
> and not vastly oversleep with small arguments.  A quick grep turns up
> 450 msleep(1) calls in the current mainline.  Andrew, if you agree, can
> you drop this into -mm?  If not, I guess I'll let it go.

> Current msleep() snoozes for at least two jiffies, causing msleep(1) to
> sleep for at least 20ms on HZ=100 systems.  Using hrtimers allows
> msleep() to sleep for something much closer to the requested time.

[snip]


Anything else I can try?

-- 
----------(  "There are times when I think Clint belongs in  )----------
----------( my RSS-hole" -- anonymous Debian Planet reader.  )----------
Simon ----(                                                  )---- Nomis
                             Htag.pl 0.0.22

[-- Attachment #2: patch1-log --]
[-- Type: text/plain, Size: 6156 bytes --]

[   15.052986] sdhci: SDHCI controller found at 0000:03:0b.3 [104c:803c] (rev 0)
[   15.053077] sdhci [sdhci_probe()]: found 1 slot(s)
[   15.053102] PCI: Enabling device 0000:03:0b.3 (0000 -> 0002)
[   15.053186] ACPI: PCI Interrupt 0000:03:0b.3[D] -> GSI 23 (level, low) -> IRQ 23
[   15.053340] sdhci [sdhci_probe_slot()]: slot 0 at 0x88089800, irq 23
[   15.054103] sdhci: ============== REGISTER DUMP ==============
[   15.054110] sdhci: Sys addr: 0x00000000 | Version:  0x00008900
[   15.054115] sdhci: Blk size: 0x00000000 | Blk cnt:  0x00000000
[   15.054120] sdhci: Argument: 0x00000000 | Trn mode: 0x00000000
[   15.054125] sdhci: Present:  0x000a0000 | Host ctl: 0x00000000
[   15.054129] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[   15.054134] sdhci: Wake-up:  0x00000000 | Clock:    0x00000000
[   15.054139] sdhci: Timeout:  0x00000000 | Int stat: 0x00000000
[   15.054144] sdhci: Int enab: 0x00ff00fb | Sig enab: 0x00ff00fb
[   15.054149] sdhci: AC12 err: 0x00000000 | Slot int: 0x00000000
[   15.054154] sdhci: Caps:     0x01e030b0 | Max curr: 0x00000000
[   15.054156] sdhci: ===========================================
[   15.054207] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0
[   15.054222] mmc0: SDHCI at 0x88089800 irq 23 DMA
[   15.054958] ACPI: PCI Interrupt 0000:02:00.0[A] -> GSI 18 (level, low) -> IRQ 18
[   15.055137] PCI: Setting latency timer of device 0000:02:00.0 to 64
[   15.055883] iwl4965: Detected Intel Wireless WiFi Link 4965AGN
[   15.056000] mmc0: clock 0Hz busmode 1 powermode 1 cs 0 Vdd 21 width 0 timing 0
[   15.058006] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   15.061014] mmc0: clock 187500Hz busmode 1 powermode 2 cs 1 Vdd 21 width 0 timing 0
[   15.062020] mmc0: starting CMD0 arg 00000000 flags 000000c0
[   15.062207] mmc0: req done (CMD0): -123: 00000000 00000000 00000000 00000000
[   15.062350] PCI: Enabling device 0000:00:1b.0 (0000 -> 0002)
[   15.062443] ACPI: PCI Interrupt 0000:00:1b.0[A] -> GSI 22 (level, low) -> IRQ 22
[   15.063326] PCI: Setting latency timer of device 0000:00:1b.0 to 64
[   15.064359] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   15.065366] mmc0: starting CMD8 arg 000001aa flags 000002f5
[   15.065403] mmc0: req done (CMD8): -123: 00000000 00000000 00000000 00000000
[   15.065408] mmc0: starting CMD5 arg 00000000 flags 000002e1
[   15.065441] mmc0: req failed (CMD5): -123, retrying...
[   15.065475] mmc0: req failed (CMD5): -123, retrying...
[   15.065498] mmc0: req failed (CMD5): -123, retrying...
[   15.065528] mmc0: req done (CMD5): -123: 00000000 00000000 00000000 00000000
[   15.065533] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   15.065557] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   15.065561] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   15.065591] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   15.065596] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   15.065620] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   15.065625] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   15.065654] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   15.065659] mmc0: starting CMD1 arg 00000000 flags 000000e1
[   15.065680] mmc0: req done (CMD1): -123: 00000000 00000000 00000000 00000000
[   15.065685] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0



[   33.923911] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00000040
[   33.936455] mmc0: clock 0Hz busmode 1 powermode 1 cs 0 Vdd 21 width 0 timing 0
[   33.938471] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   33.941487] mmc0: clock 187500Hz busmode 1 powermode 2 cs 1 Vdd 21 width 0 timing 0
[   33.942495] mmc0: starting CMD0 arg 00000000 flags 000000c0
[   33.942761] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00000001
[   33.942774] mmc0: req done (CMD0): 0: 00000000 00000000 00000000 00000000
[   33.943965] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   33.944976] mmc0: starting CMD8 arg 000001aa flags 000002f5
[   33.945148] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.945163] mmc0: req done (CMD8): -110: 00000000 00000000 00000000 00000000
[   33.945341] mmc0: starting CMD5 arg 00000000 flags 000002e1
[   33.945585] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.945602] mmc0: req failed (CMD5): -110, retrying...
[   33.946582] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.946595] mmc0: req failed (CMD5): -110, retrying...
[   33.947572] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.947584] mmc0: req failed (CMD5): -110, retrying...
[   33.947864] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.947878] mmc0: req done (CMD5): -110: 00000000 00000000 00000000 00000000
[   33.947952] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   33.948936] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.948949] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   33.949025] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   33.950006] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.950018] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   33.950092] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   33.950349] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.950363] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   33.950435] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   33.951416] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.951429] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   33.951505] mmc0: starting CMD1 arg 00000000 flags 000000e1
[   33.952486] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   33.952499] mmc0: req done (CMD1): -110: 00000000 00000000 00000000 00000000
[   33.952573] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0

[-- Attachment #3: patch2-log --]
[-- Type: text/plain, Size: 5874 bytes --]

[   18.258572] sdhci [sdhci_probe_slot()]: slot 0 at 0x88089800, irq 23
[   18.259443] sdhci: ============== REGISTER DUMP ==============
[   18.259451] sdhci: Sys addr: 0x00000000 | Version:  0x00008900
[   18.259456] sdhci: Blk size: 0x00000000 | Blk cnt:  0x00000000
[   18.259461] sdhci: Argument: 0x00000000 | Trn mode: 0x00000000
[   18.259466] sdhci: Present:  0x000a0000 | Host ctl: 0x00000000
[   18.259471] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[   18.259476] sdhci: Wake-up:  0x00000000 | Clock:    0x00000000
[   18.259481] sdhci: Timeout:  0x00000000 | Int stat: 0x00000000
[   18.259486] sdhci: Int enab: 0x00ff00fb | Sig enab: 0x00ff00fb
[   18.259490] sdhci: AC12 err: 0x00000000 | Slot int: 0x00000000
[   18.259495] sdhci: Caps:     0x01e030b0 | Max curr: 0x00000000
[   18.259498] sdhci: ===========================================
[   18.259548] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0
[   18.259564] mmc0: SDHCI at 0x88089800 irq 23 DMA
[   18.259820] mmc0: clock 0Hz busmode 1 powermode 1 cs 0 Vdd 21 width 0 timing 0
[   18.261828] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   18.262095] ACPI: PCI Interrupt 0000:02:00.0[A] -> GSI 18 (level, low) -> IRQ 18
[   18.262274] PCI: Setting latency timer of device 0000:02:00.0 to 64
[   18.263735] iwl4965: Detected Intel Wireless WiFi Link 4965AGN
[   18.265293] mmc0: clock 187500Hz busmode 1 powermode 2 cs 1 Vdd 21 width 0 timing 0
[   18.266300] mmc0: starting CMD0 arg 00000000 flags 000000c0
[   18.266319] mmc0: req done (CMD0): -123: 00000000 00000000 00000000 00000000
[   18.266477] PCI: Enabling device 0000:00:1b.0 (0000 -> 0002)
[   18.266570] ACPI: PCI Interrupt 0000:00:1b.0[A] -> GSI 22 (level, low) -> IRQ 22
[   18.267476] PCI: Setting latency timer of device 0000:00:1b.0 to 64
[   18.268512] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   18.269521] mmc0: starting CMD8 arg 000001aa flags 000002f5
[   18.269536] mmc0: req done (CMD8): -123: 00000000 00000000 00000000 00000000
[   18.269542] mmc0: starting CMD5 arg 00000000 flags 000002e1
[   18.269554] mmc0: req failed (CMD5): -123, retrying...
[   18.269564] mmc0: req failed (CMD5): -123, retrying...
[   18.269574] mmc0: req failed (CMD5): -123, retrying...
[   18.269585] mmc0: req done (CMD5): -123: 00000000 00000000 00000000 00000000
[   18.269590] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   18.269601] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   18.269606] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   18.269617] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   18.269622] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   18.269634] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   18.269639] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   18.269650] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[   18.269655] mmc0: starting CMD1 arg 00000000 flags 000000e1
[   18.269667] mmc0: req done (CMD1): -123: 00000000 00000000 00000000 00000000
[   18.269672] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0




[   43.040586] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00000040
[   43.050979] mmc0: clock 0Hz busmode 1 powermode 1 cs 0 Vdd 21 width 0 timing 0
[   43.052997] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   43.056012] mmc0: clock 187500Hz busmode 1 powermode 2 cs 1 Vdd 21 width 0 timing 0
[   43.057021] mmc0: starting CMD0 arg 00000000 flags 000000c0
[   43.057241] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00000001
[   43.057254] mmc0: req done (CMD0): 0: 00000000 00000000 00000000 00000000
[   43.058443] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[   43.059454] mmc0: starting CMD8 arg 000001aa flags 000002f5
[   43.059624] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.059638] mmc0: req done (CMD8): -110: 00000000 00000000 00000000 00000000
[   43.059830] mmc0: starting CMD5 arg 00000000 flags 000002e1
[   43.060076] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.060090] mmc0: req failed (CMD5): -110, retrying...
[   43.060428] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.060451] mmc0: req failed (CMD5): -110, retrying...
[   43.061426] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.061443] mmc0: req failed (CMD5): -110, retrying...
[   43.062415] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.062431] mmc0: req done (CMD5): -110: 00000000 00000000 00000000 00000000
[   43.062472] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   43.062777] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.062792] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   43.062804] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   43.063182] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.063207] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   43.063222] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   43.064209] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.064226] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   43.064237] mmc0: starting CMD55 arg 00000000 flags 000000f5
[   43.065207] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.065222] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[   43.065261] mmc0: starting CMD1 arg 00000000 flags 000000e1
[   43.065596] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[   43.065612] mmc0: req done (CMD1): -110: 00000000 00000000 00000000 00000000
[   43.065625] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0

  reply	other threads:[~2008-02-29 19:40 UTC|newest]

Thread overview: 16+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2008-02-29 11:52 Simon Huggins
2008-02-29 13:34 ` Ingo Molnar
2008-02-29 13:51   ` Ingo Molnar
2008-02-29 14:00     ` Ingo Molnar
2008-02-29 19:39       ` Simon Huggins [this message]
2008-02-29 20:39         ` Ingo Molnar
2008-03-01 12:42           ` Simon Huggins
2008-03-01 14:08             ` Pierre Ossman
2008-03-02 10:40 ` Pavel Machek
2008-03-02 18:04   ` Simon Huggins
2008-03-03 19:43   ` Pierre Ossman
2008-03-03 20:38     ` Pavel Machek
2008-03-03 21:05       ` Pierre Ossman
2008-03-13 21:17         ` Simon Huggins
2008-03-15 15:04           ` Pierre Ossman
2008-04-20 21:07             ` Simon Huggins

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20080229193951.GI24533@paranoidfreak.co.uk \
    --to=huggie@earth.li \
    --cc=linux-kernel@vger.kernel.org \
    --cc=mingo@elte.hu \
    --cc=tglx@linutronix.de \
    --subject='Re: Scheduler broken? sdhci issues with scheduling' \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).