Re: Unstable Kernel behavior on an ARM based board

[Thierry Reding <thierry.reding@gmail.com>]

[-- Attachment #1.1: Type: text/plain, Size: 7119 bytes --]

On Tue, Mar 05, 2019 at 11:22:26AM +0000, Russell King - ARM Linux admin wrote:
> On Tue, Mar 05, 2019 at 03:29:26PM +0500, Embedded Engineer wrote:
> > On Tue, Mar 5, 2019 at 3:07 PM Russell King - ARM Linux admin
> > <linux@armlinux.org.uk> wrote:
> > >
> > > Please apply this patch so we can see the (ptrval) values.  Thanks.
> > 
> > Please find below logs after applying patch:
> > 
> > https://pastebin.com/6TaBxPX5
> 
> So we have a pattern here:
> 
> tegra-udc 7d000000.usb: dma_pool_alloc ci_hw_qh, ec056080 (corrupted)
> 00000000: c0 00 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000010: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000020: 80 00 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000030: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> tegra-udc 7d000000.usb: dma_pool_alloc ci_hw_qh, ec056140 (corrupted)
> 00000000: 80 01 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000010: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000020: 40 01 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  @...............
> 00000030: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> tegra-udc 7d000000.usb: dma_pool_alloc ci_hw_qh, ec0561c0 (corrupted)
> 00000000: 00 02 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000010: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000020: 40 03 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  @...............
> 00000030: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> tegra-udc 7d000000.usb: dma_pool_alloc ci_hw_qh, ec056200 (corrupted)
> 00000000: 40 02 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  @...............
> 00000010: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 00000020: 40 05 00 00 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  @...............
> 00000030: a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7 a7  ................
> 
> and so it goes on.
> 
> The first four bytes are the offset to the next free block of memory in
> this page, so can be ignored.  The remainder of the bytes should all be
> 0xa7, but every word at offset 32 into these is corrupted with what
> looks to be a similar offset.
> 
> We dump 0x40 bytes, which, reading the code makes the pool size 0x40
> bytes in size.  Tabulating the object offset, the next offset, and
> the corruption at offset 32.  Corruption1 is from your latest log,
> corruption2 is derived from your previous log using the next pointer
> to tie up between the two:
> 
> object offset	next		corruption1	corruption2
> 0x0080		0x00c0		0x00000080	0x00000080
> 0x0140		0x0180		0x00000140	0x00000100
> 0x01c0		0x0200		0x00000340	0x000001c0
> 0x0200		0x0240		0x00000540	0x000001c0
> 0x0280		0x02c0		0x00000340	0x00000300
> 0x0340		0x0380		0x00000540	0x00000140
> 0x03c0		0x0400		0x00000540	0x00000300
> 0x0400		0x0440		0x000003c0	0x00000140
> 0x0480		0x04c0		0x00000540	0x000003c0
> 0x0540		0x0580		0x00000480	0x00000540
> 0x05c0		0x0600		0x000005c0	0x000005c0
> 0x0600		0x0640		0x00000500	0x000005c0
> 0x0680		0x06c0		0x00000740	0x00000680
> ??????		0x0780				0x00000740
> 0x07c0		0x0800		0x000007c0	0x00000700
> 
> The corruption looks very much like offset values, except they do not
> seem to follow any rhyme or reason.  They also appear to be different
> on each boot.
> 
> Given that the sequence here when a pool allocation occurs is:
> 
> 1. allocate DMA coherent page
> 2. memset entire page with 0xa7
> 3. write next offsets
> 4. initialise 'offset' to zero (offset of first free object)
> 5. add page to pools list of pages
> 6. allocate first object, updating offset to the next free offset read
>    from the first word of the object.
> 
> then when the next allocation request comes along, we allocate the
> next object in the same way as step 6.  At the point of allocating the
> third object, we find that there is corruption in the third object at
> 0x20 bytes into it - or 0xa0 bytes into the page.
> 
> Now, what does the driver that's allocating these do with them?  That
> is done via init_eps() in drivers/usb/chipidea/udc.c, which doesn't do
> anything with the allocated memory.  This is the only place that the
> driver allocates from this DMA pool, which is done in a loop, so we
> know that the objects allocated from this pool will be in relatively
> quick succession.
> 
> So this does not make sense.
> 
> I really doubt that there is anything wrong with the kernel - this USB
> driver is used on other SoCs (such as iMX6) and does not exhibit this
> problem - it also works on the Tegra TK1 platform as well.
> 
> You are definitely seeing memory corruption here - but given what the
> above looks like, I'd put forward another possible scenario - maybe
> u-boot or something else is leaving a USB controller or some other DMA
> agent active, which is writing over memory while the kernel is trying
> to boot, resulting in memory corruption.

That had occurred to me as well. The kernel command line contains a
couple of memory regions that I think our downstream kernel parses and
uses to reserve memory (redacted here for readability):

	console=ttyS0,115200n8
	console=tty1
	no_console_suspend=1
	lp0_vec=2064@0xf46ff000
	mem=2015M@2048M
	memtype=255
	ddr_die=2048M@2048M
	section=256M
	pmuboard=0x0177:0x0000:0x02:0x43:0x00
	tsec=32M@3913M
	otf_key=c75e5bb91eb3bd947560357b64422f85
	usbcore.old_scheme_first=1
	core_edp_mv=1150
	core_edp_ma=4000
	tegraid=40.1.1.0.0
	debug_uartport=lsport,3
	power_supply=Adapter
	audio_codec=rt5640
	modem_id=0
	android.kerneltype=normal
	fbcon=map:1
	commchip_id=0
	usb_port_owner_info=0
	lane_owner_info=6
	emc_max_dvfs=0
	touch_id=0@0
	board_info=0x0177:0x0000:0x02:0x43:0x00
	net.ifnames=0
	root=/dev/mmcblk1p1
	rw
	rootwait
	tegraboot=sdmmc
	gpt
	maxcpus=0
	pci=noaer

Two things stand out here:

	mem=2015M@2048M
	tsec=32M@3913M

So it looks like there are two carveout regions that the kernel isn't
supposed to touch and presumably somebody else could be using them. If
there's overlap between them and the DMA memory used by the DMA pool,
that could perhaps explain what's going on here.

Can you try the following patch and send the boot log again?

Thanks,
Thierry

--- >8 ---
diff --git a/mm/dmapool.c b/mm/dmapool.c
index 76a160083506..6343d74cb963 100644
--- a/mm/dmapool.c
+++ b/mm/dmapool.c
@@ -361,11 +361,11 @@ void *dma_pool_alloc(struct dma_pool *pool, gfp_t mem_flags,
 				continue;
 			if (pool->dev)
 				dev_err(pool->dev,
-					"dma_pool_alloc %s, %p (corrupted)\n",
-					pool->name, retval);
+					"dma_pool_alloc %s, %px/%pad (corrupted)\n",
+					pool->name, retval, handle);
 			else
-				pr_err("dma_pool_alloc %s, %p (corrupted)\n",
-					pool->name, retval);
+				pr_err("dma_pool_alloc %s, %px/%pad (corrupted)\n",
+					pool->name, retval, handle);
 
 			/*
 			 * Dump the first 4 bytes even if they are not

[-- Attachment #1.2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

[-- Attachment #2: Type: text/plain, Size: 176 bytes --]

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel