Re: regression: 100% io-wait with 2.6.24-rcX

[Fengguang Wu]

On Sun, Jan 13, 2008 at 12:32:30AM +0100, Joerg Platte wrote:
> Am Freitag, 11. Januar 2008 schrieb Fengguang Wu:
> > On Thu, Jan 10, 2008 at 11:03:05AM +0100, Joerg Platte wrote:
> > > Am Donnerstag, 10. Januar 2008 schrieb Fengguang Wu:
> > > > > problem, because the iowait problem disappeared today after the
> > > > > regular Debian update. I'll try to install the old package versions
> > > > > to make it show up again. Maybe that helps to debug it.
> > > >
> > > > Thank you. I'm running sid, ext2 as rootfs now ;-)
> > >
> > > The error is back and I'm getting thousands of messages like this with
> > > the patched kernel:
> > >
> > > mm/page-writeback.c 668 wb_kupdate: pdflush(146) 21115 global 3936 0 0 wc
> > > _M > tw 1024 sk 0 requeue_io 301: inode 81441 size 0 at 08:07(sda7)
> > > mm/page-writeback.c 668 wb_kupdate: pdflush(147) 17451 global 3936 0 0 wc
> > > _M > tw 1024 sk 2 requeue_io 301: inode 81441 size 0 at 08:07(sda7)
> > > mm/page-writeback.c 668 wb_kupdate: pdflush(147) 17451 global 3936 0 0 wc
> > > _M > tw 1024 sk 2 requeue_io 301: inode 81441 size 0 at 08:07(sda7)
> >
> > Joerg, what's the output of `dumpe2fs /dev/sda7` and `lsof|grep /tmp`?
> 
> After another reboot I tried to get more information about the konqueror 
> process possibly causing the iowait load by using strace -p. Here is the 
> output:
> 
> gettimeofday({1200180588, 878508}, NULL) = 0
> setitimer(ITIMER_VIRTUAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
> rt_sigaction(SIGVTALRM, {SIG_DFL}, {0xb5cffed0, [VTALRM], SA_RESTART}, 8) = 0
> gettimeofday({1200180588, 879942}, NULL) = 0
> time(NULL)                              = 1200180588
> gettimeofday({1200180588, 880838}, NULL) = 0
> gettimeofday({1200180588, 881284}, NULL) = 0

No idea yet :-/ I'm afraid I have to trouble you again - the bug just
refused to appear in my system. I prepared a kernel module for you to
gather more information:

make && insmod ext2-writeback-debug.ko && sleep 1s && rmmod ext2-writeback-debug
dmesg > ext2-writeback-debug.dmesg

Please do it when 100% iowait appears, and send the dmesg file.

Thank you,
Fengguang
obj-m := ext2-writeback-debug.o
KDIR  := /lib/modules/$(shell uname -r)/build
PWD   := $(shell pwd)

default:
	$(MAKE) -C $(KDIR) SUBDIRS=$(PWD) modules
clean:  
	rm -f *.mod.c *.ko *.o

#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/mm.h>
#include <linux/fs.h>
#include <linux/writeback.h>
#include <linux/kprobes.h>
#include <linux/pagevec.h>

void print_page(struct page *page)
{
	printk(KERN_DEBUG "%lu\t%u\t%u\t%c%c%c%c%c\n",
			page->index,
			page_count(page),
			page_mapcount(page),
			PageUptodate(page)      ? 'U' : '_',
			PageDirty(page)         ? 'D' : '_',
			PageWriteback(page)     ? 'W' : '_',
			PagePrivate(page)       ? 'P' : '_',
			PageLocked(page)        ? 'L' : '_');
}

void print_writeback_control(struct writeback_control *wbc)
{
	printk(KERN_DEBUG
			"global dirty %lu writeback %lu nfs %lu\n"
			"wbc flags %c%c towrite %ld skipped %ld\n",
			global_page_state(NR_FILE_DIRTY),
			global_page_state(NR_WRITEBACK),
			global_page_state(NR_UNSTABLE_NFS),
			wbc->encountered_congestion ? 'C':'_',
			wbc->more_io ? 'M':'_',
			wbc->nr_to_write,
			wbc->pages_skipped);
}

void print_inode_pages(struct inode *inode)
{
	struct address_space *mapping = inode->i_mapping;
	struct pagevec pvec;
	int nr_pages;
	int i;
	pgoff_t index = 0;
	struct dentry *dentry;
	int dcount;
	char *dname;

	nr_pages = pagevec_lookup_tag(&pvec, mapping, &index,
			PAGECACHE_TAG_DIRTY,
			(pgoff_t)PAGEVEC_SIZE);

	if (list_empty(&inode->i_dentry)) {
		dname = "";
		dcount = 0;
	} else {
		dentry = list_entry(inode->i_dentry.next,
					struct dentry, d_alias);
		dname = dentry->d_iname;
		dcount = atomic_read(&dentry->d_count);
	}

	printk(KERN_DEBUG "inode %lu(%s/%s) count %d,%d size %llu pages %lu\n",
			inode->i_ino,
			inode->i_sb->s_id,
			dname,
			atomic_read(&inode->i_count),
			dcount,
			i_size_read(inode),
			mapping->nrpages
	      );

	for (i = 0; i < nr_pages; i++)
		print_page(pvec.pages[i]);
}

int handler_pre(struct kprobe *p, struct pt_regs *regs)
{
	static int count = 0;

	if (count++ < 10)
		dump_stack();

	return 0;
}

void handler_post(struct kprobe *p, struct pt_regs *regs, unsigned long flags)
{
}

static struct kprobe my_kprobe = {
	.pre_handler = handler_pre,
	.post_handler = handler_post,
	.symbol_name = "submit_bio"
};


static int jdo_ext2_writepage(struct page *page, struct writeback_control *wbc)
{
	struct inode * const inode = page->mapping->host;

	if (!i_size_read(inode)) {
		printk(KERN_DEBUG "ext2_writepage:\n");
		print_page(page);
		print_writeback_control(wbc);
	}

	jprobe_return();
	return 0;
}
static struct jprobe jprobe_ext2_writepage = {
	.entry = jdo_ext2_writepage,
	.kp.symbol_name = "ext2_writepage"
};


static void jdo_requeue_io(struct inode *inode)
{
	if (!i_size_read(inode)) {
		printk(KERN_DEBUG "requeue_io:\n");
		print_inode_pages(inode);
	}

	jprobe_return();
}
static struct jprobe jprobe_requeue_io = {
	.entry = jdo_requeue_io,
	.kp.symbol_name = "requeue_io"
};

static int setup_kprobe(struct kprobe *kprobe)
{
	int ret = register_kprobe(kprobe);
	printk("register_kprobe(%s) = %d\n", kprobe->symbol_name, ret);
	return ret;
}

static int setup_jprobe(struct jprobe *jprobe)
{
	int ret = register_jprobe(jprobe);
	printk("register_jprobe(%s) = %d\n", jprobe->kp.symbol_name, ret);
	return ret;
}

static int __init jprobe_init(void)
{
	int ret;

	ret = setup_jprobe(&jprobe_ext2_writepage);
	if (ret)
		return -1;

	ret = setup_jprobe(&jprobe_requeue_io);
	if (ret)
		return -1;

	ret = setup_kprobe(&my_kprobe);
	if (ret)
		return -1;

	return 0;
}

static void __exit jprobe_exit(void)
{
	unregister_kprobe(&my_kprobe);
	unregister_jprobe(&jprobe_requeue_io);
	unregister_jprobe(&jprobe_ext2_writepage);
}

module_init(jprobe_init)
module_exit(jprobe_exit)
MODULE_LICENSE("GPL");