n900 in next-20170901

Commit Message

Joonsoo Kim Oct. 18, 2017, 8:29 a.m. UTC

On Mon, Sep 25, 2017 at 07:54:37AM -0700, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [170925 01:06]:
> > On Thu, Sep 21, 2017 at 10:28:11AM -0700, Tony Lindgren wrote:
> > > * Joonsoo Kim <[e-mail]> [170914 23:55]:
> > > > On Wed, Sep 13, 2017 at 09:31:27AM -0700, Tony Lindgren wrote:
> > > > > Yes I disabled CONFIG_HIGHMEM and n900 boots. To disable it,
> > > > > you need to remove it from arch/arm/mach-omap2/Kconfig that
> > > > > selects it if ARCH_OMAP2PLUS_TYPICAL is selected.
> > > > 
> > > > Okay. Problem would be related to address traslation. I'd like to
> > > > check address traslation more. Could you apply following patch and
> > > > test it? And, please send me the dmesg log and your kernel config.
> > > > Please test this with CONFIG_DEBUG_VIRTUAL = n and CONFIG_CMA_DEBUG=y and
> > > > CONFIG_HIGHMEM=y and with kernel bootparam 'ignore_loglevel'.
> > > > 
> > > > It would be really appreciate if you send me two logs for before/after
> > > > commit 9caf25f996e8.
> > > 
> > > Sorry for the delays, I finally got around testing this for you.
> > 
> > No problem! I really appreciate your help!
> > 
> > > Compile with your patch failed for modules with __virt_to_phys_debug
> > > being undefined so I added EXPORT_SYMBOL there. I also enabled DEBUG_LL
> > > and EARLYPRINTK to get output.
> > > 
> > > Below is dmesg output for 9caf25f996e8 + your patch. I'll send you
> > > the full logs separately.
> > 
> > Hmm...there is only one caller for the CMA memory, that is, atomic_pool_init().
> > Could you test one more time with 9caf25f996e8 + following patch?  I'd like to
> > know the actual user for the CMA memory.
> 
> Hmm not getting any stack with that patch after manually applying
> it because of tabs to spaces mangling.

Sorry for long delay.

Seems like your system doesn't use any CMA memory by CMA API.

Could you test one more thing?
This one is to disable CMA memory allocation from the page allocator.
With this, we can be sure that CMA memory isn't used at all.

If there is no difference with this patch, that is, the system down,
I think that some initialization step is broken. In this case, please
test following patch.

I make a branch in github that all these patch is applied.
Feel free to use it.

https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

Thanks.

--------------->8----------------------

Comments

Tony Lindgren Oct. 19, 2017, 6:30 p.m. UTC | #1

* Joonsoo Kim <[e-mail]> [171018 01:27]:
> On Mon, Sep 25, 2017 at 07:54:37AM -0700, Tony Lindgren wrote:
> > * Joonsoo Kim <[e-mail]> [170925 01:06]:
> > > On Thu, Sep 21, 2017 at 10:28:11AM -0700, Tony Lindgren wrote:
> > > > * Joonsoo Kim <[e-mail]> [170914 23:55]:
> > > > > On Wed, Sep 13, 2017 at 09:31:27AM -0700, Tony Lindgren wrote:
> > > > > > Yes I disabled CONFIG_HIGHMEM and n900 boots. To disable it,
> > > > > > you need to remove it from arch/arm/mach-omap2/Kconfig that
> > > > > > selects it if ARCH_OMAP2PLUS_TYPICAL is selected.
> > > > > 
> > > > > Okay. Problem would be related to address traslation. I'd like to
> > > > > check address traslation more. Could you apply following patch and
> > > > > test it? And, please send me the dmesg log and your kernel config.
> > > > > Please test this with CONFIG_DEBUG_VIRTUAL = n and CONFIG_CMA_DEBUG=y and
> > > > > CONFIG_HIGHMEM=y and with kernel bootparam 'ignore_loglevel'.
> > > > > 
> > > > > It would be really appreciate if you send me two logs for before/after
> > > > > commit 9caf25f996e8.
> > > > 
> > > > Sorry for the delays, I finally got around testing this for you.
> > > 
> > > No problem! I really appreciate your help!
> > > 
> > > > Compile with your patch failed for modules with __virt_to_phys_debug
> > > > being undefined so I added EXPORT_SYMBOL there. I also enabled DEBUG_LL
> > > > and EARLYPRINTK to get output.
> > > > 
> > > > Below is dmesg output for 9caf25f996e8 + your patch. I'll send you
> > > > the full logs separately.
> > > 
> > > Hmm...there is only one caller for the CMA memory, that is, atomic_pool_init().
> > > Could you test one more time with 9caf25f996e8 + following patch?  I'd like to
> > > know the actual user for the CMA memory.
> > 
> > Hmm not getting any stack with that patch after manually applying
> > it because of tabs to spaces mangling.
> 
> Sorry for long delay.
> 
> Seems like your system doesn't use any CMA memory by CMA API.
> 
> Could you test one more thing?
> This one is to disable CMA memory allocation from the page allocator.
> With this, we can be sure that CMA memory isn't used at all.
> 
> If there is no difference with this patch, that is, the system down,
> I think that some initialization step is broken. In this case, please
> test following patch.
> 
> I make a branch in github that all these patch is applied.
> Feel free to use it.
> 
> https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

Still not booting, dmesg output of your test branch below.

Regards,

Tony

