CacheFiles: Readpage failed on backing file

CacheFiles: Readpage failed on backing file

[Christian Kujau]

Hi there,

excited that the cachefiles made it into mainline, I've mounted an NFS 
share with "-o fsc". After a clean reboot, I only need to read some files 
off the NFS mount to get the following trace:

[  399.332262] Pid: 709, comm: kslowd Tainted: G        W  2.6.30 #1
[  399.332275] Call Trace:
[  399.332288]  [<ffffffff811e2e5b>] ? __wait_on_bit+0x6b/0x80
[  399.332301]  [<ffffffffa00c67b6>] ? cachefiles_read_waiter+0x96/0xe0 [cachefiles]
[  399.332314]  [<ffffffff8100dc70>] ? check_events+0x12/0x22
[  399.332322]  [<ffffffff81028100>] ? __wake_up_common+0x50/0x80
[  399.332330]  [<ffffffff8102814c>] ? __wake_up+0x1c/0x30
[  399.332338]  [<ffffffff81040a33>] ? __wake_up_bit+0x23/0x30
[  399.332346]  [<ffffffff810da03a>] ? ext3_truncate+0x26a/0x9e0
[  399.332354]  [<ffffffff8100dc0c>] ? xen_irq_enable_direct+0xc/0x13
[  399.332362]  [<ffffffff810e943a>] ? journal_stop+0x17a/0x240
[  399.332370]  [<ffffffff8100d5d9>] ? xen_force_evtchn_callback+0x9/0x10
[  399.332377]  [<ffffffff8100dc70>] ? check_events+0x12/0x22
[  399.332385]  [<ffffffff8106cbf5>] ? vmtruncate+0xa5/0x110
[  399.332393]  [<ffffffff81098b0e>] ? inode_setattr+0x2e/0x170
[  399.332400]  [<ffffffff810d735f>] ? ext3_setattr+0xff/0x230
[  399.332407]  [<ffffffff81098d5e>] ? notify_change+0x10e/0x350
[  399.332414]  [<ffffffff8100dc5d>] ? xen_restore_fl_direct_end+0x0/0x1
[  399.332424]  [<ffffffffa00c35ec>] ? cachefiles_attr_changed+0xec/0x190 [cachefiles]
[  399.332434]  [<ffffffffa00c3caf>] ? cachefiles_lookup_object+0x5f/0x110 [cachefiles]
[  399.332450]  [<ffffffffa005a1c0>] ? fscache_lookup_object+0x80/0x150 [fscache]
[  399.332461]  [<ffffffffa005aabe>] ? fscache_object_slow_work_execute+0x58e/0x670 [fscache]
[  399.332472]  [<ffffffff81057b2d>] ? slow_work_thread+0x2ed/0x430
[  399.332480]  [<ffffffff81040a80>] ? autoremove_wake_function+0x0/0x30
[  399.332488]  [<ffffffff81057840>] ? slow_work_thread+0x0/0x430
[  399.332495]  [<ffffffff810405f6>] ? kthread+0x96/0xa0
[  399.332502]  [<ffffffff8102afcd>] ? T.831+0x2d/0x80
[  399.332510]  [<ffffffff81010a8a>] ? child_rip+0xa/0x20
[  399.332517]  [<ffffffff810105db>] ? retint_restore_args+0x5/0x6
[  399.332525]  [<ffffffff811846a0>] ? datagram_poll+0x0/0xe0
[  399.332533]  [<ffffffff811846a0>] ? datagram_poll+0x0/0xe0
[  399.332539]  [<ffffffff81010a80>] ? child_rip+0x0/0x20
[  399.332608] CacheFiles: I/O Error: Readpage failed on backing file 4000000000000810
[  399.332617] FS-Cache: Cache cachefiles stopped due to I/O error


This is reproducible with a current (-git) vanilla kernel, 
cachefilesd-0.9-2 (Debian/unstable) in a 64 bit Xen DomU.

I've seen a simlar thing reported on the linux-cachefs list in May:
http://www.redhat.com/archives/linux-cachefs/2009-May/msg00018.html

...where the backtrace looks similar, but mine has some Xen stuff in 
between. Full dmesg & .config and /proc bits are here:
    http://nerdbynature.de/bits/2.6.30/

Thanks,
Christian.
-- 
BOFH excuse #55:

