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

From: Joerg Platte <jplatte@naasa.net>
To: Fengguang Wu <wfg@mail.ustc.edu.cn>
Cc: Peter Zijlstra <peterz@infradead.org>,
	Ingo Molnar <mingo@elte.hu>,
	linux-kernel@vger.kernel.org
Subject: Re: regression: 100% io-wait with 2.6.24-rcX
Date: Sun, 13 Jan 2008 00:32:30 +0100	[thread overview]
Message-ID: <200801130032.32495.jplatte@naasa.net> (raw)
In-Reply-To: <400029009.12072@ustc.edu.cn>

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
time(NULL)                              = 1200180588
gettimeofday({1200180588, 882131}, NULL) = 0
gettimeofday({1200180588, 882572}, NULL) = 0
ioctl(5, FIONREAD, [0])                 = 0
gettimeofday({1200180588, 883477}, NULL) = 0
select(16, [5 6 7 9 11 14 15], [], [], {0, 150095}) = 0 (Timeout)
gettimeofday({1200180589, 34269}, NULL) = 0
gettimeofday({1200180589, 34885}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 36672}, NULL) = 0
rt_sigaction(SIGVTALRM, {0xb5cffed0, [VTALRM], SA_RESTART}, {SIG_DFL}, 8) = 0
setitimer(ITIMER_VIRTUAL, {it_interval={10, 0}, it_value={5, 0}}, 
{it_interval={0, 0}, it_value={0, 0}}) = 0
gettimeofday({1200180589, 38555}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 39802}, 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({1200180589, 40912}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 42019}, NULL) = 0
gettimeofday({1200180589, 42458}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 43303}, NULL) = 0
gettimeofday({1200180589, 43747}, NULL) = 0
ioctl(5, FIONREAD, [0])                 = 0
gettimeofday({1200180589, 45834}, NULL) = 0
select(16, [5 6 7 9 11 14 15], [], [], {0, 149913}) = 0 (Timeout)
gettimeofday({1200180589, 194815}, NULL) = 0
ioctl(5, FIONREAD, [0])                 = 0
gettimeofday({1200180589, 195730}, NULL) = 0
select(16, [5 6 7 9 11 14 15], [], [], {0, 17}) = 0 (Timeout)
gettimeofday({1200180589, 197555}, NULL) = 0
gettimeofday({1200180589, 198020}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 198884}, NULL) = 0
rt_sigaction(SIGVTALRM, {0xb5cffed0, [VTALRM], SA_RESTART}, {SIG_DFL}, 8) = 0
setitimer(ITIMER_VIRTUAL, {it_interval={10, 0}, it_value={5, 0}}, 
{it_interval={0, 0}, it_value={0, 0}}) = 0
gettimeofday({1200180589, 200702}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 200806}, 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({1200180589, 202975}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 203837}, NULL) = 0
gettimeofday({1200180589, 204319}, NULL) = 0
time(NULL)                              = 1200180589
gettimeofday({1200180589, 205169}, NULL) = 0
gettimeofday({1200180589, 205613}, NULL) = 0
ioctl(5, FIONREAD, [0])                 = 0
gettimeofday({1200180589, 206515}, NULL) = 0
select(16, [5 6 7 9 11 14 15], [], [], {0, 149098} <unfinished ...>

Fengguang, do you have any idea what's going wrong here?

regards,
Jörg

-- 
PGP Key: send mail with subject 'SEND PGP-KEY' PGP Key-ID: FD 4E 21 1D
PGP Fingerprint: 388A872AFC5649D3 BCEC65778BE0C605