[Sdhci-devel] sdhci problems with debug log

Wed Dec 5 10:34:44 CET 2007

Hi Pierre,

On Sat, Dec 01, 2007 at 10:49:49PM +0100, Pierre Ossman wrote:
> On Fri, 23 Nov 2007 17:37:28 +0000
> Simon Huggins <huggie at earth.li> wrote:
> > 'ello Pierre
> Sorry about the delay.

And mine.  I'm not about til the 12th now.

> > On Mon, Nov 19, 2007 at 07:29:21PM +0100, Pierre Ossman wrote:
> > > I'd like you to patch mmc_detect_change() in drivers/mmc/core/core.c and add:
> > > 	printk("mmc_detect_change(%d)\n", delay);
> > > That will give us a printk timestamp of when it's called and confirm
> > > that it has a proper value. Also, I need to know which HZ you've
> > > configured your kernel for.
> > Sure.  I've attached with_mmc_detect_change.works and .noworky
> > HZ is 250.  I have some preempt bits turned on and SMP.
> > I've attached my full .config.
> Ok, your dump shows that we get proper values for the delay. For some
> reason it isn't respected though... Oddly enough, that delay is also
> the same for both working and non-working. Instead you have a delay
> just before the first command.

> Anyway... Just for the sake of it, add a msleep(500); at the beginning
> of mmc_rescan(). Hopefully that will get the delay we should already
> have.

This doesn't work but gives the following log.  I added a printk too
just to be sure I was using the right code; search for "msleep(500) added".

[  871.754182] sdhci: Secure Digital Host Controller Interface driver
[  871.754192] sdhci: Copyright(c) Pierre Ossman
[  871.754254] sdhci: SDHCI controller found at 0000:03:0b.3 [104c:803c] (rev 0)
[  871.754271] sdhci [sdhci_probe()]: found 1 slot(s)
[  871.754308] ACPI: PCI Interrupt 0000:03:0b.3[D] -> GSI 23 (level, low) -> IRQ 23
[  871.754322] sdhci [sdhci_probe_slot()]: slot 0 at 0x88089800, irq 23
[  871.755425] sdhci: ============== REGISTER DUMP ==============
[  871.755434] sdhci: Sys addr: 0x00000000 | Version:  0x00008900
[  871.755441] sdhci: Blk size: 0x00000000 | Blk cnt:  0x00000000
[  871.755449] sdhci: Argument: 0x00000000 | Trn mode: 0x00000000
[  871.755456] sdhci: Present:  0x000a0000 | Host ctl: 0x00000000
[  871.755463] sdhci: Power:    0x00000000 | Blk gap:  0x00000000
[  871.755471] sdhci: Wake-up:  0x00000000 | Clock:    0x00000000
[  871.755478] sdhci: Timeout:  0x00000000 | Int stat: 0x00000000
[  871.755486] sdhci: Int enab: 0x00ff00fb | Sig enab: 0x00ff00fb
[  871.755493] sdhci: AC12 err: 0x00000000 | Slot int: 0x00000000
[  871.755501] sdhci: Caps:     0x01e030b0 | Max curr: 0x00000000
[  871.755504] sdhci: ===========================================
[  871.755584] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0
[  871.755593] mmc_detect_change(0)
[  871.755607] mmc0: SDHCI at 0x88089800 irq 23 DMA
[  871.755695] msleep(500) added
[  871.791470] mmc0: clock 0Hz busmode 1 powermode 1 cs 0 Vdd 21 width 0 timing 0
[  871.793488] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[  871.796504] mmc0: clock 187500Hz busmode 1 powermode 2 cs 1 Vdd 21 width 0 timing 0
[  871.797514] mmc0: starting CMD0 arg 00000000 flags 000000c0
[  871.799085] mmc0: req done (CMD0): -123: 00000000 00000000 00000000 00000000
[  871.800486] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[  871.801497] mmc0: starting CMD8 arg 000001aa flags 000002f5
[  871.801876] mmc0: req done (CMD8): -123: 00000000 00000000 00000000 00000000
[  871.802128] mmc0: starting CMD5 arg 00000000 flags 000002e1
[  871.802181] mmc0: req failed (CMD5): -123, retrying...
[  871.802196] mmc0: req failed (CMD5): -123, retrying...
[  871.802210] mmc0: req failed (CMD5): -123, retrying...
[  871.802225] mmc0: req done (CMD5): -123: 00000000 00000000 00000000 00000000
[  871.802606] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  871.802626] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[  871.802780] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  871.802799] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[  871.802951] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  871.802969] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[  871.803119] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  871.803137] mmc0: req done (CMD55): -123: 00000000 00000000 00000000 00000000
[  871.803288] mmc0: starting CMD1 arg 00000000 flags 000000e1
[  871.803306] mmc0: req done (CMD1): -123: 00000000 00000000 00000000 00000000
[  871.803457] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0
[  873.138775] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00000040
[  873.138794] mmc_detect_change(125)
[  873.190739] msleep(500) added
[  873.233854] mmc0: clock 0Hz busmode 1 powermode 1 cs 0 Vdd 21 width 0 timing 0
[  873.235951] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[  873.238967] mmc0: clock 187500Hz busmode 1 powermode 2 cs 1 Vdd 21 width 0 timing 0
[  873.240038] mmc0: starting CMD0 arg 00000000 flags 000000c0
[  873.240190] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00000001
[  873.240201] mmc0: req done (CMD0): 0: 00000000 00000000 00000000 00000000
[  873.241266] mmc0: clock 187500Hz busmode 1 powermode 2 cs 0 Vdd 21 width 0 timing 0
[  873.242309] mmc0: starting CMD8 arg 000001aa flags 000002f5
[  873.243291] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.243306] mmc0: req done (CMD8): -110: 00000000 00000000 00000000 00000000
[  873.243367] mmc0: starting CMD5 arg 00000000 flags 000002e1
[  873.244348] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.244362] mmc0: req failed (CMD5): -110, retrying...
[  873.245339] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.245352] mmc0: req failed (CMD5): -110, retrying...
[  873.246321] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.246333] mmc0: req failed (CMD5): -110, retrying...
[  873.247303] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.247317] mmc0: req done (CMD5): -110: 00000000 00000000 00000000 00000000
[  873.247379] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  873.248353] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.248366] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[  873.248430] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  873.249399] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.249416] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[  873.249475] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  873.249727] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.249742] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[  873.249809] mmc0: starting CMD55 arg 00000000 flags 000000f5
[  873.250790] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.250803] mmc0: req done (CMD55): -110: 00000000 00000000 00000000 00000000
[  873.250869] mmc0: starting CMD1 arg 00000000 flags 000000e1
[  873.251844] sdhci [sdhci_irq()]: *** sdhci:slot0 got interrupt: 0x00018000
[  873.251858] mmc0: req done (CMD1): -110: 00000000 00000000 00000000 00000000
[  873.251924] mmc0: clock 0Hz busmode 1 powermode 0 cs 0 Vdd 0 width 0 timing 0

-- 
----------(   "I got everything up to the part about `Now    )----------
Simon ----(           listen closely'" - The Cat.            )---- Nomis
                             Htag.pl 0.0.22