From mboxrd@z Thu Jan 1 00:00:00 1970 From: vinod.koul@intel.com (Vinod Koul) Date: Wed, 12 Jun 2013 13:24:51 +0530 Subject: [BUG ?] ARM: imx27: dmaengine: imx-dma: SD-Card: copy hangs forever In-Reply-To: <1370813946.5019.254.camel@mars> References: <1330676927-7330-1-git-send-email-javier.martin@vista-silicon.com> <1370813946.5019.254.camel@mars> Message-ID: <20130612075451.GJ4107@intel.com> To: linux-arm-kernel@lists.infradead.org List-Id: linux-arm-kernel.lists.infradead.org On Sun, Jun 09, 2013 at 11:39:06PM +0200, Christoph Fritz wrote: > Hi, Thanks for the bug report, we are discussing this issue in [1] -- ~Vinod [1]: http://www.spinics.net/lists/arm-kernel/msg249815.html > > an imx27-board (pca100) hits a DEADLOCK with current stable Kernel > 3.4.47 while adding a SD-Card: > > ================================= > [ INFO: inconsistent lock state ] > 3.4.47-00059-ga5527fe #213 Not tainted > --------------------------------- > inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage. > swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes: > (&(&imxdma->lock)->rlock){?.-...}, at: [] imxdma_tasklet+0x1c/0x138 > {IN-HARDIRQ-W} state was registered at: > [] __lock_acquire+0x97c/0x1900 > [] lock_acquire+0x64/0x78 > [] _raw_spin_lock+0x40/0x50 > [] dma_irq_handler+0xc8/0x358 > [] handle_irq_event_percpu+0x50/0x1c8 > [] handle_irq_event+0x3c/0x5c > [] handle_level_irq+0x8c/0xd8 > [] generic_handle_irq+0x34/0x48 > [] handle_IRQ+0x30/0x84 > [] avic_handle_irq+0x2c/0x4c > [] __irq_svc+0x44/0x74 > [] default_idle+0x40/0x48 > [] cpu_idle+0x6c/0xe8 > [] start_kernel+0x264/0x2a4 > irq event stamp: 20208 > hardirqs last enabled at (20208): [] tasklet_action+0x30/0xe0 > hardirqs last disabled at (20207): [] tasklet_action+0x18/0xe0 > softirqs last enabled at (20202): [] irq_enter+0x6c/0x70 > softirqs last disabled at (20203): [] irq_exit+0x9c/0xa8 > > other info that might help us debug this: > Possible unsafe locking scenario: > > CPU0 > ---- > lock(&(&imxdma->lock)->rlock); > > lock(&(&imxdma->lock)->rlock); > > *** DEADLOCK *** > > no locks held by swapper/0. > > stack backtrace: > [] (unwind_backtrace+0x0/0xf0) from [] (print_usage_bug.part.25+0x208/0x268) > [] (print_usage_bug.part.25+0x208/0x268) from [] (mark_lock+0x4fc/0x620) > [] (mark_lock+0x4fc/0x620) from [] (__lock_acquire+0x880/0x1900) > [] (__lock_acquire+0x880/0x1900) from [] (lock_acquire+0x64/0x78) > [] (lock_acquire+0x64/0x78) from [] (_raw_spin_lock+0x40/0x50) > [] (_raw_spin_lock+0x40/0x50) from [] (imxdma_tasklet+0x1c/0x138) > [] (imxdma_tasklet+0x1c/0x138) from [] (tasklet_action+0x78/0xe0) > [] (tasklet_action+0x78/0xe0) from [] (__do_softirq+0xc8/0x17c) > [] (__do_softirq+0xc8/0x17c) from [] (irq_exit+0x9c/0xa8) > [] (irq_exit+0x9c/0xa8) from [] (handle_IRQ+0x34/0x84) > [] (handle_IRQ+0x34/0x84) from [] (avic_handle_irq+0x2c/0x4c) > [] (avic_handle_irq+0x2c/0x4c) from [] (__irq_svc+0x44/0x74) > Exception stack(0xc0549f60 to 0xc0549fa8) > 9f60: 00000001 00000001 00000000 20000013 c0548000 c058dae8 c0554118 c0548000 > 9f80: c0b96500 41069264 a053ff1c 00000000 600000d3 c0549fa8 c0050664 c00098c4 > 9fa0: 20000013 ffffffff > [] (__irq_svc+0x44/0x74) from [] (default_idle+0x40/0x48) > [] (default_idle+0x40/0x48) from [] (cpu_idle+0x6c/0xe8) > [] (cpu_idle+0x6c/0xe8) from [] (start_kernel+0x264/0x2a4) > > > This is also curious and may be related: > > When CONFIG_IMX_DMA is disabled, copying a file to SD-Card is relatively > fast: > $ dd if=/dev/zero of=/mnt/test count=102400 bs=1K > 102400+0 records in > 102400+0 records out > 104857600 bytes (105 MB) copied, 33.573 s, 3.1 MB/s > > When CONFIG_IMX_DMA is enabled, copying a file to SD-Card is > very slow for small files and takes forever for files roughly bigger > than 1.0MB: > > $ dd if=/dev/zero of=/mnt/test count=100000 bs=10 > 100000+0 records in > 100000+0 records out > 1000000 bytes (1.0 MB) copied, 18.3172 s, 54.6 kB/s > > $ dd if=/dev/zero of=/mnt/performance_test.102400KB count=100000 bs=20 > > INFO: task mmcqd/0:592 blocked for more than 30 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > mmcqd/0 D c03bbf14 0 592 2 0x00000000 > [] (__schedule+0x220/0x590) from [] (schedule_timeout+0x154/0x1bc) > [] (schedule_timeout+0x154/0x1bc) from [] (wait_for_common+0xac/0x150) > [] (wait_for_common+0xac/0x150) from [] (mmc_wait_for_req_done+0x1c/0x74) > [] (mmc_wait_for_req_done+0x1c/0x74) from [] (mmc_start_req+0x54/0x118) > [] (mmc_start_req+0x54/0x118) from [] (mmc_blk_issue_rw_rq+0x64/0x380) > [] (mmc_blk_issue_rw_rq+0x64/0x380) from [] (mmc_blk_issue_rq+0x1b0/0x484) > [] (mmc_blk_issue_rq+0x1b0/0x484) from [] (mmc_queue_thread+0x58/0xf4) > [] (mmc_queue_thread+0x58/0xf4) from [] (kthread+0x84/0x90) > [] (kthread+0x84/0x90) from [] (kernel_thread_exit+0x0/0x8) > no locks held by mmcqd/0/592. > INFO: task kjournald:595 blocked for more than 30 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > kjournald D c03bbf14 0 595 2 0x00000000 > [] (__schedule+0x220/0x590) from [] (io_schedule+0x60/0x94) > [] (io_schedule+0x60/0x94) from [] (sleep_on_buffer+0x8/0x10) > [] (sleep_on_buffer+0x8/0x10) from [] (__wait_on_bit+0x74/0xb8) > [] (__wait_on_bit+0x74/0xb8) from [] (out_of_line_wait_on_bit+0x64/0x70) > [] (out_of_line_wait_on_bit+0x64/0x70) from [] (journal_commit_transaction+0x6a0/0x14ac) > [] (journal_commit_transaction+0x6a0/0x14ac) from [] (kjournald+0xc0/0x25c) > [] (kjournald+0xc0/0x25c) from [] (kthread+0x84/0x90) > [] (kthread+0x84/0x90) from [] (kernel_thread_exit+0x0/0x8) > no locks held by kjournald/595. > INFO: task dd:601 blocked for more than 30 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > dd D c03bbf14 0 601 586 0x00000000 > [] (__schedule+0x220/0x590) from [] (io_schedule+0x60/0x94) > [] (io_schedule+0x60/0x94) from [] (sleep_on_page+0x8/0x10) > [] (sleep_on_page+0x8/0x10) from [] (__wait_on_bit+0x74/0xb8) > [] (__wait_on_bit+0x74/0xb8) from [] (wait_on_page_bit+0xbc/0xd0) > [] (wait_on_page_bit+0xbc/0xd0) from [] (grab_cache_page_write_begin+0x98/0xc4) > [] (grab_cache_page_write_begin+0x98/0xc4) from [] (ext3_write_begin+0x74/0x208) > [] (ext3_write_begin+0x74/0x208) from [] (generic_file_buffered_write+0x19c/0x260) > [] (generic_file_buffered_write+0x19c/0x260) from [] (__generic_file_aio_write+0x234/0x490) > [] (__generic_file_aio_write+0x234/0x490) from [] (generic_file_aio_write+0x60/0xcc) > [] (generic_file_aio_write+0x60/0xcc) from [] (do_sync_write+0xa8/0xdc) > [] (do_sync_write+0xa8/0xdc) from [] (vfs_write+0xa8/0x138) > [] (vfs_write+0xa8/0x138) from [] (sys_write+0x40/0x6c) > [] (sys_write+0x40/0x6c) from [] (ret_fast_syscall+0x0/0x38) > 1 lock held by dd/601: > #0: (&sb->s_type->i_mutex_key#12){+.+.+.}, at: [] generic_file_aio_write+0x44/0xcc > INFO: task mmcqd/0:592 blocked for more than 30 seconds. > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > > > With git bisect this issue was boiled down to this commit: > > | commit 9e15db7ce949e9f2d8bb6ce32a74212a4f662370 > | Author: Javier Martin > | Date: Fri Mar 2 09:28:47 2012 +0100 > | > | dmaengine: Add support for multiple descriptors for imx-dma. > | > | dmaengine specifies the possibility that several descriptors > | can be queued for transfer. It also indicates that tasklets > | must be used for DMA callbacks. > > I'm not sure if it only triggers a side effect. Any ideas? > > Thanks > -- Christoph > --