Can't mount QSPI-FLASH to userland on Lager

Can't mount QSPI-FLASH to userland on Lager

[Cao Minh Hiep]

Hi Rob Herring-san.
I'm sorry to bother you!

I'm Hiep from Jinzai Solution (a Japanese Company).
We are testing Linux kernel v4.0-rc2 on Lager and Koelsch Board ( 
Renesas's boards).
When we tried to test QSPI-FLASH, we can't mount the device file of 
QSPI-FLASH on Lager.
(Koelsch has no problems)
The logs is showed as below:
#mount /dev/mtdblock2 /mnt/
"EXT3-fs (mtdblock2): error: can't find ext3 filesystem on dev mtdblock2.
EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
FAT-fs (mtdblock2): bogus number of reserved sectors
FAT-fs (mtdblock2): Can't find a valid FAT filesystem
FAT-fs (mtdblock2): bogus number of reserved sectors
FAT-fs (mtdblock2): Can't find a valid FAT filesystem
mount: you must specify the filesystem type"

We found that, after removing this patch(as below),
QSPI-FLASH can mount on Lager very well without any problems.
"9064bf3　spi: spi-pxa2xx: only include mach/dma.h for legacy DMA"
I'd like to report it to you and please review it when you have time.


Best Regards,
Jinso/Cao Minh Hiep.

Re: Can't mount QSPI-FLASH to userland on Lager

[Geert Uytterhoeven]

Hi Hiep-san,

On Mon, Mar 23, 2015 at 2:36 AM, Cao Minh Hiep <cm-hiep@jinso.co.jp> wrote:
> Hi Rob Herring-san.
> I'm sorry to bother you!
>
> I'm Hiep from Jinzai Solution (a Japanese Company).
> We are testing Linux kernel v4.0-rc2 on Lager and Koelsch Board ( Renesas's
> boards).
> When we tried to test QSPI-FLASH, we can't mount the device file of
> QSPI-FLASH on Lager.
> (Koelsch has no problems)

This is strange: Koelsch and Lager are very similar w.r.t. SPI.
Are you booting the same kernel image?
Do the qspi device nodes in both r8a7790.dtsi and r8a7791.dtsi have dma
properties?
Is there any significant difference in the kernel logs of koelsch and lager?

> The logs is showed as below:
> #mount /dev/mtdblock2 /mnt/
> "EXT3-fs (mtdblock2): error: can't find ext3 filesystem on dev mtdblock2.
> EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
> EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
> FAT-fs (mtdblock2): bogus number of reserved sectors
> FAT-fs (mtdblock2): Can't find a valid FAT filesystem
> FAT-fs (mtdblock2): bogus number of reserved sectors
> FAT-fs (mtdblock2): Can't find a valid FAT filesystem
> mount: you must specify the filesystem type"
>
> We found that, after removing this patch(as below),
> QSPI-FLASH can mount on Lager very well without any problems.
> "9064bf3　spi: spi-pxa2xx: only include mach/dma.h for legacy DMA"
> I'd like to report it to you and please review it when you have time.

That commit looks like a fairly innocent change to me, but you never know
when mach/*.h is involved...

Which kernel config are you using? shmobile_defconfig?
Do you have CONFIG_SPI_PXA2XX enabled in your .config?
It seems CONFIG_SPI_PXA2XX can be enabled if !ARCH_PXA, while
CONFIG_SPI_PXA2XX_DMA can't. And ARCH_PXA doesn't support
multi-platform.

Which kernel version are you using?

Thanks!

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: Can't mount QSPI-FLASH to userland on Lager

[Cao Minh Hiep]

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

Hi Geert-san, Rob Herring-san.

Thank you for pointing it out.

>> Hi Rob Herring-san.
>> I'm sorry to bother you!
>>
>> I'm Hiep from Jinzai Solution (a Japanese Company).
>> We are testing Linux kernel v4.0-rc2 on Lager and Koelsch Board ( Renesas's
>> boards).
>> When we tried to test QSPI-FLASH, we can't mount the device file of
>> QSPI-FLASH on Lager.
>> (Koelsch has no problems)
> This is strange: Koelsch and Lager are very similar w.r.t. SPI.
> Are you booting the same kernel image?
> Do the qspi device nodes in both r8a7790.dtsi and r8a7791.dtsi have dma
> properties?
> Is there any significant difference in the kernel logs of koelsch and lager?
(snip)
> Which kernel version are you using?

We tested both of boards on linux v4.0-rc2. And DMA is available on two 
boards.
I attached the image building history and test logs files of Lager and 
Koelsch.
File1: qspi_v4.0-rc2_test_logs_on_koelsch.txt
File2: qspi_v4.0-rc2_test_logs_on_lager.txt

>> The logs is showed as below:
>> #mount /dev/mtdblock2 /mnt/
>> "EXT3-fs (mtdblock2): error: can't find ext3 filesystem on dev mtdblock2.
>> EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
>> EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
>> FAT-fs (mtdblock2): bogus number of reserved sectors
>> FAT-fs (mtdblock2): Can't find a valid FAT filesystem
>> FAT-fs (mtdblock2): bogus number of reserved sectors
>> FAT-fs (mtdblock2): Can't find a valid FAT filesystem
>> mount: you must specify the filesystem type"
>>
>> We found that, after removing this patch(as below),
>> QSPI-FLASH can mount on Lager very well without any problems.
>> "9064bf3　spi: spi-pxa2xx: only include mach/dma.h for legacy DMA"
>> I'd like to report it to you and please review it when you have time.
> That commit looks like a fairly innocent change to me, but you never know
> when mach/*.h is involved...
>
> Which kernel config are you using? shmobile_defconfig?
> Do you have CONFIG_SPI_PXA2XX enabled in your .config?
> It seems CONFIG_SPI_PXA2XX can be enabled if !ARCH_PXA, while
> CONFIG_SPI_PXA2XX_DMA can't. And ARCH_PXA doesn't support
> multi-platform.
I'm sorry. This is my mistake. I was wrong about this patch.
Besides that, we found an other series of patches that added between 
v3.19..v4.0-rc1 as below:

"fc9e0f7 spi: Only idle the message pump in the worker kthread
0461a41 spi: Pump transfers inside calling context for spi_sync()
983aee5 spi: Check to see if the device is processing a message before 
we idle
5424d43 spi: Move queue data structure initialisation to main master init"

when we tried to revert fc9e0f7 and 0461a41 then re-build image for Lager,
This problem has disappeared on Lager.
I attached the image building history and test logs files.
File: qspi_v4.0-rc2_after_reverting_patches_test_logs_on_lager.txt

Best Regards,
Cao Minh Hiep.



[-- Attachment #2: qspi_v4.0-rc2_test_logs_on_lager.txt --]
[-- Type: text/plain, Size: 2454 bytes --]

Image Building History:

jinso02@jinso02:~/WORK/linux$ git log --oneline -3
13a7a6a Linux 4.0-rc2
9128b04 drm/i915: Fix modeset state confusion in the load detect code
023a600 Merge tag 'gpio-v4.0-2' of git://git.kernel.org/pub/scm/linux/kernel/git/linusw/linux-gpio
 2233  make shmobile_defconfig
 2234  make menuconfig		(Enabled ext3 and ext4)
 2235  make -j16 uImage LOADADDR=0x40008000
 2236  make r8a7790-lager.dtb
 2237  vim arch/arm/boot/dts/r8a7790-lager.dts
 2238  make r8a7790-lager.dtb
 2239  cat arch/arm/boot/zImage arch/arm/boot/dts/r8a7790-lager.dtb > zImage.dtb 
 2240  mkimage -A arm -O linux -C none  -T kernel -a 0x40008000 -e 0x40008000 -n 'Linux-4.0.0-rc2' -d zImage.dtb uImage.dtb
 2241  sudo cp uImage.dtb /var/lib/tftpboot/Lager/



Kernel:

renesas_spi e6b10000.spi: DMA available
m25p80 spi0.0: s25fl512s (65536 Kbytes)
3 ofpart partitions found on MTD device spi0.0
Creating 3 MTD partitions on "spi0.0":
0x000000000000-0x000000040000 : "loader"
0x000000040000-0x000000440000 : "user"
0x000000440000-0x000004000000 : "flash"
renesas_spi e6b10000.spi: probed


root@localhost:~# uname -a
Linux localhost.localdomain 4.0.0-rc2 #2 SMP Mon Mar 23 17:54:15 JST 2015 armv7l armv7l armv7l GNU/Lx
root@localhost:~# 

root@localhost:~# mkfs.ext3 /dev/mtdblock2 
mke2fs 1.42.5 (29-Jul-2012)
Filesystem label=
OS type: Linux
Block size=1024 (log=0)
Fragment size=1024 (log=0)
Stride=0 blocks, Stripe width=0 blocks
15296 inodes, 61184 blocks
3059 blocks (5.00%) reserved for the super user
First data block=1
Maximum filesystem blocks=62652416
8 block groups
8192 blocks per group, 8192 fragments per group
1912 inodes per group
Superblock backups stored on blocks: 
        8193, 24577, 40961, 57345

Allocating group tables: done                            
Writing inode tables: done                            
Creating journal (4096 blocks): done
Writing superblocks and filesystem accounting information: done

root@localhost:~# 
root@localhost:~# mount /dev/mtdblock2 /mnt/
EXT3-fs (mtdblock2): error: can't find ext3 filesystem on dev mtdblock2.
EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
EXT4-fs (mtdblock2): VFS: Can't find ext4 filesystem
FAT-fs (mtdblock2): bogus number of reserved sectors
FAT-fs (mtdblock2): Can't find a valid FAT filesystem
FAT-fs (mtdblock2): bogus number of reserved sectors
FAT-fs (mtdblock2): Can't find a valid FAT filesystem
mount: you must specify the filesystem type
root@localhost:~# 


[-- Attachment #3: qspi_v4.0-rc2_test_logs_on_koelsch.txt --]
[-- Type: text/plain, Size: 2198 bytes --]


Koelsch: Image Building History:

jinso02@jinso02:~/WORK/linux$ git log --oneline -3
13a7a6a Linux 4.0-rc2
9128b04 drm/i915: Fix modeset state confusion in the load detect code
023a600 Merge tag 'gpio-v4.0-2' of git://git.kernel.org/pub/scm/linux/kernel/git/linusw/linux-gpio

 2269  make shmobile_defconfig
 2270  make menuconfig
 2271  make -j16 uImage LOADADDR=0x40008000
 2272  make r8a7791-koelsch.dtb
 2273  vim arch/arm/boot/dts/r8a7791-koelsch.dts
 2274  make r8a7791-koelsch.dtb
 2275  cat arch/arm/boot/zImage arch/arm/boot/dts/r8a7791-koelsch.dtb > zImage.dtb 
 2276  mkimage -A arm -O linux -C none  -T kernel -a 0x40008000 -e 0x40008000 -n 'Linux-4.0.0-rc2' -d zImage.dtb uImage.dtb
 2277  sudo cp uImage.dtb /var/lib/tftpboot/Koelsch/



Kernel test logs:

renesas_spi e6b10000.spi: DMA available
m25p80 spi0.0: s25fl512s (65536 Kbytes)
3 ofpart partitions found on MTD device spi0.0
Creating 3 MTD partitions on "spi0.0":
0x000000000000-0x000000080000 : "loader"
0x000000080000-0x000000600000 : "user"
0x000000600000-0x000004000000 : "flash"
renesas_spi e6b10000.spi: probed

root@localhost:~# 
root@localhost:~# uname -a
Linux localhost.localdomain 4.0.0-rc2 #1 SMP Mon Mar 23 18:31:01 JST 2015 armv7l armv7l armv7l GNU/Lx
root@localhost:~# 
root@localhost:~# mkfs.ext3 /dev/mtdblock2 
mke2fs 1.42.5 (29-Jul-2012)
Filesystem label=
OS type: Linux
Block size=1024 (log=0)
Fragment size=1024 (log=0)
Stride=0 blocks, Stripe width=0 blocks
14848 inodes, 59392 blocks
2969 blocks (5.00%) reserved for the super user
First data block=1
Maximum filesystem blocks=60817408
8 block groups
8192 blocks per group, 8192 fragments per group
1856 inodes per group
Superblock backups stored on blocks: 
        8193, 24577, 40961, 57345

Allocating group tables: done                            
Writing inode tables: done                            
Creating journal (4096 blocks): done
Writing superblocks and filesystem accounting information:    
done

root@localhost:~# 
root@localhost:~# mount /dev/mtdblock2 /mnt/
kjournald starting.  Commit interval 5 seconds
EXT3-fs (mtdblock2): using internal journal
EXT3-fs (mtdblock2): mounted filesystem with ordered data mode
root@localhost:~# 


[-- Attachment #4: qspi_v4.0-rc2_after_reverting_patches_test_logs_on_lager.txt --]
[-- Type: text/plain, Size: 2658 bytes --]

V4.0-rc2 after reverting patches image building history:

jinso02@jinso02:~/WORK/linux$ git revert fc9e0f7
[linux-v4.0-rc2 9452ebb] Revert "spi: Only idle the message pump in the worker kthread"
 1 file changed, 6 insertions(+), 26 deletions(-)
jinso02@jinso02:~/WORK/linux$ git revert 0461a41
[linux-v4.0-rc2 3b5327b] Revert "spi: Pump transfers inside calling context for spi_sync()"
 2 files changed, 8 insertions(+), 60 deletions(-)
jinso02@jinso02:~/WORK/linux$ 
jinso02@jinso02:~/WORK/linux$ git log --oneline -3
3b5327b Revert "spi: Pump transfers inside calling context for spi_sync()"
9452ebb Revert "spi: Only idle the message pump in the worker kthread"
13a7a6a Linux 4.0-rc2
jinso02@jinso02:~/WORK/linux$...
jinso02@jinso02:~/WORK/linux$history

 2248  make distclean
 2249  rm zImage.dtb uImage.dtb 
 2250  ls
 2251  make shmobile_defconfig
 2252  make menuconfig				(Enabled ext3 and ext4)
 2253  make -j16 uImage LOADADDR=0x40008000
 2254  make r8a7790-lager.dtb
 2255  cat arch/arm/boot/zImage arch/arm/boot/dts/r8a7790-lager.dtb > zImage.dtb 
 2256  mkimage -A arm -O linux -C none  -T kernel -a 0x40008000 -e 0x40008000 -n 'Linux-4.0.0-rc2-00002-g3b5327b-d' -d zImage.dtb uImage.dtb
 2257  sudo cp uImage.dtb /var/lib/tftpboot/Lager/


Kernel test logs:

renesas_spi e6b10000.spi: DMA available
m25p80 spi0.0: s25fl512s (65536 Kbytes)
3 ofpart partitions found on MTD device spi0.0
Creating 3 MTD partitions on "spi0.0":
0x000000000000-0x000000040000 : "loader"
0x000000040000-0x000000440000 : "user"
0x000000440000-0x000004000000 : "flash"
renesas_spi e6b10000.spi: probed


root@localhost:~# uname -a
Linux localhost.localdomain 4.0.0-rc2-00002-g3b5327b-dirty #1 SMP Mon Mar 23 18:12:15 JST 2015 armv7x
root@localhost:~# 
root@localhost:~# mkfs.ext3 /dev/mtdblock2 
mke2fs 1.42.5 (29-Jul-2012)
Filesystem label=
OS type: Linux
Block size=1024 (log=0)
Fragment size=1024 (log=0)
Stride=0 blocks, Stripe width=0 blocks
15296 inodes, 61184 blocks
3059 blocks (5.00%) reserved for the super user
First data block=1
Maximum filesystem blocks=62652416
8 block groups
8192 blocks per group, 8192 fragments per group
1912 inodes per group
Superblock backups stored on blocks: 
        8193, 24577, 40961, 57345

Allocating group tables: done                            
Writing inode tables: done                            
Creating journal (4096 blocks): done
Writing superblocks and filesystem accounting information: done

root@localhost:~# mount /dev/mtdblock2 /mnt/
kjournald starting.  Commit interval 5 seconds
EXT3-fs (mtdblock2): using internal journal
EXT3-fs (mtdblock2): mounted filesystem with ordered data mode
root@localhost:~# 

Re: Can't mount QSPI-FLASH to userland on Lager

[Mark Brown]

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

On Mon, Mar 23, 2015 at 07:02:18PM +0900, Cao Minh Hiep wrote:

> "fc9e0f7 spi: Only idle the message pump in the worker kthread
> 0461a41 spi: Pump transfers inside calling context for spi_sync()
> 983aee5 spi: Check to see if the device is processing a message before we
> idle
> 5424d43 spi: Move queue data structure initialisation to main master init"

> when we tried to revert fc9e0f7 and 0461a41 then re-build image for Lager,
> This problem has disappeared on Lager.
> I attached the image building history and test logs files.
> File: qspi_v4.0-rc2_after_reverting_patches_test_logs_on_lager.txt

Interesting...  nobody else has reported any problems.  Can you collect
traces from the failing and successful systems with ftrace (turn on
/sys/kernel/debug/tracing/events/spi/enable to get all the SPI logging)
please?

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

Re: Can't mount QSPI-FLASH to userland on Lager

[Geert Uytterhoeven]

Hi Hiep-san,

On Tue, Mar 24, 2015 at 8:17 AM, Cao Minh Hiep <cm-hiep@jinso.co.jp> wrote:
> On 2015年03月24日 01:27, Mark Brown wrote:
>>
>> On Mon, Mar 23, 2015 at 07:02:18PM +0900, Cao Minh Hiep wrote:
>>
>>> "fc9e0f7 spi: Only idle the message pump in the worker kthread
>>> 0461a41 spi: Pump transfers inside calling context for spi_sync()
>>> 983aee5 spi: Check to see if the device is processing a message before we
>>> idle
>>> 5424d43 spi: Move queue data structure initialisation to main master
>>> init"
>>> when we tried to revert fc9e0f7 and 0461a41 then re-build image for
>>> Lager,
>>> This problem has disappeared on Lager.
>>> I attached the image building history and test logs files.
>>> File: qspi_v4.0-rc2_after_reverting_patches_test_logs_on_lager.txt
>>
>> Interesting...  nobody else has reported any problems.  Can you collect
>> traces from the failing and successful systems with ftrace (turn on
>> /sys/kernel/debug/tracing/events/spi/enable to get all the SPI logging)
>> please?
>
> I attached the traces logs file of failing and successful systems:
> file1: qspi_v4.0-rc2_added_tracer_test_logs_lager.txt
> file2: qspi_v4.0-rc2_added_tracer_and_reverting_patches_test_logs_lager.txt

Thanks!

This seems to trigger a bug in the SPI trace code:

Writing superblocks and filesystem accounting information: Unable to
handle kernel NULL pointer8
pgd = c0004000
[00000168] *pgd\0000000
Internal error: Oops: 17 [#1] SMP ARM
CPU: 0 PID: 633 Comm: spi0 Tainted: G        W       4.0.0-rc2-dirty #2
Hardware name: Generic R8A7790 (Flattened Device Tree)
task: eea2a040 ti: ee1f2000 task.ti: ee1f2000
PC is at ftrace_raw_event_spi_message_done+0x54/0x94
LR is at ring_buffer_event_data+0x10/0x14
pc : [<c037ebb0>]    lr : [<c0091144>]    psr: a0070013
sp : ee1f3e60  ip : ee1f3e28  fp : ee1f3e94
r10: 00000000  r9 : 00000001  r8 : eeaa9410
r7 : eeaa9410  r6 : ee819628  r5 : 00000003  r4 : ee945c4c
r3 : 00000000  r2 : 00000007  r1 : 00000004  r0 : eebd8840
Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
Control: 10c5307d  Table: 6c0a406a  DAC: 00000015
Process spi0 (pid: 633, stack limit = 0xee1f2210)
Stack: (0xee1f3e60 to 0xee1f4000)
3e60: ee803100 eebd883c ee819628 eebd8840 60070013 00000000 c0059710 ecc0fed0
3e80: ee945c18 ee945c4c ee1f3ebc ee1f3e98 c037fc64 c037eb68 ee945c18 ee945c4c
3ea0: ee272800 c0808f08 00000000 00000001 ee1f3eec ee1f3ec0 c037feb8 c037fb10
3ec0: c037fc7c ee272800 ee945c18 ee945c4c eeaa9410 ee272a0c eeaa9410 00000002
3ee0: ee1f3f2c ee1f3ef0 c0380400 c037fc88 00000100 c07b0400 c05831fc ee1f2000
3f00: ee1f2000 ee2729bc ee1f2000 c081c2b8 00000000 00000000 00000000 00000000
3f20: ee1f3f3c ee1f3f30 c0380458 c037fee4 ee1f3f5c ee1f3f40 c0042080 c0380444
3f40: ee27a640 00000000 ee2729bc c0041fa8 ee1f3fac ee1f3f60 c0041784 c0041fb4
3f60: c0039834 00000000 c000a3e4 ee2729bc 00000000 00000000 ee1f3f78 ee1f3f78
3f80: 00000000 00000000 ee1f3f88 ee1f3f88 ee27a640 c004169c 00000000 00000000
3fa0: 00000000 ee1f3fb0 c000eea0 c00416a8 00000000 00000000 00000000 00000000
3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
Backtrace:
[<c037eb5c>] (ftrace_raw_event_spi_message_done) from [<c037fc64>]
(spi_finalize_current_messag)
 r6:ee945c4c r5:ee945c18 r4:ecc0fed0
[<c037fb04>] (spi_finalize_current_message) from [<c037feb8>]
(spi_transfer_one_message+0x23c/0)
 r9:00000001 r8:00000000 r7:c0808f08 r6:ee272800 r5:ee945c4c r4:ee945c18

Can you please send the full boot kernel logs (dmesg), too?
I'm still intrigued by the difference between koelsch and lager.

Thanks!

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: Can't mount QSPI-FLASH to userland on Lager

[Mark Brown]

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

On Tue, Mar 24, 2015 at 04:17:32PM +0900, Cao Minh Hiep wrote:
> On 2015年03月24日 01:27, Mark Brown wrote:

> >Interesting...  nobody else has reported any problems.  Can you collect
> >traces from the failing and successful systems with ftrace (turn on
> >/sys/kernel/debug/tracing/events/spi/enable to get all the SPI logging)
> >please?

> I attached the traces logs file of failing and successful systems:
> file1: qspi_v4.0-rc2_added_tracer_test_logs_lager.txt
> file2: qspi_v4.0-rc2_added_tracer_and_reverting_patches_test_logs_lager.txt

> And also attached the logs file of 10times for testing in before/after
> reverting patches without tracer.
> file3: qspi_v4.0-rc2_test_logs_for_10times_lager.txt
> file4: qspi_v4.0-rc2_after_reverting_patches_test_logs_for_10times_lager.txt

These all look like console logs, not ftrace logs?

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

Re: Can't mount QSPI-FLASH to userland on Lager

[Mark Brown]

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

On Tue, Mar 24, 2015 at 04:42:44PM +0100, Geert Uytterhoeven wrote:

> This seems to trigger a bug in the SPI trace code:

There was a use after free bug which should be fixed in current code.

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

Re: Can't mount QSPI-FLASH to userland on Lager

[Cao Minh Hiep]

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

Hi Geert-san

Thanks for your comments,

On 2015年03月25日 00:42, Geert Uytterhoeven wrote:
> Hi Hiep-san,
>
> On Tue, Mar 24, 2015 at 8:17 AM, Cao Minh Hiep <cm-hiep@jinso.co.jp> wrote:
>> On 2015年03月24日 01:27, Mark Brown wrote:
>>> On Mon, Mar 23, 2015 at 07:02:18PM +0900, Cao Minh Hiep wrote:
>>>
>>>> "fc9e0f7 spi: Only idle the message pump in the worker kthread
>>>> 0461a41 spi: Pump transfers inside calling context for spi_sync()
>>>> 983aee5 spi: Check to see if the device is processing a message before we
>>>> idle
>>>> 5424d43 spi: Move queue data structure initialisation to main master
>>>> init"
>>>> when we tried to revert fc9e0f7 and 0461a41 then re-build image for
>>>> Lager,
>>>> This problem has disappeared on Lager.
>>>> I attached the image building history and test logs files.
>>>> File: qspi_v4.0-rc2_after_reverting_patches_test_logs_on_lager.txt
>>> Interesting...  nobody else has reported any problems.  Can you collect
>>> traces from the failing and successful systems with ftrace (turn on
>>> /sys/kernel/debug/tracing/events/spi/enable to get all the SPI logging)
>>> please?
>> I attached the traces logs file of failing and successful systems:
>> file1: qspi_v4.0-rc2_added_tracer_test_logs_lager.txt
>> file2: qspi_v4.0-rc2_added_tracer_and_reverting_patches_test_logs_lager.txt
> Thanks!
>
> This seems to trigger a bug in the SPI trace code:
>
> Writing superblocks and filesystem accounting information: Unable to
> handle kernel NULL pointer8
> pgd = c0004000
> [00000168] *pgd=00000000
> Internal error: Oops: 17 [#1] SMP ARM
> CPU: 0 PID: 633 Comm: spi0 Tainted: G        W       4.0.0-rc2-dirty #2
> Hardware name: Generic R8A7790 (Flattened Device Tree)
> task: eea2a040 ti: ee1f2000 task.ti: ee1f2000
> PC is at ftrace_raw_event_spi_message_done+0x54/0x94
> LR is at ring_buffer_event_data+0x10/0x14
> pc : [<c037ebb0>]    lr : [<c0091144>]    psr: a0070013
> sp : ee1f3e60  ip : ee1f3e28  fp : ee1f3e94
> r10: 00000000  r9 : 00000001  r8 : eeaa9410
> r7 : eeaa9410  r6 : ee819628  r5 : 00000003  r4 : ee945c4c
> r3 : 00000000  r2 : 00000007  r1 : 00000004  r0 : eebd8840
> Flags: NzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
> Control: 10c5307d  Table: 6c0a406a  DAC: 00000015
> Process spi0 (pid: 633, stack limit = 0xee1f2210)
> Stack: (0xee1f3e60 to 0xee1f4000)
> 3e60: ee803100 eebd883c ee819628 eebd8840 60070013 00000000 c0059710 ecc0fed0
> 3e80: ee945c18 ee945c4c ee1f3ebc ee1f3e98 c037fc64 c037eb68 ee945c18 ee945c4c
> 3ea0: ee272800 c0808f08 00000000 00000001 ee1f3eec ee1f3ec0 c037feb8 c037fb10
> 3ec0: c037fc7c ee272800 ee945c18 ee945c4c eeaa9410 ee272a0c eeaa9410 00000002
> 3ee0: ee1f3f2c ee1f3ef0 c0380400 c037fc88 00000100 c07b0400 c05831fc ee1f2000
> 3f00: ee1f2000 ee2729bc ee1f2000 c081c2b8 00000000 00000000 00000000 00000000
> 3f20: ee1f3f3c ee1f3f30 c0380458 c037fee4 ee1f3f5c ee1f3f40 c0042080 c0380444
> 3f40: ee27a640 00000000 ee2729bc c0041fa8 ee1f3fac ee1f3f60 c0041784 c0041fb4
> 3f60: c0039834 00000000 c000a3e4 ee2729bc 00000000 00000000 ee1f3f78 ee1f3f78
> 3f80: 00000000 00000000 ee1f3f88 ee1f3f88 ee27a640 c004169c 00000000 00000000
> 3fa0: 00000000 ee1f3fb0 c000eea0 c00416a8 00000000 00000000 00000000 00000000
> 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000 00000000
> Backtrace:
> [<c037eb5c>] (ftrace_raw_event_spi_message_done) from [<c037fc64>]
> (spi_finalize_current_messag)
>   r6:ee945c4c r5:ee945c18 r4:ecc0fed0
> [<c037fb04>] (spi_finalize_current_message) from [<c037feb8>]
> (spi_transfer_one_message+0x23c/0)
>   r9:00000001 r8:00000000 r7:c0808f08 r6:ee272800 r5:ee945c4c r4:ee945c18
>
> Can you please send the full boot kernel logs (dmesg), too?
> I'm still intrigued by the difference between koelsch and lager.
I attached the kernel bootlogs files of Koelsch and Lager.

Thank you.
Hiep.

[-- Attachment #2: Koelsch_v4.0-rc2_boot_logs.txt --]
[-- Type: text/plain, Size: 20093 bytes --]

=>  
KOELSCH SPI_LOADER(DDR3L) V0.12 2014.03.14
DEVICE S25FL512


U-Boot 2013.01.01-g46367b1 (Jan 22 2015 - 09:04:15)

CPU: Renesas Electronics R8A7791 rev 2.0
Board: Koelsch Board

DRAM:  1 GiB
MMC:   sh-sdhi: 0, sh-sdhi: 1, sh-sdhi: 2
SF: Detected S25FL512S with page size 256 KiB, total 64 MiB
In:    serial
Out:   serial
Err:   serial
Net:   sh_eth
=> bootp;bootm
sh_eth Waiting for PHY auto negotiation to complete.. done
sh_eth: 100Base/Full
BOOTP broadcast 1
DHCP client bound to address 172.16.1.36
Using sh_eth device
TFTP from server 172.16.1.9; our IP address is 172.16.1.36
Filename 'Koelsch/uImage.dtb'.
Load address: 0x40007fc0
Loading: #################################################################
         #################################################################
         #################################################################
         ######################################
         3.6 MiB/s
done
Bytes transferred = 3417193 (342469 hex)
## Booting kernel from Legacy Image at 40007fc0 ...
   Image Name:   Linux-4.0.0-rc2
   Image Type:   ARM Linux Kernel Image (uncompressed)
   Data Size:    3417129 Bytes = 3.3 MiB
   Load Address: 40008000
   Entry Point:  40008000
   Verifying Checksum ... OK
   XIP Kernel Image ... OK
OK

Starting kernel ...

Booting Linux on physical CPU 0x0
Linux version 4.0.0-rc2 (jinso02@jinso02) (gcc version 4.9.2 20140904 (prerelease) (crosstool-NG linaro-1.13.1-4.9-205
CPU: ARMv7 Processor [413fc0f2] revision 2 (ARMv7), cr=10c5307d
CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
Machine model: Koelsch
Ignoring memory block 0x200000000 - 0x240000000
debug: ignoring loglevel setting.
Memory policy: Data cache writealloc
On node 0 totalpages: 262144
free_area_init_node: node 0, pgdat c06b6340, node_mem_map eeff9000
  Normal zone: 1520 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 194560 pages, LIFO batch:31
  HighMem zone: 67584 pages, LIFO batch:15
PERCPU: Embedded 8 pages/cpu @eefca000 s11456 r0 d21312 u32768
pcpu-alloc: s11456 r0 d21312 u32768 alloc=8*4096
pcpu-alloc: [0] 0 [0] 1 
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 260624
Kernel command line: console=ttySC0, ignore_loglevel rw root=/dev/nfs ip=dhcp
PID hash table entries: 4096 (order: 2, 16384 bytes)
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 1032296K/1048576K available (5032K kernel code, 207K rwdata, 1324K rodata, 276K init, 193K bss, 16280K reserv)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xf0000000 - 0xff000000   ( 240 MB)
    lowmem  : 0xc0000000 - 0xef800000   ( 760 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
      .text : 0xc0008000 - 0xc063e044   (6361 kB)
      .init : 0xc063f000 - 0xc0684000   ( 276 kB)
      .data : 0xc0684000 - 0xc06b7c80   ( 208 kB)
       .bss : 0xc06b7c80 - 0xc06e832c   ( 194 kB)
Hierarchical RCU implementation.
        Additional per-CPU info printed with stalls.
        RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=2.
RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
NR_IRQS:16 nr_irqs:16 16
Architected cp15 timer(s) running at 10.00MHz (virt).
sched_clock: 56 bits at 10MHz, resolution 100ns, wraps every 3435973836800ns
Switching to timer-based delay loop, resolution 100ns
Console: colour dummy device 80x30
Calibrating delay loop (skipped), value calculated using timer frequency.. 20.00 BogoMIPS (lpj=100000)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
CPU: Testing write buffer coherency: ok
CPU0: update cpu_capacity 1024
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Setting up static identity map for 0x404f0498 - 0x404f04f0
Unable to boot CPU1 when MD21 is set
CPU1: failed to boot: -524
Brought up 1 CPUs
SMP: Total of 1 processors activated (20.00 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0
pinctrl core: initialized pinctrl subsystem
NET: Registered protocol family 16
DMA: preallocated 256 KiB pool for atomic coherent allocations
renesas_irqc e61c0000.interrupt-controller: driving 10 irqs
sh-pfc e6060000.pfc: r8a77910_pfc support registered
No ATAGs?
hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
hw-breakpoint: maximum watchpoint size is 8 bytes.
platform regulator@0: Driver reg-fixed-voltage requests probe deferral
platform regulator@2: Driver reg-fixed-voltage requests probe deferral
platform regulator@4: Driver reg-fixed-voltage requests probe deferral
gpio-regulator regulator@1: Could not obtain regulator setting GPIOs: -517
platform regulator@1: Driver gpio-regulator requests probe deferral
gpio-regulator regulator@3: Could not obtain regulator setting GPIOs: -517
platform regulator@3: Driver gpio-regulator requests probe deferral
gpio-regulator regulator@5: Could not obtain regulator setting GPIOs: -517
platform regulator@5: Driver gpio-regulator requests probe deferral
vgaarb: loaded
SCSI subsystem initialized
libata version 3.00 loaded.
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
i2c-sh_mobile e60b0000.i2c: I2C adapter 6, bus speed 100000 Hz
media: Linux media interface: v0.10
Linux video capture interface: v2.00
sh_cmt ffca0000.timer: ch0: used for clock events
sh_cmt ffca0000.timer: ch1: used as clock source
Advanced Linux Sound Architecture Driver Initialized.
Switched to clocksource arch_sys_counter
NET: Registered protocol family 2
TCP established hash table entries: 8192 (order: 3, 32768 bytes)
TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
TCP: Hash tables configured (established 8192 bind 8192)
TCP: reno registered
UDP hash table entries: 512 (order: 2, 16384 bytes)
UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
PCI: CLS 0 bytes, default 64
futex hash table entries: 512 (order: 3, 32768 bytes)
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
nfs4filelayout_init: NFSv4 File Layout Driver Registering...
nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
bounce: pool size: 64 pages
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
gpio_rcar e6050000.gpio: driving 32 GPIOs
gpio_rcar e6051000.gpio: driving 32 GPIOs
gpio_rcar e6052000.gpio: driving 32 GPIOs
gpio_rcar e6053000.gpio: driving 32 GPIOs
gpio_rcar e6054000.gpio: driving 32 GPIOs
gpio_rcar e6055000.gpio: driving 32 GPIOs
gpio_rcar e6055400.gpio: driving 32 GPIOs
gpio_rcar e6055800.gpio: driving 26 GPIOs
pci-rcar-gen2 ee090000.pci: PCI: bus0 revision 11
pci-rcar-gen2 ee090000.pci: PCI host bridge to bus 0000:00
pci_bus 0000:00: root bus resource [io  0xee080000-0xee0810ff]
pci_bus 0000:00: root bus resource [mem 0xee080000-0xee0810ff]
pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
pci 0000:00:00.0: [1033:0000] type 00 class 0x060000
pci 0000:00:00.0: reg 0x10: [mem 0xee090800-0xee090bff]
pci 0000:00:00.0: reg 0x14: [mem 0x40000000-0x7fffffff pref]
pci 0000:00:01.0: [1033:0035] type 00 class 0x0c0310
pci 0000:00:01.0: reg 0x10: [mem 0x00000000-0x00000fff]
pci 0000:00:01.0: supports D1 D2
pci 0000:00:01.0: PME# supported from D0 D1 D2 D3hot
pci 0000:00:02.0: [1033:00e0] type 00 class 0x0c0320
pci 0000:00:02.0: reg 0x10: [mem 0x00000000-0x000000ff]
pci 0000:00:02.0: supports D1 D2
pci 0000:00:02.0: PME# supported from D0 D1 D2 D3hot
PCI: bus0: Fast back to back transfers disabled
pci_bus 0000:00: busn_res: [bus 00-ff] end is updated to 00
pci 0000:00:01.0: can't enable device: BAR 0 [mem 0x00000000-0x00000fff] not claimed
pci 0000:00:01.0: Can't enable PCI device, BIOS handoff failed.
pci 0000:00:02.0: can't enable device: BAR 0 [mem 0x00000000-0x000000ff] not claimed
pci 0000:00:02.0: Can't enable PCI device, BIOS handoff failed.
pci 0000:00:01.0: BAR 0: assigned [mem 0xee080000-0xee080fff]
pci 0000:00:02.0: BAR 0: assigned [mem 0xee081000-0xee0810ff]
pci-rcar-gen2 ee0d0000.pci: PCI: bus0 revision 11
pci-rcar-gen2 ee0d0000.pci: PCI host bridge to bus 0001:01
pci_bus 0001:01: root bus resource [io  0xee0c0000-0xee0c10ff]
pci_bus 0001:01: root bus resource [mem 0xee0c0000-0xee0c10ff]
pci_bus 0001:01: No busn resource found for root bus, will use [bus 01-ff]
pci 0001:01:00.0: [1033:0000] type 00 class 0x060000
pci 0001:01:00.0: reg 0x10: [mem 0xee0d0800-0xee0d0bff]
pci 0001:01:00.0: reg 0x14: [mem 0x40000000-0x7fffffff pref]
pci 0001:01:01.0: [1033:0035] type 00 class 0x0c0310
pci 0001:01:01.0: reg 0x10: [mem 0x00000000-0x00000fff]
pci 0001:01:01.0: supports D1 D2
pci 0001:01:01.0: PME# supported from D0 D1 D2 D3hot
pci 0001:01:02.0: [1033:00e0] type 00 class 0x0c0320
pci 0001:01:02.0: reg 0x10: [mem 0x00000000-0x000000ff]
pci 0001:01:02.0: supports D1 D2
pci 0001:01:02.0: PME# supported from D0 D1 D2 D3hot
PCI: bus1: Fast back to back transfers disabled
pci_bus 0001:01: busn_res: [bus 01-ff] end is updated to 01
pci 0001:01:01.0: can't enable device: BAR 0 [mem 0x00000000-0x00000fff] not claimed
pci 0001:01:01.0: Can't enable PCI device, BIOS handoff failed.
pci 0001:01:02.0: can't enable device: BAR 0 [mem 0x00000000-0x000000ff] not claimed
pci 0001:01:02.0: Can't enable PCI device, BIOS handoff failed.
pci 0001:01:01.0: BAR 0: assigned [mem 0xee0c0000-0xee0c0fff]
pci 0001:01:02.0: BAR 0: assigned [mem 0xee0c1000-0xee0c10ff]
rcar-pcie fe000000.pcie: PCIe link down
Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
SuperH (H)SCI(F) driver initialized
e6e60000.serial: ttySC0 at MMIO 0xe6e60000 (irq = 107, base_baud = 0) is a scif
console [ttySC0] enabled
e6e68000.serial: ttySC1 at MMIO 0xe6e68000 (irq = 108, base_baud = 0) is a scif
[drm] Initialized drm 1.1.0 20060810
rcar-du feb00000.display: error: no encoder could be initialized
rcar-du feb00000.display: failed to initialize DRM/KMS
rcar-du: probe of feb00000.display failed with error -22
scsi host0: sata_rcar
ata1: SATA max UDMA/133 irq 110
renesas_spi e6b10000.spi: DMA available
m25p80 spi0.0: s25fl512s (65536 Kbytes)
3 ofpart partitions found on MTD device spi0.0
Creating 3 MTD partitions on "spi0.0":
0x000000000000-0x000000080000 : "loader"
0x000000080000-0x000000600000 : "user"
0x000000600000-0x000004000000 : "flash"
renesas_spi e6b10000.spi: probed
spi_sh_msiof e6e20000.spi: DMA available
libphy: sh_mii: probed
sh-eth ee700000.ethernet eth0: Base address at 0xee700000, 2e:09:0a:00:75:df, IRQ 109.
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ehci-pci: EHCI PCI platform driver
ehci-pci 0000:00:02.0: enabling device (0140 -> 0142)
ehci-pci 0000:00:02.0: EHCI Host Controller
ehci-pci 0000:00:02.0: new USB bus registered, assigned bus number 1
ehci-pci 0000:00:02.0: irq 120, io mem 0xee081000
ehci-pci 0000:00:02.0: USB 2.0 started, EHCI 1.00
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 1 port detected
ehci-pci 0001:01:02.0: enabling device (0140 -> 0142)
ehci-pci 0001:01:02.0: EHCI Host Controller
ehci-pci 0001:01:02.0: new USB bus registered, assigned bus number 2
ehci-pci 0001:01:02.0: irq 121, io mem 0xee0c1000
ehci-pci 0001:01:02.0: USB 2.0 started, EHCI 1.00
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 1 port detected
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
ohci-pci: OHCI PCI platform driver
ohci-pci 0000:00:01.0: enabling device (0140 -> 0142)
ohci-pci 0000:00:01.0: OHCI PCI host controller
ohci-pci 0000:00:01.0: new USB bus registered, assigned bus number 3
ohci-pci 0000:00:01.0: irq 120, io mem 0xee080000
ata1: link resume succeeded after 1 retries
ohci-pci 0000:00:01.0: init err (00002edf 0000)
ohci-pci 0000:00:01.0: can't start
ohci-pci 0000:00:01.0: startup error -75
ohci-pci 0000:00:01.0: USB bus 3 deregistered
ohci-pci 0000:00:01.0: init 0000:00:01.0 fail, -75
ohci-pci: probe of 0000:00:01.0 failed with error -75
ohci-pci 0001:01:01.0: enabling device (0140 -> 0142)
ohci-pci 0001:01:01.0: OHCI PCI host controller
ohci-pci 0001:01:01.0: new USB bus registered, assigned bus number 3
ohci-pci 0001:01:01.0: irq 121, io mem 0xee0c0000
ata1: SATA link down (SStatus 0 SControl 300)
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 1 port detected
sh-pfc e6060000.pfc: pin GP_7_23 already requested by ee090000.pci; cannot claim for e6590000.usb
sh-pfc e6060000.pfc: pin-247 (e6590000.usb) status -22
sh-pfc e6060000.pfc: could not request pin 247 (GP_7_23) from group usb0  on device sh-pfc
renesas_usbhs e6590000.usb: Error applying setting, reverse things back
renesas_usbhs e6590000.usb: gadget probed
renesas_usbhs e6590000.usb: platform init failed.
renesas_usbhs e6590000.usb: probe failed
mousedev: PS/2 mouse device common for all mice
i2c /dev entries driver
at24 2-0050: 256 byte 24c02 EEPROM, writable, 16 bytes/write
i2c-rcar e6530000.i2c: probed
adv7180 2-0020: chip found @ 0x20 (e6530000.i2c)
soc-camera-pdrv soc-camera-pdrv.0: Probing soc-camera-pdrv.0
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1 at drivers/base/devres.c:887 devm_kfree+0x30/0x40()
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.0.0-rc2 #5
Hardware name: Generic R8A7791 (Flattened Device Tree)
Backtrace: 
[<c0011e94>] (dump_backtrace) from [<c001203c>] (show_stack+0x18/0x1c)
 r7:c05fe3bc r6:ee82f9c0 r5:00000009 r4:00000000
[<c0012024>] (show_stack) from [<c04ec01c>] (dump_stack+0x78/0x94)
[<c04ebfa4>] (dump_stack) from [<c0025210>] (warn_slowpath_common+0x88/0xb4)
 r5:00000009 r4:00000000
[<c0025188>] (warn_slowpath_common) from [<c0025314>] (warn_slowpath_null+0x24/0x2c)
 r9:ee05b8a8 r8:eefe0398 r7:ee0b4810 r6:ee0b4c20 r5:fffffffa r4:ee05b890
[<c00252f0>] (warn_slowpath_null) from [<c02bbfd8>] (devm_kfree+0x30/0x40)
[<c02bbfa8>] (devm_kfree) from [<c0389050>] (soc_of_bind.isra.14+0x194/0x1d4)
[<c0388ebc>] (soc_of_bind.isra.14) from [<c0389b10>] (soc_camera_host_register+0x208/0x31c)
 r9:00000070 r8:eefe7384 r7:ee960210 r6:00000000 r5:eefe7000 r4:ee0b4c20
[<c0389908>] (soc_camera_host_register) from [<c038bc7c>] (rcar_vin_probe+0x1f8/0x23c)
 r9:00000070 r8:ee960200 r7:00000008 r6:ee960210 r5:ee0b4c10 r4:c06ab9b0
[<c038ba84>] (rcar_vin_probe) from [<c02ba274>] (platform_drv_probe+0x50/0xa0)
 r10:00000000 r9:c06ab7bc r8:00000000 r7:c06db980 r6:c06ab7bc r5:ee960210
 r4:ffffffef
[<c02ba224>] (platform_drv_probe) from [<c02b8df8>] (driver_probe_device+0xc4/0x208)
 r7:c06db980 r6:c06db974 r5:00000000 r4:ee960210
[<c02b8d34>] (driver_probe_device) from [<c02b8ff8>] (__driver_attach+0x70/0x94)
 r9:c06b7c80 r8:00000000 r7:c06a40a0 r6:c06ab7bc r5:ee960244 r4:ee960210
[<c02b8f88>] (__driver_attach) from [<c02b7740>] (bus_for_each_dev+0x74/0x98)
 r7:c06a40a0 r6:c02b8f88 r5:c06ab7bc r4:00000000
[<c02b76cc>] (bus_for_each_dev) from [<c02b90cc>] (driver_attach+0x20/0x28)
 r6:ee066500 r5:00000000 r4:c06ab7bc
[<c02b90ac>] (driver_attach) from [<c02b7efc>] (bus_add_driver+0xdc/0x1c4)
[<c02b7e20>] (bus_add_driver) from [<c02b97e0>] (driver_register+0xa4/0xe8)
 r7:c06770d8 r6:c06770d8 r5:c065cbe4 r4:c06ab7bc
[<c02b973c>] (driver_register) from [<c02babbc>] (__platform_driver_register+0x50/0x64)
 r5:c065cbe4 r4:ee0b1d00
[<c02bab6c>] (__platform_driver_register) from [<c065cbfc>] (rcar_vin_driver_init+0x18/0x20)
[<c065cbe4>] (rcar_vin_driver_init) from [<c063fdec>] (do_one_initcall+0x10c/0x1bc)
[<c063fce0>] (do_one_initcall) from [<c063ffb4>] (kernel_init_freeable+0x118/0x1e0)
 r8:c06b7c80 r7:c067fc58 r6:c0677904 r5:000000ad r4:00000006
[<c063fe9c>] (kernel_init_freeable) from [<c04e8f80>] (kernel_init+0x14/0xec)
 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c04e8f6c r4:c06b7c80
[<c04e8f6c>] (kernel_init) from [<c000eba0>] (ret_from_fork+0x14/0x34)
 r5:c04e8f6c r4:00000000
---[ end trace c90e1070ae3e566c ]---
rcar_vin e6ef1000.video: group probe failed: -6
rcar_thermal e61f0000.thermal: 1 sensor probed
Driver 'mmcblk' needs updating - please use bus_type methods
sh_mobile_sdhi ee100000.sd: Got CD GPIO
sh_mobile_sdhi ee100000.sd: Got WP GPIO
platform ee100000.sd: Driver sh_mobile_sdhi requests probe deferral
sh_mobile_sdhi ee140000.sd: Got CD GPIO
sh_mobile_sdhi ee140000.sd: Got WP GPIO
platform ee140000.sd: Driver sh_mobile_sdhi requests probe deferral
sh_mobile_sdhi ee160000.sd: Got CD GPIO
platform ee160000.sd: Driver sh_mobile_sdhi requests probe deferral
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
platform sound: Driver asoc-simple-card requests probe deferral
rcar_sound ec500000.rcar_sound: can't get dma channel
rcar_sound ec500000.rcar_sound: src[2] (Gen2) failed
rcar_sound ec500000.rcar_sound: ssi[0] fallback to PIO mode
rcar_sound ec500000.rcar_sound: can't get dma channel       
rcar_sound ec500000.rcar_sound: src[3] (Gen2) failed        
rcar_sound ec500000.rcar_sound: ssi[1] fallback to PIO mode 
rcar_sound ec500000.rcar_sound: probed                      
TCP: cubic registered                                       
NET: Registered protocol family 10                          
sit: IPv6 over IPv4 tunneling driver                        
NET: Registered protocol family 17                          
Key type dns_resolver registered                            
Registering SWP/SWPB emulation handler                      
sh_mobile_sdhi ee100000.sd: Got CD GPIO                     
sh_mobile_sdhi ee100000.sd: Got WP GPIO                     
sh_mobile_sdhi ee100000.sd: mmc0 base at 0xee100000 clock rate 97 MHz
sh_mobile_sdhi ee140000.sd: Got CD GPIO                     
sh_mobile_sdhi ee140000.sd: Got WP GPIO                     
sh_mobile_sdhi ee140000.sd: mmc1 base at 0xee140000 clock rate 97 MHz
sh_mobile_sdhi ee160000.sd: Got CD GPIO                     
sh_mobile_sdhi ee160000.sd: mmc2 base at 0xee160000 clock rate 97 MHz
asoc-simple-card sound: ak4642-hifi <-> ec500000.rcar_sound mapping ok
input: keyboard as /devices/platform/keyboard/input/input0
drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
sh-eth ee700000.ethernet eth0: attached PHY 1 (IRQ 375) to driver Micrel KSZ8041RNLI
Sending DHCP requests .
sh-eth ee700000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
., OK
IP-Config: Got DHCP answer from 172.16.1.9, my address is 172.16.1.36
IP-Config: Complete:
     device=eth0, hwaddr=2e:09:0a:00:75:df, ipaddr=172.16.1.36, mask=255.255.255.0, gw=172.16.1.9
     host=172.16.1.36, domain=, nis-domain=(none)
     bootserver=172.16.1.9, rootserver=172.16.1.9, rootpath=
     nameserver0=172.16.1.30, nameserver1=172.16.1.40, nameserver2=8.8.8.8
SDHI2 VccQ: disabling
SDHI1 VccQ: disabling
SDHI0 VccQ: disabling
SDHI2 Vcc: disabling
SDHI1 Vcc: disabling
SDHI0 Vcc: disabling
ALSA device list:
  #0: rsnd-dai.0-ak4642-hifi
VFS: Mounted root (nfs filesystem) on device 0:13.
devtmpfs: mounted
Freeing unused kernel memory: 276K (c063f000 - c0684000)
random: init urandom read with 35 bits of entropy available
init: ureadahead main process (790) terminated with status 5
udevd[857]: starting version 175
random: nonblocking pool is initialized
init: udev-fallback-graphics main process (1359) terminated with status 1
init: plymouth main process (791) killed by ABRT signal
init: plymouth-splash main process (1392) terminated with status 2
init: failsafe main process (1399) killed by TERM signal
�s�nP 3�00PY8k��2�2=pF�\x19�0��:82\x1dY��2���p�\x19����\x19��3���(���p��3�x\x19��C�Нl�3�r���sy&����}
root@localhost:~# 
root@localhost:~# 
root@localhost:~# uname -a
Linux localhost.localdomain 4.0.0-rc2 #5 SMP Wed Mar 25 09:42:01 JST 2015 armv7l armv7l armv7l GNU/Linux
root@localhost:~# 


[-- Attachment #3: Lager_v4.0-rc2_boot_logs.txt --]
[-- Type: text/plain, Size: 26032 bytes --]

LAGER SPI_LOADER V0.28 2014.09.29
DEVICE S25FL512
root@linaro-nano:~#                                                             
root@linaro-nano:~#                                                             
U-Boot 2013.01.01-g46367b1 (Feb 02 2015 - 11:09:08)
root@linaro-nano:~#                                                             
CPU: Renesas Electronics R8A7790 rev 2.0
Board: Lager Board
Linux version 3.19.0 (nguyen@ky) (gcc version 4.9.2 20140904 (prerelease) (cros5
DRAM:  2 GiB
MMC:   sh_mmcif: 0, sh-sdhi: 1, sh-sdhi: 2
SF: Detected S25FL512S with page size 256 KiB, total 64 MiB
In:    serial
Out:   serial
Err:   serial
Net:   sh_eth
#N/A
sh_eth Waiting for PHY auto negotiation to complete.. done
sh_eth: 100Base/Full
BOOTP broadcast 1
DHCP client bound to address 172.16.1.35
Using sh_eth device
TFTP from server 172.16.1.37; our IP address is 172.16.1.35
Filename 'lager/uImage.dtb'.
Load address: 0x40007fc0
Loading: #################################################################
         #################################################################
         #################################################################
         #######################################
         1.7 MiB/s
done
Bytes transferred = 3430264 (345778 hex)
#N/A
## Booting kernel from Legacy Image at 40007fc0 ...
   Image Name:   Linux-4.0.0-rc2-00001-g674194d-d
   Image Type:   ARM Linux Kernel Image (uncompressed)
   Data Size:    3430200 Bytes = 3.3 MiB
   Load Address: 40008000
   Entry Point:  40008000
   Verifying Checksum ... OK
   XIP Kernel Image ... OK
OK
Architected cp15 timer(s) running at 10.00MHz (virt).                           
Starting kernel ...
Switching to timer-based delay loop, resolution 100ns                           
Booting Linux on physical CPU 0x0
Linux version 4.0.0-rc2 (jinso@jinso) (gcc version 4.9.2 20140904 (pre5
CPU: ARMv7 Processor [413fc0f2] revision 2 (ARMv7), cr=30c5307d
CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
Machine model: Lager
debug: ignoring loglevel setting.
Forcing write-allocate cache policy for SMP
Memory policy: Data cache writealloc
On node 0 totalpages: 1048576
free_area_init_node: node 0, pgdat c06bcd80, node_mem_map ebff9000
  DMA zone: 1520 pages used for memmap
  DMA zone: 0 pages reserved
  DMA zone: 194560 pages, LIFO batch:31
  HighMem zone: 854016 pages, LIFO batch:31
PERCPU: Embedded 8 pages/cpu @ebf8f000 s11520 r0 d21248 u32768
pcpu-alloc: s11520 r0 d21248 u32768 alloc=8*4096
pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 [0] 4 [0] 5 [0] 6 [0] 7 
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 1047056
Kernel command line: console=ttySC0,38400 ignore_loglevel rw root=/dev/nfs ip=dhcp
PID hash table entries: 4096 (order: 2, 16384 bytes)
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Memory: 4153180K/4194304K available (5052K kernel code, 210K rwdata, 1324K rodata, 280K ini)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xf0000000 - 0xff000000   ( 240 MB)
    lowmem  : 0xc0000000 - 0xef800000   ( 760 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
      .text : 0xc0008000 - 0xc0643044   (6381 kB)
      .init : 0xc0644000 - 0xc068a000   ( 280 kB)
      .data : 0xc068a000 - 0xc06bea40   ( 211 kB)
       .bss : 0xc06bea40 - 0xc06effac   ( 198 kB)
Hierarchical RCU implementation.
        Additional per-CPU info printed with stalls.
NR_IRQS:16 nr_irqs:16 16
Architected cp15 timer(s) running at 10.00MHz (virt).
sched_clock: 56 bits at 10MHz, resolution 100ns, wraps every 3435973836800ns
Switching to timer-based delay loop, resolution 100ns
Console: colour dummy device 80x30
Calibrating delay loop (skipped), value calculated using timer frequency.. 20.00 BogoMIPS ()
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
CPU: Testing write buffer coherency: ok
CPU0: update cpu_capacity 1535
CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
Setting up static identity map for 0x404f5418 - 0x404f5470
CPU1: update cpu_capacity 1535
CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
CPU2: update cpu_capacity 1535
CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
CPU3: update cpu_capacity 1535
CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
CPU4: failed to boot: -22
CPU5: failed to boot: -22
CPU6: failed to boot: -22
CPU7: failed to boot: -22
Brought up 4 CPUs
SMP: Total of 4 processors activated (80.00 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0
pinctrl core: initialized pinctrl subsystem
NET: Registered protocol family 16
DMA: preallocated 256 KiB pool for atomic coherent allocations
renesas_irqc e61c0000.interrupt-controller: driving 4 irqs
sh-pfc e6060000.pfc: r8a77900_pfc support registered
No ATAGs?
hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
hw-breakpoint: maximum watchpoint size is 8 bytes.
platform regulator@1: Driver reg-fixed-voltage requests probe deferral
platform regulator@3: Driver reg-fixed-voltage requests probe deferral
gpio-regulator regulator@2: Could not obtain regulator setting GPIOs: -517
platform regulator@2: Driver gpio-regulator requests probe deferral
gpio-regulator regulator@4: Could not obtain regulator setting GPIOs: -517
platform regulator@4: Driver gpio-regulator requests probe deferral
vgaarb: loaded
SCSI subsystem initialized
libata version 3.00 loaded.
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
i2c-sh_mobile e6500000.i2c: I2C adapter 4, bus speed 100000 Hz
i2c-sh_mobile e6510000.i2c: I2C adapter 5, bus speed 100000 Hz
i2c-sh_mobile e6520000.i2c: I2C adapter 6, bus speed 100000 Hz
i2c-sh_mobile e60b0000.i2c: I2C adapter 7, bus speed 100000 Hz
media: Linux media interface: v0.10
Linux video capture interface: v2.00
sh_cmt ffca0000.timer: ch0: used for clock events
sh_cmt ffca0000.timer: ch1: used as clock source
Advanced Linux Sound Architecture Driver Initialized.
Switched to clocksource arch_sys_counter
NET: Registered protocol family 2
TCP established hash table entries: 8192 (order: 3, 32768 bytes)
TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
TCP: Hash tables configured (established 8192 bind 8192)
TCP: reno registered
UDP hash table entries: 512 (order: 2, 16384 bytes)
UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
PCI: CLS 0 bytes, default 64
futex hash table entries: 2048 (order: 5, 131072 bytes)
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
nfs4filelayout_init: NFSv4 File Layout Driver Registering...
nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
bounce: pool size: 64 pages
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
gpio_rcar e6050000.gpio: driving 32 GPIOs
gpio_rcar e6051000.gpio: driving 32 GPIOs
gpio_rcar e6052000.gpio: driving 32 GPIOs
gpio_rcar e6053000.gpio: driving 32 GPIOs
gpio_rcar e6054000.gpio: driving 32 GPIOs
gpio_rcar e6055000.gpio: driving 32 GPIOs
pci-rcar-gen2 ee090000.pci: PCI: bus0 revision 11
pci-rcar-gen2 ee090000.pci: PCI host bridge to bus 0000:00
pci_bus 0000:00: root bus resource [io  0xee080000-0xee0810ff]
pci_bus 0000:00: root bus resource [mem 0xee080000-0xee0810ff]
pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
pci 0000:00:00.0: [1033:0000] type 00 class 0x060000
pci 0000:00:00.0: reg 0x10: [mem 0xee090800-0xee090bff]
pci 0000:00:00.0: reg 0x14: [mem 0x40000000-0x7fffffff pref]
pci 0000:00:01.0: [1033:0035] type 00 class 0x0c0310
pci 0000:00:01.0: reg 0x10: [mem 0x00000000-0x00000fff]
pci 0000:00:01.0: supports D1 D2
pci 0000:00:01.0: PME# supported from D0 D1 D2 D3hot
pci 0000:00:02.0: [1033:00e0] type 00 class 0x0c0320
pci 0000:00:02.0: reg 0x10: [mem 0x00000000-0x000000ff]
pci 0000:00:02.0: supports D1 D2
pci 0000:00:02.0: PME# supported from D0 D1 D2 D3hot
PCI: bus0: Fast back to back transfers disabled
pci_bus 0000:00: busn_res: [bus 00-ff] end is updated to 00
pci 0000:00:01.0: can't enable device: BAR 0 [mem 0x00000000-0x00000fff] not claimed
pci 0000:00:01.0: Can't enable PCI device, BIOS handoff failed.
pci 0000:00:02.0: can't enable device: BAR 0 [mem 0x00000000-0x000000ff] not claimed
pci 0000:00:02.0: Can't enable PCI device, BIOS handoff failed.
pci 0000:00:01.0: BAR 0: assigned [mem 0xee080000-0xee080fff]
pci 0000:00:02.0: BAR 0: assigned [mem 0xee081000-0xee0810ff]
pci-rcar-gen2 ee0b0000.pci: PCI: bus0 revision 11
pci-rcar-gen2 ee0b0000.pci: PCI host bridge to bus 0001:01
pci_bus 0001:01: root bus resource [io  0xee0a0000-0xee0a10ff]
pci_bus 0001:01: root bus resource [mem 0xee0a0000-0xee0a10ff]
pci_bus 0001:01: No busn resource found for root bus, will use [bus 01-ff]
pci 0001:01:00.0: [1033:0000] type 00 class 0x060000
pci 0001:01:00.0: reg 0x10: [mem 0xee0b0800-0xee0b0bff]
pci 0001:01:00.0: reg 0x14: [mem 0x40000000-0x7fffffff pref]
pci 0001:01:01.0: [1033:0035] type 00 class 0x0c0310
pci 0001:01:01.0: reg 0x10: [mem 0x00000000-0x00000fff]
pci 0001:01:01.0: supports D1 D2
pci 0001:01:01.0: PME# supported from D0 D1 D2 D3hot
pci 0001:01:02.0: [1033:00e0] type 00 class 0x0c0320
pci 0001:01:02.0: reg 0x10: [mem 0x00000000-0x000000ff]
pci 0001:01:02.0: supports D1 D2
pci 0001:01:02.0: PME# supported from D0 D1 D2 D3hot
PCI: bus1: Fast back to back transfers disabled
pci_bus 0001:01: busn_res: [bus 01-ff] end is updated to 01
pci 0001:01:01.0: can't enable device: BAR 0 [mem 0x00000000-0x00000fff] not claimed
pci 0001:01:01.0: Can't enable PCI device, BIOS handoff failed.
pci 0001:01:02.0: can't enable device: BAR 0 [mem 0x00000000-0x000000ff] not claimed
pci 0001:01:02.0: Can't enable PCI device, BIOS handoff failed.
pci 0001:01:01.0: BAR 0: assigned [mem 0xee0a0000-0xee0a0fff]
pci 0001:01:02.0: BAR 0: assigned [mem 0xee0a1000-0xee0a10ff]
pci-rcar-gen2 ee0d0000.pci: PCI: bus0 revision 11
pci-rcar-gen2 ee0d0000.pci: PCI host bridge to bus 0002:02
pci_bus 0002:02: root bus resource [io  0xee0c0000-0xee0c10ff]
pci_bus 0002:02: root bus resource [mem 0xee0c0000-0xee0c10ff]
pci_bus 0002:02: No busn resource found for root bus, will use [bus 02-ff]
pci 0002:02:00.0: [1033:0000] type 00 class 0x060000
pci 0002:02:00.0: reg 0x10: [mem 0xee0d0800-0xee0d0bff]
pci 0002:02:00.0: reg 0x14: [mem 0x40000000-0x7fffffff pref]
pci 0002:02:01.0: [1033:0035] type 00 class 0x0c0310
pci 0002:02:01.0: reg 0x10: [mem 0x00000000-0x00000fff]
pci 0002:02:01.0: supports D1 D2
pci 0002:02:01.0: PME# supported from D0 D1 D2 D3hot
pci 0002:02:02.0: [1033:00e0] type 00 class 0x0c0320
pci 0002:02:02.0: reg 0x10: [mem 0x00000000-0x000000ff]
pci 0002:02:02.0: supports D1 D2
pci 0002:02:02.0: PME# supported from D0 D1 D2 D3hot
PCI: bus2: Fast back to back transfers disabled
pci_bus 0002:02: busn_res: [bus 02-ff] end is updated to 02
pci 0002:02:01.0: can't enable device: BAR 0 [mem 0x00000000-0x00000fff] not claimed
pci 0002:02:01.0: Can't enable PCI device, BIOS handoff failed.
pci 0002:02:02.0: can't enable device: BAR 0 [mem 0x00000000-0x000000ff] not claimed
pci 0002:02:02.0: Can't enable PCI device, BIOS handoff failed.
pci 0002:02:01.0: BAR 0: assigned [mem 0xee0c0000-0xee0c0fff]
pci 0002:02:02.0: BAR 0: assigned [mem 0xee0c1000-0xee0c10ff]
Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
SuperH (H)SCI(F) driver initialized
e6c40000.serial: ttySC0 at MMIO 0xe6c40000 (irq = 101, base_baud = 0) is a scifa
console [ttySC0] enabled
e6c50000.serial: ttySC1 at MMIO 0xe6c50000 (irq = 102, base_baud = 0) is a scifa
[drm] Initialized drm 1.1.0 20060810
rcar-du feb00000.display: fb0:  frame buffer device
rcar-du feb00000.display: registered panic notifier
[drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[drm] No driver support for vblank timestamp query.
[drm] Initialized rcar-du 1.0.0 20130110 on minor 0
scsi host0: sata_rcar
ata1: SATA max UDMA/133 irq 104
renesas_spi e6b10000.spi: DMA available
m25p80 spi0.0: s25fl512s (65536 Kbytes)
3 ofpart partitions found on MTD device spi0.0
Creating 3 MTD partitions on "spi0.0":
0x000000000000-0x000000040000 : "loader"
0x000000040000-0x000000440000 : "user"
0x000000440000-0x000004000000 : "flash"
renesas_spi e6b10000.spi: probed
spi_sh_msiof e6e10000.spi: DMA available
libphy: sh_mii: probed
sh-eth ee700000.ethernet eth0: Base address at 0xee700000, 2e:09:0a:00:7c:ff, IRQ 103.
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ehci-pci: EHCI PCI platform driver
ehci-pci 0000:00:02.0: enabling device (0140 -> 0142)
ehci-pci 0000:00:02.0: EHCI Host Controller
ehci-pci 0000:00:02.0: new USB bus registered, assigned bus number 1
ehci-pci 0000:00:02.0: irq 117, io mem 0xee081000
ehci-pci 0000:00:02.0: USB 2.0 started, EHCI 1.00
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 1 port detected
ehci-pci 0001:01:02.0: enabling device (0140 -> 0142)
ehci-pci 0001:01:02.0: EHCI Host Controller
ehci-pci 0001:01:02.0: new USB bus registered, assigned bus number 2
ehci-pci 0001:01:02.0: irq 118, io mem 0xee0a1000
ehci-pci 0001:01:02.0: USB 2.0 started, EHCI 1.00
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 1 port detected
ehci-pci 0002:02:02.0: enabling device (0140 -> 0142)
ehci-pci 0002:02:02.0: EHCI Host Controller
ehci-pci 0002:02:02.0: new USB bus registered, assigned bus number 3
ehci-pci 0002:02:02.0: irq 119, io mem 0xee0c1000
ehci-pci 0002:02:02.0: USB 2.0 started, EHCI 1.00
ata1: link resume succeeded after 1 retries
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 1 port detected
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
ohci-pci: OHCI PCI platform driver
ohci-pci 0000:00:01.0: enabling device (0140 -> 0142)
ohci-pci 0000:00:01.0: OHCI PCI host controller
ohci-pci 0000:00:01.0: new USB bus registered, assigned bus number 4
ohci-pci 0000:00:01.0: irq 117, io mem 0xee080000
ata1: SATA link down (SStatus 0 SControl 300)
ohci-pci 0000:00:01.0: init err (00002edf 0000)
ohci-pci 0000:00:01.0: can't start
ohci-pci 0000:00:01.0: startup error -75
ohci-pci 0000:00:01.0: USB bus 4 deregistered
ohci-pci 0000:00:01.0: init 0000:00:01.0 fail, -75
ohci-pci: probe of 0000:00:01.0 failed with error -75
ohci-pci 0001:01:01.0: enabling device (0140 -> 0142)
ohci-pci 0001:01:01.0: OHCI PCI host controller
ohci-pci 0001:01:01.0: new USB bus registered, assigned bus number 4
ohci-pci 0001:01:01.0: irq 118, io mem 0xee0a0000
hub 4-0:1.0: USB hub found
hub 4-0:1.0: 1 port detected
ohci-pci 0002:02:01.0: enabling device (0140 -> 0142)
ohci-pci 0002:02:01.0: OHCI PCI host controller
ohci-pci 0002:02:01.0: new USB bus registered, assigned bus number 5
ohci-pci 0002:02:01.0: irq 119, io mem 0xee0c0000
hub 5-0:1.0: USB hub found
hub 5-0:1.0: 1 port detected
sh-pfc e6060000.pfc: pin GP_5_19 already requested by ee090000.pci; cannot claim for e65900b
sh-pfc e6060000.pfc: pin-179 (e6590000.usb) status -22
sh-pfc e6060000.pfc: could not request pin 179 (GP_5_19) from group usb0_ovc_vbus  on devicc
renesas_usbhs e6590000.usb: Error applying setting, reverse things back
renesas_usbhs e6590000.usb: gadget probed
renesas_usbhs e6590000.usb: platform init failed.
renesas_usbhs e6590000.usb: probe failed
mousedev: PS/2 mouse device common for all mice
i2c /dev entries driver
adv7180 6-0020: chip found @ 0x20 (e6520000.i2c)
soc-camera-pdrv soc-camera-pdrv.0: Probing soc-camera-pdrv.0
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1 at drivers/base/devres.c:887 devm_kfree+0x30/0x40()
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.0.0-rc2-00001-g674194d-dirty #25
Hardware name: Generic R8A7790 (Flattened Device Tree)
Backtrace: 
[<c0011e9c>] (dump_backtrace) from [<c0012044>] (show_stack+0x18/0x1c)
 r7:c0603501 r6:ed8329c0 r5:00000009 r4:00000000
[<c001202c>] (show_stack) from [<c04f0f9c>] (dump_stack+0x78/0x94)
[<c04f0f24>] (dump_stack) from [<c002622c>] (warn_slowpath_common+0x88/0xb4)
 r5:00000009 r4:00000000
[<c00261a4>] (warn_slowpath_common) from [<c0026330>] (warn_slowpath_null+0x24/0x2c)
 r9:ed9208a8 r8:ebfd64b4 r7:ecbe8210 r6:ecbe8620 r5:fffffffa r4:ed920890
[<c002630c>] (warn_slowpath_null) from [<c02c0640>] (devm_kfree+0x30/0x40)
[<c02c0610>] (devm_kfree) from [<c038dc60>] (soc_of_bind.isra.14+0x194/0x1d4)
[<c038dacc>] (soc_of_bind.isra.14) from [<c038e720>] (soc_camera_host_register+0x208/0x31c)
 r9:0000006a r8:ebfdc2c8 r7:eda98e10 r6:00000000 r5:ebfdbf44 r4:ecbe8620
[<c038e518>] (soc_camera_host_register) from [<c039088c>] (rcar_vin_probe+0x1f8/0x23c)
 r9:0000006a r8:eda98e00 r7:00000008 r6:eda98e10 r5:ecbe8610 r4:c06b2484
[<c0390694>] (rcar_vin_probe) from [<c02be8dc>] (platform_drv_probe+0x50/0xa0)
 r10:00000000 r9:c06b21cc r8:00000000 r7:c06e3540 r6:c06b21cc r5:eda98e10
 r4:ffffffef
[<c02be88c>] (platform_drv_probe) from [<c02bd460>] (driver_probe_device+0xc4/0x208)
 r7:c06e3540 r6:c06e3534 r5:00000000 r4:eda98e10
[<c02bd39c>] (driver_probe_device) from [<c02bd660>] (__driver_attach+0x70/0x94)
 r9:c06bea40 r8:00000000 r7:c06aaa70 r6:c06b21cc r5:eda98e44 r4:eda98e10
[<c02bd5f0>] (__driver_attach) from [<c02bbda8>] (bus_for_each_dev+0x74/0x98)
 r7:c06aaa70 r6:c02bd5f0 r5:c06b21cc r4:00000000
[<c02bbd34>] (bus_for_each_dev) from [<c02bd734>] (driver_attach+0x20/0x28)
 r6:ed920080 r5:00000000 r4:c06b21cc
[<c02bd714>] (driver_attach) from [<c02bc564>] (bus_add_driver+0xdc/0x1c4)
[<c02bc488>] (bus_add_driver) from [<c02bde48>] (driver_register+0xa4/0xe8)
 r7:c067ce78 r6:c067ce78 r5:c06626f8 r4:c06b21cc
[<c02bdda4>] (driver_register) from [<c02bf224>] (__platform_driver_register+0x50/0x64)
 r5:c06626f8 r4:ecbe2880
[<c02bf1d4>] (__platform_driver_register) from [<c0662710>] (rcar_vin_driver_init+0x18/0x20)
[<c06626f8>] (rcar_vin_driver_init) from [<c0644e0c>] (do_one_initcall+0x10c/0x1bc)
[<c0644d00>] (do_one_initcall) from [<c0644fd4>] (kernel_init_freeable+0x118/0x1e0)
 r8:c06bea40 r7:c0685b08 r6:c067d6a4 r5:000000ad r4:00000006
[<c0644ebc>] (kernel_init_freeable) from [<c04edee8>] (kernel_init+0x14/0xec)
 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c04eded4 r4:c06bea40
[<c04eded4>] (kernel_init) from [<c000eba0>] (ret_from_fork+0x14/0x34)
 r5:c04eded4 r4:00000000
---[ end trace 065b5203d55eb3a3 ]---
rcar_vin e6ef1000.video: group probe failed: -6
rcar_thermal e61f0000.thermal: 1 sensor probed
Driver 'mmcblk' needs updating - please use bus_type methods
sh_mobile_sdhi ee100000.sd: Got CD GPIO
platform ee100000.sd: Driver sh_mobile_sdhi requests probe deferral
sh_mobile_sdhi ee140000.sd: Got CD GPIO
platform ee140000.sd: Driver sh_mobile_sdhi requests probe deferral
sh_mmcif ee220000.mmc: No vqmmc regulator found
sh_mmcif ee220000.mmc: Chip version 0x0003, clock rate 12MHz
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
platform sound: Driver asoc-simple-card requests probe deferral
rcar_sound ec500000.rcar_sound: can't get dma channel
rcar_sound ec500000.rcar_sound: src[2] (Gen2) failed
rcar_sound ec500000.rcar_sound: ssi[0] fallback to PIO mode
rcar_sound ec500000.rcar_sound: can't get dma channel
rcar_sound ec500000.rcar_sound: src[3] (Gen2) failed
rcar_sound ec500000.rcar_sound: ssi[1] fallback to PIO mode
rcar_sound ec500000.rcar_sound: probed
TCP: cubic registered
NET: Registered protocol family 10
sit: IPv6 over IPv4 tunneling driver
NET: Registered protocol family 17
Key type dns_resolver registered
Registering SWP/SWPB emulation handler
sh_mobile_sdhi ee100000.sd: Got CD GPIO
mmc0: MAN_BKOPS_EN bit is not set
mmc0: new high speed MMC card at address 0001
mmcblk0: mmc0:0001 MMC08G 7.32 GiB 
mmcblk0boot0: mmc0:0001 MMC08G partition 1 2.00 MiB
sh_mobile_sdhi ee100000.sd: mmc1 base at 0xee100000 clock rate 97 MHz
sh_mobile_sdhi ee140000.sd: Got CD GPIO
mmcblk0boot1: mmc0:0001 MMC08G partition 2 2.00 MiB
 mmcblk0: p1
sh_mobile_sdhi ee140000.sd: mmc2 base at 0xee140000 clock rate 97 MHz
asoc-simple-card sound: ak4642-hifi <-> ec500000.rcar_sound mapping ok
input: keyboard as /devices/platform/keyboard/input/input0
drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
sh-eth ee700000.ethernet eth0: attached PHY 1 (IRQ 312) to driver Micrel KSZ8041RNLI
Sending DHCP requests .
mmc1: new high speed SDHC card at address 1234
mmcblk1: mmc1:1234 SA04G 3.67 GiB 
 mmcblk1: p1
mmc2: new high speed SD card at address 0007
mmcblk2: mmc2:0007 SD01G 952 MiB 
 mmcblk2: p1
.
sh-eth ee700000.ethernet eth0: Link is Up - 100Mbps/Full - flow control off
., OK
IP-Config: Got DHCP answer from 172.16.1.37, my address is 172.16.1.35
IP-Config: Complete:
     device=eth0, hwaddr=2e:09:0a:00:7c:ff, ipaddr=172.16.1.35, mask=255.255.255.0, gw=172.7
     host=172.16.1.35, domain=, nis-domain=(none)
     bootserver=172.16.1.37, rootserver=172.16.1.37, rootpath=
     nameserver0=172.16.1.30, nameserver1=172.16.1.40, nameserver2=8.8.8.8
ALSA device list:
  #0: rsnd-dai.0-ak4642-hifi
VFS: Mounted root (nfs filesystem) on device 0:14.
devtmpfs: mounted
Freeing unused kernel memory: 280K (c0644000 - c068a000)
Mount failed for selinuxfs on /sys/fs/selinux:  No such file or directory
random: init urandom read with 57 bits of entropy available
init: plymouth-upstart-bridge main process (894) terminated with status 1
init: plymouth-upstart-bridge main process ended, respawning
init: plymouth-upstart-bridge main process (905) terminated with status 1
init: plymouth-upstart-bridge main process ended, respawning
random: nonblocking pool is initialized
systemd-udevd[1000]: starting version 204
init: systemd-logind pre-start process (1483) terminated with status 32
systemd-udevd[1056]: could not open moddep file '/lib/modules/4.0.0-rc2-00001-g674194d-dirt'
CPU4: failed to boot: -22
CPU7: failed to boot: -22
CPU6: failed to boot: -22
CPU5: failed to boot: -22
init: udev-fallback-graphics main process (1616) terminated with status 1
 * Stopping Send an event to indicate plymouth is up[ OK ]
 * Starting Mount filesystems on boot[ OK ]
 * Starting Signal sysvinit that the rootfs is mounted[ OK ]
 * Starting Populate /dev filesystem[ OK ]
 * Stopping Populate /dev filesystem[ OK ]
 * Starting Clean /tmp directory[ OK ]
 * Stopping Clean /tmp directory[ OK ]
 * Starting Populate and link to /run filesystem[ OK ]
 * Stopping Populate and link to /run filesystem[ OK ]
 * Stopping Track if upstart is running in a container[ OK ]
 * Starting set console keymap[ OK ]
 * Starting Signal sysvinit that virtual filesystems are mounted[ OK ]
 * Starting Signal sysvinit that virtual filesystems are mounted[ OK ]
 * Starting Bridge udev events into upstart[ OK ]
 * Starting Signal sysvinit that local filesystems are mounted[ OK ]
 * Stopping set console keymap[ OK ]
 * Starting Signal sysvinit that remote filesystems are mounted[ OK ]
 * Starting device node and kernel event manager[ OK ]
 * Starting flush early job output to logs[ OK ]
 * Starting load modules from /etc/modules[ OK ]
 * Starting cold plug devices[ OK ]
 * Starting log initial device creation[ OK ]
 * Starting D-Bus system message bus[ OK ]
 * Stopping Mount filesystems on boot[ OK ]
 * Stopping flush early job output to logs[ OK ]
 * Stopping load modules from /etc/modules[ OK ]
 * Starting SystemD login management service[fail]
 * Stopping SystemD login management service[ OK ]
 * Stopping cold plug devices[ OK ]
 * Stopping log initial device creation[ OK ]
 * Starting load fallback graphics devices[ OK ]
 * Starting configure network device security[ OK ]
 * Starting load fallback graphics devices[fail]
 * Starting save udev log and update rules[ OK ]
 * Starting set console font[ OK ]
 * Starting system logging daemon[ OK ]
 * Stopping set console font[ OK ]
 * Stopping save udev log and update rules[ OK ]
 * Starting userspace bootsplash[ OK ]
 * Stopping userspace bootsplash[ OK ]
 * Starting Send an event to indicate plymouth is up[ OK ]
 * Stopping Send an event to indicate plymouth is up[ OK ]
 * Starting configure network device security[ OK ]
 * Starting System V initialisation compatibility[ OK ]
 * Starting configure network device[ OK ]
 * Starting configure virtual network devices[ OK ]
 * Starting configure network device security[ OK ]
 * Starting configure network device security[ OK ]
 * Starting configure network device[ OK ]
No sensors found!
Make sure you loaded all the kernel drivers you need.
Try sensors-detect to find out which these are.
No sensors found!
Make sure you loaded all the kernel drivers you need.
Try sensors-detect to find out which these are.
 * Setting sensors limits        * Starting configure network device[ OK ]
[ OK ]
 * Starting Mount network filesystems[ OK ]
 * Starting Failsafe Boot Delay[ OK ]
 * Stopping Mount network filesystems[ OK ]
 * Starting Bridge socket events into upstart[ OK ]
 * Starting Bridge file events into upstart[ OK ]
[ OK ]ting up X socket directories...        
 * Stopping System V initialisation compatibility[ OK ]
 * Starting System V runlevel compatibility[ OK ]
 * Starting Restore Sound Card State[ OK ]
 * Starting reinit: alsa-restore main process (1852) terminated with status 99
gular background program processing daemon[ OK ]
 * Starting save kernel messages[ OK ]
 * Starting Restore Sound Card State[fail]
 * Starting OpenSSH server[ OK ]
 * Stopping System V runlevel compatibility[ OK ]

Last login: Thu Jan  1 00:00:16 UTC 1970 on tty1
init: plymouth-upstart-bridge main process ended, respawning
Welcome to Linaro 14.04 (GNU/Linux 4.0.0-rc2-00001-g674194d-dirty armv7l)

 * Documentation:  https://wiki.linaro.org/
init: tty1 main process (1889) killed by TERM signal
root@linaro-nano:~# 

Re: Can't mount QSPI-FLASH to userland on Lager

[Cao Minh Hiep]

Hi Mark-san

Thanks for your comments,

On 2015年03月25日 01:24, Mark Brown wrote:
> On Tue, Mar 24, 2015 at 04:17:32PM +0900, Cao Minh Hiep wrote:
>> On 2015年03月24日 01:27, Mark Brown wrote:
>>> Interesting...  nobody else has reported any problems.  Can you collect
>>> traces from the failing and successful systems with ftrace (turn on
>>> /sys/kernel/debug/tracing/events/spi/enable to get all the SPI logging)
>>> please?
>> I attached the traces logs file of failing and successful systems:
>> file1: qspi_v4.0-rc2_added_tracer_test_logs_lager.txt
>> file2: qspi_v4.0-rc2_added_tracer_and_reverting_patches_test_logs_lager.txt
>> And also attached the logs file of 10times for testing in before/after
>> reverting patches without tracer.
>> file3: qspi_v4.0-rc2_test_logs_for_10times_lager.txt
>> file4: qspi_v4.0-rc2_after_reverting_patches_test_logs_for_10times_lager.txt
> These all look like console logs, not ftrace logs?
The file3 and file4 are logs of normal 10times test which enabled ext3, 
ext4 in configuration.

The file1 and file2 are logs after enabling Kernel Function Tracer and 
Trace syscalls
...debug/tracing/events/spi/enable is not showed in default config.
Could you please tell me the correct way to get ftrace logs?

Thank you!
Hiep.

Re: Can't mount QSPI-FLASH to userland on Lager

[Mark Brown]

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

On Wed, Mar 25, 2015 at 10:14:54AM +0900, Cao Minh Hiep wrote:

> The file1 and file2 are logs after enabling Kernel Function Tracer and Trace
> syscalls
> ...debug/tracing/events/spi/enable is not showed in default config.
> Could you please tell me the correct way to get ftrace logs?

After you enable the tracing you can extract the logging that got turned
on from /sys/kernel/debug/tracing/trace.

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

Re: Can't mount QSPI-FLASH to userland on Lager

[Geert Uytterhoeven]

Hi Hiep-san,

On Wed, Mar 25, 2015 at 1:55 AM, Cao Minh Hiep <cm-hiep@jinso.co.jp> wrote:
> I attached the kernel bootlogs files of Koelsch and Lager.

Thanks!

Looking at the logs, the Lager seems to use systemd, the Koelsch doesn't?
Could this be the reason?

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: Can't mount QSPI-FLASH to userland on Lager

[Mark Brown]

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

On Wed, Mar 25, 2015 at 05:54:31AM +0100, Geert Uytterhoeven wrote:
> On Wed, Mar 25, 2015 at 1:55 AM, Cao Minh Hiep <cm-hiep@jinso.co.jp> wrote:
> > I attached the kernel bootlogs files of Koelsch and Lager.

> Thanks!

> Looking at the logs, the Lager seems to use systemd, the Koelsch doesn't?
> Could this be the reason?

Given the area of code that was changed I'm thinking it's likely to be
some timing thing so that seems entirely plausible.

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 473 bytes --]

Re: Can't mount QSPI-FLASH to userland on Lager

[Mark Brown]

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

On Wed, Mar 25, 2015 at 07:01:47PM +0900, Cao Minh Hiep wrote:

> This is my trace logs file with default config (before reverting the
> patches).

OK, so at a first glance I think that trace is being obscured by the
fact that you've not got the fix I mentioned the other day for a use
after free in the trace code - please update to Linus' latest tree or
pick 391949b6f02121371e3d7d9082c6d17fd9853034 (spi: trigger trace event
for message-done before mesg->complete) into your tree.

I've had a brief look at the rspi driver code and I can't immediately
see any driver specific issues there.

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 473 bytes --]