8< -------------------------
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.13.0-rc7-next-20170901-00010-gf93e559a038d (tmlind@sampyla) (gcc version 6.3.1 20170109 (crosstool-NG crosstool-ng-1.23.0)) #475 SMP Thu Oct 19 11:09:34 PDT 2017
[    0.000000] CPU: ARMv7 Processor [411fc083] revision 3 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[    0.000000] OF: fdt: Machine model: Nokia N900
[    0.000000] Memory policy: Data cache writeback
[    0.000000] cma: Reserved 16 MiB at 0x8e800000
[    0.000000] CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00010-gf93e559a038d #475
[    0.000000] Hardware name: Nokia RX-51 board
[    0.000000] [<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[    0.000000] [<c010caec>] (show_stack) from [<c082eac4>] (dump_stack+0xac/0xe0)
[    0.000000] [<c082eac4>] (dump_stack) from [<c0c06f10>] (dma_contiguous_remap+0x64/0x168)
[    0.000000] [<c0c06f10>] (dma_contiguous_remap) from [<c0c08114>] (paging_init+0x324/0x700)
[    0.000000] [<c0c08114>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[    0.000000] [<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[    0.000000] [<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
[    0.000000] CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00010-gf93e559a038d #475
[    0.000000] Hardware name: Nokia RX-51 board
[    0.000000] [<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[    0.000000] [<c010caec>] (show_stack) from [<c082eac4>] (dump_stack+0xac/0xe0)
[    0.000000] [<c082eac4>] (dump_stack) from [<c0c06f50>] (dma_contiguous_remap+0xa4/0x168)
[    0.000000] [<c0c06f50>] (dma_contiguous_remap) from [<c0c08114>] (paging_init+0x324/0x700)
[    0.000000] [<c0c08114>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[    0.000000] [<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[    0.000000] [<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
[    0.000000] CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00010-gf93e559a038d #475
[    0.000000] Hardware name: Nokia RX-51 board
[    0.000000] [<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[    0.000000] [<c010caec>] (show_stack) from [<c082eac4>] (dump_stack+0xac/0xe0)
[    0.000000] [<c082eac4>] (dump_stack) from [<c0c06fcc>] (dma_contiguous_remap+0x120/0x168)
[    0.000000] [<c0c06fcc>] (dma_contiguous_remap) from [<c0c08114>] (paging_init+0x324/0x700)
[    0.000000] [<c0c08114>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[    0.000000] [<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[    0.000000] [<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
[    0.000000] On node 0 totalpages: 65024
[    0.000000] free_area_init_node: node 0, pgdat c0dc5040, node_mem_map cfa8b000
[    0.000000]   Normal zone: 572 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 65024 pages, LIFO batch:15
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] OMAP3430/3530 ES3.1 (l2cache iva sgx neon isp)
[    0.000000] random: fast init done
[    0.000000] percpu: Embedded 18 pages/cpu @cfd9c000 s41644 r8192 d23892 u73728
[    0.000000] pcpu-alloc: s41644 r8192 d23892 u73728 alloc=18*4096
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 64452
[    0.000000] Kernel command line: root=/dev/nfs ip=dhcp console=ttyO2,115200 memmap=2M$0x88000000 ramoops.mem_address=0x88000000 ramoops.mem_size=0x200000 ramoops.record_size=0x40000 debug earlyprintk init=/root/init
[    0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes)
[    0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Memory: 220052K/260096K available (8192K kernel code, 816K rwdata, 2420K rodata, 1024K init, 7557K bss, 23660K reserved, 16384K cma-reserved, 0K highmem)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xd0000000 - 0xff800000   ( 760 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xcfe00000   ( 254 MB)
[    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[    0.000000]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
[    0.000000]       .text : 0xc0008000 - 0xc0900000   (9184 kB)
[    0.000000]       .init : 0xc0c00000 - 0xc0d00000   (1024 kB)
[    0.000000]       .data : 0xc0d00000 - 0xc0dcc280   ( 817 kB)
[    0.000000]        .bss : 0xc0dce000 - 0xc152f644   (7558 kB)
[    0.000000] Running RCU self tests
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	RCU event tracing is enabled.
[    0.000000] 	RCU lockdep checking is enabled.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] IRQ: Found an INTC at 0xfa200000 (revision 4.0) with 96 interrupts
[    0.000000] Clocking rate (Crystal/Core/MPU): 19.2/332/500 MHz
[    0.000000] OMAP clockevent source: timer1 at 32768 Hz
[    0.000000] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
[    0.000030] sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 65535999984741ns
[    0.000061] OMAP clocksource: 32k_counter at 32768 Hz
[    0.002716] Console: colour dummy device 80x30
[    0.002807] WARNING: Your 'console=ttyO2' has been replaced by 'ttyS2'
[    0.002838] This ensures that you still see kernel messages. Please
[    0.002868] update your kernel commandline.
[    0.002899] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.002929] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.002960] ... MAX_LOCK_DEPTH:          48
[    0.002990] ... MAX_LOCKDEP_KEYS:        8191
[    0.003021] ... CLASSHASH_SIZE:          4096
[    0.003051] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.003082] ... MAX_LOCKDEP_CHAINS:      65536
[    0.003112] ... CHAINHASH_SIZE:          32768
[    0.003143]  memory used by lock dependency info: 4655 kB
[    0.003173]  per task-struct memory footprint: 1536 bytes
[    0.003234] Calibrating delay loop... 493.97 BogoMIPS (lpj=2469888)
[    0.104431] pid_max: default: 32768 minimum: 301
[    0.105895] Security Framework initialized
[    0.106658] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.106781] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.116973] CPU: Testing write buffer coherency: ok
[    0.121459] CPU0: thread -1, cpu 0, socket -1, mpidr 0
[    0.128570] Setting up static identity map for 0x80100000 - 0x80100078
[    0.130950] Hierarchical SRCU implementation.
[    0.140258] smp: Bringing up secondary CPUs ...
[    0.140380] smp: Brought up 1 node, 1 CPU
[    0.140502] SMP: Total of 1 processors activated (493.97 BogoMIPS).
[    0.140594] CPU: All CPU(s) started in SVC mode.
[    0.152923] devtmpfs: initialized
[    0.661376] Built 1 zonelists, mobility grouping on.  Total pages: 59109
[    0.665405] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 1
[    0.669372] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.669586] futex hash table entries: 256 (order: 2, 16384 bytes)
[    0.671386] pinctrl core: initialized pinctrl subsystem
[    0.690399] NET: Registered protocol family 16
[    0.691802] __alloc_from_contiguous
[    0.691925] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.13.0-rc7-next-20170901-00010-gf93e559a038d #475
[    0.692016] Hardware name: Nokia RX-51 board
[    0.692138] [<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[    0.692260] [<c010caec>] (show_stack) from [<c082eac4>] (dump_stack+0xac/0xe0)
[    0.692382] [<c082eac4>] (dump_stack) from [<c011653c>] (__alloc_from_contiguous+0x30/0xf8)
[    0.692504] [<c011653c>] (__alloc_from_contiguous) from [<c0c06d60>] (atomic_pool_init+0x7c/0x178)
[    0.692626] [<c0c06d60>] (atomic_pool_init) from [<c0101df4>] (do_one_initcall+0x3c/0x170)
[    0.692718] [<c0101df4>] (do_one_initcall) from [<c0c00ee4>] (kernel_init_freeable+0x1fc/0x2c4)
[    0.692840] [<c0c00ee4>] (kernel_init_freeable) from [<c0842a0c>] (kernel_init+0x8/0x110)
[    0.692962] [<c0842a0c>] (kernel_init) from [<c0107d78>] (ret_from_fork+0x14/0x3c)
[    0.726104] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    1.273651] omap_hwmod: mcbsp2_sidetone using broken dt data from mcbsp
[    1.289337] omap_hwmod: mcbsp3_sidetone using broken dt data from mcbsp
[    1.796203] cpuidle: using governor menu
[    1.798645] SRAM_ADDR: omap_map_sram: P: 0x40208000 - 0x4020f000
[    1.798736] SRAM_ADDR: omap_map_sram: V: 0xd0050000 - 0xd0057000
[    1.798889] SRAM_ADDR: omap_sram_push_address: 0xd0056f00 - 0xd0056ffc
[    1.798980] SRAM_ADDR: omap_sram_push_address: 0xd0056e98 - 0xd0056f00
[    1.799163] Reprogramming SDRC clock to 332000000 Hz
[    1.865997] gpio gpiochip0: (gpio): added GPIO chardev (254:0)
[    1.868011] gpiochip_setup_dev: registered GPIOs 0 to 31 on device: gpiochip0 (gpio)
[    1.868835] OMAP GPIO hardware version 2.5
[    1.880462] gpio gpiochip1: (gpio): added GPIO chardev (254:1)
[    1.882446] gpiochip_setup_dev: registered GPIOs 32 to 63 on device: gpiochip1 (gpio)
[    1.894042] gpio gpiochip2: (gpio): added GPIO chardev (254:2)
[    1.895568] gpiochip_setup_dev: registered GPIOs 64 to 95 on device: gpiochip2 (gpio)
[    1.907318] gpio gpiochip3: (gpio): added GPIO chardev (254:3)
[    1.908843] gpiochip_setup_dev: registered GPIOs 96 to 127 on device: gpiochip3 (gpio)
[    1.920501] gpio gpiochip4: (gpio): added GPIO chardev (254:4)
[    1.922424] gpiochip_setup_dev: registered GPIOs 128 to 159 on device: gpiochip4 (gpio)
[    1.933990] gpio gpiochip5: (gpio): added GPIO chardev (254:5)
[    1.935485] gpiochip_setup_dev: registered GPIOs 160 to 191 on device: gpiochip5 (gpio)
[    2.065551] omap-gpmc 6e000000.gpmc: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_gpmc_pins, deferring probe
[    2.119781] hw-breakpoint: debug architecture 0x4 unsupported.
[    2.123596] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[    2.123748] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    2.131469] Reserving DMA channels 0 and 1 for HS ROM code
[    2.131591] OMAP DMA hardware revision 4.0
[    2.426635] omap-dma-engine 48056000.dma-controller: OMAP DMA engine driver
[    2.460449] omap-iommu 480bd400.mmu: 480bd400.mmu registered
[    2.465270] iommu: Adding device 480bc000.isp to group 0
[    2.477874] SCSI subsystem initialized
[    2.481719] libata version 3.00 loaded.
[    2.485290] omap_i2c 48070000.i2c: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_i2c1_pins, deferring probe
[    2.485931] omap_i2c 48072000.i2c: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_i2c2_pins, deferring probe
[    2.486511] omap_i2c 48060000.i2c: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_i2c3_pins, deferring probe
[    2.488647] pps_core: LinuxPPS API ver. 1 registered
[    2.488739] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[e-mail]>
[    2.489166] PTP clock support registered
[    2.505584] clocksource: Switched to clocksource 32k_counter
[    3.327270] VFS: Disk quotas dquot_6.6.0
[    3.328155] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    3.490722] NET: Registered protocol family 2
[    3.497497] TCP established hash table entries: 2048 (order: 1, 8192 bytes)
[    3.497741] TCP bind hash table entries: 2048 (order: 4, 81920 bytes)
[    3.498992] TCP: Hash tables configured (established 2048 bind 2048)
[    3.500183] UDP hash table entries: 256 (order: 2, 24576 bytes)
[    3.500701] UDP-Lite hash table entries: 256 (order: 2, 24576 bytes)
[    3.503479] NET: Registered protocol family 1
[    3.511474] RPC: Registered named UNIX socket transport module.
[    3.511627] RPC: Registered udp transport module.
[    3.511749] RPC: Registered tcp transport module.
[    3.511871] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    3.538238] hw perfevents: no interrupt-affinity property for /pmu@54000000, guessing.
[    3.540618] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
[    3.572448] audit: initializing netlink subsys (disabled)
[    3.587646] audit: type=2000 audit(3.571:1): state=initialized audit_enabled=0 res=1
[    3.590087] workingset: timestamp_bits=14 max_order=16 bucket_order=2
[    3.602478] NFS: Registering the id_resolver key type
[    3.603515] Key type id_resolver registered
[    3.603668] Key type id_legacy registered
[    3.604309] jffs2: version 2.2. (NAND) (SUMMARY)  © 2001-2006 Red Hat, Inc.
[    3.637115] io scheduler noop registered
[    3.637237] io scheduler deadline registered
[    3.637512] io scheduler cfq registered (default)
[    3.637634] io scheduler mq-deadline registered
[    3.637756] io scheduler kyber registered
[    3.658416] pinctrl-single 48002030.pinmux: 284 pins at pa fa002030 size 568
[    3.663146] pinctrl-single 48002a00.pinmux: 46 pins at pa fa002a00 size 92
[    3.668548] pinctrl-single 480025d8.pinmux: 18 pins at pa fa0025d8 size 36
[    3.711212] Serial: 8250/16550 driver, 6 ports, IRQ sharing enabled
[    3.759765] 4806c000.serial: ttyS1 at MMIO 0x4806c000 (irq = 89, base_baud = 3000000) is a 8250
[    3.774414] 49020000.serial: ttyS2 at MMIO 0x49020000 (irq = 90, base_baud = 3000000) is a 8250
[    5.113739] console [ttyS2] enabled
[    5.301635] brd: module loaded
[    5.439788] loop: module loaded
[    5.459564] mtdoops: mtd device (mtddev=name/number) must be supplied
[    5.530944] mdio_bus fixed-0: GPIO lookup for consumer reset
[    5.537200] mdio_bus fixed-0: using lookup tables for GPIO lookup
[    5.543701] mdio_bus fixed-0: lookup for GPIO reset failed
[    5.550903] libphy: Fixed MDIO Bus: probed
[    5.582519] i2c /dev entries driver
[    5.603973] omap_hsmmc 4809c000.mmc: GPIO lookup for consumer cd
[    5.610595] omap_hsmmc 4809c000.mmc: using device tree for GPIO lookup
[    5.617767] of_get_named_gpiod_flags: parsed 'cd-gpios' property of node '/ocp@68000000/mmc@4809c000[0]' - status (0)
[    5.629211] omap_hsmmc 4809c000.mmc: Got CD GPIO
[    5.634033] omap_hsmmc 4809c000.mmc: GPIO lookup for consumer wp
[    5.640502] omap_hsmmc 4809c000.mmc: using device tree for GPIO lookup
[    5.647491] of_get_named_gpiod_flags: can't parse 'wp-gpios' property of node '/ocp@68000000/mmc@4809c000[0]'
[    5.657928] of_get_named_gpiod_flags: can't parse 'wp-gpio' property of node '/ocp@68000000/mmc@4809c000[0]'
[    5.668212] omap_hsmmc 4809c000.mmc: using lookup tables for GPIO lookup
[    5.675109] omap_hsmmc 4809c000.mmc: lookup for GPIO wp failed
[    5.693267] omap_hsmmc 480b4000.mmc: GPIO lookup for consumer wp
[    5.699981] omap_hsmmc 480b4000.mmc: using device tree for GPIO lookup
[    5.707031] of_get_named_gpiod_flags: can't parse 'wp-gpios' property of node '/ocp@68000000/mmc@480b4000[0]'
[    5.717437] of_get_named_gpiod_flags: can't parse 'wp-gpio' property of node '/ocp@68000000/mmc@480b4000[0]'
[    5.727752] omap_hsmmc 480b4000.mmc: using lookup tables for GPIO lookup
[    5.734619] omap_hsmmc 480b4000.mmc: lookup for GPIO wp failed
[    5.749328] ledtrig-cpu: registered to indicate activity on CPUs
[    5.761383] oprofile: using arm/armv7
[    5.767517] Initializing XFRM netlink socket
[    5.773590] NET: Registered protocol family 10
[    5.789123] Segment Routing with IPv6
[    5.793579] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    5.808959] NET: Registered protocol family 17
[    5.813842] NET: Registered protocol family 15
[    5.819976] Key type dns_resolver registered
[    5.825561] omap2_set_init_voltage: unable to find boot up OPP for vdd_mpu_iva
[    5.832977] omap2_set_init_voltage: unable to set vdd_mpu_iva
[    5.839263] omap2_set_init_voltage: unable to find boot up OPP for vdd_core
[    5.846710] omap2_set_init_voltage: unable to set vdd_core
[    5.864746] save_secure_sram() returns 00000019
[    5.869445] save_secure_sram()'s param: 0: 0x4
[    5.874023] save_secure_sram()'s param: 1: 0x8e700000
[    5.879211] save_secure_sram()'s param: 2: 0x0
[    5.883789] save_secure_sram()'s param: 3: 0x1
[    5.888366] save_secure_sram()'s param: 4: 0x1

Joonsoo Kim Oct. 20, 2017, 1:55 a.m. UTC | #2

On Thu, Oct 19, 2017 at 11:30:34AM -0700, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [171018 01:27]:
> > On Mon, Sep 25, 2017 at 07:54:37AM -0700, Tony Lindgren wrote:
> > > * Joonsoo Kim <[e-mail]> [170925 01:06]:
> > > > On Thu, Sep 21, 2017 at 10:28:11AM -0700, Tony Lindgren wrote:
> > > > > * Joonsoo Kim <[e-mail]> [170914 23:55]:
> > > > > > On Wed, Sep 13, 2017 at 09:31:27AM -0700, Tony Lindgren wrote:
> > > > > > > Yes I disabled CONFIG_HIGHMEM and n900 boots. To disable it,
> > > > > > > you need to remove it from arch/arm/mach-omap2/Kconfig that
> > > > > > > selects it if ARCH_OMAP2PLUS_TYPICAL is selected.
> > > > > > 
> > > > > > Okay. Problem would be related to address traslation. I'd like to
> > > > > > check address traslation more. Could you apply following patch and
> > > > > > test it? And, please send me the dmesg log and your kernel config.
> > > > > > Please test this with CONFIG_DEBUG_VIRTUAL = n and CONFIG_CMA_DEBUG=y and
> > > > > > CONFIG_HIGHMEM=y and with kernel bootparam 'ignore_loglevel'.
> > > > > > 
> > > > > > It would be really appreciate if you send me two logs for before/after
> > > > > > commit 9caf25f996e8.
> > > > > 
> > > > > Sorry for the delays, I finally got around testing this for you.
> > > > 
> > > > No problem! I really appreciate your help!
> > > > 
> > > > > Compile with your patch failed for modules with __virt_to_phys_debug
> > > > > being undefined so I added EXPORT_SYMBOL there. I also enabled DEBUG_LL
> > > > > and EARLYPRINTK to get output.
> > > > > 
> > > > > Below is dmesg output for 9caf25f996e8 + your patch. I'll send you
> > > > > the full logs separately.
> > > > 
> > > > Hmm...there is only one caller for the CMA memory, that is, atomic_pool_init().
> > > > Could you test one more time with 9caf25f996e8 + following patch?  I'd like to
> > > > know the actual user for the CMA memory.
> > > 
> > > Hmm not getting any stack with that patch after manually applying
> > > it because of tabs to spaces mangling.
> > 
> > Sorry for long delay.
> > 
> > Seems like your system doesn't use any CMA memory by CMA API.
> > 
> > Could you test one more thing?
> > This one is to disable CMA memory allocation from the page allocator.
> > With this, we can be sure that CMA memory isn't used at all.
> > 
> > If there is no difference with this patch, that is, the system down,
> > I think that some initialization step is broken. In this case, please
> > test following patch.
> > 
> > I make a branch in github that all these patch is applied.
> > Feel free to use it.
> > 
> > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> 
> Still not booting, dmesg output of your test branch below.

Oops... I made a mistak. Could you test with reverting commit
c977ee2803787363187d6aca9cebdabc793c6531 ("omap: forcibly call
save_secure_ram_context() for test") in that branch?
Without reverting it, it doesn't call 'smc' so it always cause a
hang.

Thanks.

Tony Lindgren Oct. 20, 2017, 5:31 p.m. UTC | #3

* Joonsoo Kim <[e-mail]> [171019 18:53]:
> Oops... I made a mistak. Could you test with reverting commit
> c977ee2803787363187d6aca9cebdabc793c6531 ("omap: forcibly call
> save_secure_ram_context() for test") in that branch?
> Without reverting it, it doesn't call 'smc' so it always cause a
> hang.

Oops I should have noticed that one. Here you go with commit
c977ee280378 reverted. Still not booting.

Regards,

Tony

8< ---------------------------
Booting Linux on physical CPU 0x0
Linux version 4.13.0-rc7-next-20170901-00011-geca3cddaf1a8 (tmlind@sampyla) (gcc version 6.3.1 20170109 (crosstool-NG crosstool-ng-1.23.0)) #541 SMP Fri Oct 20 10:15:45 PDT 2017
CPU: ARMv7 Processor [411fc083] revision 3 (ARMv7), cr=10c5387d
CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
OF: fdt: Machine model: Nokia N900
Memory policy: Data cache writeback
cma: Reserved 16 MiB at 0x8e800000
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00011-geca3cddaf1a8 #541
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eae4>] (dump_stack+0xac/0xe0)
[<c082eae4>] (dump_stack) from [<c0c06f10>] (dma_contiguous_remap+0x64/0x168)
[<c0c06f10>] (dma_contiguous_remap) from [<c0c08114>] (paging_init+0x324/0x700)
[<c0c08114>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00011-geca3cddaf1a8 #541
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eae4>] (dump_stack+0xac/0xe0)
[<c082eae4>] (dump_stack) from [<c0c06f50>] (dma_contiguous_remap+0xa4/0x168)
[<c0c06f50>] (dma_contiguous_remap) from [<c0c08114>] (paging_init+0x324/0x700)
[<c0c08114>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00011-geca3cddaf1a8 #541
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eae4>] (dump_stack+0xac/0xe0)
[<c082eae4>] (dump_stack) from [<c0c06fcc>] (dma_contiguous_remap+0x120/0x168)
[<c0c06fcc>] (dma_contiguous_remap) from [<c0c08114>] (paging_init+0x324/0x700)
[<c0c08114>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
On node 0 totalpages: 65024
free_area_init_node: node 0, pgdat c0dc5040, node_mem_map cfa8b000
  Normal zone: 572 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 65024 pages, LIFO batch:15
CPU: All CPU(s) started in SVC mode.
OMAP3430/3530 ES3.1 (l2cache iva sgx neon isp)
random: fast init done
percpu: Embedded 18 pages/cpu @cfd9c000 s41644 r8192 d23892 u73728
pcpu-alloc: s41644 r8192 d23892 u73728 alloc=18*4096
pcpu-alloc: [0] 0
Built 1 zonelists, mobility grouping on.  Total pages: 64452
Kernel command line: root=/dev/nfs ip=dhcp console=ttyO2,115200 memmap=2M$0x88000000 ramoops.mem_address=0x88000000 ramoops.mem_size=0x200000 ramoops.record_size=0x40000 debug earlyprintk init=/root/init
PID hash table entries: 1024 (order: 0, 4096 bytes)
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 220052K/260096K available (8192K kernel code, 816K rwdata, 2420K rodata, 1024K init, 7557K bss, 23660K reserved, 16384K cma-reserved, 0K highmem)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xd0000000 - 0xff800000   ( 760 MB)
    lowmem  : 0xc0000000 - 0xcfe00000   ( 254 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
    modules : 0xbf000000 - 0xbfe00000   (  14 MB)
      .text : 0xc0008000 - 0xc0900000   (9184 kB)
      .init : 0xc0c00000 - 0xc0d00000   (1024 kB)
      .data : 0xc0d00000 - 0xc0dcc280   ( 817 kB)
       .bss : 0xc0dce000 - 0xc152f644   (7558 kB)
Running RCU self tests
Hierarchical RCU implementation.
	RCU event tracing is enabled.
	RCU lockdep checking is enabled.
	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
IRQ: Found an INTC at 0xfa200000 (revision 4.0) with 96 interrupts
Clocking rate (Crystal/Core/MPU): 19.2/332/500 MHz
OMAP clockevent source: timer1 at 32768 Hz
clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 65535999984741ns
OMAP clocksource: 32k_counter at 32768 Hz
Console: colour dummy device 80x30
WARNING: Your 'console=ttyO2' has been replaced by 'ttyS2'
This ensures that you still see kernel messages. Please
update your kernel commandline.
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES:  8
... MAX_LOCK_DEPTH:          48
... MAX_LOCKDEP_KEYS:        8191
... CLASSHASH_SIZE:          4096
... MAX_LOCKDEP_ENTRIES:     32768
... MAX_LOCKDEP_CHAINS:      65536
... CHAINHASH_SIZE:          32768
 memory used by lock dependency info: 4655 kB
 per task-struct memory footprint: 1536 bytes
Calibrating delay loop... 493.97 BogoMIPS (lpj=2469888)
pid_max: default: 32768 minimum: 301
Security Framework initialized
Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket -1, mpidr 0
Setting up static identity map for 0x80100000 - 0x80100078
Hierarchical SRCU implementation.
smp: Bringing up secondary CPUs ...
smp: Brought up 1 node, 1 CPU
SMP: Total of 1 processors activated (493.97 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
Built 1 zonelists, mobility grouping on.  Total pages: 59109
VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 1
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
futex hash table entries: 256 (order: 2, 16384 bytes)
pinctrl core: initialized pinctrl subsystem
NET: Registered protocol family 16
__alloc_from_contiguous
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.13.0-rc7-next-20170901-00011-geca3cddaf1a8 #541
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eae4>] (dump_stack+0xac/0xe0)
[<c082eae4>] (dump_stack) from [<c011653c>] (__alloc_from_contiguous+0x30/0xf8)
[<c011653c>] (__alloc_from_contiguous) from [<c0c06d60>] (atomic_pool_init+0x7c/0x178)
[<c0c06d60>] (atomic_pool_init) from [<c0101df4>] (do_one_initcall+0x3c/0x170)
[<c0101df4>] (do_one_initcall) from [<c0c00ee4>] (kernel_init_freeable+0x1fc/0x2c4)
[<c0c00ee4>] (kernel_init_freeable) from [<c0842a2c>] (kernel_init+0x8/0x110)
[<c0842a2c>] (kernel_init) from [<c0107d78>] (ret_from_fork+0x14/0x3c)
DMA: preallocated 256 KiB pool for atomic coherent allocations
omap_hwmod: mcbsp2_sidetone using broken dt data from mcbsp
omap_hwmod: mcbsp3_sidetone using broken dt data from mcbsp
cpuidle: using governor menu
SRAM_ADDR: omap_map_sram: P: 0x40208000 - 0x4020f000
SRAM_ADDR: omap_map_sram: V: 0xd0050000 - 0xd0057000
SRAM_ADDR: omap_sram_push_address: 0xd0056f00 - 0xd0056ffc
SRAM_ADDR: omap_sram_push_address: 0xd0056e90 - 0xd0056efc
Reprogramming SDRC clock to 332000000 Hz
gpio gpiochip0: (gpio): added GPIO chardev (254:0)
gpiochip_setup_dev: registered GPIOs 0 to 31 on device: gpiochip0 (gpio)
OMAP GPIO hardware version 2.5
gpio gpiochip1: (gpio): added GPIO chardev (254:1)
gpiochip_setup_dev: registered GPIOs 32 to 63 on device: gpiochip1 (gpio)
gpio gpiochip2: (gpio): added GPIO chardev (254:2)
gpiochip_setup_dev: registered GPIOs 64 to 95 on device: gpiochip2 (gpio)
gpio gpiochip3: (gpio): added GPIO chardev (254:3)
gpiochip_setup_dev: registered GPIOs 96 to 127 on device: gpiochip3 (gpio)
gpio gpiochip4: (gpio): added GPIO chardev (254:4)
gpiochip_setup_dev: registered GPIOs 128 to 159 on device: gpiochip4 (gpio)
gpio gpiochip5: (gpio): added GPIO chardev (254:5)
gpiochip_setup_dev: registered GPIOs 160 to 191 on device: gpiochip5 (gpio)
omap-gpmc 6e000000.gpmc: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_gpmc_pins, deferring probe
hw-breakpoint: debug architecture 0x4 unsupported.
omap4_sram_init:Unable to allocate sram needed to handle errata I688
omap4_sram_init:Unable to get sram pool needed to handle errata I688
Reserving DMA channels 0 and 1 for HS ROM code
OMAP DMA hardware revision 4.0
omap-dma-engine 48056000.dma-controller: OMAP DMA engine driver
omap-iommu 480bd400.mmu: 480bd400.mmu registered
iommu: Adding device 480bc000.isp to group 0
SCSI subsystem initialized
libata version 3.00 loaded.
omap_i2c 48070000.i2c: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_i2c1_pins, deferring probe
omap_i2c 48072000.i2c: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_i2c2_pins, deferring probe
omap_i2c 48060000.i2c: could not find pctldev for node /ocp@68000000/l4@48000000/scm@2000/pinmux@30/pinmux_i2c3_pins, deferring probe
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[e-mail]>
PTP clock support registered
clocksource: Switched to clocksource 32k_counter
VFS: Disk quotas dquot_6.6.0
VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
NET: Registered protocol family 2
TCP established hash table entries: 2048 (order: 1, 8192 bytes)
TCP bind hash table entries: 2048 (order: 4, 81920 bytes)
TCP: Hash tables configured (established 2048 bind 2048)
UDP hash table entries: 256 (order: 2, 24576 bytes)
UDP-Lite hash table entries: 256 (order: 2, 24576 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.
hw perfevents: no interrupt-affinity property for /pmu@54000000, guessing.
hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available
audit: initializing netlink subsys (disabled)
audit: type=2000 audit(3.541:1): state=initialized audit_enabled=0 res=1
workingset: timestamp_bits=14 max_order=16 bucket_order=2
NFS: Registering the id_resolver key type
Key type id_resolver registered
Key type id_legacy registered
jffs2: version 2.2. (NAND) (SUMMARY)  © 2001-2006 Red Hat, Inc.
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
io scheduler mq-deadline registered
io scheduler kyber registered
pinctrl-single 48002030.pinmux: 284 pins at pa fa002030 size 568
pinctrl-single 48002a00.pinmux: 46 pins at pa fa002a00 size 92
pinctrl-single 480025d8.pinmux: 18 pins at pa fa0025d8 size 36
Serial: 8250/16550 driver, 6 ports, IRQ sharing enabled
4806c000.serial: ttyS1 at MMIO 0x4806c000 (irq = 89, base_baud = 3000000) is a 8250
49020000.serial: ttyS2 at MMIO 0x49020000 (irq = 90, base_baud = 3000000) is a 8250
console [ttyS2] enabled
brd: module loaded
loop: module loaded
mtdoops: mtd device (mtddev=name/number) must be supplied
mdio_bus fixed-0: GPIO lookup for consumer reset
mdio_bus fixed-0: using lookup tables for GPIO lookup
mdio_bus fixed-0: lookup for GPIO reset failed
libphy: Fixed MDIO Bus: probed
i2c /dev entries driver
omap_hsmmc 4809c000.mmc: GPIO lookup for consumer cd
omap_hsmmc 4809c000.mmc: using device tree for GPIO lookup
of_get_named_gpiod_flags: parsed 'cd-gpios' property of node '/ocp@68000000/mmc@4809c000[0]' - status (0)
omap_hsmmc 4809c000.mmc: Got CD GPIO
omap_hsmmc 4809c000.mmc: GPIO lookup for consumer wp
omap_hsmmc 4809c000.mmc: using device tree for GPIO lookup
of_get_named_gpiod_flags: can't parse 'wp-gpios' property of node '/ocp@68000000/mmc@4809c000[0]'
of_get_named_gpiod_flags: can't parse 'wp-gpio' property of node '/ocp@68000000/mmc@4809c000[0]'
omap_hsmmc 4809c000.mmc: using lookup tables for GPIO lookup
omap_hsmmc 4809c000.mmc: lookup for GPIO wp failed
omap_hsmmc 480b4000.mmc: GPIO lookup for consumer wp
omap_hsmmc 480b4000.mmc: using device tree for GPIO lookup
of_get_named_gpiod_flags: can't parse 'wp-gpios' property of node '/ocp@68000000/mmc@480b4000[0]'
of_get_named_gpiod_flags: can't parse 'wp-gpio' property of node '/ocp@68000000/mmc@480b4000[0]'
omap_hsmmc 480b4000.mmc: using lookup tables for GPIO lookup
omap_hsmmc 480b4000.mmc: lookup for GPIO wp failed
ledtrig-cpu: registered to indicate activity on CPUs
oprofile: using arm/armv7
Initializing XFRM netlink socket
NET: Registered protocol family 10
Segment Routing with IPv6
sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
NET: Registered protocol family 17
NET: Registered protocol family 15
Key type dns_resolver registered
omap2_set_init_voltage: unable to find boot up OPP for vdd_mpu_iva
omap2_set_init_voltage: unable to set vdd_mpu_iva
omap2_set_init_voltage: unable to find boot up OPP for vdd_core
omap2_set_init_voltage: unable to set vdd_core
save_secure_sram() returns 0000ff02
save_secure_sram()'s param: 0: 0x4
save_secure_sram()'s param: 1: 0x8e700000
save_secure_sram()'s param: 2: 0x0
save_secure_sram()'s param: 3: 0x1
save_secure_sram()'s param: 4: 0x1

Joonsoo Kim Oct. 23, 2017, 4:53 a.m. UTC | #4

On Fri, Oct 20, 2017 at 10:31:47AM -0700, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [171019 18:53]:
> > Oops... I made a mistak. Could you test with reverting commit
> > c977ee2803787363187d6aca9cebdabc793c6531 ("omap: forcibly call
> > save_secure_ram_context() for test") in that branch?
> > Without reverting it, it doesn't call 'smc' so it always cause a
> > hang.
> 
> Oops I should have noticed that one. Here you go with commit
> c977ee280378 reverted. Still not booting.

Still very thanks to you. :)

Okay. Could you test my updated branch? In there, I also disable
atomic_pool initialization and disable to remap the CMA area in order
to completely make any operation on CMA area as no-op.

And, it enables memblock_debug to check how memblock region is
allocated.

https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

Thanks.

Tony Lindgren Oct. 25, 2017, 5:31 p.m. UTC | #5

* Joonsoo Kim <[e-mail]> [171022 21:51]:
> On Fri, Oct 20, 2017 at 10:31:47AM -0700, Tony Lindgren wrote:
> > * Joonsoo Kim <[e-mail]> [171019 18:53]:
> > > Oops... I made a mistak. Could you test with reverting commit
> > > c977ee2803787363187d6aca9cebdabc793c6531 ("omap: forcibly call
> > > save_secure_ram_context() for test") in that branch?
> > > Without reverting it, it doesn't call 'smc' so it always cause a
> > > hang.
> > 
> > Oops I should have noticed that one. Here you go with commit
> > c977ee280378 reverted. Still not booting.
> 
> Still very thanks to you. :)

No problem, sorry for the delay in testing this one.

> Okay. Could you test my updated branch? In there, I also disable
> atomic_pool initialization and disable to remap the CMA area in order
> to completely make any operation on CMA area as no-op.
> 
> And, it enables memblock_debug to check how memblock region is
> allocated.
> 
> https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

Great, this branch boots on n900! Early parts of the dmesg attached
below.

Regards,

Tony

8< --------------------------
Booting Linux on physical CPU 0x0
Linux version 4.13.0-rc7-next-20170901-00015-g32cc67b3e8c6 (tmlind@sampyla) (gcc version 6.3.1 20170109 (crosstool-NG crosstool-ng-1.23.0)) #544 SMP Wed Oct 25 10:22:42 PDT 2017
CPU: ARMv7 Processor [411fc083] revision 3 (ARMv7), cr=10c5387d
CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
OF: fdt: Machine model: Nokia N900
memblock_add: [0x80000000-0x8fffffff] early_init_dt_scan_memory+0xec/0x158
Memory policy: Data cache writeback
memblock_reserve: [0x80100000-0x8152f643] arm_memblock_init+0x30/0x1b0
memblock_reserve: [0x80004000-0x80007fff] arm_memblock_init+0x13c/0x1b0
memblock_reserve: [0x8ff00000-0x8fffffff] memblock_alloc_range_nid+0x38/0x50
   memblock_free: [0x8ff00000-0x8fffffff] arm_memblock_steal+0x30/0x48
memblock_reserve: [0x8fe00000-0x8fefffff] memblock_alloc_range_nid+0x38/0x50
   memblock_free: [0x8fe00000-0x8fefffff] arm_memblock_steal+0x30/0x48
memblock_reserve: [0x8fccb000-0x8fcddfff] arm_memblock_init+0x150/0x1b0
memblock_reserve: [0x8fccb000-0x8fcddfff] early_init_fdt_scan_reserved_mem+0x58/0x7c
memblock_reserve: [0x8e800000-0x8f7fffff] memblock_alloc_range_nid+0x38/0x50
cma: Reserved 16 MiB at 0x8e800000
MEMBLOCK configuration:
 memory size = 0x0fe00000 reserved size = 0x02446644
 memory.cnt  = 0x1
 memory[0x0]	[0x80000000-0x8fdfffff], 0x0fe00000 bytes flags: 0x0
 reserved.cnt  = 0x4
 reserved[0x0]	[0x80004000-0x80007fff], 0x00004000 bytes flags: 0x0
 reserved[0x1]	[0x80100000-0x8152f643], 0x0142f644 bytes flags: 0x0
 reserved[0x2]	[0x8e800000-0x8f7fffff], 0x01000000 bytes flags: 0x0
 reserved[0x3]	[0x8fccb000-0x8fcddfff], 0x00013000 bytes flags: 0x0
memblock_reserve: [0x8fdfe000-0x8fdfffff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfd000-0x8fdfdfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcee8-0x8fdfcfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcec0-0x8fdfcee7] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce98-0x8fdfcebf] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce70-0x8fdfce97] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce48-0x8fdfce6f] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce20-0x8fdfce47] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfb000-0x8fdfbfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfa000-0x8fdfafff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdf9000-0x8fdf9fff] memblock_alloc_range_nid+0x38/0x50
On node 0 totalpages: 65024
memblock_virt_alloc_try_nid_nopanic: 2359296 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 alloc_node_mem_map.constprop.10+0x68/0xb4
memblock_reserve: [0x8fa8b000-0x8fccafff] memblock_virt_alloc_internal+0xfc/0x1c0
free_area_init_node: node 0, pgdat c0dc5040, node_mem_map cfa8b000
  Normal zone: 572 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 65024 pages, LIFO batch:15
memblock_virt_alloc_try_nid_nopanic: 16 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 setup_usemap.constprop.12+0x5c/0x6c
memblock_reserve: [0x8fdfce00-0x8fdfce0f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 16 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 setup_usemap.constprop.12+0x5c/0x6c
memblock_reserve: [0x8fdfcdc0-0x8fdfcdcf] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 32 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 setup_arch+0x6e8/0xc94
memblock_reserve: [0x8fdfcd80-0x8fdfcd9f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_reserve: [0x8fdb0548-0x8fdf8fff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcde8-0x8fdfcdff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcdd0-0x8fdfcde7] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcda4-0x8fdfcdbe] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd64-0x8fdfcd7e] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd48-0x8fdfcd62] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd30-0x8fdfcd47] memblock_alloc_range_nid+0x38/0x50
CPU: All CPU(s) started in SVC mode.
OMAP3430/3530 ES3.1 (l2cache iva sgx neon isp)
memblock_virt_alloc_try_nid: 8 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 omap2_clk_legacy_provider_init+0x2c/0x44
memblock_reserve: [0x8fdfcd00-0x8fdfcd07] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 8 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 omap2_clk_legacy_provider_init+0x2c/0x44
memblock_reserve: [0x8fdfccc0-0x8fdfccc7] memblock_virt_alloc_internal+0xfc/0x1c0
random: fast init done
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0x9c/0x3fc
memblock_reserve: [0x8fdfcc00-0x8fdfccb6] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0xc0/0x3fc
memblock_reserve: [0x8fdfcb40-0x8fdfcbf6] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0xe4/0x3fc
memblock_reserve: [0x8fdfca80-0x8fdfcb36] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_alloc_info+0x4c/0x88
memblock_reserve: [0x8fdaf540-0x8fdb053f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_embed_first_chunk+0x464/0x714
memblock_reserve: [0x8fdae540-0x8fdaf53f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 73728 bytes align=0x1000 nid=-1 from=0xbfffffff max_addr=0x0 pcpu_dfl_fc_alloc+0x3c/0x44
memblock_reserve: [0x8fd9c000-0x8fdadfff] memblock_virt_alloc_internal+0xfc/0x1c0
__memblock_free_early: [0x0000008fdae000-0x0000008fdadfff] pcpu_embed_first_chunk+0x5d8/0x714
percpu: Embedded 18 pages/cpu @cfd9c000 s41644 r8192 d23892 u73728
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0xf0/0x678
memblock_reserve: [0x8fdfca40-0x8fdfca43] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x110/0x678
memblock_reserve: [0x8fdfca00-0x8fdfca03] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x130/0x678
memblock_reserve: [0x8fdfc9c0-0x8fdfc9c3] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x150/0x678
memblock_reserve: [0x8fdfc980-0x8fdfc983] memblock_virt_alloc_internal+0xfc/0x1c0
pcpu-alloc: s41644 r8192 d23892 u73728 alloc=18*4096
pcpu-alloc: [0] 0
memblock_virt_alloc_try_nid: 128 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x41c/0x678
memblock_reserve: [0x8fdfc900-0x8fdfc97f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 69 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0x64/0x2b4
memblock_reserve: [0x8fdfc880-0x8fdfc8c4] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 384 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xa8/0x2b4
memblock_reserve: [0x8fdfc700-0x8fdfc87f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 388 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xc8/0x2b4
memblock_reserve: [0x8fdfc540-0x8fdfc6c3] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 60 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xf4/0x2b4
memblock_reserve: [0x8fdfc500-0x8fdfc53b] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 69 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0x64/0x2b4
memblock_reserve: [0x8fdfc480-0x8fdfc4c4] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 768 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xa8/0x2b4
memblock_reserve: [0x8fdfc180-0x8fdfc47f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 772 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xc8/0x2b4
memblock_reserve: [0x8fdae200-0x8fdae503] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 120 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xf4/0x2b4
memblock_reserve: [0x8fdfc100-0x8fdfc177] memblock_virt_alloc_internal+0xfc/0x1c0
__memblock_free_early: [0x0000008fdaf540-0x0000008fdb053f] pcpu_embed_first_chunk+0x664/0x714
__memblock_free_early: [0x0000008fdae540-0x0000008fdaf53f] pcpu_embed_first_chunk+0x6c4/0x714
Built 1 zonelists, mobility grouping on.  Total pages: 64452
Kernel command line: root=/dev/nfs ip=dhcp console=ttyO2,115200 memmap=2M$0x88000000 ramoops.mem_address=0x88000000 ramoops.mem_size=0x200000 ramoops.record_size=0x40000 debug earlyprintk init=/root/init
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fdaf540-0x8fdb053f] memblock_virt_alloc_internal+0xfc/0x1c0
PID hash table entries: 1024 (order: 0, 4096 bytes)
memblock_virt_alloc_try_nid_nopanic: 131072 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fd7c000-0x8fd9bfff] memblock_virt_alloc_internal+0xfc/0x1c0
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
memblock_virt_alloc_try_nid_nopanic: 65536 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fd6c000-0x8fd7bfff] memblock_virt_alloc_internal+0xfc/0x1c0
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 220052K/260096K available (8192K kernel code, 816K rwdata, 2420K rodata, 1024K init, 7557K bss, 23660K reserved, 16384K cma-reserved, 0K highmem)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xd0000000 - 0xff800000   ( 760 MB)
    lowmem  : 0xc0000000 - 0xcfe00000   ( 254 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
    modules : 0xbf000000 - 0xbfe00000   (  14 MB)
      .text : 0xc0008000 - 0xc0900000   (9184 kB)
      .init : 0xc0c00000 - 0xc0d00000   (1024 kB)
      .data : 0xc0d00000 - 0xc0dcc280   ( 817 kB)
       .bss : 0xc0dce000 - 0xc152f644   (7558 kB)
Running RCU self tests
Hierarchical RCU implementation.
	RCU event tracing is enabled.
	RCU lockdep checking is enabled.
	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
IRQ: Found an INTC at 0xfa200000 (revision 4.0) with 96 interrupts
Clocking rate (Crystal/Core/MPU): 19.2/332/500 MHz
OMAP clockevent source: timer1 at 32768 Hz
clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 65535999984741ns
OMAP clocksource: 32k_counter at 32768 Hz
Console: colour dummy device 80x30
WARNING: Your 'console=ttyO2' has been replaced by 'ttyS2'
This ensures that you still see kernel messages. Please
update your kernel commandline.
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES:  8
... MAX_LOCK_DEPTH:          48
... MAX_LOCKDEP_KEYS:        8191
... CLASSHASH_SIZE:          4096
... MAX_LOCKDEP_ENTRIES:     32768
... MAX_LOCKDEP_CHAINS:      65536
... CHAINHASH_SIZE:          32768
 memory used by lock dependency info: 4655 kB
 per task-struct memory footprint: 1536 bytes
Calibrating delay loop... 493.97 BogoMIPS (lpj=2469888)
pid_max: default: 32768 minimum: 301
Security Framework initialized
Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket -1, mpidr 0
Setting up static identity map for 0x80100000 - 0x80100078
Hierarchical SRCU implementation.
smp: Bringing up secondary CPUs ...
smp: Brought up 1 node, 1 CPU
SMP: Total of 1 processors activated (493.97 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
Built 1 zonelists, mobility grouping on.  Total pages: 59109
VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 1
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
futex hash table entries: 256 (order: 2, 16384 bytes)
pinctrl core: initialized pinctrl subsystem
...

Joonsoo Kim Oct. 26, 2017, 4:48 a.m. UTC | #6

On Wed, Oct 25, 2017 at 10:31:38AM -0700, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [171022 21:51]:
> > On Fri, Oct 20, 2017 at 10:31:47AM -0700, Tony Lindgren wrote:
> > > * Joonsoo Kim <[e-mail]> [171019 18:53]:
> > > > Oops... I made a mistak. Could you test with reverting commit
> > > > c977ee2803787363187d6aca9cebdabc793c6531 ("omap: forcibly call
> > > > save_secure_ram_context() for test") in that branch?
> > > > Without reverting it, it doesn't call 'smc' so it always cause a
> > > > hang.
> > > 
> > > Oops I should have noticed that one. Here you go with commit
> > > c977ee280378 reverted. Still not booting.
> > 
> > Still very thanks to you. :)
> 
> No problem, sorry for the delay in testing this one.
> 
> > Okay. Could you test my updated branch? In there, I also disable
> > atomic_pool initialization and disable to remap the CMA area in order
> > to completely make any operation on CMA area as no-op.
> > 
> > And, it enables memblock_debug to check how memblock region is
> > allocated.
> > 
> > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> 
> Great, this branch boots on n900! Early parts of the dmesg attached
> below.

Sound good. Perhaps, problem is due to the cache management. With my
patchset, direct mapping for CMA area is cleared in
dma_contiguous_remap() if CONFIG_HIGHMEM. I guess that proper cache
operation is required there.

Could you test my newly updated branch again? I re-enable
dma_contiguous_remap() to clear direct mapping for CMA area and add
proper(?) cache operation although I'm not the expert on that area.

https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

Thanks.

Tony Lindgren Oct. 26, 2017, 2:16 p.m. UTC | #7

* Joonsoo Kim <[e-mail]> [171025 21:45]:
> On Wed, Oct 25, 2017 at 10:31:38AM -0700, Tony Lindgren wrote:
> > Great, this branch boots on n900! Early parts of the dmesg attached
> > below.
> 
> Sound good. Perhaps, problem is due to the cache management. With my
> patchset, direct mapping for CMA area is cleared in
> dma_contiguous_remap() if CONFIG_HIGHMEM. I guess that proper cache
> operation is required there.
> 
> Could you test my newly updated branch again? I re-enable
> dma_contiguous_remap() to clear direct mapping for CMA area and add
> proper(?) cache operation although I'm not the expert on that area.
> 
> https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

Yeah that one boots too, dmesg below. I wonder why flushing the range
with dmac_flush_range() and outer_flush_range() no longer seems enough
though?

Reverting the arch/arm/mm/dma-mapping.c changes in your patch
"arm/dma: re-enable to remap the CMA area and flush cache before
remapping" also boots, but produces the following build warnings:

arch/arm/mm/dma-mapping.c: In function 'dma_contiguous_remap':
arch/arm/mm/dma-mapping.c:503:20: warning: passing argument 1 of
'cpu_cache.dma_flush_range' makes pointer from integer without a
cast [-Wint-conversion]
dmac_flush_range(map.virtual, map.virtual + map.length);
                    ^~~
arch/arm/mm/dma-mapping.c:503:20: note: expected 'const void *' but
argument is of type 'long unsigned int'
arch/arm/mm/dma-mapping.c:503:33: warning: passing argument 2 of
'cpu_cache.dma_flush_range' makes pointer from integer without a
cast [-Wint-conversion]
dmac_flush_range(map.virtual, map.virtual + map.length);

Regards,

Tony

8< -----------------------
Linux version 4.13.0-rc7-next-20170901-00016-g69a5a607f945 (tmlind@sampyla) (gcc version 6.3.1 20170109 (crosstool-NG crosstool-ng-1.23.0)) #546 SMP Thu Oct 26 07:03:19 PDT 2017
CPU: ARMv7 Processor [411fc083] revision 3 (ARMv7), cr=10c5387d
CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
OF: fdt: Machine model: Nokia N900
memblock_add: [0x80000000-0x8fffffff] early_init_dt_scan_memory+0xec/0x158
Memory policy: Data cache writeback
memblock_reserve: [0x80100000-0x8152f643] arm_memblock_init+0x30/0x1b0
memblock_reserve: [0x80004000-0x80007fff] arm_memblock_init+0x13c/0x1b0
memblock_reserve: [0x8ff00000-0x8fffffff] memblock_alloc_range_nid+0x38/0x50
   memblock_free: [0x8ff00000-0x8fffffff] arm_memblock_steal+0x30/0x48
memblock_reserve: [0x8fe00000-0x8fefffff] memblock_alloc_range_nid+0x38/0x50
   memblock_free: [0x8fe00000-0x8fefffff] arm_memblock_steal+0x30/0x48
memblock_reserve: [0x8fccb000-0x8fcddfff] arm_memblock_init+0x150/0x1b0
memblock_reserve: [0x8fccb000-0x8fcddfff] early_init_fdt_scan_reserved_mem+0x58/0x7c
memblock_reserve: [0x8e800000-0x8f7fffff] memblock_alloc_range_nid+0x38/0x50
cma: Reserved 16 MiB at 0x8e800000
MEMBLOCK configuration:
 memory size = 0x0fe00000 reserved size = 0x02446644
 memory.cnt  = 0x1
 memory[0x0]	[0x80000000-0x8fdfffff], 0x0fe00000 bytes flags: 0x0
 reserved.cnt  = 0x4
 reserved[0x0]	[0x80004000-0x80007fff], 0x00004000 bytes flags: 0x0
 reserved[0x1]	[0x80100000-0x8152f643], 0x0142f644 bytes flags: 0x0
 reserved[0x2]	[0x8e800000-0x8f7fffff], 0x01000000 bytes flags: 0x0
 reserved[0x3]	[0x8fccb000-0x8fcddfff], 0x00013000 bytes flags: 0x0
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00016-g69a5a607f945 #546
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082e9e4>] (dump_stack+0xac/0xe0)
[<c082e9e4>] (dump_stack) from [<c0c06d9c>] (dma_contiguous_remap+0x60/0x140)
[<c0c06d9c>] (dma_contiguous_remap) from [<c0c07f7c>] (paging_init+0x324/0x700)
[<c0c07f7c>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00016-g69a5a607f945 #546
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082e9e4>] (dump_stack+0xac/0xe0)
[<c082e9e4>] (dump_stack) from [<c0c06dcc>] (dma_contiguous_remap+0x90/0x140)
[<c0c06dcc>] (dma_contiguous_remap) from [<c0c07f7c>] (paging_init+0x324/0x700)
[<c0c07f7c>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00016-g69a5a607f945 #546
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082e9e4>] (dump_stack+0xac/0xe0)
[<c082e9e4>] (dump_stack) from [<c0c06e34>] (dma_contiguous_remap+0xf8/0x140)
[<c0c06e34>] (dma_contiguous_remap) from [<c0c07f7c>] (paging_init+0x324/0x700)
[<c0c07f7c>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
memblock_reserve: [0x8fdfe000-0x8fdfffff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfd000-0x8fdfdfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcee8-0x8fdfcfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcec0-0x8fdfcee7] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce98-0x8fdfcebf] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce70-0x8fdfce97] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce48-0x8fdfce6f] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce20-0x8fdfce47] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfb000-0x8fdfbfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfa000-0x8fdfafff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdf9000-0x8fdf9fff] memblock_alloc_range_nid+0x38/0x50
On node 0 totalpages: 65024
memblock_virt_alloc_try_nid_nopanic: 2359296 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 alloc_node_mem_map.constprop.10+0x68/0xb4
memblock_reserve: [0x8fa8b000-0x8fccafff] memblock_virt_alloc_internal+0xfc/0x1c0
free_area_init_node: node 0, pgdat c0dc5040, node_mem_map cfa8b000
  Normal zone: 572 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 65024 pages, LIFO batch:15