Plumber mistook routing panel for decorative wall fixture

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

[David Howells]

Christian Kujau <lists@nerdbynature.de> wrote:

> [  399.332346]  [<ffffffff810da03a>] ? ext3_truncate+0x26a/0x9e0

Can you try the attached patch, please?

David
---
From: David Howells <dhowells@redhat.com>
Subject: [PATCH] CacheFiles: Don't write a full page if there's only a partial page to cache

cachefiles_write_page() writes a full page to the backing file for the last
page of the netfs file, even if the netfs file's last page is only a partial
page.

This causes the EOF on the backing file to be extended beyond the EOF of the
netfs, and thus the backing file will be truncated by cachefiles_attr_changed()
called from cachefiles_lookup_object().

So we need to limit the write we make to the backing file on that last page
such that it doesn't push the EOF too far.


Also, if a backing file that has a partial page at the end is expanded, we
discard the partial page and refetch it on the basis that we then have a hole
in the file with invalid data, and should the power go out...  A better way to
deal with this could be to record a note that the partial page contains invalid
data until the correct data is written into it.

This isn't a problem for netfs's that discard the whole backing file if the
file size changes (such as NFS).

Signed-off-by: David Howells <dhowells@redhat.com>
---

 fs/cachefiles/interface.c     |   20 +++++++++++++++++---
 fs/cachefiles/rdwr.c          |   23 +++++++++++++++++++----
 include/linux/fscache-cache.h |    3 +++
 3 files changed, 39 insertions(+), 7 deletions(-)


diff --git a/fs/cachefiles/interface.c b/fs/cachefiles/interface.c
index 431accd..919a7b6 100644
--- a/fs/cachefiles/interface.c
+++ b/fs/cachefiles/interface.c
@@ -403,12 +403,26 @@ static int cachefiles_attr_changed(struct fscache_object *_object)
 	if (oi_size == ni_size)
 		return 0;
 
-	newattrs.ia_size = ni_size;
-	newattrs.ia_valid = ATTR_SIZE;
-
 	cachefiles_begin_secure(cache, &saved_cred);
 	mutex_lock(&object->backer->d_inode->i_mutex);
+
+	/* if there's an extension to a partial page at the end of the backing
+	 * file, we need to discard the partial page so that we pick up new
+	 * data after it */
+	if (oi_size & ~PAGE_MASK && ni_size > oi_size) {
+		_debug("discard tail %llx", oi_size);
+		newattrs.ia_valid = ATTR_SIZE;
+		newattrs.ia_size = oi_size & PAGE_MASK;
+		ret = notify_change(object->backer, &newattrs);
+		if (ret < 0)
+			goto truncate_failed;
+	}
+
+	newattrs.ia_valid = ATTR_SIZE;
+	newattrs.ia_size = ni_size;
 	ret = notify_change(object->backer, &newattrs);
+
+truncate_failed:
 	mutex_unlock(&object->backer->d_inode->i_mutex);
 	cachefiles_end_secure(cache, saved_cred);
 
diff --git a/fs/cachefiles/rdwr.c b/fs/cachefiles/rdwr.c
index a69787e..86639c1 100644
--- a/fs/cachefiles/rdwr.c
+++ b/fs/cachefiles/rdwr.c
@@ -801,7 +801,8 @@ int cachefiles_write_page(struct fscache_storage *op, struct page *page)
 	struct cachefiles_cache *cache;
 	mm_segment_t old_fs;
 	struct file *file;
-	loff_t pos;
+	loff_t pos, eof;
+	size_t len;
 	void *data;
 	int ret;
 
@@ -835,15 +836,29 @@ int cachefiles_write_page(struct fscache_storage *op, struct page *page)
 		ret = -EIO;
 		if (file->f_op->write) {
 			pos = (loff_t) page->index << PAGE_SHIFT;
+
+			/* we mustn't write more data than we have, so we have
+			 * to beware of a partial page at EOF */
+			eof = object->fscache.store_limit_l;
+			len = PAGE_SIZE;
+			if (eof & ~PAGE_MASK) {
+				ASSERTCMP(pos, <, eof);
+				if (eof - pos < PAGE_SIZE) {
+					_debug("cut short %llx to %llx",
+					       pos, eof);
+					len = eof - pos;
+					ASSERTCMP(pos + len, ==, eof);
+				}
+			}
+
 			data = kmap(page);
 			old_fs = get_fs();
 			set_fs(KERNEL_DS);
 			ret = file->f_op->write(
-				file, (const void __user *) data, PAGE_SIZE,
-				&pos);
+				file, (const void __user *) data, len, &pos);
 			set_fs(old_fs);
 			kunmap(page);
