Extreme I/O latency

Extreme I/O latency

[Fredrik Tolf]

Dear list,

I'm having some problems with a Linux system using XFS filesystems, on top 
of LVM, on top of mdraid, and I'm lacking ideas for how to proceed with 
debugging it. The problem manifests itself in that certain, simple I/O 
operations sometimes take extremely long to complete -- not seldomly up to 
20-30 seconds!

I used to have lesser problems of a similar kind previously, but this 
extremeness only started showing up since I upgraded the system from 
Debian Lenny (using Linux 2.6.26) to Squeeze (using 2.6.32). I've since 
upgraded to 3.2.0, and now to 3.5.4, and they all exhibit the same 
problem.

The process having the worst problems with it usually sees them when it 
calls upon Berkeley DB, the stack traces in which seems to tell me that 
it's trying to do mmap'ed I/O in its region files, so I can only assume 
that the stop happens when it's pulling in pages from disk. I can't say I 
know for sure, but I'm getting the feeling that it happens when some other 
process calls fdatasync() or somesuch operation. I get this feeling 
because the problems very often seem to happen exactly when I fetch a 
MySQL-backed webpage from the system's HTTP server (at which point mysqld 
syncs its data to disk after some session table update or the like).

Does anyone have any clue as to what might cause symptoms like these, or, 
if not, how I can debug the issue further? Admittedly, it's not as if I 
can be sure that the problem belongs with XFS proper rather than LVM or 
mdraid, but I have to being somewhere. At least XFS is the direct 
interface that my programs call before getting stuck. :)

Your most obt. St. &c&c,
Fredrik Tolf

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: Extreme I/O latency

[Dave Chinner]

On Tue, Oct 02, 2012 at 03:53:08AM +0200, Fredrik Tolf wrote:
> Dear list,
> 
> I'm having some problems with a Linux system using XFS filesystems,
> on top of LVM, on top of mdraid, and I'm lacking ideas for how to
> proceed with debugging it. The problem manifests itself in that
> certain, simple I/O operations sometimes take extremely long to
> complete -- not seldomly up to 20-30 seconds!

What is a "simple IO operation"?

> I used to have lesser problems of a similar kind previously, but
> this extremeness only started showing up since I upgraded the system
> from Debian Lenny (using Linux 2.6.26) to Squeeze (using 2.6.32).
> I've since upgraded to 3.2.0, and now to 3.5.4, and they all exhibit
> the same problem.
> 
> The process having the worst problems with it usually sees them when
> it calls upon Berkeley DB, the stack traces in which seems to tell
> me that it's trying to do mmap'ed I/O in its region files, so I can
> only assume that the stop happens when it's pulling in pages from
> disk. I can't say I know for sure, but I'm getting the feeling that
> it happens when some other process calls fdatasync() or somesuch
> operation. I get this feeling because the problems very often seem
> to happen exactly when I fetch a MySQL-backed webpage from the
> system's HTTP server (at which point mysqld syncs its data to disk
> after some session table update or the like).

So is causing random 4k write IO?

> Does anyone have any clue as to what might cause symptoms like
> these, or, if not, how I can debug the issue further? Admittedly,
> it's not as if I can be sure that the problem belongs with XFS
> proper rather than LVM or mdraid, but I have to being somewhere. At
> least XFS is the direct interface that my programs call before
> getting stuck. :)

More information about your setup needed and what is happening
during the hangs:

http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F

Also: ftrace or latencytop might point you at where the the latency
is occurring. Then we might have some idea of what is causing it.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: Extreme I/O latency

[Fredrik Tolf]

On Tue, 2 Oct 2012, Dave Chinner wrote:
> On Tue, Oct 02, 2012 at 03:53:08AM +0200, Fredrik Tolf wrote:
> What is a "simple IO operation"?

Sorry, what I meant by "simple" is mostly on the interface level. Like, a 
single syscall (with far less than a page of data in the case of read or 
write), or, in this case, reading a single mmap'ed page.

>> The process having the worst problems with it usually sees them when
>> it calls upon Berkeley DB, the stack traces in which seems to tell
>> me that it's trying to do mmap'ed I/O in its region files, so I can
>> only assume that the stop happens when it's pulling in pages from
>> disk. I can't say I know for sure, but I'm getting the feeling that
>> it happens when some other process calls fdatasync() or somesuch
>> operation. I get this feeling because the problems very often seem
>> to happen exactly when I fetch a MySQL-backed webpage from the
>> system's HTTP server (at which point mysqld syncs its data to disk
>> after some session table update or the like).
>
> So is causing random 4k write IO?

