| Message ID | 87a8o9ex9r.fsf@belgarion.home |
|---|---|
| State | Accepted |
| Headers | show |
On 01/13/2016 08:47 PM, Robert Jarzmik wrote: > Hi Michael, >> Any suggestion, help or hint will be very much appreciated. > Actually I have one. > Before we change the timeout, I'd like to see the sequence of register accesses. > > As I owe a patch to Brian on this topic, I'd like to have you as a tester. In > return, I'll analyse the output of debug traces it generates for you. > > The patch is at the bottom of this mail, and a "git am" on the mail should apply > it to your kernel. It leaves up to you to add the "#define VERBOSE_DEBUG 1" in > pxa3xx-nand.c, recompile, and take the traces. > > Once I have the traces, I will be able to compare with my traces on pxa3xx > platforms and spot if there is a difference. Then we'll be able to see if > increasing the timeout is the only option. > > Cheers. > Hi Robert, Thank you for your reply. I am happy to be the tester for this issue. The complete output of debug traces and boot log from your debug patch is in the attachment. Thanks, Michael
Michael Wang <Michael.Wang@alliedtelesis.co.nz> writes: > The complete output of debug traces and boot log from your debug patch > is in the attachment. Okay, thanks, that's great. Might a ask another capture, but with : 1) the timestamps this time (ie. CONFIG_PRINTK_TIME=y) ? This will give me the timing of your failure, in the dmesg you will provide me. 2) on the first line of drain_fifo(), add a single : nand_readl(info, NDSR) This will enable me to see how your board behaves on the temporal aspect, as today I only have this, which looks correct AFAICT: pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():445 nand_writel(0x1, NDECCCTRL) pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():465 nand_writel(0xfff, NDSR) pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():466 nand_writel(0x0, NDCR) pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():467 nand_writel(0xd104b000, NDCR) pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():656 nand_readl(NDSR): 0x1 pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():706 nand_writel(0x1, NDSR) pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():720 nand_writel(0x100d3000, NDCB0) pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():721 nand_writel(0x4ff0000, NDCB0) pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():722 nand_writel(0x2, NDCB0) pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():726 nand_writel(0x820, NDCB0) => RJK: here the read command is submitted pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():656 nand_readl(NDSR): 0x1800 pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():706 nand_writel(0x1800, NDSR) => RJK: here the read command is completed pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():656 nand_readl(NDSR): 0x2 pxa3xx-nand f10d0000.nand: Wait time out!!! => RJK: here data is available in NAND controller, and yet it's too late pxa3xx-nand f10d0000.nand: pxa3xx_nand_stop():476 nand_readl(0x0000): 0xd104b000 pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq_thread():636 nand_writel(0x6, 0x0014) => RJK: here we finish the read data transfer operation, too late Cheers. -- Robert
On 01/17/2016 12:53 PM, Robert Jarzmik wrote: > Might a ask another capture, but with : > 1) the timestamps this time > (ie. CONFIG_PRINTK_TIME=y) ? This will give me the timing of your failure, > in the dmesg you will provide me. > 2) on the first line of drain_fifo(), add a single : > nand_readl(info, NDSR) > > This will enable me to see how your board behaves on the temporal aspect, as > today I only have this, which looks correct AFAICT Hi Robert, Thank you for your analysis. The attachment file contains the complete debug output with the additional info you requested. I just want to mention that I get slightly different results on my board with debugs enabled/disabled. Without your debugs, the kernel will fail to boot up properly with command timing out and nand controller in invalid state: >pxa3xx-nand f10d0000.nand: Wait time out!!! >pxa3xx-nand f10d0000.nand: handle_data_pio: invalid state 0 With your debugs, commands still time out a few times, but handle_data_pio() doesn't get into invalid state and the kernel boots up fine. Thanks, Michael
Michael Wang <Michael.Wang@alliedtelesis.co.nz> writes: > On 01/17/2016 12:53 PM, Robert Jarzmik wrote: >> Might a ask another capture, but with : >> 1) the timestamps this time >> (ie. CONFIG_PRINTK_TIME=y) ? This will give me the timing of your failure, >> in the dmesg you will provide me. >> 2) on the first line of drain_fifo(), add a single : >> nand_readl(info, NDSR) >> >> This will enable me to see how your board behaves on the temporal aspect, as >> today I only have this, which looks correct AFAICT > Hi Robert, > > Thank you for your analysis. > > The attachment file contains the complete debug output with the > additional info you requested. > > I just want to mention that I get slightly different results on my board > with debugs enabled/disabled. > > Without your debugs, the kernel will fail to boot up properly with > command timing out and nand > controller in invalid state: > >pxa3xx-nand f10d0000.nand: Wait time out!!! > >pxa3xx-nand f10d0000.nand: handle_data_pio: invalid state 0 > > With your debugs, commands still time out a few times, but > handle_data_pio() doesn't get into > invalid state and the kernel boots up fine. Ok, I analysed with the timings, and now I'm pretty against the timeout change if the analysis below is correct. See in the log extract in [1], you have a contiguous sequence of one working read followed by one broken read : - in the working read, the irq thread is scheduled in 8ms, which is pretty decent. - in the broken read, the irq thread is scheduled in 160ms, which is just unbearable. From this analysis I think you have something broken in your platform, a driver taking a lock and blocking the scheduling or something like that. Your timeouts seem to come from there. If you want to add 2 prinks to validate the theory (and remove my debug logs which change the realtime behavior) : - put one just before the "ret = IRQ_WAKE_THREAD"; - put the other on the first line of pxa3xx_nand_irq_thread() - and calculate the difference. Cheers. -- Robert [1] Extract of your log => RJK: begin of the working read [ 2172.409771] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():445 nand_writel(0x1, NDECCCTRL) [ 2172.417844] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():465 nand_writel(0xfff, NDSR) [ 2172.426084] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():466 nand_writel(0x0, NDCR) [ 2172.434147] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():467 nand_writel(0xd104b000, NDCR) [ 2172.442823] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():658 nand_readl(NDSR): 0x1 [ 2172.450608] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():708 nand_writel(0x1, NDSR) [ 2172.458479] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():722 nand_writel(0x300d3000, NDCB0) [ 2172.466961] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():723 nand_writel(0x7fcb0000, NDCB0) [ 2172.475442] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():724 nand_writel(0x3, NDCB0) [ 2172.483312] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():728 nand_writel(0x820, NDCB0) [ 2172.491450] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():658 nand_readl(NDSR): 0x2 [ 2172.499259] pxa3xx-nand f10d0000.nand: drain_fifo():509 nand_readl(NDSR): 0x2 => RJK: here the irq thread was scheduled in 8ms [ 2172.506741] pxa3xx-nand f10d0000.nand: drain_fifo():509 nand_readl(NDSR): 0x2 [ 2172.514106] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq_thread():638 nand_writel(0x6, NDSR) [ 2172.522606] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():658 nand_readl(NDSR): 0x500 [ 2172.530565] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():708 nand_writel(0x500, NDSR) => RJK: begin of the broken read [ 2172.538671] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():445 nand_writel(0x1, NDECCCTRL) [ 2172.546753] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():465 nand_writel(0xfff, NDSR) [ 2172.554991] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():466 nand_writel(0x0, NDCR) [ 2172.563050] pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():467 nand_writel(0xd104b000, NDCR) [ 2172.571722] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():658 nand_readl(NDSR): 0x1 [ 2172.579508] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():708 nand_writel(0x1, NDSR) [ 2172.587379] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():722 nand_writel(0x100d3000, NDCB0) [ 2172.595860] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():723 nand_writel(0xfefd0000, NDCB0) [ 2172.604341] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():724 nand_writel(0x2, NDCB0) [ 2172.612212] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():728 nand_writel(0x820, NDCB0) [ 2172.620319] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():658 nand_readl(NDSR): 0x1800 [ 2172.628367] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():708 nand_writel(0x1800, NDSR) [ 2172.636519] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():658 nand_readl(NDSR): 0x2 [ 2172.798485] pxa3xx-nand f10d0000.nand: drain_fifo():509 nand_readl(NDSR): 0x2 => RJK: here the irq thread was scheduled in 160ms [ 2172.805996] pxa3xx-nand f10d0000.nand: drain_fifo():509 nand_readl(NDSR): 0x2 [ 2172.813379] pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq_thread():638 nand_writel(0x6, NDSR) [ 2172.821017] pxa3xx-nand f10d0000.nand: Wait time out!!! [ 2172.821029] pxa3xx-nand f10d0000.nand: pxa3xx_nand_stop():476 nand_readl(NDCR): 0xc104b000 [ 2172.821038] pxa3xx-nand f10d0000.nand: pxa3xx_nand_stop():487 nand_writel(0xfff, NDSR)
On 01/19/2016 10:13 AM, Robert Jarzmik wrote: > From this analysis I think you have something broken in your platform, a driver > taking a lock and blocking the scheduling or something like that. Your timeouts > seem to come from there. > > If you want to add 2 prinks to validate the theory (and remove my debug logs > which change the realtime behavior) : > - put one just before the "ret = IRQ_WAKE_THREAD"; > - put the other on the first line of pxa3xx_nand_irq_thread() > - and calculate the difference. Hi Robert, Thank you very much for your help. I have added the 2 printks, and I think you are right that there is something blocking the scheduling. [ 146.372745] pxa3xx_nand_irq:700 IRQ_WAKE_THREAD status=2 [ 146.378106] pxa3xx_nand_irq_thread:643 [ 146.411117] pxa3xx_nand_irq:700 IRQ_WAKE_THREAD status=2 [ 146.537124] pxa3xx_nand_irq_thread:643 => irq thread was scheduled in 0.126 ms [ 146.541245] pxa3xx_nand_irq:700 IRQ_WAKE_THREAD status=2 [ 146.546603] pxa3xx_nand_irq_thread:643 I will continue to investigate the cause of this delay. Thanks, Michael
Hi Robert, On Sun, Jan 17, 2016 at 12:53:06AM +0100, Robert Jarzmik wrote: > Michael Wang <Michael.Wang@alliedtelesis.co.nz> writes: > > > The complete output of debug traces and boot log from your debug patch > > is in the attachment. > > Okay, thanks, that's great. > Might a ask another capture, but with : > 1) the timestamps this time > (ie. CONFIG_PRINTK_TIME=y) ? This will give me the timing of your failure, > in the dmesg you will provide me. > 2) on the first line of drain_fifo(), add a single : > nand_readl(info, NDSR) > > This will enable me to see how your board behaves on the temporal aspect, as > today I only have this, which looks correct AFAICT: > > pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():445 nand_writel(0x1, NDECCCTRL) > pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():465 nand_writel(0xfff, NDSR) > pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():466 nand_writel(0x0, NDCR) > pxa3xx-nand f10d0000.nand: pxa3xx_nand_start():467 nand_writel(0xd104b000, NDCR) > > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():656 nand_readl(NDSR): 0x1 > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():706 nand_writel(0x1, NDSR) > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():720 nand_writel(0x100d3000, NDCB0) > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():721 nand_writel(0x4ff0000, NDCB0) > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():722 nand_writel(0x2, NDCB0) > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():726 nand_writel(0x820, NDCB0) > => RJK: here the read command is submitted > > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():656 nand_readl(NDSR): 0x1800 > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():706 nand_writel(0x1800, NDSR) > => RJK: here the read command is completed > > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq():656 nand_readl(NDSR): 0x2 > pxa3xx-nand f10d0000.nand: Wait time out!!! > => RJK: here data is available in NAND controller, and yet it's too late > > pxa3xx-nand f10d0000.nand: pxa3xx_nand_stop():476 nand_readl(0x0000): 0xd104b000 > pxa3xx-nand f10d0000.nand: pxa3xx_nand_irq_thread():636 nand_writel(0x6, 0x0014) > => RJK: here we finish the read data transfer operation, too late I'm not extremely familiar with this driver, but you've caused me to take a second look at this commit: commit 24542257a3b987025d4b998ec2d15e556c98ad3f Author: Robert Jarzmik <robert.jarzmik@free.fr> Date: Fri Feb 20 19:36:43 2015 +0100 mtd: pxa3xx-nand: handle PIO in threaded interrupt And now I'm wondering: when does the completion get triggered? i.e.: complete(&info->cmd_complete); ? It seems to me like you've short-circuited some of the IRQ handling code, so that the threaded handler is buggy. AIUI, if the completion event ever happens, it's actually happening *before* the full (threaded) handler is actually finished, since it occurs in pxa3xx_nand_irq(), before pxa3xx_nand_irq_thread() ever runs. Now, I'm not sure if that causes a real problem in practice, since you used IRQF_ONESHOT, but I would think that's also suspect. Brian
Brian Norris <computersforpeace@gmail.com> writes: > Hi Robert, > > On Sun, Jan 17, 2016 at 12:53:06AM +0100, Robert Jarzmik wrote: > commit 24542257a3b987025d4b998ec2d15e556c98ad3f > Author: Robert Jarzmik <robert.jarzmik@free.fr> > Date: Fri Feb 20 19:36:43 2015 +0100 > > mtd: pxa3xx-nand: handle PIO in threaded interrupt > > > And now I'm wondering: when does the completion get triggered? i.e.: > > complete(&info->cmd_complete); > It seems to me like you've short-circuited some of the IRQ handling > code, so that the threaded handler is buggy. AIUI, if the completion > event ever happens, it's actually happening *before* the full (threaded) > handler is actually finished, since it occurs in pxa3xx_nand_irq(), > before pxa3xx_nand_irq_thread() ever runs. Now, I'm not sure if that > causes a real problem in practice, since you used IRQF_ONESHOT, but I > would think that's also suspect. I think you're very right, this "goto NORMAL_IRQ_EXIT" creates a short-cirtcuit. That makes me think that I should : - add static void pxa3xx_nand_data_finished(struct pxa3xx_nand_info *info) { unsigned int done; cmd_done = info->cs ? NDSR_CS1_CMDD : NDSR_CS0_CMDD; nand_writel(info, NDSR, cmd_done); complete(&inf0->cmd_complete); } - in pxa3xx_nand_irq_thread(), I should add at the end: pxa3xx_nand_data_finished(info); - in pxa3xx_nand_data_dma_irq(), I should add at the end: pxa3xx_nand_data_finished(info); Ezequiel, would you have a look at that code snippet and tell me if I'm missing something in the driver's structure ? Cheers. -- Robert
On 25 January 2016 at 17:48, Robert Jarzmik <robert.jarzmik@free.fr> wrote: > Brian Norris <computersforpeace@gmail.com> writes: > >> Hi Robert, >> >> On Sun, Jan 17, 2016 at 12:53:06AM +0100, Robert Jarzmik wrote: >> commit 24542257a3b987025d4b998ec2d15e556c98ad3f >> Author: Robert Jarzmik <robert.jarzmik@free.fr> >> Date: Fri Feb 20 19:36:43 2015 +0100 >> >> mtd: pxa3xx-nand: handle PIO in threaded interrupt >> >> >> And now I'm wondering: when does the completion get triggered? i.e.: >> >> complete(&info->cmd_complete); > >> It seems to me like you've short-circuited some of the IRQ handling >> code, so that the threaded handler is buggy. AIUI, if the completion >> event ever happens, it's actually happening *before* the full (threaded) >> handler is actually finished, since it occurs in pxa3xx_nand_irq(), >> before pxa3xx_nand_irq_thread() ever runs. Now, I'm not sure if that >> causes a real problem in practice, since you used IRQF_ONESHOT, but I >> would think that's also suspect. > > I think you're very right, this "goto NORMAL_IRQ_EXIT" creates a > short-cirtcuit. That makes me think that I should : > - add > static void pxa3xx_nand_data_finished(struct pxa3xx_nand_info *info) > { > unsigned int done; > > cmd_done = info->cs ? NDSR_CS1_CMDD : NDSR_CS0_CMDD; > nand_writel(info, NDSR, cmd_done); > complete(&inf0->cmd_complete); > } > > - in pxa3xx_nand_irq_thread(), I should add at the end: > pxa3xx_nand_data_finished(info); > > - in pxa3xx_nand_data_dma_irq(), I should add at the end: > pxa3xx_nand_data_finished(info); > > Ezequiel, would you have a look at that code snippet and tell me if I'm missing > something in the driver's structure ? > Although it seems Brian is right, I'm not so sure about it. As far as I can recall, the IRQ sequence is (please correct me if I'm wrong!): 1. Write command request (WRCMDREQ), the IRQ handler writes the command. 2. Read/write data request (RDDREQ | WRDREQ). The IRQ handler fires the threaded handler, which does data transfer. 3. Command done IRQ (CMDD), the IRQ handler completes the completion. I don't think data request and command done can be found simultaneously, so I don't think this is a real issue. Ideas? Regarding the fixed proposed up there, it seems wrong: the completion should be completed only after a command done IRQ is found, and not as the result of data transfer being finished.
Hi Robert, Ezequiel, and Brian, I have been working with Michael Wang on this issue and wanted to update you on our results as we think there is a wider issue to resolve here. I believe Ezequiel's analysis of the IRQ sequence is correct. The proposed patch from Brian is not needed, not does it resolve our issue. Further, we have debugged in more detail with kernel tracing and see that the problem occurs because nothing calls 'schedule()' in the kernel within the timeout period (200ms) to actually allow the IRQ bottom-half thread ((pxa3xx_nand_irq_thread()) to run. With the trace enabled we were able to see long delays between the IRQ thread being queued for run as a result of the return with IRQ_WAKE_THREAD in pxa3xx_nand_irq(), and a call to schedule() actually selecting the thread for execution. This delay was tied to whatever else was happening in our system during the boot up when this issue occurs. For instance, if a mutex got unlocked this would ultimately lead to a call to schedule() and our thread (pxa3xx_nand_irq_thread()) would run. If some file system ops happened schedule() would get called. These unrelated activities were required so that schedule() got called and the scheduler would let the bottom-half execute. In our tracing we saw the issue occur whenever the call to schedule() didn't occur before the timeout expired. In short, if we got lucky and something completely unrelated happened that led to a call to 'schedule()', then the issue didn't occur. If we got unlucky and nothing called schedule(), the issue was observed. We have enabled CONFIG_PREEMPT in our system to resolve this. This has the effect of leading to a triggering of 'schedule()' at the end of processing interrupts. This means that we now see a nice tight execution of pxa3xx_nand threaded IRQ such that we see all ops completing with less that 20ms delay. I wanted to highlight this to you because I think it shows that the change to a threaded IRQ is probably only safe if we can guarantee scheduling of the bottom-half thread within the time out period (200ms). I think this is not safe for systems with CONFIG_PREEMPT not configured. Or perhaps there is a better way to resolve this. Is this a deficiency in the Armada XP code? What do you think? Thanks, Hamish Martin On 01/27/2016 02:03 AM, Ezequiel Garcia wrote: > On 25 January 2016 at 17:48, Robert Jarzmik <robert.jarzmik@free.fr> wrote: >> Brian Norris <computersforpeace@gmail.com> writes: >> >>> Hi Robert, >>> >>> On Sun, Jan 17, 2016 at 12:53:06AM +0100, Robert Jarzmik wrote: >>> commit 24542257a3b987025d4b998ec2d15e556c98ad3f >>> Author: Robert Jarzmik <robert.jarzmik@free.fr> >>> Date: Fri Feb 20 19:36:43 2015 +0100 >>> >>> mtd: pxa3xx-nand: handle PIO in threaded interrupt >>> >>> >>> And now I'm wondering: when does the completion get triggered? i.e.: >>> >>> complete(&info->cmd_complete); >>> It seems to me like you've short-circuited some of the IRQ handling >>> code, so that the threaded handler is buggy. AIUI, if the completion >>> event ever happens, it's actually happening *before* the full (threaded) >>> handler is actually finished, since it occurs in pxa3xx_nand_irq(), >>> before pxa3xx_nand_irq_thread() ever runs. Now, I'm not sure if that >>> causes a real problem in practice, since you used IRQF_ONESHOT, but I >>> would think that's also suspect. >> I think you're very right, this "goto NORMAL_IRQ_EXIT" creates a >> short-cirtcuit. That makes me think that I should : >> - add >> static void pxa3xx_nand_data_finished(struct pxa3xx_nand_info *info) >> { >> unsigned int done; >> >> cmd_done =nfo->cs ? NDSR_CS1_CMDD : NDSR_CS0_CMDD; >> nand_writel(info, NDSR, cmd_done); >> complete(&inf0->cmd_complete); >> } >> >> - in pxa3xx_nand_irq_thread(), I should add at the end: >> pxa3xx_nand_data_finished(info); >> >> - in pxa3xx_nand_data_dma_irq(), I should add at the end: >> pxa3xx_nand_data_finished(info); >> >> Ezequiel, would you have a look at that code snippet and tell me if I'm missing >> something in the driver's structure ? >> > Although it seems Brian is right, I'm not so sure about it. As far as > I can recall, the IRQ sequence is (please correct me if I'm wrong!): > > 1. Write command request (WRCMDREQ), the IRQ handler writes the command. > 2. Read/write data request (RDDREQ | WRDREQ). The IRQ handler fires > the threaded handler, which does data transfer. > 3. Command done IRQ (CMDD), the IRQ handler completes the completion. > > I don't think data request and command done can be found > simultaneously, so I don't think this is a real issue. Ideas? > > Regarding the fixed proposed up there, it seems wrong: the completion > should be completed only after a command done IRQ is found, and not as > the result of data transfer being finished.
+Richard, Boris and Thomas On 1 March 2016 at 19:17, Hamish Martin <Hamish.Martin@alliedtelesis.co.nz> wrote: > Hi Robert, Ezequiel, and Brian, > > I have been working with Michael Wang on this issue and wanted to update > you on our results as we think there is a wider issue to resolve here. > > I believe Ezequiel's analysis of the IRQ sequence is correct. The > proposed patch from Brian is not needed, not does it resolve our issue. > > Further, we have debugged in more detail with kernel tracing and see > that the problem occurs because nothing calls 'schedule()' in the kernel > within the timeout period (200ms) to actually allow the IRQ bottom-half > thread ((pxa3xx_nand_irq_thread()) to run. > > With the trace enabled we were able to see long delays between the IRQ > thread being queued for run as a result of the return with > IRQ_WAKE_THREAD in pxa3xx_nand_irq(), and a call to schedule() actually > selecting the thread for execution. This delay was tied to whatever else > was happening in our system during the boot up when this issue occurs. > For instance, if a mutex got unlocked this would ultimately lead to a > call to schedule() and our thread (pxa3xx_nand_irq_thread()) would run. > If some file system ops happened schedule() would get called. These > unrelated activities were required so that schedule() got called and the > scheduler would let the bottom-half execute. > In our tracing we saw the issue occur whenever the call to schedule() > didn't occur before the timeout expired. In short, if we got lucky and > something completely unrelated happened that led to a call to > 'schedule()', then the issue didn't occur. If we got unlucky and nothing > called schedule(), the issue was observed. > > We have enabled CONFIG_PREEMPT in our system to resolve this. This has > the effect of leading to a triggering of 'schedule()' at the end of > processing interrupts. This means that we now see a nice tight execution > of pxa3xx_nand threaded IRQ such that we see all ops completing with > less that 20ms delay. > > I wanted to highlight this to you because I think it shows that the > change to a threaded IRQ is probably only safe if we can guarantee > scheduling of the bottom-half thread within the time out period (200ms). > I think this is not safe for systems with CONFIG_PREEMPT not configured. > Or perhaps there is a better way to resolve this. Is this a deficiency > in the Armada XP code? > > What do you think? > Thanks a lot for updating us. Richard, Boris and I have discussed about this on IRC. We came to the following conclusions: 1. There's no way to guarantee that the thread will be scheduled soon enough to always do the data transfer in time. Using CONFIG_PREEMPT could prevent a timeout in many (most?) cases, but it's not guaranteed to work. 2. The pxa3xx-nand driver is poorly designed, and it shouldn't do any data transfer in the IRQ (threaded or not) handler. Instead, this should be done in {read,write}_buf, i.e. in the context of the calling process that asks data to be read/write. This is potentially a big rework. 3. Richard proposed to get rid of the timeout (using wait_for_completion_interruptible instead?). I'm wondering if that could avoid these kind of issues (false timeouts), as a less invasive solution, until someone steps up to rework the driver. How does it sound?
Hi Ezequiel, I'm glad my analysis was correct and we more fully understand the problem now. CONFIG_PREEMPT seems to work for us now, but it does seem like the wrong fix, and if you guys think it will not guarantee preventing the issue then we'd rather back that change out. I had contemplated using wait_for_completion_interruptible() but was a bit unsure if it was safe. Do you have a proposed patch? We would be happy to apply it to our system, turn off CONFIG_PREEMPT, and see how it goes. Out issue is highly reproducible so I think it would be a good first test for a change? Thanks, Hamish M. On 03/04/2016 08:24 AM, Ezequiel Garcia wrote: > +Richard, Boris and Thomas > > On 1 March 2016 at 19:17, Hamish Martin > <Hamish.Martin@alliedtelesis.co.nz> wrote: >> Hi Robert, Ezequiel, and Brian, >> >> I have been working with Michael Wang on this issue and wanted to update >> you on our results as we think there is a wider issue to resolve here. >> >> I believe Ezequiel's analysis of the IRQ sequence is correct. The >> proposed patch from Brian is not needed, not does it resolve our issue. >> >> Further, we have debugged in more detail with kernel tracing and see >> that the problem occurs because nothing calls 'schedule()' in the kernel >> within the timeout period (200ms) to actually allow the IRQ bottom-half >> thread ((pxa3xx_nand_irq_thread()) to run. >> >> With the trace enabled we were able to see long delays between the IRQ >> thread being queued for run as a result of the return with >> IRQ_WAKE_THREAD in pxa3xx_nand_irq(), and a call to schedule() actually >> selecting the thread for execution. This delay was tied to whatever else >> was happening in our system during the boot up when this issue occurs. >> For instance, if a mutex got unlocked this would ultimately lead to a >> call to schedule() and our thread (pxa3xx_nand_irq_thread()) would run. >> If some file system ops happened schedule() would get called. These >> unrelated activities were required so that schedule() got called and the >> scheduler would let the bottom-half execute. >> In our tracing we saw the issue occur whenever the call to schedule() >> didn't occur before the timeout expired. In short, if we got lucky and >> something completely unrelated happened that led to a call to >> 'schedule()', then the issue didn't occur. If we got unlucky and nothing >> called schedule(), the issue was observed. >> >> We have enabled CONFIG_PREEMPT in our system to resolve this. This has >> the effect of leading to a triggering of 'schedule()' at the end of >> processing interrupts. This means that we now see a nice tight execution >> of pxa3xx_nand threaded IRQ such that we see all ops completing with >> less that 20ms delay. >> >> I wanted to highlight this to you because I think it shows that the >> change to a threaded IRQ is probably only safe if we can guarantee >> scheduling of the bottom-half thread within the time out period (200ms). >> I think this is not safe for systems with CONFIG_PREEMPT not configured. >> Or perhaps there is a better way to resolve this. Is this a deficiency >> in the Armada XP code? >> >> What do you think? >> > Thanks a lot for updating us. Richard, Boris and I have > discussed about this on IRC. > > We came to the following conclusions: > > 1. There's no way to guarantee that the thread will be scheduled > soon enough to always do the data transfer in time. > > Using CONFIG_PREEMPT could prevent a timeout in many (most?) > cases, but it's not guaranteed to work. > > 2. The pxa3xx-nand driver is poorly designed, and it shouldn't > do any data transfer in the IRQ (threaded or not) handler. > > Instead, this should be done in {read,write}_buf, i.e. in the > context of the calling process that asks data to be read/write. > This is potentially a big rework. > > 3. Richard proposed to get rid of the timeout > (using wait_for_completion_interruptible instead?). > > I'm wondering if that could avoid these kind of issues (false > timeouts), as a less invasive solution, until someone steps > up to rework the driver. > > How does it sound?
Am 03.03.2016 um 20:24 schrieb Ezequiel Garcia: > +Richard, Boris and Thomas > > On 1 March 2016 at 19:17, Hamish Martin > <Hamish.Martin@alliedtelesis.co.nz> wrote: >> Hi Robert, Ezequiel, and Brian, >> >> I have been working with Michael Wang on this issue and wanted to update >> you on our results as we think there is a wider issue to resolve here. >> >> I believe Ezequiel's analysis of the IRQ sequence is correct. The >> proposed patch from Brian is not needed, not does it resolve our issue. >> >> Further, we have debugged in more detail with kernel tracing and see >> that the problem occurs because nothing calls 'schedule()' in the kernel >> within the timeout period (200ms) to actually allow the IRQ bottom-half >> thread ((pxa3xx_nand_irq_thread()) to run. >> >> With the trace enabled we were able to see long delays between the IRQ >> thread being queued for run as a result of the return with >> IRQ_WAKE_THREAD in pxa3xx_nand_irq(), and a call to schedule() actually >> selecting the thread for execution. This delay was tied to whatever else >> was happening in our system during the boot up when this issue occurs. >> For instance, if a mutex got unlocked this would ultimately lead to a >> call to schedule() and our thread (pxa3xx_nand_irq_thread()) would run. >> If some file system ops happened schedule() would get called. These >> unrelated activities were required so that schedule() got called and the >> scheduler would let the bottom-half execute. >> In our tracing we saw the issue occur whenever the call to schedule() >> didn't occur before the timeout expired. In short, if we got lucky and >> something completely unrelated happened that led to a call to >> 'schedule()', then the issue didn't occur. If we got unlucky and nothing >> called schedule(), the issue was observed. >> >> We have enabled CONFIG_PREEMPT in our system to resolve this. This has >> the effect of leading to a triggering of 'schedule()' at the end of >> processing interrupts. This means that we now see a nice tight execution >> of pxa3xx_nand threaded IRQ such that we see all ops completing with >> less that 20ms delay. >> >> I wanted to highlight this to you because I think it shows that the >> change to a threaded IRQ is probably only safe if we can guarantee >> scheduling of the bottom-half thread within the time out period (200ms). >> I think this is not safe for systems with CONFIG_PREEMPT not configured. >> Or perhaps there is a better way to resolve this. Is this a deficiency >> in the Armada XP code? >> >> What do you think? >> > > Thanks a lot for updating us. Richard, Boris and I have > discussed about this on IRC. > > We came to the following conclusions: > > 1. There's no way to guarantee that the thread will be scheduled > soon enough to always do the data transfer in time. > > Using CONFIG_PREEMPT could prevent a timeout in many (most?) > cases, but it's not guaranteed to work. > > 2. The pxa3xx-nand driver is poorly designed, and it shouldn't > do any data transfer in the IRQ (threaded or not) handler. > > Instead, this should be done in {read,write}_buf, i.e. in the > context of the calling process that asks data to be read/write. > This is potentially a big rework. > > 3. Richard proposed to get rid of the timeout > (using wait_for_completion_interruptible instead?). Getting rid of the timeout can work but definitely needs more clarification. Before commit 24542257a3b987025d4b998ec2d15e556c98ad3f it made sense but now the thread can be delayed for unknown time. Thanks, //richard
On 3 March 2016 at 17:16, Hamish Martin <Hamish.Martin@alliedtelesis.co.nz> wrote: > Hi Ezequiel, > > I'm glad my analysis was correct and we more fully understand the > problem now. CONFIG_PREEMPT seems to work for us now, but it does seem > like the wrong fix, and if you guys think it will not guarantee > preventing the issue then we'd rather back that change out. > Do you have any good reason for NOT enabling CONFIG_PREEMPT? I've had very bad experiences on embedded systems when not using CONFIG_PREEMPT, and came to the conclusion that enable full preemption, unless there's a good reason not to. Enabling CONFIG_PREEMPT would result in slightly lower throughput, but maximum latency will be greatly reduced. For instance, in a kernel without preemption, a UBI static volume check (which happens on the first UBI static volume open call), can take several seconds. > I had contemplated using wait_for_completion_interruptible() but was a > bit unsure if it was safe. Do you have a proposed patch? We would be > happy to apply it to our system, turn off CONFIG_PREEMPT, and see how it > goes. Out issue is highly reproducible so I think it would be a good > first test for a change? > Sure, I can try to cook a patch for you.
Hi Ezequiel, On 03/04/2016 01:03 PM, Ezequiel Garcia wrote: > On 3 March 2016 at 17:16, Hamish Martin > <Hamish.Martin@alliedtelesis.co.nz> wrote: >> Hi Ezequiel, >> >> I'm glad my analysis was correct and we more fully understand the >> problem now. CONFIG_PREEMPT seems to work for us now, but it does seem >> like the wrong fix, and if you guys think it will not guarantee >> preventing the issue then we'd rather back that change out. >> > Do you have any good reason for NOT enabling CONFIG_PREEMPT? > > I've had very bad experiences on embedded systems when not > using CONFIG_PREEMPT, and came to the conclusion that > enable full preemption, unless there's a good reason not to. > > Enabling CONFIG_PREEMPT would result in slightly lower throughput, > but maximum latency will be greatly reduced. > > For instance, in a kernel without preemption, a UBI static volume check > (which happens on the first UBI static volume open call), can take > several seconds. We don't have a good reason, it is mainly an historic artifact. We are happy to go with that as a fix and we are investigating it for other platforms too. I think it is an oversight that hasn't been given the thought it should. I think we still need to consider operation of the driver without CONFIG_PREEMPT enabled. > >> I had contemplated using wait_for_completion_interruptible() but was a >> bit unsure if it was safe. Do you have a proposed patch? We would be >> happy to apply it to our system, turn off CONFIG_PREEMPT, and see how it >> goes. Out issue is highly reproducible so I think it would be a good >> first test for a change? >> > Sure, I can try to cook a patch for you. Thanks for your help with this guys. Send me the patch when you have one you want me to test out for you. Cheers, Hamish M.
diff --git a/drivers/mtd/nand/pxa3xx_nand.c b/drivers/mtd/nand/pxa3xx_nand.c index e453ae9a17fa..0845d09e14c1 100644 --- a/drivers/mtd/nand/pxa3xx_nand.c +++ b/drivers/mtd/nand/pxa3xx_nand.c @@ -136,11 +136,23 @@ #define READ_ID_BYTES 7 /* macros for registers read/write */ -#define nand_writel(info, off, val) \ - writel_relaxed((val), (info)->mmio_base + (off)) - -#define nand_readl(info, off) \ - readl_relaxed((info)->mmio_base + (off)) +#define nand_writel(info, off, val) \ + do { \ + dev_vdbg(&info->pdev->dev, \ + "%s():%d nand_writel(0x%x, 0x%04x)\n", \ + __func__, __LINE__, (val), (off)); \ + writel_relaxed((val), (info)->mmio_base + (off)); \ + } while (0) + +#define nand_readl(info, off) \ + ({ \ + unsigned int _v; \ + _v = readl_relaxed((info)->mmio_base + (off)); \ + dev_vdbg(&info->pdev->dev, \ + "%s():%d nand_readl(0x%04x): 0x%x\n", \ + __func__, __LINE__, (off), _v); \ + _v; \ + }) /* error code and state */ enum {