memblock_virt_alloc_try_nid_nopanic: 16 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 setup_usemap.constprop.12+0x5c/0x6c
memblock_reserve: [0x8fdfce00-0x8fdfce0f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 16 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 setup_usemap.constprop.12+0x5c/0x6c
memblock_reserve: [0x8fdfcdc0-0x8fdfcdcf] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 32 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 setup_arch+0x6e8/0xc94
memblock_reserve: [0x8fdfcd80-0x8fdfcd9f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_reserve: [0x8fdb0548-0x8fdf8fff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcde8-0x8fdfcdff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcdd0-0x8fdfcde7] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcda4-0x8fdfcdbe] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd64-0x8fdfcd7e] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd48-0x8fdfcd62] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd30-0x8fdfcd47] memblock_alloc_range_nid+0x38/0x50
CPU: All CPU(s) started in SVC mode.
OMAP3430/3530 ES3.1 (l2cache iva sgx neon isp)
memblock_virt_alloc_try_nid: 8 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 omap2_clk_legacy_provider_init+0x2c/0x44
memblock_reserve: [0x8fdfcd00-0x8fdfcd07] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 8 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 omap2_clk_legacy_provider_init+0x2c/0x44
memblock_reserve: [0x8fdfccc0-0x8fdfccc7] memblock_virt_alloc_internal+0xfc/0x1c0
random: fast init done
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0x9c/0x3fc
memblock_reserve: [0x8fdfcc00-0x8fdfccb6] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0xc0/0x3fc
memblock_reserve: [0x8fdfcb40-0x8fdfcbf6] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0xe4/0x3fc
memblock_reserve: [0x8fdfca80-0x8fdfcb36] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_alloc_info+0x4c/0x88
memblock_reserve: [0x8fdaf540-0x8fdb053f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_embed_first_chunk+0x464/0x714
memblock_reserve: [0x8fdae540-0x8fdaf53f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 73728 bytes align=0x1000 nid=-1 from=0xbfffffff max_addr=0x0 pcpu_dfl_fc_alloc+0x3c/0x44
memblock_reserve: [0x8fd9c000-0x8fdadfff] memblock_virt_alloc_internal+0xfc/0x1c0
__memblock_free_early: [0x0000008fdae000-0x0000008fdadfff] pcpu_embed_first_chunk+0x5d8/0x714
percpu: Embedded 18 pages/cpu @cfd9c000 s41644 r8192 d23892 u73728
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0xf0/0x678
memblock_reserve: [0x8fdfca40-0x8fdfca43] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x110/0x678
memblock_reserve: [0x8fdfca00-0x8fdfca03] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x130/0x678
memblock_reserve: [0x8fdfc9c0-0x8fdfc9c3] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x150/0x678
memblock_reserve: [0x8fdfc980-0x8fdfc983] memblock_virt_alloc_internal+0xfc/0x1c0
pcpu-alloc: s41644 r8192 d23892 u73728 alloc=18*4096
pcpu-alloc: [0] 0
memblock_virt_alloc_try_nid: 128 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x41c/0x678
memblock_reserve: [0x8fdfc900-0x8fdfc97f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 69 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0x64/0x2b4
memblock_reserve: [0x8fdfc880-0x8fdfc8c4] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 384 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xa8/0x2b4
memblock_reserve: [0x8fdfc700-0x8fdfc87f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 388 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xc8/0x2b4
memblock_reserve: [0x8fdfc540-0x8fdfc6c3] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 60 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xf4/0x2b4
memblock_reserve: [0x8fdfc500-0x8fdfc53b] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 69 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0x64/0x2b4
memblock_reserve: [0x8fdfc480-0x8fdfc4c4] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 768 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xa8/0x2b4
memblock_reserve: [0x8fdfc180-0x8fdfc47f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 772 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xc8/0x2b4
memblock_reserve: [0x8fdae200-0x8fdae503] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 120 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xf4/0x2b4
memblock_reserve: [0x8fdfc100-0x8fdfc177] memblock_virt_alloc_internal+0xfc/0x1c0
__memblock_free_early: [0x0000008fdaf540-0x0000008fdb053f] pcpu_embed_first_chunk+0x664/0x714
__memblock_free_early: [0x0000008fdae540-0x0000008fdaf53f] pcpu_embed_first_chunk+0x6c4/0x714
Built 1 zonelists, mobility grouping on.  Total pages: 64452
Kernel command line: root=/dev/nfs ip=dhcp console=ttyO2,115200 memmap=2M$0x88000000 ramoops.mem_address=0x88000000 ramoops.mem_size=0x200000 ramoops.record_size=0x40000 debug earlyprintk init=/root/init
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fdaf540-0x8fdb053f] memblock_virt_alloc_internal+0xfc/0x1c0
PID hash table entries: 1024 (order: 0, 4096 bytes)
memblock_virt_alloc_try_nid_nopanic: 131072 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fd7c000-0x8fd9bfff] memblock_virt_alloc_internal+0xfc/0x1c0
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
memblock_virt_alloc_try_nid_nopanic: 65536 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fd6c000-0x8fd7bfff] memblock_virt_alloc_internal+0xfc/0x1c0
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 220052K/260096K available (8192K kernel code, 816K rwdata, 2420K rodata, 1024K init, 7557K bss, 23660K reserved, 16384K cma-reserved, 0K highmem)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xd0000000 - 0xff800000   ( 760 MB)
    lowmem  : 0xc0000000 - 0xcfe00000   ( 254 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
    modules : 0xbf000000 - 0xbfe00000   (  14 MB)
      .text : 0xc0008000 - 0xc0900000   (9184 kB)
      .init : 0xc0c00000 - 0xc0d00000   (1024 kB)
      .data : 0xc0d00000 - 0xc0dcc280   ( 817 kB)
       .bss : 0xc0dce000 - 0xc152f644   (7558 kB)
Running RCU self tests
Hierarchical RCU implementation.
	RCU event tracing is enabled.
	RCU lockdep checking is enabled.
	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
IRQ: Found an INTC at 0xfa200000 (revision 4.0) with 96 interrupts
Clocking rate (Crystal/Core/MPU): 19.2/332/500 MHz
OMAP clockevent source: timer1 at 32768 Hz
clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 65535999984741ns
OMAP clocksource: 32k_counter at 32768 Hz
Console: colour dummy device 80x30
WARNING: Your 'console=ttyO2' has been replaced by 'ttyS2'
This ensures that you still see kernel messages. Please
update your kernel commandline.
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES:  8
... MAX_LOCK_DEPTH:          48
... MAX_LOCKDEP_KEYS:        8191
... CLASSHASH_SIZE:          4096
... MAX_LOCKDEP_ENTRIES:     32768
... MAX_LOCKDEP_CHAINS:      65536
... CHAINHASH_SIZE:          32768
 memory used by lock dependency info: 4655 kB
 per task-struct memory footprint: 1536 bytes
Calibrating delay loop... 493.97 BogoMIPS (lpj=2469888)
...

Joonsoo Kim Nov. 7, 2017, 5:33 a.m. UTC | #8

Hello,

Sorry for dealy. I was on vacation during last week.

On Thu, Oct 26, 2017 at 07:16:27AM -0700, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [171025 21:45]:
> > On Wed, Oct 25, 2017 at 10:31:38AM -0700, Tony Lindgren wrote:
> > > Great, this branch boots on n900! Early parts of the dmesg attached
> > > below.
> > 
> > Sound good. Perhaps, problem is due to the cache management. With my
> > patchset, direct mapping for CMA area is cleared in
> > dma_contiguous_remap() if CONFIG_HIGHMEM. I guess that proper cache
> > operation is required there.
> > 
> > Could you test my newly updated branch again? I re-enable
> > dma_contiguous_remap() to clear direct mapping for CMA area and add
> > proper(?) cache operation although I'm not the expert on that area.
> > 
> > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> 
> Yeah that one boots too, dmesg below. I wonder why flushing the range
> with dmac_flush_range() and outer_flush_range() no longer seems enough
> though?

I don't know the reason. AFAIK, it should be enough to flush cpu cache
before clearing page table entry, however, it doesn't work for n900.

flush_cache_all() has not only d-cache flushing but also i-cache
flushing. So, I'd like to test effect of i-cache flushing.

Could you test follwing updated branch?

https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

It has three relevant commits on top and enables CMA memory use.

"arm/dma: remove i-cache flush"
"arm/dma: flush i-cache and d-cache separately"
"arm/dma: call flush_cache_all() and don't do outer cache operation"

I think that flush_cache_all() here looks fine because size of CMA
area is usually large enough to use flush_cache_all() but
understanding root cause would be important so I ask this test. If u
don't mind, please test each commit with reverting one by one and let
me know the result of each test.

> Reverting the arch/arm/mm/dma-mapping.c changes in your patch
> "arm/dma: re-enable to remap the CMA area and flush cache before
> remapping" also boots, but produces the following build warnings:
> 
> arch/arm/mm/dma-mapping.c: In function 'dma_contiguous_remap':
> arch/arm/mm/dma-mapping.c:503:20: warning: passing argument 1 of
> 'cpu_cache.dma_flush_range' makes pointer from integer without a
> cast [-Wint-conversion]
> dmac_flush_range(map.virtual, map.virtual + map.length);
>                     ^~~
> arch/arm/mm/dma-mapping.c:503:20: note: expected 'const void *' but
> argument is of type 'long unsigned int'
> arch/arm/mm/dma-mapping.c:503:33: warning: passing argument 2 of
> 'cpu_cache.dma_flush_range' makes pointer from integer without a
> cast [-Wint-conversion]
> dmac_flush_range(map.virtual, map.virtual + map.length);

Thanks for info.
I think that incorrect type would not be related to this problem.

Thanks.

Tony Lindgren Nov. 7, 2017, 3:48 p.m. UTC | #9

Hi,

* Joonsoo Kim <[e-mail]> [171107 05:30]:
> Could you test follwing updated branch?
> 
> https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> 
> It has three relevant commits on top and enables CMA memory use.

Okie dokie.

> "arm/dma: remove i-cache flush"

Your branch at the above commit is not booting on n900.

> "arm/dma: flush i-cache and d-cache separately"

Not booting at this commit either.

> "arm/dma: call flush_cache_all() and don't do outer cache operation"

Not booting at this commit either.

Earlier commit f14f3479c0d7 ("arm/dma: re-enable to remap the CMA
area and flush cache before remapping") in you branch boots.

Then the following commit d6512d6d0171 ("Revert "arm/mm: disable
atomic_pool"") won't boot.

Also your tree at commit 6d0525cef962 ("arm/dma: remove i-cache
flush") with only commit d6512d6d0171 ("Revert "arm/mm: disable
atomic_pool"") reverted boots on n900.

So it seems the issue is currently at the atomic_pool_init()
related code?

Regards,

Tony

Joonsoo Kim Nov. 8, 2017, 7:46 a.m. UTC | #10

On Tue, Nov 07, 2017 at 07:48:42AM -0800, Tony Lindgren wrote:
> Hi,
> 
> * Joonsoo Kim <[e-mail]> [171107 05:30]:
> > Could you test follwing updated branch?
> > 
> > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> > 
> > It has three relevant commits on top and enables CMA memory use.
> 
> Okie dokie.
> 
> > "arm/dma: remove i-cache flush"
> 
> Your branch at the above commit is not booting on n900.
> 
> > "arm/dma: flush i-cache and d-cache separately"
> 
> Not booting at this commit either.
> 
> > "arm/dma: call flush_cache_all() and don't do outer cache operation"
> 
> Not booting at this commit either.
> 
> Earlier commit f14f3479c0d7 ("arm/dma: re-enable to remap the CMA
> area and flush cache before remapping") in you branch boots.
> 
> Then the following commit d6512d6d0171 ("Revert "arm/mm: disable
> atomic_pool"") won't boot.
> 
> Also your tree at commit 6d0525cef962 ("arm/dma: remove i-cache
> flush") with only commit d6512d6d0171 ("Revert "arm/mm: disable
> atomic_pool"") reverted boots on n900.

Thanks a lot!

> So it seems the issue is currently at the atomic_pool_init()
> related code?

Yes, your test showed it although I can't find any clue in
atomic_pool_init().

Could you test updated branch?

https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901

There are two relevant commits.

arm/dma: stop dma allocation before __dma_alloc_remap()
arm/dma: disable atomic pool after dma allocation

atomic pool initialization will be done partially to check
exact point of failure. These are brain-dead commits however I have no
idea what's going on here until now. :/

Thanks.

Tony Lindgren Nov. 8, 2017, 4:34 p.m. UTC | #11

* Joonsoo Kim <[e-mail]> [171108 07:43]:
> On Tue, Nov 07, 2017 at 07:48:42AM -0800, Tony Lindgren wrote:
> > So it seems the issue is currently at the atomic_pool_init()
> > related code?
> 
> Yes, your test showed it although I can't find any clue in
> atomic_pool_init().
> 
> Could you test updated branch?
> 
> https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> 
> There are two relevant commits.
> 
> arm/dma: stop dma allocation before __dma_alloc_remap()
> arm/dma: disable atomic pool after dma allocation
> 
> atomic pool initialization will be done partially to check
> exact point of failure. These are brain-dead commits however I have no
> idea what's going on here until now. :/

OK that booted, dmesg output below. Hopefully that provides
you with some more clues.

Regards,

Tony

8< ---------------------
Linux version 4.13.0-rc7-next-20170901-00024-gcf9a104b2f62 (tmlind@sampyla) (gcc version 6.3.1 20170109 (crosstool-NG crosstool-ng-1.23.0)) #568 SMP Wed Nov 8 08:25:47 PST 2017
CPU: ARMv7 Processor [411fc083] revision 3 (ARMv7), cr=10c5387d
CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
OF: fdt: Machine model: Nokia N900
memblock_add: [0x80000000-0x8fffffff] early_init_dt_scan_memory+0xec/0x158
Memory policy: Data cache writeback
memblock_reserve: [0x80100000-0x8152f643] arm_memblock_init+0x30/0x1b0
memblock_reserve: [0x80004000-0x80007fff] arm_memblock_init+0x13c/0x1b0
memblock_reserve: [0x8ff00000-0x8fffffff] memblock_alloc_range_nid+0x38/0x50
   memblock_free: [0x8ff00000-0x8fffffff] arm_memblock_steal+0x30/0x48
memblock_reserve: [0x8fe00000-0x8fefffff] memblock_alloc_range_nid+0x38/0x50
   memblock_free: [0x8fe00000-0x8fefffff] arm_memblock_steal+0x30/0x48
memblock_reserve: [0x8fccb000-0x8fcddfff] arm_memblock_init+0x150/0x1b0
memblock_reserve: [0x8fccb000-0x8fcddfff] early_init_fdt_scan_reserved_mem+0x58/0x7c
memblock_reserve: [0x8e800000-0x8f7fffff] memblock_alloc_range_nid+0x38/0x50
cma: Reserved 16 MiB at 0x8e800000
MEMBLOCK configuration:
 memory size = 0x0fe00000 reserved size = 0x02446644
 memory.cnt  = 0x1
 memory[0x0]	[0x80000000-0x8fdfffff], 0x0fe00000 bytes flags: 0x0
 reserved.cnt  = 0x4
 reserved[0x0]	[0x80004000-0x80007fff], 0x00004000 bytes flags: 0x0
 reserved[0x1]	[0x80100000-0x8152f643], 0x0142f644 bytes flags: 0x0
 reserved[0x2]	[0x8e800000-0x8f7fffff], 0x01000000 bytes flags: 0x0
 reserved[0x3]	[0x8fccb000-0x8fcddfff], 0x00013000 bytes flags: 0x0
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00024-gcf9a104b2f62 #568
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eb04>] (dump_stack+0xac/0xe0)
[<c082eb04>] (dump_stack) from [<c0c06e94>] (dma_contiguous_remap+0x70/0x144)
[<c0c06e94>] (dma_contiguous_remap) from [<c0c08068>] (paging_init+0x324/0x700)
[<c0c08068>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00024-gcf9a104b2f62 #568
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eb04>] (dump_stack+0xac/0xe0)
[<c082eb04>] (dump_stack) from [<c0c06eb8>] (dma_contiguous_remap+0x94/0x144)
[<c0c06eb8>] (dma_contiguous_remap) from [<c0c08068>] (paging_init+0x324/0x700)
[<c0c08068>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
CMA_ADDR: __phys_to_virt_debug: 0x8e800000 to 0xce800000
CPU: 0 PID: 0 Comm: swapper Not tainted 4.13.0-rc7-next-20170901-00024-gcf9a104b2f62 #568
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eb04>] (dump_stack+0xac/0xe0)
[<c082eb04>] (dump_stack) from [<c0c06f24>] (dma_contiguous_remap+0x100/0x144)
[<c0c06f24>] (dma_contiguous_remap) from [<c0c08068>] (paging_init+0x324/0x700)
[<c0c08068>] (paging_init) from [<c0c042ac>] (setup_arch+0x5b4/0xc94)
[<c0c042ac>] (setup_arch) from [<c0c00940>] (start_kernel+0x54/0x3fc)
[<c0c00940>] (start_kernel) from [<8000807c>] (0x8000807c)
memblock_reserve: [0x8fdfe000-0x8fdfffff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfd000-0x8fdfdfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcee8-0x8fdfcfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcec0-0x8fdfcee7] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce98-0x8fdfcebf] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce70-0x8fdfce97] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce48-0x8fdfce6f] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfce20-0x8fdfce47] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfb000-0x8fdfbfff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfa000-0x8fdfafff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdf9000-0x8fdf9fff] memblock_alloc_range_nid+0x38/0x50
On node 0 totalpages: 65024
memblock_virt_alloc_try_nid_nopanic: 2359296 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 alloc_node_mem_map.constprop.10+0x68/0xb4
memblock_reserve: [0x8fa8b000-0x8fccafff] memblock_virt_alloc_internal+0xfc/0x1c0
free_area_init_node: node 0, pgdat c0dc5040, node_mem_map cfa8b000
  Normal zone: 572 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 65024 pages, LIFO batch:15