Which one, do you mean? The mmap'ed I/O would be a random 4k read, rather 
than a write. Exactly what happens as a result of the fdatasync that MySQL 
calls is not something I am completely privy to. The point being that the 
fdatasync operation also seems to cause other, otherwise unrelated, 
processes to stop dead in their tracks when they try to do I/O while the 
fdatasync is running.

Though, don't take my gut feeling that fdatasync is the cause too 
seriously. I haven't been able to debug it well enough to say conclusively 
that it only happens while syncs are running.

> More information about your setup needed and what is happening
> during the hangs:
>
> http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F

Oh, sorry. I'll provide that if necessary, but...

> Also: ftrace or latencytop might point you at where the the latency
> is occurring. Then we might have some idea of what is causing it.

... thanks a lot! Those sound precisely like the kind of debugging tools 
that I've been looking for. I've been Googling around like crazy for tools 
to enable me to see what happens in the kernel, but I have thus far been 
unable to find any. I'll see how far I can get on my own using these.

--

Fredrik Tolf

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: Extreme I/O latency

[Dave Chinner]

On Tue, Oct 02, 2012 at 05:25:53AM +0200, Fredrik Tolf wrote:
> On Tue, 2 Oct 2012, Dave Chinner wrote:
> >On Tue, Oct 02, 2012 at 03:53:08AM +0200, Fredrik Tolf wrote:
> >What is a "simple IO operation"?
> 
> Sorry, what I meant by "simple" is mostly on the interface level.
> Like, a single syscall (with far less than a page of data in the
> case of read or write), or, in this case, reading a single mmap'ed
> page.

Which might be "simple" by themselves, but when an application is
doing thousands of such operations a second, the result is far from
simple....

> 
> >>The process having the worst problems with it usually sees them when
> >>it calls upon Berkeley DB, the stack traces in which seems to tell
> >>me that it's trying to do mmap'ed I/O in its region files, so I can
> >>only assume that the stop happens when it's pulling in pages from
> >>disk. I can't say I know for sure, but I'm getting the feeling that
> >>it happens when some other process calls fdatasync() or somesuch
> >>operation. I get this feeling because the problems very often seem
> >>to happen exactly when I fetch a MySQL-backed webpage from the
> >>system's HTTP server (at which point mysqld syncs its data to disk
> >>after some session table update or the like).
> >
> >So is causing random 4k write IO?
> 
> Which one, do you mean? The mmap'ed I/O would be a random 4k read,
> rather than a write. Exactly what happens as a result of the
> fdatasync that MySQL calls is not something I am completely privy
> to.

fdatasync does not cause read operations to occur. It will cause
dirty pages to be written to disk. My assumption is that the pages
are being faulted by mmap access to modify the data within them, and
hence you then get them written back when a a fdatasync occurs...

> The point being that the fdatasync operation also seems to cause
> other, otherwise unrelated, processes to stop dead in their tracks
> when they try to do I/O while the fdatasync is running.

Which tends to imply that there is random write IO to a RAID5/6
volume occurring...

> Though, don't take my gut feeling that fdatasync is the cause too
> seriously. I haven't been able to debug it well enough to say
> conclusively that it only happens while syncs are running.

While writeback is occurring, hence...

> >More information about your setup needed and what is happening
> >during the hangs:
> >
> >http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F
> 
> Oh, sorry. I'll provide that if necessary, but...

stuff like iostat output will tell you what sort of IO is occurring.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs

Re: Extreme I/O latency

[Fredrik Tolf]

On Tue, 2 Oct 2012, Dave Chinner wrote:
> On Tue, Oct 02, 2012 at 05:25:53AM +0200, Fredrik Tolf wrote:
>> On Tue, 2 Oct 2012, Dave Chinner wrote:
>>> On Tue, Oct 02, 2012 at 03:53:08AM +0200, Fredrik Tolf wrote:
>>> What is a "simple IO operation"?
>>
>> Sorry, what I meant by "simple" is mostly on the interface level.
>> Like, a single syscall (with far less than a page of data in the
>> case of read or write), or, in this case, reading a single mmap'ed
>> page.
>
> Which might be "simple" by themselves, but when an application is
> doing thousands of such operations a second, the result is far from
> simple....

Certainly; though I seem to be bad at communicating it, the point I was 
trying to make is that it is, from the point of view of userspace, 
individual calls that take extremely long, rather than total throughput 
being poor. :)

--

Fredrik Tolf

_______________________________________________
xfs mailing list
xfs@oss.sgi.com
http://oss.sgi.com/mailman/listinfo/xfs