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

[Takashi Iwai <tiwai@suse.de>]

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.


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