memblock_virt_alloc_try_nid_nopanic: 16 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 setup_usemap.constprop.12+0x5c/0x6c
memblock_reserve: [0x8fdfce00-0x8fdfce0f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 16 bytes align=0x0 nid=0 from=0x0 max_addr=0x0 setup_usemap.constprop.12+0x5c/0x6c
memblock_reserve: [0x8fdfcdc0-0x8fdfcdcf] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 32 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 setup_arch+0x6e8/0xc94
memblock_reserve: [0x8fdfcd80-0x8fdfcd9f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_reserve: [0x8fdb0548-0x8fdf8fff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcde8-0x8fdfcdff] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcdd0-0x8fdfcde7] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcda4-0x8fdfcdbe] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd64-0x8fdfcd7e] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd48-0x8fdfcd62] memblock_alloc_range_nid+0x38/0x50
memblock_reserve: [0x8fdfcd30-0x8fdfcd47] memblock_alloc_range_nid+0x38/0x50
CPU: All CPU(s) started in SVC mode.
OMAP3430/3530 ES3.1 (l2cache iva sgx neon isp)
memblock_virt_alloc_try_nid: 8 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 omap2_clk_legacy_provider_init+0x2c/0x44
memblock_reserve: [0x8fdfcd00-0x8fdfcd07] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 8 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 omap2_clk_legacy_provider_init+0x2c/0x44
memblock_reserve: [0x8fdfccc0-0x8fdfccc7] memblock_virt_alloc_internal+0xfc/0x1c0
random: fast init done
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0x9c/0x3fc
memblock_reserve: [0x8fdfcc00-0x8fdfccb6] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0xc0/0x3fc
memblock_reserve: [0x8fdfcb40-0x8fdfcbf6] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 183 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 start_kernel+0xe4/0x3fc
memblock_reserve: [0x8fdfca80-0x8fdfcb36] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_alloc_info+0x4c/0x88
memblock_reserve: [0x8fdaf540-0x8fdb053f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_embed_first_chunk+0x464/0x714
memblock_reserve: [0x8fdae540-0x8fdaf53f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid_nopanic: 73728 bytes align=0x1000 nid=-1 from=0xbfffffff max_addr=0x0 pcpu_dfl_fc_alloc+0x3c/0x44
memblock_reserve: [0x8fd9c000-0x8fdadfff] memblock_virt_alloc_internal+0xfc/0x1c0
__memblock_free_early: [0x0000008fdae000-0x0000008fdadfff] pcpu_embed_first_chunk+0x5d8/0x714
percpu: Embedded 18 pages/cpu @cfd9c000 s41644 r8192 d23892 u73728
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0xf0/0x678
memblock_reserve: [0x8fdfca40-0x8fdfca43] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x110/0x678
memblock_reserve: [0x8fdfca00-0x8fdfca03] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x130/0x678
memblock_reserve: [0x8fdfc9c0-0x8fdfc9c3] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 4 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x150/0x678
memblock_reserve: [0x8fdfc980-0x8fdfc983] memblock_virt_alloc_internal+0xfc/0x1c0
pcpu-alloc: s41644 r8192 d23892 u73728 alloc=18*4096
pcpu-alloc: [0] 0
memblock_virt_alloc_try_nid: 128 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_setup_first_chunk+0x41c/0x678
memblock_reserve: [0x8fdfc900-0x8fdfc97f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 69 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0x64/0x2b4
memblock_reserve: [0x8fdfc880-0x8fdfc8c4] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 384 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xa8/0x2b4
memblock_reserve: [0x8fdfc700-0x8fdfc87f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 388 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xc8/0x2b4
memblock_reserve: [0x8fdfc540-0x8fdfc6c3] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 60 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xf4/0x2b4
memblock_reserve: [0x8fdfc500-0x8fdfc53b] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 69 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0x64/0x2b4
memblock_reserve: [0x8fdfc480-0x8fdfc4c4] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 768 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xa8/0x2b4
memblock_reserve: [0x8fdfc180-0x8fdfc47f] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 772 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xc8/0x2b4
memblock_reserve: [0x8fdae200-0x8fdae503] memblock_virt_alloc_internal+0xfc/0x1c0
memblock_virt_alloc_try_nid: 120 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 pcpu_alloc_first_chunk+0xf4/0x2b4
memblock_reserve: [0x8fdfc100-0x8fdfc177] memblock_virt_alloc_internal+0xfc/0x1c0
__memblock_free_early: [0x0000008fdaf540-0x0000008fdb053f] pcpu_embed_first_chunk+0x664/0x714
__memblock_free_early: [0x0000008fdae540-0x0000008fdaf53f] pcpu_embed_first_chunk+0x6c4/0x714
Built 1 zonelists, mobility grouping on.  Total pages: 64452
Kernel command line: root=/dev/nfs ip=dhcp console=ttyO2,115200 memmap=2M$0x88000000 ramoops.mem_address=0x88000000 ramoops.mem_size=0x200000 ramoops.record_size=0x40000 debug earlyprintk init=/root/init
memblock_virt_alloc_try_nid_nopanic: 4096 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fdaf540-0x8fdb053f] memblock_virt_alloc_internal+0xfc/0x1c0
PID hash table entries: 1024 (order: 0, 4096 bytes)
memblock_virt_alloc_try_nid_nopanic: 131072 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fd7c000-0x8fd9bfff] memblock_virt_alloc_internal+0xfc/0x1c0
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
memblock_virt_alloc_try_nid_nopanic: 65536 bytes align=0x0 nid=-1 from=0x0 max_addr=0x0 alloc_large_system_hash+0x180/0x268
memblock_reserve: [0x8fd6c000-0x8fd7bfff] memblock_virt_alloc_internal+0xfc/0x1c0
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 220052K/260096K available (8192K kernel code, 816K rwdata, 2420K rodata, 1024K init, 7557K bss, 23660K reserved, 16384K cma-reserved, 0K highmem)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xd0000000 - 0xff800000   ( 760 MB)
    lowmem  : 0xc0000000 - 0xcfe00000   ( 254 MB)
    pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
    modules : 0xbf000000 - 0xbfe00000   (  14 MB)
      .text : 0xc0008000 - 0xc0900000   (9184 kB)
      .init : 0xc0c00000 - 0xc0d00000   (1024 kB)
      .data : 0xc0d00000 - 0xc0dcc280   ( 817 kB)
       .bss : 0xc0dce000 - 0xc152f644   (7558 kB)
Running RCU self tests
Hierarchical RCU implementation.
	RCU event tracing is enabled.
	RCU lockdep checking is enabled.
	RCU restricting CPUs from NR_CPUS=2 to nr_cpu_ids=1.
RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
IRQ: Found an INTC at 0xfa200000 (revision 4.0) with 96 interrupts
Clocking rate (Crystal/Core/MPU): 19.2/332/500 MHz
OMAP clockevent source: timer1 at 32768 Hz
clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
sched_clock: 32 bits at 32kHz, resolution 30517ns, wraps every 65535999984741ns
OMAP clocksource: 32k_counter at 32768 Hz
Console: colour dummy device 80x30
WARNING: Your 'console=ttyO2' has been replaced by 'ttyS2'
This ensures that you still see kernel messages. Please
update your kernel commandline.
Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
... MAX_LOCKDEP_SUBCLASSES:  8
... MAX_LOCK_DEPTH:          48
... MAX_LOCKDEP_KEYS:        8191
... CLASSHASH_SIZE:          4096
... MAX_LOCKDEP_ENTRIES:     32768
... MAX_LOCKDEP_CHAINS:      65536
... CHAINHASH_SIZE:          32768
 memory used by lock dependency info: 4655 kB
 per task-struct memory footprint: 1536 bytes
Calibrating delay loop... 493.97 BogoMIPS (lpj=2469888)
pid_max: default: 32768 minimum: 301
Security Framework initialized
Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
CPU: Testing write buffer coherency: ok
CPU0: thread -1, cpu 0, socket -1, mpidr 0
Setting up static identity map for 0x80100000 - 0x80100078
Hierarchical SRCU implementation.
smp: Bringing up secondary CPUs ...
smp: Brought up 1 node, 1 CPU
SMP: Total of 1 processors activated (493.97 BogoMIPS).
CPU: All CPU(s) started in SVC mode.
devtmpfs: initialized
Built 1 zonelists, mobility grouping on.  Total pages: 59109
VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 1
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
futex hash table entries: 256 (order: 2, 16384 bytes)
pinctrl core: initialized pinctrl subsystem
NET: Registered protocol family 16
__alloc_from_contiguous
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.13.0-rc7-next-20170901-00024-gcf9a104b2f62 #568
Hardware name: Nokia RX-51 board
[<c0110b38>] (unwind_backtrace) from [<c010caec>] (show_stack+0x10/0x14)
[<c010caec>] (show_stack) from [<c082eb04>] (dump_stack+0xac/0xe0)
[<c082eb04>] (dump_stack) from [<c0118b94>] (__alloc_from_contiguous.constprop.7+0x28/0x68)
[<c0118b94>] (__alloc_from_contiguous.constprop.7) from [<c0c06d3c>] (atomic_pool_init+0x58/0xf0)
[<c0c06d3c>] (atomic_pool_init) from [<c0101df4>] (do_one_initcall+0x3c/0x170)
[<c0101df4>] (do_one_initcall) from [<c0c00ee4>] (kernel_init_freeable+0x1fc/0x2c4)
[<c0c00ee4>] (kernel_init_freeable) from [<c0842a4c>] (kernel_init+0x8/0x110)
[<c0842a4c>] (kernel_init) from [<c0107d78>] (ret_from_fork+0x14/0x3c)
atomic_pool_init: DMA: disable atomic_pool
omap_hwmod: mcbsp2_sidetone using broken dt data from mcbsp
omap_hwmod: mcbsp3_sidetone using broken dt data from mcbsp
cpuidle: using governor menu
SRAM_ADDR: omap_map_sram: P: 0x40208000 - 0x4020f000
SRAM_ADDR: omap_map_sram: V: 0xd0008000 - 0xd000f000
SRAM_ADDR: omap_sram_push_address: 0xd000ef00 - 0xd000effc
SRAM_ADDR: omap_sram_push_address: 0xd000ee90 - 0xd000eefc
Reprogramming SDRC clock to 332000000 Hz
...

Joonsoo Kim Nov. 9, 2017, 12:08 a.m. UTC | #12

On Wed, Nov 08, 2017 at 08:34:13AM -0800, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [171108 07:43]:
> > On Tue, Nov 07, 2017 at 07:48:42AM -0800, Tony Lindgren wrote:
> > > So it seems the issue is currently at the atomic_pool_init()
> > > related code?
> > 
> > Yes, your test showed it although I can't find any clue in
> > atomic_pool_init().
> > 
> > Could you test updated branch?
> > 
> > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> > 
> > There are two relevant commits.
> > 
> > arm/dma: stop dma allocation before __dma_alloc_remap()
> > arm/dma: disable atomic pool after dma allocation
> > 
> > atomic pool initialization will be done partially to check
> > exact point of failure. These are brain-dead commits however I have no
> > idea what's going on here until now. :/
> 
> OK that booted, dmesg output below. Hopefully that provides
> you with some more clues.

Thanks!

Could you let me know which one is booted? Both of them? or just top
commit ("arm/dma: stop dma allocation before __dma_alloc_remap()")?

Thanks.

Tony Lindgren Nov. 9, 2017, 12:11 a.m. UTC | #13

* Joonsoo Kim <[e-mail]> [171109 00:05]:
> On Wed, Nov 08, 2017 at 08:34:13AM -0800, Tony Lindgren wrote:
> > * Joonsoo Kim <[e-mail]> [171108 07:43]:
> > > On Tue, Nov 07, 2017 at 07:48:42AM -0800, Tony Lindgren wrote:
> > > > So it seems the issue is currently at the atomic_pool_init()
> > > > related code?
> > > 
> > > Yes, your test showed it although I can't find any clue in
> > > atomic_pool_init().
> > > 
> > > Could you test updated branch?
> > > 
> > > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> > > 
> > > There are two relevant commits.
> > > 
> > > arm/dma: stop dma allocation before __dma_alloc_remap()
> > > arm/dma: disable atomic pool after dma allocation
> > > 
> > > atomic pool initialization will be done partially to check
> > > exact point of failure. These are brain-dead commits however I have no
> > > idea what's going on here until now. :/
> > 
> > OK that booted, dmesg output below. Hopefully that provides
> > you with some more clues.
> 
> Thanks!
> 
> Could you let me know which one is booted? Both of them? or just top
> commit ("arm/dma: stop dma allocation before __dma_alloc_remap()")?

Oh OK. Only the top commit boots.

Regards,

Tony

Joonsoo Kim Nov. 9, 2017, 12:36 a.m. UTC | #14

On Wed, Nov 08, 2017 at 04:11:13PM -0800, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [171109 00:05]:
> > On Wed, Nov 08, 2017 at 08:34:13AM -0800, Tony Lindgren wrote:
> > > * Joonsoo Kim <[e-mail]> [171108 07:43]:
> > > > On Tue, Nov 07, 2017 at 07:48:42AM -0800, Tony Lindgren wrote:
> > > > > So it seems the issue is currently at the atomic_pool_init()
> > > > > related code?
> > > > 
> > > > Yes, your test showed it although I can't find any clue in
> > > > atomic_pool_init().
> > > > 
> > > > Could you test updated branch?
> > > > 
> > > > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> > > > 
> > > > There are two relevant commits.
> > > > 
> > > > arm/dma: stop dma allocation before __dma_alloc_remap()
> > > > arm/dma: disable atomic pool after dma allocation
> > > > 
> > > > atomic pool initialization will be done partially to check
> > > > exact point of failure. These are brain-dead commits however I have no
> > > > idea what's going on here until now. :/
> > > 
> > > OK that booted, dmesg output below. Hopefully that provides
> > > you with some more clues.
> > 
> > Thanks!
> > 
> > Could you let me know which one is booted? Both of them? or just top
> > commit ("arm/dma: stop dma allocation before __dma_alloc_remap()")?
> 
> Oh OK. Only the top commit boots.

Okay! I will try to analyze!

Thanks.

Joonsoo Kim Nov. 9, 2017, 3:50 a.m. UTC | #15

On Thu, Nov 09, 2017 at 09:36:39AM +0900, Joonsoo Kim wrote:
> On Wed, Nov 08, 2017 at 04:11:13PM -0800, Tony Lindgren wrote:
> > * Joonsoo Kim <[e-mail]> [171109 00:05]:
> > > On Wed, Nov 08, 2017 at 08:34:13AM -0800, Tony Lindgren wrote:
> > > > * Joonsoo Kim <[e-mail]> [171108 07:43]:
> > > > > On Tue, Nov 07, 2017 at 07:48:42AM -0800, Tony Lindgren wrote:
> > > > > > So it seems the issue is currently at the atomic_pool_init()
> > > > > > related code?
> > > > > 
> > > > > Yes, your test showed it although I can't find any clue in
> > > > > atomic_pool_init().
> > > > > 
> > > > > Could you test updated branch?
> > > > > 
> > > > > https://github.com/JoonsooKim/linux/tree/cma-debug4-next-20180901
> > > > > 
> > > > > There are two relevant commits.
> > > > > 
> > > > > arm/dma: stop dma allocation before __dma_alloc_remap()
> > > > > arm/dma: disable atomic pool after dma allocation
> > > > > 
> > > > > atomic pool initialization will be done partially to check
> > > > > exact point of failure. These are brain-dead commits however I have no
> > > > > idea what's going on here until now. :/
> > > > 
> > > > OK that booted, dmesg output below. Hopefully that provides
> > > > you with some more clues.
> > > 
> > > Thanks!
> > > 
> > > Could you let me know which one is booted? Both of them? or just top
> > > commit ("arm/dma: stop dma allocation before __dma_alloc_remap()")?
> > 
> > Oh OK. Only the top commit boots.
> 
> Okay! I will try to analyze!
> 

Could you test following two commits on my updated branch?

"arm/dma: vmalloc area allocation"
"arm/dma: defer atomic pool initialization"

I suspect that changed virtual address of the sram due to early
__dma_alloc_remap() call causes the problem and above two commits test
this theory.

Thanks.

Tony Lindgren Nov. 9, 2017, 3:08 p.m. UTC | #16

* Joonsoo Kim <[e-mail]> [171109 03:47]:
> Could you test following two commits on my updated branch?
> 
> "arm/dma: vmalloc area allocation"

Won't boot at this commit:

[    6.747283] save_secure_sram() returns 0000ff02
[    6.751983] save_secure_sram()'s param: 0: 0x4
[    6.756561] save_secure_sram()'s param: 1: 0x8e700000
[    6.761749] save_secure_sram()'s param: 2: 0x0
[    6.766326] save_secure_sram()'s param: 3: 0x1
[    6.770904] save_secure_sram()'s param: 4: 0x1

> "arm/dma: defer atomic pool initialization"

Boots at this commit.

> I suspect that changed virtual address of the sram due to early
> __dma_alloc_remap() call causes the problem and above two commits test
> this theory.

Hmm OK. Does your first patch above now have the initcall issue too?
It boots if I make that also subsys_initcall and then I get:

[    2.078094] vmalloc_pool_init: DMA: get vmalloc area: d0010000

Regards,

Tony

Joonsoo Kim Nov. 10, 2017, 12:13 a.m. UTC | #17

On Thu, Nov 09, 2017 at 07:08:54AM -0800, Tony Lindgren wrote:
> * Joonsoo Kim <[e-mail]> [171109 03:47]:
> > Could you test following two commits on my updated branch?
> > 
> > "arm/dma: vmalloc area allocation"
> 
> Won't boot at this commit:
> 
> [    6.747283] save_secure_sram() returns 0000ff02
> [    6.751983] save_secure_sram()'s param: 0: 0x4
> [    6.756561] save_secure_sram()'s param: 1: 0x8e700000
> [    6.761749] save_secure_sram()'s param: 2: 0x0
> [    6.766326] save_secure_sram()'s param: 3: 0x1
> [    6.770904] save_secure_sram()'s param: 4: 0x1
> 
> > "arm/dma: defer atomic pool initialization"
> 
> Boots at this commit.
> 
> > I suspect that changed virtual address of the sram due to early
> > __dma_alloc_remap() call causes the problem and above two commits test
> > this theory.
> 
> Hmm OK. Does your first patch above now have the initcall issue too?
> It boots if I make that also subsys_initcall and then I get:

> [    2.078094] vmalloc_pool_init: DMA: get vmalloc area: d0010000

Yes, first patch has the initcall issue and it's intentional in order
to check the theory. I checked following log for this.

- Boot failure
SRAM_ADDR: omap_map_sram: P: 0x40208000 - 0x4020f000
SRAM_ADDR: omap_map_sram: V: 0xd0050000 - 0xd0057000

- Boot success
SRAM_ADDR: omap_map_sram: P: 0x40208000 - 0x4020f000
SRAM_ADDR: omap_map_sram: V: 0xd0008000 - 0xd000f000

When failure, virtual address for sram is higher than normal one due
to vmalloc area allocation in __dma_alloc_remap(). If it is deferred,
virtual address is the same with success case and then the system work.

So, my next theory is that there is n900 specific assumption that sram
should have that address. Could you check if any working tree for n900
which doesn't have my CMA series work or not with adding
"arm/dma: vmalloc area allocation"?

Thanks.

Patch

diff --git a/mm/page_alloc.c b/mm/page_alloc.c
index 6dbc49e..1e48e67 100644
--- a/mm/page_alloc.c
+++ b/mm/page_alloc.c
@@ -1861,7 +1861,7 @@  static int fallbacks[MIGRATE_TYPES][4] = {
 static struct page *__rmqueue_cma_fallback(struct zone *zone,
                                        unsigned int order)
 {
-       return __rmqueue_smallest(zone, order, MIGRATE_CMA);
+       return NULL;
 }
 #else
 static inline struct page *__rmqueue_cma_fallback(struct zone *zone,

----------------->8----------------------
diff --git a/arch/arm/mm/dma-mapping.c b/arch/arm/mm/dma-mapping.c
index c68f34a..c72b4c3 100644
--- a/arch/arm/mm/dma-mapping.c
+++ b/arch/arm/mm/dma-mapping.c
@@ -497,6 +497,9 @@  void __init dma_contiguous_remap(void)
                map.length = end - start;
                map.type = MT_MEMORY_DMA_READY;
 
+               dmac_flush_range(map.virtual, map.virtual + map.length);
+               outer_flush_range(start, end);
+
                /*
                 * Clear previous low-memory mapping to ensure that the
                 * TLB does not see any conflicting entries, then flush
@@ -510,6 +513,7 @@  void __init dma_contiguous_remap(void)
                     addr += PMD_SIZE)
                        pmd_clear(pmd_off_k(addr));
 
+               flush_cache_all();
                flush_tlb_kernel_range(__phys_to_virt(start),
                                       __phys_to_virt(end));