-			if (ret != PAGE_SIZE)
+			if (ret != len)
 				ret = -EIO;
 		}
 		fput(file);
diff --git a/include/linux/fscache-cache.h b/include/linux/fscache-cache.h
index 84d3532..97229be 100644
--- a/include/linux/fscache-cache.h
+++ b/include/linux/fscache-cache.h
@@ -374,6 +374,7 @@ struct fscache_object {
 	struct list_head	dep_link;	/* link in parent's dependents list */
 	struct list_head	pending_ops;	/* unstarted operations on this object */
 	pgoff_t			store_limit;	/* current storage limit */
+	loff_t			store_limit_l;	/* current storage limit */
 };
 
 extern const char *fscache_object_states[];
@@ -414,6 +415,7 @@ void fscache_object_init(struct fscache_object *object,
 	object->events = object->event_mask = 0;
 	object->flags = 0;
 	object->store_limit = 0;
+	object->store_limit_l = 0;
 	object->cache = cache;
 	object->cookie = cookie;
 	object->parent = NULL;
@@ -460,6 +462,7 @@ static inline void fscache_object_lookup_error(struct fscache_object *object)
 static inline
 void fscache_set_store_limit(struct fscache_object *object, loff_t i_size)
 {
+	object->store_limit_l = i_size;
 	object->store_limit = i_size >> PAGE_SHIFT;
 	if (i_size & ~PAGE_MASK)
 		object->store_limit++;

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

[Takashi Iwai]

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

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

[David Howells]

Takashi Iwai <tiwai@suse.de> wrote:

> The log is below.  FWIW, it's on ext3.

This is with that patch?

David

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

[Takashi Iwai]

At Mon, 22 Jun 2009 16:21:32 +0100,
David Howells wrote:
> 
> Takashi Iwai <tiwai@suse.de> wrote:
> 
> > The log is below.  FWIW, it's on ext3.
> 
> This is with that patch?

Yes.


Takashi

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

[Christian Kujau]

On Mon, 22 Jun 2009, David Howells wrote:
>> [  399.332346]  [<ffffffff810da03a>] ? ext3_truncate+0x26a/0x9e0
> 
> Can you try the attached patch, please?

The patch helps, I think. Without this patch I was able to reproduce 
this very quickly, just running "grep -lr foo /share/nfs" was enough to
trigger the backtrace. With this patch, grep is still running (and 
utilizing cachefiles) but no warnings so far.

Thanks!
Christian.
-- 
BOFH excuse #83:

Support staff hung over, send aspirin and come back LATER.

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

[Christian Kujau]

On Mon, 22 Jun 2009, Christian Kujau wrote:
> On Mon, 22 Jun 2009, David Howells wrote:
> >> [  399.332346]  [<ffffffff810da03a>] ? ext3_truncate+0x26a/0x9e0
> > 
> > Can you try the attached patch, please?
> 
> The patch helps, I think. Without this patch I was able to reproduce 
> this very quickly, just running "grep -lr foo /share/nfs" was enough to
> trigger the backtrace. With this patch, grep is still running (and 
> utilizing cachefiles) but no warnings so far.

Unfortunately, now the system just freezes when doing *a lot* of read
operations on the NFS share (grep -r foo again). I don't know if it's 
related to your patch or something else, debugging is kinda hard at the 
moment, as it's a Xen DomU (no netconsole; serial redirection magic still 
not working), it'll take me a while to figure out what's going on here.

FWIW, I'm able to compile kernels over this very same (readonly) NFS 
share, only "grep -r" was able to trigger the freeze.

Thanks,
Christian.
-- 
BOFH excuse #323:

Your processor has processed too many instructions.  Turn it off immediately, do not type any commands!!

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

[Takashi Iwai]

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/
> 

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

[David Howells]

Takashi Iwai <tiwai@suse.de> wrote:

> The bug is still present on 2.6.31-rc2.

Yeah...  Sorry about that, I ran into another bug that was interfering with my
ability to test stuff, and so had to run that one down first...  And then
there was yet another bug - you know how it goes.

David

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

[Takashi Iwai]

At Tue, 07 Jul 2009 14:00:06 +0100,
David Howells wrote:
> 
> Takashi Iwai <tiwai@suse.de> wrote:
> 
> > The bug is still present on 2.6.31-rc2.
> 
> Yeah...  Sorry about that, I ran into another bug that was interfering with my
> ability to test stuff, and so had to run that one down first...  And then
> there was yet another bug - you know how it goes.

Oh, it was just a reminder, so don't feel a pressure :)
Anyway, if you have any new patch, I'd happily test.


thanks,

Takashi

Incorrect circular locking dependency?

[David Howells]

Takashi Iwai <tiwai@suse.de> wrote:

> =======================================================
> [ 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.

Okay.  I think I understand this:

 (1) cachefiles_read_waiter() intercepts wake up events, and, as such, is run
     inside the waitqueue spinlock for the page bit waitqueue.

 (2) cachefiles_read_waiter() calls fscache_enqueue_retrieval() which calls
     fscache_enqueue_operation() which calls schedule_work() for fast
     operations, thus taking a per-CPU workqueue spinlock.

 (3) queue_work(), which is called by many things, calls __queue_work(), which
     takes the per-CPU workqueue spinlock.

 (4) __queue_work() then calls insert_work(), which calls wake_up(), which
     takes the waitqueue spinlock for the per-CPU workqueue waitqueue.

Even though the two waitqueues are separate, I think lockdep sees them as
having the same lock.

Ingo: Is there any way around this?

David
---
> 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

Re: Incorrect circular locking dependency?

[Peter Zijlstra]

On Mon, 2009-07-27 at 15:37 +0100, David Howells wrote:
> Takashi Iwai <tiwai@suse.de> wrote:
> 
> > =======================================================
> > [ 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.
> 
> Okay.  I think I understand this:
> 
>  (1) cachefiles_read_waiter() intercepts wake up events, and, as such, is run
>      inside the waitqueue spinlock for the page bit waitqueue.
> 
>  (2) cachefiles_read_waiter() calls fscache_enqueue_retrieval() which calls
>      fscache_enqueue_operation() which calls schedule_work() for fast
>      operations, thus taking a per-CPU workqueue spinlock.
> 
>  (3) queue_work(), which is called by many things, calls __queue_work(), which
>      takes the per-CPU workqueue spinlock.
> 
>  (4) __queue_work() then calls insert_work(), which calls wake_up(), which
>      takes the waitqueue spinlock for the per-CPU workqueue waitqueue.
> 
> Even though the two waitqueues are separate, I think lockdep sees them as
> having the same lock.

Yeah, it looks like cwq->lock is always in the same lock class.

Creating a new class for your second workqueue might help, we'd have to
pass a second key through __create_workqueue_key() and pass that into
init_cpu_workqueue() and apply it to cwq->lock using lockdep_set_class()
and co.

~ Peter

> ---
> > 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

Re: Incorrect circular locking dependency?

[David Howells]

Peter Zijlstra <peterz@infradead.org> wrote:

> Creating a new class for your second workqueue might help,

I only have one workqueue.  The problem is there are two waitqueues, but
init_waitqueue_head() always sets q->lock to the same class.

> we'd have to pass a second key through __create_workqueue_key() and pass
> that into init_cpu_workqueue() and apply it to cwq->lock using
> lockdep_set_class() and co.

Actually, wouldn't just making init_cpu_workqueue() apply a class to
cwq->more_work that's common to all workqueues suffice?  Or even, have
init_waitqueue_head() apply an alternate class to q->lock?

David

Re: Incorrect circular locking dependency?

[Oleg Nesterov]

On 08/04, Peter Zijlstra wrote:
>
> On Mon, 2009-07-27 at 15:37 +0100, David Howells wrote:
> > Takashi Iwai <tiwai@suse.de> wrote:
> >
> > > =======================================================
> > > [ 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.
> >
> > Okay.  I think I understand this:
> >
> >  (1) cachefiles_read_waiter() intercepts wake up events, and, as such, is run
> >      inside the waitqueue spinlock for the page bit waitqueue.
> >
> >  (2) cachefiles_read_waiter() calls fscache_enqueue_retrieval() which calls
> >      fscache_enqueue_operation() which calls schedule_work() for fast
> >      operations, thus taking a per-CPU workqueue spinlock.
> >
> >  (3) queue_work(), which is called by many things, calls __queue_work(), which
> >      takes the per-CPU workqueue spinlock.
> >
> >  (4) __queue_work() then calls insert_work(), which calls wake_up(), which
> >      takes the waitqueue spinlock for the per-CPU workqueue waitqueue.
> >
> > Even though the two waitqueues are separate, I think lockdep sees them as
> > having the same lock.
>
> Yeah, it looks like cwq->lock is always in the same lock class.
>
> Creating a new class for your second workqueue might help, we'd have to
> pass a second key through __create_workqueue_key() and pass that into
> init_cpu_workqueue() and apply it to cwq->lock using lockdep_set_class()
> and co.

Agreed.


But otoh, it would be nice to kill cwq->more_work and speedup workqueues
a bit. We don't actually need wait_queue_head_t, we have a single thread
cwq->thread which should be woken.  However this change is not completely
trivial, we need cwq->please_wakeup_me to avoid unnecessary wakeups inside
run_workqueue(). Not sure this worth the trouble.

Oleg.

Re: Incorrect circular locking dependency?

[Peter Zijlstra]

On Tue, 2009-08-04 at 16:50 +0100, David Howells wrote:
> Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > Creating a new class for your second workqueue might help,
> 
> I only have one workqueue.  The problem is there are two waitqueues, but
> init_waitqueue_head() always sets q->lock to the same class.

Ah, right, I read it backwards then.

> > we'd have to pass a second key through __create_workqueue_key() and pass
> > that into init_cpu_workqueue() and apply it to cwq->lock using
> > lockdep_set_class() and co.
> 
> Actually, wouldn't just making init_cpu_workqueue() apply a class to
> cwq->more_work that's common to all workqueues suffice? 

That's the default behaviour.

>  Or even, have
> init_waitqueue_head() apply an alternate class to q->lock?

Right, that would work. Something akin to all the other per instance
classes would do I guess.


Utterly untested..

---
 include/linux/wait.h |    9 ++++++++-
 kernel/wait.c        |    5 +++--
 2 files changed, 11 insertions(+), 3 deletions(-)

diff --git a/include/linux/wait.h b/include/linux/wait.h
index 6788e1a..cf3c2f5 100644
--- a/include/linux/wait.h
+++ b/include/linux/wait.h
@@ -77,7 +77,14 @@ struct task_struct;
 #define __WAIT_BIT_KEY_INITIALIZER(word, bit)				\
 	{ .flags = word, .bit_nr = bit, }
 
-extern void init_waitqueue_head(wait_queue_head_t *q);
+extern void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *);
+
+#define init_waitqueue_head(q)				\
+	do {						\
+		static struct lock_class_key __key;	\
+							\
+		__init_waitqueue_head((q), &__key);	\
+	} while (0)
 
 #ifdef CONFIG_LOCKDEP
 # define __WAIT_QUEUE_HEAD_INIT_ONSTACK(name) \
diff --git a/kernel/wait.c b/kernel/wait.c
index ea7c3b4..c4bd3d8 100644
--- a/kernel/wait.c
+++ b/kernel/wait.c
@@ -10,13 +10,14 @@
 #include <linux/wait.h>
 #include <linux/hash.h>
 
-void init_waitqueue_head(wait_queue_head_t *q)
+void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *key)
 {
 	spin_lock_init(&q->lock);
+	lockdep_set_class(&q->lock, key);
 	INIT_LIST_HEAD(&q->task_list);
 }
 
-EXPORT_SYMBOL(init_waitqueue_head);
+EXPORT_SYMBOL(__init_waitqueue_head);
 
 void add_wait_queue(wait_queue_head_t *q, wait_queue_t *wait)
 {

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

[David Howells]

Takashi Iwai <tiwai@suse.de> wrote:

> =======================================================
> [ 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.
> ...

Can you try the attached patch from Peter Zijlstra?  It should cause the work
queue's waitqueue spinlock to have a separate lockdep class from the page
bit's waitqueue.

David
---
From: Peter Zijlstra <peterz@infradead.org>
Subject: [PATCH] Give waitqueue spinlocks their own lockdep classes

Give waitqueue spinlocks their own lockdep classes when they are initialised
from init_waitqueue_head().  This means that struct wait_queue::func functions
can operate other waitqueues.

This is used by CacheFiles to catch the page from a backing fs being unlocked
and to wake up another thread to take a copy of it.
---

 include/linux/wait.h |    9 ++++++++-
 kernel/wait.c        |    5 +++--
 2 files changed, 11 insertions(+), 3 deletions(-)


diff --git a/include/linux/wait.h b/include/linux/wait.h
index 6788e1a..cf3c2f5 100644
--- a/include/linux/wait.h
+++ b/include/linux/wait.h
@@ -77,7 +77,14 @@ struct task_struct;
 #define __WAIT_BIT_KEY_INITIALIZER(word, bit)				\
 	{ .flags = word, .bit_nr = bit, }
 
-extern void init_waitqueue_head(wait_queue_head_t *q);
+extern void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *);
+
+#define init_waitqueue_head(q)				\
+	do {						\
+		static struct lock_class_key __key;	\
+							\
+		__init_waitqueue_head((q), &__key);	\
+	} while (0)
 
 #ifdef CONFIG_LOCKDEP
 # define __WAIT_QUEUE_HEAD_INIT_ONSTACK(name) \
diff --git a/kernel/wait.c b/kernel/wait.c
index ea7c3b4..c4bd3d8 100644
--- a/kernel/wait.c
+++ b/kernel/wait.c
@@ -10,13 +10,14 @@
 #include <linux/wait.h>
 #include <linux/hash.h>
 
-void init_waitqueue_head(wait_queue_head_t *q)
+void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *key)
 {
 	spin_lock_init(&q->lock);
+	lockdep_set_class(&q->lock, key);
 	INIT_LIST_HEAD(&q->task_list);
 }
 
-EXPORT_SYMBOL(init_waitqueue_head);
+EXPORT_SYMBOL(__init_waitqueue_head);
 
 void add_wait_queue(wait_queue_head_t *q, wait_queue_t *wait)
 {

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

[Takashi Iwai]

At Tue, 04 Aug 2009 18:23:44 +0100,
David Howells wrote:
> 
> 
> Takashi Iwai <tiwai@suse.de> wrote:
> 
> > =======================================================
> > [ 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.
> > ...
> 
> Can you try the attached patch from Peter Zijlstra?  It should cause the work
> queue's waitqueue spinlock to have a separate lockdep class from the page
> bit's waitqueue.

I'm willing to test it, but could you clarify which patches to be
tested together with this one?  There are a few flying around...


thanks,

Takashi


> 
> David
> ---
> From: Peter Zijlstra <peterz@infradead.org>
> Subject: [PATCH] Give waitqueue spinlocks their own lockdep classes
> 
> Give waitqueue spinlocks their own lockdep classes when they are initialised
> from init_waitqueue_head().  This means that struct wait_queue::func functions
> can operate other waitqueues.
> 
> This is used by CacheFiles to catch the page from a backing fs being unlocked
> and to wake up another thread to take a copy of it.
> ---
> 
>  include/linux/wait.h |    9 ++++++++-
>  kernel/wait.c        |    5 +++--
>  2 files changed, 11 insertions(+), 3 deletions(-)
> 
> 
> diff --git a/include/linux/wait.h b/include/linux/wait.h
> index 6788e1a..cf3c2f5 100644
> --- a/include/linux/wait.h
> +++ b/include/linux/wait.h
> @@ -77,7 +77,14 @@ struct task_struct;
>  #define __WAIT_BIT_KEY_INITIALIZER(word, bit)				\
>  	{ .flags = word, .bit_nr = bit, }
>  
> -extern void init_waitqueue_head(wait_queue_head_t *q);
> +extern void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *);
> +
> +#define init_waitqueue_head(q)				\
> +	do {						\
> +		static struct lock_class_key __key;	\
> +							\
> +		__init_waitqueue_head((q), &__key);	\
> +	} while (0)
>  
>  #ifdef CONFIG_LOCKDEP
>  # define __WAIT_QUEUE_HEAD_INIT_ONSTACK(name) \
> diff --git a/kernel/wait.c b/kernel/wait.c
> index ea7c3b4..c4bd3d8 100644
> --- a/kernel/wait.c
> +++ b/kernel/wait.c
> @@ -10,13 +10,14 @@
>  #include <linux/wait.h>
>  #include <linux/hash.h>
>  
> -void init_waitqueue_head(wait_queue_head_t *q)
> +void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *key)
>  {
>  	spin_lock_init(&q->lock);
> +	lockdep_set_class(&q->lock, key);
>  	INIT_LIST_HEAD(&q->task_list);
>  }
>  
> -EXPORT_SYMBOL(init_waitqueue_head);
> +EXPORT_SYMBOL(__init_waitqueue_head);
>  
>  void add_wait_queue(wait_queue_head_t *q, wait_queue_t *wait)
>  {
> 

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

[Takashi Iwai]

At Tue, 04 Aug 2009 18:23:44 +0100,
David Howells wrote:
> 
> 
> Takashi Iwai <tiwai@suse.de> wrote:
> 
> > =======================================================
> > [ 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.
> > ...
> 
> Can you try the attached patch from Peter Zijlstra?  It should cause the work
> queue's waitqueue spinlock to have a separate lockdep class from the page
> bit's waitqueue.

OK, I've been running the patched kernel for a day, and it seems working
fine.  FWIW, I applied your previous fix
    CacheFiles: Handle truncate unlocking the page we're reading
as well.

Tested-by: Takashi Iwai <tiwai@suse.de>


Thanks!

Takashi

> 
> David
> ---
> From: Peter Zijlstra <peterz@infradead.org>
> Subject: [PATCH] Give waitqueue spinlocks their own lockdep classes
> 
> Give waitqueue spinlocks their own lockdep classes when they are initialised
> from init_waitqueue_head().  This means that struct wait_queue::func functions
> can operate other waitqueues.
> 
> This is used by CacheFiles to catch the page from a backing fs being unlocked
> and to wake up another thread to take a copy of it.
> ---
> 
>  include/linux/wait.h |    9 ++++++++-
>  kernel/wait.c        |    5 +++--
>  2 files changed, 11 insertions(+), 3 deletions(-)
> 
> 
> diff --git a/include/linux/wait.h b/include/linux/wait.h
> index 6788e1a..cf3c2f5 100644
> --- a/include/linux/wait.h
> +++ b/include/linux/wait.h
> @@ -77,7 +77,14 @@ struct task_struct;
>  #define __WAIT_BIT_KEY_INITIALIZER(word, bit)				\
>  	{ .flags = word, .bit_nr = bit, }
>  
> -extern void init_waitqueue_head(wait_queue_head_t *q);
> +extern void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *);
> +
> +#define init_waitqueue_head(q)				\
> +	do {						\
> +		static struct lock_class_key __key;	\
> +							\
> +		__init_waitqueue_head((q), &__key);	\
> +	} while (0)
>  
>  #ifdef CONFIG_LOCKDEP
>  # define __WAIT_QUEUE_HEAD_INIT_ONSTACK(name) \
> diff --git a/kernel/wait.c b/kernel/wait.c
> index ea7c3b4..c4bd3d8 100644
> --- a/kernel/wait.c
> +++ b/kernel/wait.c
> @@ -10,13 +10,14 @@
>  #include <linux/wait.h>
>  #include <linux/hash.h>
>  
> -void init_waitqueue_head(wait_queue_head_t *q)
> +void __init_waitqueue_head(wait_queue_head_t *q, struct lock_class_key *key)
>  {
>  	spin_lock_init(&q->lock);
> +	lockdep_set_class(&q->lock, key);
>  	INIT_LIST_HEAD(&q->task_list);
>  }
>  
> -EXPORT_SYMBOL(init_waitqueue_head);
> +EXPORT_SYMBOL(__init_waitqueue_head);
>  
>  void add_wait_queue(wait_queue_head_t *q, wait_queue_t *wait)
>  {
> 

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

[David Howells]

Takashi Iwai <tiwai@suse.de> wrote:

> OK, I've been running the patched kernel for a day, and it seems working
> fine.  FWIW, I applied your previous fix
>     CacheFiles: Handle truncate unlocking the page we're reading
> as well.
> 
> Tested-by: Takashi Iwai <tiwai@suse.de>

Thanks!

David