Closed msperl closed 9 years ago
msperl
commented
9 years ago Looking at a buffer of 8448 bytes (8k+256) it show the same behavior, so there is something that applies to more than 2 pages that triggers this (as if some mapping is not removed)
popcornmix
commented
9 years ago No immediate thoughts. I can't think of any downstream patches that could affect this - we don't really change anything in the core of the kernel. Obviously if this is a memory corruption issue, then the fact it's not visible in upstream kernel may just mean it's corrupting something less critical there, rather than proving it's a bug in the Pi kernel tree (although I'm not ruling that out).
pelwell
commented
9 years ago Are you using CMA, as that can involve some interesting remapping?
popcornmix
commented
9 years ago The other thought is if you are dma-ing to a buffer and use the wrong caching (either the top-two bits of address means it is incorrectly cached in GPU's L1/L2 cache), or the wrong arm side caching, and you then realloc (so buffer moves physically), you may later get corruption when the cached data gets written back (e.g. if dma output was in GPU's L2 cache).
msperl
commented
9 years ago as said: it seems to fail on krealloc - what that may take as memory pools is the question (and that may be configurable per "platform").
As I am unable to repeat this upstream (4.1-rc2) I have to assume it is downstream... It could be some concurrency issue...
msperl
commented
9 years ago @popcornmix: Well - actually I have disabled the actual DMA transfer - I just let the framework do the mapping and then fall back to interrupts.
So corruption due to DMA is out of the picture - everything is just calls to kernel.
The driver changes to get that far are actually minimal:
So there could be an issue in DMA-engine that triggers this. And that is obviously different to the one upstream.
notro
commented
9 years ago Are you using CMA, as that can involve some interesting remapping?
If you mean drivers/char/broadcom/vc_cma/vc_cma.c, I just tried disabling it without any effect. I'm using plain bcmrpi_config with the SPI dma patch.
I will try enabling BCM2708_NOL2CACHE.
popcornmix
commented
9 years ago Are you using non-arm-cached allocations? Are you using bcm2709_defconfig, or your own config? Do you have CONIG_DMA_CMA enabled? See: https://github.com/raspberrypi/linux/issues/575#issuecomment-41812586
pelwell
commented
9 years ago Yes, that's what I meant. I'm happy that we can rule it out.
popcornmix
commented
9 years ago @notro BCM2708_NOL2CACHE needs to be in sync with config.txt option disable_l2cache (if you are using non-default options).
notro
commented
9 years ago BCM2708_NOL2CACHE needs to be in sync with config.txt option disable_l2cache
Thanks.
But it didn't help.
Verification that the offset has changed:
[ 1.369449] BCM2708FB: allocated DMA memory 5bc00000
BCM2708_NOL2CACHE
[ 1.460828] BCM2708FB: allocated DMA memory dbc00000Thinking of it: there are 2 more calls that we can try to identify which is the culprit! Dma_map_sg and sg_set_page/sg_set_buf I will try if I can discern which one it is later tonight.
notro
commented
9 years ago Do you have CONIG_DMA_CMA enabled?
According to kconfig help on this option, cma=0 on the kernel command line should disable this. I tried it, but it didn't help.
regular
[ 0.000000] cma: Reserved 8 MiB at 0x1b800000
[ 0.000000] Memory: 436696K/458752K available (5994K kernel code, 328K rwdata, 1912K rodata, 348K init, 711K bss, 13864K reserved, 8192K cma-reserved)
cma=0
[ 0.000000] Memory: 444904K/458752K available (5994K kernel code, 328K rwdata, 1912K rodata, 348K init, 711K bss, 13848K reserved, 0K cma-reserved)I believe you want CONFIG_DMA_CMA enabled to avoid cache coherency issues, not disabled.
notro
commented
9 years ago Ok.
notro
commented
9 years ago I found this: Re: dma_unmap causing issues with __get_free_pages
Which led me to try and remove the freeing of the dummy buffer in __spi_pump_messages():
// kfree(master->dummy_rx);
// master->dummy_rx = NULL;And voila, the error is gone! So it can have something to do with kfree/dma_unmap in the wrong order.
notro
commented
9 years ago Yes, dma_unmap is happening after kfree (the actual kfree is disabled in my kernel, this is only a message):
[ 58.319845] krealloc(dummy_rx=da4039e0, max_rx=16384)
[ 58.319908] krealloc returned: d9058000, page: db787c60, pfn:19058
[ 58.319956] spi_map_buf: dma_map_sg(dma=0xdb820000)
[ 58.319990] spi_map_buf: dma_map_sg(dma=0xd9058000)
[ 58.324416] __spi_pump_messages: kfree(master->dummy_rx=d9058000)
[ 58.324487] spi_unmap_buf: dma_unmap_sg(dma=0xd9058000)
[ 58.324531] spi_unmap_buf: dma_unmap_sg(dma=0xdb820000)But why does it impact the foundation kernel, but not the upstream 4.1?
Also this "workaround" is mostly an optimization that you are doing: avoiding some reallocations... Imo the whole setup inside spi.c does not make a lot of sense, as it will even map rx- buffers where it is not needed (for short-non-dma cases, so wasting cycles unnecessarily)
But still the order is ok -the free happens at the beginning of the pump task(if it is null it is also ok) Allocate and map via spi_map_mesg. And release via finalize_current_msg and in there via spi_unmap_msg
The order of mapping is imo also ok: In spi_map_buf: sgset followed by dma_map_sg In spi_unmap_buf: dma_unmap_sg followed by sg_free_table
My guess is that there is something in sg_ that does not do what is needed...
Note that: Dma_map_sg_attrs calls dma_map_ops->map_sg Dma_unmap_sg_attrs calls dma_map_ops->unmap_sg So it could be one of those 2 functions that does not do what is fully expected...
msperl
commented
9 years ago Ok- it happens but I do not understand why it would get freed before the finalize_current_msg is called. I guess I need to instrument the 4.1 kernel like you did to see if it is changed...
notro
commented
9 years ago It seems that spi_finalize_current_message() is kicking the worker thread which frees the buffer, then it continues with spi_unmap_msg():
[ 52.012752] __spi_sync
[ 52.012783] __spi_pump_messages(in_kthread=0) IN
[ 52.012803] __spi_pump_messages(in_kthread=0) prepare
[ 52.012818] __spi_pump_messages(in_kthread=0) spi_map_msg
[ 52.012835] krealloc(dummy_rx=da53f9e0, max_rx=16384)
[ 52.012873] krealloc returned: da684000, page: db7b9a90, pfn:1a684
[ 52.012918] spi_map_buf: dma_map_sg(dma=0xdb820000)
[ 52.012952] spi_map_buf: dma_map_sg(dma=0xda684000)
[ 52.012972] __spi_pump_messages(in_kthread=0) transfer_one_message
[ 52.020610] spi_finalize_current_message IN
[ 52.020697] __spi_pump_messages(in_kthread=1) IN
[ 52.020734] __spi_pump_messages(in_kthread=1): kfree(master->dummy_rx=da684000) Begin
[ 52.020755] __spi_pump_messages(in_kthread=1) idle OUT
[ 52.020803] spi_unmap_buf: dma_unmap_sg(dma=0xda684000)
[ 52.020844] spi_unmap_buf: dma_unmap_sg(dma=0xdb820000)
[ 52.020870] spi_finalize_current_message OUT
[ 52.020890] __spi_pump_messages(in_kthread=0) OUTIt seems to be a race of some kind. When I add pr_info's to spi_transfer_one_message(), the freeing waits until the end:
[ 47.111580] __spi_sync
[ 47.111615] __spi_pump_messages(in_kthread=0) IN
[ 47.111634] __spi_pump_messages(in_kthread=0) prepare
[ 47.111649] __spi_pump_messages(in_kthread=0) spi_map_msg
[ 47.111665] krealloc(dummy_rx=d9070000, max_rx=16384)
[ 47.111685] krealloc returned: d9070000, page: db787fc0, pfn:19070
[ 47.111721] spi_map_buf: dma_map_sg(dma=0xdb820000)
[ 47.111754] spi_map_buf: dma_map_sg(dma=0xd9070000)
[ 47.111772] __spi_pump_messages(in_kthread=0) transfer_one_message
[ 47.111785] spi_transfer_one_message IN
[ 47.111927] __spi_pump_messages(in_kthread=1) IN
[ 47.116160] spi_finalize_current_message IN
[ 47.116224] spi_unmap_buf: dma_unmap_sg(dma=0xd9070000)
[ 47.116345] spi_unmap_buf: dma_unmap_sg(dma=0xdb820000)
[ 47.116380] spi_finalize_current_message OUT
[ 47.116397] spi_transfer_one_message OUT ret=0
[ 47.116413] __spi_pump_messages(in_kthread=0) OUT
[ 47.154759] __spi_pump_messages(in_kthread=1) IN
[ 47.154800] __spi_pump_messages(in_kthread=1): kfree(master->dummy_rx=d9070000) Begin
[ 47.154823] __spi_pump_messages(in_kthread=1) idle OUT
I slow some things down with all these log messages so the next message is begun before the worker thread kicks in:
[ 47.286403] spi_transfer_one_message IN
[ 47.286588] __spi_pump_messages(in_kthread=1) IN
[ 47.286629] __spi_pump_messages(in_kthread=1) OUT already runningThis stops the thread from freeing the buffer.
Full log: https://gist.github.com/notro/78dd25cae4adca8f30c9
static void __spi_pump_messages(struct spi_master *master, bool in_kthread)
{
unsigned long flags;
bool was_busy = false;
int ret;
pr_info("%s(in_kthread=%i) IN\n", __func__, in_kthread);
/* Lock queue */
spin_lock_irqsave(&master->queue_lock, flags);
/* Make sure we are not already running a message */
if (master->cur_msg) {
spin_unlock_irqrestore(&master->queue_lock, flags);
pr_info("%s(in_kthread=%i) OUT already running\n", __func__, in_kthread);
return;
}But why is spi_finalize_current_message() kicking the thread before unmapping? I need a break. Will look at unmapping before kicking later.
msperl
commented
9 years ago So that may also be the reason why it fails completely for the RPI with the timeout. I know that 4.1 has some major optimizations on the spi-front, so this issue may have gotten solved... But a quick look at finalize_current_message in 4.1 and 4.0 shows the same sequence... queue pump_message and then umap_msg...
Can you check if moving the unmap before the spin_lock_irqsave(&master->queue_lock, flags); solves the issue?
We will need to raise this with Mark...
msperl
commented
9 years ago This should solve the issue:
diff --git a/drivers/spi/spi.c b/drivers/spi/spi.c
index 57a1950..1e662a0 100644
--- a/drivers/spi/spi.c
+++ b/drivers/spi/spi.c
@@ -1089,6 +1089,8 @@ void spi_finalize_current_message(struct spi_master *master)
unsigned long flags;
int ret;
+ spi_unmap_msg(master, master->cur_msg);
+
spin_lock_irqsave(&master->queue_lock, flags);
mesg = master->cur_msg;
master->cur_msg = NULL;
@@ -1096,8 +1098,6 @@ void spi_finalize_current_message(struct spi_master *master)
queue_kthread_work(&master->kworker, &master->pump_messages);
spin_unlock_irqrestore(&master->queue_lock, flags);
- spi_unmap_msg(master, mesg);
-
if (master->cur_msg_prepared && master->unprepare_message) {
ret = master->unprepare_message(master, mesg);
if (ret) {
the issue does not longer show for me when this is applied...
notro
commented
9 years ago Yes it works for me too on Pi1. But is it ok to do this while interrupts are disabled? It might be other sideeffects also. Mark can probably answer.
msperl
commented
9 years ago If you look, I have corrected the patch to do it outside of the spinlock in the meantime (because I also saw the issue after posting it)...
Also I have just sent an email to the spi-list - let us see what the answer is, but I guess this will mean we will need to cherry-pick that patch to go into 4.0.
notro
commented
9 years ago Please add
Suggested-by: Noralf Trønnes <noralf@tronnes.org>
if you send it in.
Or if the solution turns out to be something else:
Reported-by: Noralf Trønnes <noralf@tronnes.org>
msperl
commented
9 years ago Slight variation - moving need to move it into to lock context again. (so essentially the first)
Will create and add them as soon as I find the time today...
msperl
commented
9 years ago well - testing the now proposed patch with feedback by Mark shows that I get issues with another driver that - this time - result in kernel panics, which I have not seen without this "patch".
So it may take slightly longer to fix...
msperl
commented
9 years ago @notro: sent an email to you with the patch to apply to fix the "free before unmap" issue. Please test and I will forward it upstream so that we can merge it into 4.0.
msperl
commented
9 years ago Sent patch upstream.
Closing this issue but I will open a separate issue for a merge from upstream as soon as it goes in.
@notro found some issue when testing the new feature of the spi-bcm2835 driver that strangely ONLY occurs in the foundation kernel - it does NOT show in 4.1.0-rc2.
Here an example output of what we see on the console:
We have now traced this down to spi_map_msg, which:
if both code sections are run together, then things break and also impact OTHER parts of the kernel like this one:
This does NOT happen with an upstream 4.1.0-rc2 kernel, so it must be something specific to downstream/custom code
It also only happens for the second mapping request that is 16384 bytes (actually might be anything > 8192 bytes - it was only tested with 4K/8K/16K/32K transfers)
Here with some dev_info messages arround the krealloc:
Finally see also discussions in this thread: https://github.com/msperl/spi-bcm2835/issues/13#issuecomment-99460803