Re: [Linux-cachefs] CacheFiles: Readpage failed on backing file

[Takashi Iwai <tiwai@suse.de>]

At Mon, 22 Jun 2009 16:54:39 +0200,
I wrote:
> 
> At Mon, 22 Jun 2009 09:58:18 +0100,
> David Howells wrote:
> > 
> > Christian Kujau <lists@nerdbynature.de> wrote:
> > 
> > > [  399.332346]  [<ffffffff810da03a>] ? ext3_truncate+0x26a/0x9e0
> > 
> > Can you try the attached patch, please?
> 
> I've got similar messages with the very latest Linus git tree,
> and tried you patch, but still gives the same error.
> 
> The log is below.  FWIW, it's on ext3.

The bug is still present on 2.6.31-rc2.


Takashi


> 
> 
> thanks,
> 
> Takashi
> 
> ===
> 
> FS-Cache: Netfs 'nfs' registered for caching
> 
> =======================================================
> [ INFO: possible circular locking dependency detected ]
> 2.6.30-test #7
> -------------------------------------------------------
> swapper/0 is trying to acquire lock:
>  (&cwq->lock){-.-...}, at: [<c01519f3>] __queue_work+0x1f/0x4e
> 
> but task is already holding lock:
>  (&q->lock){-.-.-.}, at: [<c012cc9c>] __wake_up+0x26/0x5c
> 
> which lock already depends on the new lock.
> 
> 
> the existing dependency chain (in reverse order) is:
> 
> -> #1 (&q->lock){-.-.-.}:
>        [<c0168746>] __lock_acquire+0xfd6/0x12d5
>        [<c0168afc>] lock_acquire+0xb7/0xeb
>        [<c03d1249>] _spin_lock_irqsave+0x3d/0x5e
>        [<c012cc9c>] __wake_up+0x26/0x5c
>        [<c0151053>] insert_work+0x7b/0x95
>        [<c0151a02>] __queue_work+0x2e/0x4e
>        [<c0151a5e>] delayed_work_timer_fn+0x3c/0x4f
>        [<c014925b>] run_timer_softirq+0x180/0x206
>        [<c01445cb>] __do_softirq+0xc3/0x18d
>        [<c01446d9>] do_softirq+0x44/0x7a
>        [<c0144823>] irq_exit+0x43/0x87
>        [<c0117cbd>] smp_apic_timer_interrupt+0x7c/0x9b
>        [<c0103956>] apic_timer_interrupt+0x36/0x40
>        [<c0101ed0>] cpu_idle+0xa2/0xbe
>        [<c03bcef6>] rest_init+0x66/0x79
>        [<c0537a98>] start_kernel+0x396/0x3ae
>        [<c053707f>] __init_begin+0x7f/0x98
>        [<ffffffff>] 0xffffffff
> 
> -> #0 (&cwq->lock){-.-...}:
>        [<c0168496>] __lock_acquire+0xd26/0x12d5
>        [<c0168afc>] lock_acquire+0xb7/0xeb
>        [<c03d1249>] _spin_lock_irqsave+0x3d/0x5e
>        [<c01519f3>] __queue_work+0x1f/0x4e
>        [<c0151ab9>] queue_work_on+0x48/0x63
>        [<c0151c1d>] queue_work+0x23/0x38
>        [<c0151c50>] schedule_work+0x1e/0x31
>        [<f7f9ed69>] fscache_enqueue_operation+0xc5/0x102 [fscache]
>        [<f80b6142>] cachefiles_read_waiter+0xb3/0xcd [cachefiles]
>        [<c01292ae>] __wake_up_common+0x4c/0x85
>        [<c012ccae>] __wake_up+0x38/0x5c
>        [<c015568f>] __wake_up_bit+0x34/0x4b
>        [<c01ad459>] unlock_page+0x55/0x6a
>        [<c020fb6b>] mpage_end_io_read+0x4e/0x71
>        [<c020a4da>] bio_endio+0x31/0x44
>        [<c027759c>] req_bio_endio+0xab/0xde
>        [<c027774c>] blk_update_request+0x17d/0x321
>        [<c0277912>] blk_update_bidi_request+0x22/0x62
>        [<c02792c4>] blk_end_bidi_request+0x25/0x6e
>        [<c0279371>] blk_end_request+0x1a/0x30
>        [<f82811da>] scsi_io_completion+0x193/0x3bb [scsi_mod]
>        [<f827a888>] scsi_finish_command+0xd9/0xf2 [scsi_mod]
>        [<f8281522>] scsi_softirq_done+0xf4/0x10d [scsi_mod]
>        [<c027fcdf>] blk_done_softirq+0x6f/0x8e
>        [<c01445cb>] __do_softirq+0xc3/0x18d
>        [<c01446d9>] do_softirq+0x44/0x7a
>        [<c0144823>] irq_exit+0x43/0x87
>        [<c01049fd>] do_IRQ+0x8d/0xb2
>        [<c0103595>] common_interrupt+0x35/0x40
>        [<c0101ed0>] cpu_idle+0xa2/0xbe
>        [<c03bcef6>] rest_init+0x66/0x79
>        [<c0537a98>] start_kernel+0x396/0x3ae
>        [<c053707f>] __init_begin+0x7f/0x98
>        [<ffffffff>] 0xffffffff
> 
> other info that might help us debug this:
> 
> 1 lock held by swapper/0:
>  #0:  (&q->lock){-.-.-.}, at: [<c012cc9c>] __wake_up+0x26/0x5c
> 
> stack backtrace:
> Pid: 0, comm: swapper Not tainted 2.6.30-test #7
> Call Trace:
>  [<c03cde42>] ? printk+0x1d/0x33
>  [<c0167349>] print_circular_bug_tail+0xaf/0xcb
>  [<c0168496>] __lock_acquire+0xd26/0x12d5
>  [<c01519f3>] ? __queue_work+0x1f/0x4e
>  [<c0168afc>] lock_acquire+0xb7/0xeb
>  [<c01519f3>] ? __queue_work+0x1f/0x4e
>  [<c01519f3>] ? __queue_work+0x1f/0x4e
>  [<c03d1249>] _spin_lock_irqsave+0x3d/0x5e
>  [<c01519f3>] ? __queue_work+0x1f/0x4e
>  [<c01519f3>] __queue_work+0x1f/0x4e
>  [<c0151ab9>] queue_work_on+0x48/0x63
>  [<c0151c1d>] queue_work+0x23/0x38
>  [<c0151c50>] schedule_work+0x1e/0x31
>  [<f7f9ed69>] fscache_enqueue_operation+0xc5/0x102 [fscache]
>  [<f80b6142>] cachefiles_read_waiter+0xb3/0xcd [cachefiles]
>  [<c01292ae>] __wake_up_common+0x4c/0x85
>  [<c012ccae>] __wake_up+0x38/0x5c
>  [<c015568f>] __wake_up_bit+0x34/0x4b
>  [<c01ad459>] unlock_page+0x55/0x6a
>  [<c020fb6b>] mpage_end_io_read+0x4e/0x71
>  [<c020a4da>] bio_endio+0x31/0x44
>  [<c027759c>] req_bio_endio+0xab/0xde
>  [<c027774c>] blk_update_request+0x17d/0x321
>  [<c0277912>] blk_update_bidi_request+0x22/0x62
>  [<c02792c4>] blk_end_bidi_request+0x25/0x6e
>  [<c0279371>] blk_end_request+0x1a/0x30
>  [<f82811da>] scsi_io_completion+0x193/0x3bb [scsi_mod]
>  [<c0166b5b>] ? trace_hardirqs_on+0x19/0x2c
>  [<f8280f43>] ? scsi_device_unbusy+0x92/0xaa [scsi_mod]
>  [<f827a888>] scsi_finish_command+0xd9/0xf2 [scsi_mod]
>  [<f8281522>] scsi_softirq_done+0xf4/0x10d [scsi_mod]
>  [<c027fcdf>] blk_done_softirq+0x6f/0x8e
>  [<c01445cb>] __do_softirq+0xc3/0x18d
>  [<c01446d9>] do_softirq+0x44/0x7a
>  [<c0144823>] irq_exit+0x43/0x87
>  [<c01049fd>] do_IRQ+0x8d/0xb2
>  [<c0103595>] common_interrupt+0x35/0x40
>  [<c0109860>] ? mwait_idle+0x98/0xec
>  [<c0101ed0>] cpu_idle+0xa2/0xbe
>  [<c03bcef6>] rest_init+0x66/0x79
>  [<c0537a98>] start_kernel+0x396/0x3ae
>  [<c053707f>] __init_begin+0x7f/0x98
> Pid: 2282, comm: kslowd Not tainted 2.6.30-test #7
> Call Trace:
>  [<f80b60e9>] cachefiles_read_waiter+0x5a/0xcd [cachefiles]
>  [<c01292ae>] __wake_up_common+0x4c/0x85
>  [<c012ccae>] __wake_up+0x38/0x5c
>  [<c015568f>] __wake_up_bit+0x34/0x4b
>  [<c01ad459>] unlock_page+0x55/0x6a
>  [<f8b3de99>] ext3_truncate+0x40f/0x79d [ext3]
>  [<c0166b5b>] ? trace_hardirqs_on+0x19/0x2c
>  [<c01c50d6>] ? vmtruncate+0xe3/0x12e
>  [<c01c50ec>] vmtruncate+0xf9/0x12e
>  [<c01fa209>] inode_setattr+0x67/0x149
>  [<f8b3b719>] ext3_setattr+0x170/0x1c6 [ext3]
>  [<c01fa463>] notify_change+0x178/0x2c9
>  [<c03cf97e>] ? mutex_lock_nested+0x259/0x272
>  [<f80b367d>] cachefiles_attr_changed+0x16f/0x1ef [cachefiles]
>  [<f80b367d>] ? cachefiles_attr_changed+0x16f/0x1ef [cachefiles]
>  [<f80b3cb9>] cachefiles_lookup_object+0x92/0xc1 [cachefiles]
>  [<f7f9e235>] fscache_lookup_object+0xe9/0x10d [fscache]
>  [<f7f9e6e4>] fscache_object_slow_work_execute+0x1b4/0x65e [fscache]
>  [<c0166b5b>] ? trace_hardirqs_on+0x19/0x2c
>  [<c01a64a9>] slow_work_thread+0x25a/0x435
>  [<c01556e3>] ? autoremove_wake_function+0x0/0x50
>  [<c01a624f>] ? slow_work_thread+0x0/0x435
>  [<c01553b9>] kthread+0x71/0x76
>  [<c0155348>] ? kthread+0x0/0x76
>  [<c0103be7>] kernel_thread_helper+0x7/0x10
> CacheFiles: I/O Error: Readpage failed on backing file 10000810
> FS-Cache: Cache cachefiles stopped due to I/O error
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>