Higher than expected disk write(2) latency

Higher than expected disk write(2) latency

[Martin Lucina]

Hi,

we're getting some rather high figures for write(2) latency when testing
synchronous writing to disk.  The test I'm running writes 2000 blocks of
contiguous data to a raw device, using O_DIRECT and various block sizes
down to a minimum of 512 bytes.  

The disk is a Seagate ST380817AS SATA connected to an Intel ICH7
using ata_piix.  Write caching has been explicitly disabled on the
drive, and there is no other activity that should affect the test
results (all system filesystems are on a separate drive).  The system is
running Debian etch, with a 2.6.24 kernel.

Observed results:

size=1024, N=2000, took=4.450788 s, thput=3 mb/s seekc=1
write: avg=8.388851 max=24.998846 min=8.335624 ms
8 ms: 1992 cases
9 ms: 2 cases
10 ms: 1 cases
14 ms: 1 cases
16 ms: 3 cases
24 ms: 1 cases

size=512, N=2000, took=4.401289 s, thput=1 mb/s seekc=1
write: avg=8.364283 max=16.692206 min=2.010072 ms
2 ms: 1 cases
7 ms: 1 cases
8 ms: 1995 cases
16 ms: 3 cases

Measurement of the write(2) time is performed using the TSC, so any
latency there is negligible.

The datasheet for the drive being used gives the following figures:

Average latency (msec): 4.16
Track-to-track seek time (msec typical): <1.2 (write)
Average seek, write (msec typical): 9.5

If these figures are to be believed, then why are we seeing latencies of
8.3 msec?  Is this normal?  Or are we just being overly optimistic in
our performance expectations?

What we find suspicious is that the latency we see is so close to the
Average seek latency specified for the drive, almost as if the drive was
performing a seek on every write.

For comparison, here are the results of the same test with the disk
write cache *enabled*:

size=1024, N=2000, took=0.296284 s, thput=55 mb/s seekc=1
write: avg=0.147745 max=0.606990 min=0.117246 ms
0 ms: 2000 cases

size=512, N=2000, took=0.304614 s, thput=26 mb/s seekc=1
write: avg=0.152089 max=0.533234 min=0.125370 ms
0 ms: 2000 cases

We also ran the same test on a different system with recent SAS disks
connected via a HP/Compaq CCISS controller.  I don't have the exact
details of the drives used, since I don't know how to get them out of
the cciss driver, but the latencies we got were around 4 msec.  Whilst
this is better than the "commodity" hardware used in the tests above, it
still seems excessive.

Any advice would be appreciated.

Thanks,

-mato

Re: Higher than expected disk write(2) latency

[Roger Heflin]

Martin Lucina wrote:
> Hi,
> 
> we're getting some rather high figures for write(2) latency when testing
> synchronous writing to disk.  The test I'm running writes 2000 blocks of
> contiguous data to a raw device, using O_DIRECT and various block sizes
> down to a minimum of 512 bytes.  
> 
> The disk is a Seagate ST380817AS SATA connected to an Intel ICH7
> using ata_piix.  Write caching has been explicitly disabled on the
> drive, and there is no other activity that should affect the test
> results (all system filesystems are on a separate drive).  The system is
> running Debian etch, with a 2.6.24 kernel.
> 
> Observed results:
> 
> size=1024, N=2000, took=4.450788 s, thput=3 mb/s seekc=1
> write: avg=8.388851 max=24.998846 min=8.335624 ms
> 8 ms: 1992 cases
> 9 ms: 2 cases
> 10 ms: 1 cases
> 14 ms: 1 cases
> 16 ms: 3 cases
> 24 ms: 1 cases
> 
> size=512, N=2000, took=4.401289 s, thput=1 mb/s seekc=1
> write: avg=8.364283 max=16.692206 min=2.010072 ms
> 2 ms: 1 cases
> 7 ms: 1 cases
> 8 ms: 1995 cases
> 16 ms: 3 cases
> 
> Measurement of the write(2) time is performed using the TSC, so any
> latency there is negligible.
> 
> The datasheet for the drive being used gives the following figures:
> 
> Average latency (msec): 4.16
> Track-to-track seek time (msec typical): <1.2 (write)
> Average seek, write (msec typical): 9.5
> 
> If these figures are to be believed, then why are we seeing latencies of
> 8.3 msec?  Is this normal?  Or are we just being overly optimistic in
> our performance expectations?

Consider this, 60/7200rpm=8.3ms for one rotation.

You write sector n and n+1, it takes some amount of time for that first set of 
sectors to come under the head, when it does you write it and immediately 
return.   Immediately after that you attempt write sector n+2 and n+3 which just 
a bit ago passed under the head, so you have to wait an *ENTIRE* revolution for 
those sectors to again come under the head to be written, another ~8.3ms, and 
you continue to repeat this with each block being written.   If the sector was 
randomly placed in the rotation (ie 50% chance of the disk being off by 1/2 a 
rotation or less-you would have a 4.15 ms average seek time for your test)-but 
the case of sequential sync writes this leaves the sector about as far as 
possible from the head (it just passed under the head).

> 
> What we find suspicious is that the latency we see is so close to the
> Average seek latency specified for the drive, almost as if the drive was
> performing a seek on every write.
> 
> For comparison, here are the results of the same test with the disk
> write cache *enabled*:
> 
> size=1024, N=2000, took=0.296284 s, thput=55 mb/s seekc=1
> write: avg=0.147745 max=0.606990 min=0.117246 ms
> 0 ms: 2000 cases
> 
> size=512, N=2000, took=0.304614 s, thput=26 mb/s seekc=1
> write: avg=0.152089 max=0.533234 min=0.125370 ms
> 0 ms: 2000 cases

Write cache allows a return without writing to the actual disk, so you don't 
have to wait, and on top of that it queues up all of the writes that are 
together on the track and does them at one pass of the head over all of the sectors.

> 
> We also ran the same test on a different system with recent SAS disks
> connected via a HP/Compaq CCISS controller.  I don't have the exact
> details of the drives used, since I don't know how to get them out of
> the cciss driver, but the latencies we got were around 4 msec.  Whilst
> this is better than the "commodity" hardware used in the tests above, it
> still seems excessive.

Almost the same case as for the 7200 rpm disk, but I bet these SAS drives are 
15k drives?   If so 60/15000=4ms.

> 
> Any advice would be appreciated.
> 
> Thanks,
> 

                        Roger

Re: Higher than expected disk write(2) latency

[David Newall]

Martin Lucina wrote:
> Measurement of the write(2) time is performed using the TSC, so any
> latency there is negligible.

Measuring each write is lavish and bound to impact the results.  To
measure sustained throughput, get the time only at start and end, and
divide the difference by the number of writes.

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

David Newall wrote:
> Martin Lucina wrote:
>> Measurement of the write(2) time is performed using the TSC, so any
>> latency there is negligible.
> 
> Measuring each write is lavish and bound to impact the results.  To
> measure sustained throughput, get the time only at start and end, and
> divide the difference by the number of writes.

Hi,

We're using RDTSC to measure time, which takes ~30 nanoseconds to 
complete. I would say this is negligible given that latency of a write 
is 5 orders of magnitude higher.

Martin

Re: Higher than expected disk write(2) latency

[Robert Hancock]

Martin Lucina wrote:
> Hi,
> 
> we're getting some rather high figures for write(2) latency when testing
> synchronous writing to disk.  The test I'm running writes 2000 blocks of
> contiguous data to a raw device, using O_DIRECT and various block sizes
> down to a minimum of 512 bytes.  
> 
> The disk is a Seagate ST380817AS SATA connected to an Intel ICH7
> using ata_piix.  Write caching has been explicitly disabled on the
> drive, and there is no other activity that should affect the test
> results (all system filesystems are on a separate drive).  The system is
> running Debian etch, with a 2.6.24 kernel.
> 
> Observed results:

Well, write performance on SATA with no command queueing and write cache 
disabled is always going to be pretty atrocious, since the drive has no 
opportunity to reorder the writes at all, and it also can't receive the 
next write command until the previous one completes so that it may have 
to wait for another rotation in order to perform each write. In this 
case I don't think command queueing even helps you though, as only one 
write from the app is ever outstanding at a time. I suspect the only 
thing that would really help this workload is a RAID controller with a 
battery-backed write cache (that way those tiny O_DIRECT writes don't 
all have to hit the physical disk).

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

Hi Roger,

>> If these figures are to be believed, then why are we seeing latencies of
>> 8.3 msec?  Is this normal?  Or are we just being overly optimistic in
>> our performance expectations?
> 
> Consider this, 60/7200rpm=8.3ms for one rotation.
> 
> You write sector n and n+1, it takes some amount of time for that first 
> set of sectors to come under the head, when it does you write it and 
> immediately return.   Immediately after that you attempt write sector 
> n+2 and n+3 which just a bit ago passed under the head, so you have to 
> wait an *ENTIRE* revolution for those sectors to again come under the 
> head to be written, another ~8.3ms, and you continue to repeat this with 
> each block being written.   If the sector was randomly placed in the 
> rotation (ie 50% chance of the disk being off by 1/2 a rotation or 
> less-you would have a 4.15 ms average seek time for your test)-but the 
> case of sequential sync writes this leaves the sector about as far as 
> possible from the head (it just passed under the head).

Fair enough. That exaplains the behaviour. Would AIO help here? If we 
are able to enqueue next write before the first one is finished, it can 
start writing it immediately without waiting for a revolution.

>> We also ran the same test on a different system with recent SAS disks
>> connected via a HP/Compaq CCISS controller.  I don't have the exact
>> details of the drives used, since I don't know how to get them out of
>> the cciss driver, but the latencies we got were around 4 msec.  Whilst
>> this is better than the "commodity" hardware used in the tests above, it
>> still seems excessive.
> 
> Almost the same case as for the 7200 rpm disk, but I bet these SAS 
> drives are 15k drives?   If so 60/15000=4ms.

Bingo!

Thanks.
Martin

Re: Higher than expected disk write(2) latency

[Roger Heflin]

Martin Sustrik wrote:
> Hi Roger,
> 
>>> If these figures are to be believed, then why are we seeing latencies of
>>> 8.3 msec?  Is this normal?  Or are we just being overly optimistic in
>>> our performance expectations?
>>
>> Consider this, 60/7200rpm=8.3ms for one rotation.
>>
>> You write sector n and n+1, it takes some amount of time for that 
>> first set of sectors to come under the head, when it does you write it 
>> and immediately return.   Immediately after that you attempt write 
>> sector n+2 and n+3 which just a bit ago passed under the head, so you 
>> have to wait an *ENTIRE* revolution for those sectors to again come 
>> under the head to be written, another ~8.3ms, and you continue to 
>> repeat this with each block being written.   If the sector was 
>> randomly placed in the rotation (ie 50% chance of the disk being off 
>> by 1/2 a rotation or less-you would have a 4.15 ms average seek time 
>> for your test)-but the case of sequential sync writes this leaves the 
>> sector about as far as possible from the head (it just passed under 
>> the head).
> 
> Fair enough. That exaplains the behaviour. Would AIO help here? If we 
> are able to enqueue next write before the first one is finished, it can 
> start writing it immediately without waiting for a revolution.

If you could get them queued at the disk level, things that would need to be 
watched were if the disk can queue things up (and all controllers/drivers 
support it), and how many things the disk can queue up, and how large each of 
those things can be, if they aren't queued at the disk, there is the chance that 
the machine cannot get the data to the disk faster enough for that next sector.

I have always avoided fully sync operations as things *ALWAYS* got really really 
slow because of all of the requirements need to make sure that it always got the 
data to disk correctly on a unexpected crash, and typically the type of 
applications I dealt with, if the machine crashed the currently outputting data 
was known to be incomplete and generally useless, so things were reran.

Depending on your application you could always get a small fast solid state 
device (no seek or RPM issues), and use it to keep a journal that could be 
replayed on an unexpected crash...and then just use various syncs to force 
things to disk at various points.

> 
>>> We also ran the same test on a different system with recent SAS disks
>>> connected via a HP/Compaq CCISS controller.  I don't have the exact
>>> details of the drives used, since I don't know how to get them out of
>>> the cciss driver, but the latencies we got were around 4 msec.  Whilst
>>> this is better than the "commodity" hardware used in the tests above, it
>>> still seems excessive.
>>
>> Almost the same case as for the 7200 rpm disk, but I bet these SAS 
>> drives are 15k drives?   If so 60/15000=4ms.
> 
> Bingo!

Note that in my experience the SAS drives do deal with more concurrently a lot 
better than the SATA drives, one would expect a SAS drive to scale about 2x 
better than a SATA drive (faster RPM) but the test results indicate that they 
were considerably better when hitting it with more concurrent streams that would 
be expected.

                              Roger

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

Hi Roger,

>> Fair enough. That exaplains the behaviour. Would AIO help here? If we 
>> are able to enqueue next write before the first one is finished, it 
>> can start writing it immediately without waiting for a revolution.
> 
> If you could get them queued at the disk level, things that would need 
> to be watched were if the disk can queue things up (and all 
> controllers/drivers support it), and how many things the disk can queue 
> up, and how large each of those things can be, if they aren't queued at 
> the disk, there is the chance that the machine cannot get the data to 
> the disk faster enough for that next sector.

We'll try with AIO and we'll see what the impact would be.

> Depending on your application you could always get a small fast solid 
> state device (no seek or RPM issues), and use it to keep a journal that 
> could be replayed on an unexpected crash...and then just use various 
> syncs to force things to disk at various points.

Yes, that's one thing we want to do. However, we cannot assume that 
every user will have SSD, thus we should try to get the best latencies 
possible even on standard HD.

Martin

Re: Higher than expected disk write(2) latency

[Bernd Eckenfels]

In article <48695C20.6050704@fastmq.com> you wrote:
> Yes, that's one thing we want to do. However, we cannot assume that 
> every user will have SSD, thus we should try to get the best latencies 
> possible even on standard HD.

In that case controller (SAN) based write back cache as well as Striping
helps a bit.

Gruss
Bernd

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

Hi Roger,

>> Fair enough. That exaplains the behaviour. Would AIO help here? If we 
>> are able to enqueue next write before the first one is finished, it 
>> can start writing it immediately without waiting for a revolution.
> 
> If you could get them queued at the disk level, things that would need 
> to be watched were if the disk can queue things up (and all 
> controllers/drivers support it), and how many things the disk can queue 
> up, and how large each of those things can be, if they aren't queued at 
> the disk, there is the chance that the machine cannot get the data to 
> the disk faster enough for that next sector.
> 
> I have always avoided fully sync operations as things *ALWAYS* got 
> really really slow because of all of the requirements need to make sure 
> that it always got the data to disk correctly on a unexpected crash, and 
> typically the type of applications I dealt with, if the machine crashed 
> the currently outputting data was known to be incomplete and generally 
> useless, so things were reran.
> 
> Depending on your application you could always get a small fast solid 
> state device (no seek or RPM issues), and use it to keep a journal that 
> could be replayed on an unexpected crash...and then just use various 
> syncs to force things to disk at various points.

We've tried AIO and the results are quite disappointing. If you open the 
file with O_SYNC, the latencies are the same as with sync I/O - each 
write takes 8.3ms (7500rpm disk).

If you use O_ASYNC the latencies are nice (160us mean), however, the 
first one is ~900us meaning that the data were not physically written to 
the disk before AIO confirmation is sent. (Moving head to right position 
would take much more than 900us.)

Still, my feeling is that our use case is pretty straightforward, i.e. 
write data to the disk with any optimisations you are able to do and 
notify me when the data are physically written to the medium.

Isn't there a way to achieve this kind of behaviour?

Martin

Re: Higher than expected disk write(2) latency

[Jeff Moyer]

Martin Sustrik <sustrik@fastmq.com> writes:

> Hi Roger,
>
>>> Fair enough. That exaplains the behaviour. Would AIO help here? If
>>> we are able to enqueue next write before the first one is finished,
>>> it can start writing it immediately without waiting for a
>>> revolution.
>>
>> If you could get them queued at the disk level, things that would
>> need to be watched were if the disk can queue things up (and all
>> controllers/drivers support it), and how many things the disk can
>> queue up, and how large each of those things can be, if they aren't
>> queued at the disk, there is the chance that the machine cannot get
>> the data to the disk faster enough for that next sector.
>>
>> I have always avoided fully sync operations as things *ALWAYS* got
>> really really slow because of all of the requirements need to make
>> sure that it always got the data to disk correctly on a unexpected
>> crash, and typically the type of applications I dealt with, if the
>> machine crashed the currently outputting data was known to be
>> incomplete and generally useless, so things were reran.
>>
>> Depending on your application you could always get a small fast
>> solid state device (no seek or RPM issues), and use it to keep a
>> journal that could be replayed on an unexpected crash...and then
>> just use various syncs to force things to disk at various points.
>
> We've tried AIO and the results are quite disappointing. If you open
> the file with O_SYNC, the latencies are the same as with sync I/O -
> each write takes 8.3ms (7500rpm disk).

I thought you were doing I/O to the underlying block device.  If so,
there's no need to open with O_SYNC.  You do, however, need to open the
device with O_DIRECT and align your buffers (and buffer lengths)
properly.

Which AIO interface are you using, libaio or librt?  How many I/Os are
you queueing to the device?  You may want to take a look at aio-stress.c
as a way to test your device (this uses libaio, the in-kernel AIO
interface).

Cheers,

Jeff

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

> I thought you were doing I/O to the underlying block device.  If so,
> there's no need to open with O_SYNC.  You do, however, need to open the
> device with O_DIRECT and align your buffers (and buffer lengths)
> properly.

Yes, we are using O_DIRECT + aligning the buffers. However, usign O_SYNC 
vs. O_ASYNC seems to matter (different latency). Maybe this is because 
we are using librt?

> Which AIO interface are you using, libaio or librt?  How many I/Os are
> you queueing to the device?  You may want to take a look at aio-stress.c
> as a way to test your device (this uses libaio, the in-kernel AIO
> interface).

We are using librt, queueing 10240 writes, 512 bytes each.

We'll retry with libaio. Thanks for advice.

Martin

Re: Higher than expected disk write(2) latency

[Roger Heflin]

Martin Sustrik wrote:
> Hi Roger,
> 
>>> Fair enough. That exaplains the behaviour. Would AIO help here? If we 
>>> are able to enqueue next write before the first one is finished, it 
>>> can start writing it immediately without waiting for a revolution.
>>
>> If you could get them queued at the disk level, things that would need 
>> to be watched were if the disk can queue things up (and all 
>> controllers/drivers support it), and how many things the disk can 
>> queue up, and how large each of those things can be, if they aren't 
>> queued at the disk, there is the chance that the machine cannot get 
>> the data to the disk faster enough for that next sector.
>>
>> I have always avoided fully sync operations as things *ALWAYS* got 
>> really really slow because of all of the requirements need to make 
>> sure that it always got the data to disk correctly on a unexpected 
>> crash, and typically the type of applications I dealt with, if the 
>> machine crashed the currently outputting data was known to be 
>> incomplete and generally useless, so things were reran.
>>
>> Depending on your application you could always get a small fast solid 
>> state device (no seek or RPM issues), and use it to keep a journal 
>> that could be replayed on an unexpected crash...and then just use 
>> various syncs to force things to disk at various points.
> 
> We've tried AIO and the results are quite disappointing. If you open the 
> file with O_SYNC, the latencies are the same as with sync I/O - each 
> write takes 8.3ms (7500rpm disk).
> 
> If you use O_ASYNC the latencies are nice (160us mean), however, the 
> first one is ~900us meaning that the data were not physically written to 
> the disk before AIO confirmation is sent. (Moving head to right position 
> would take much more than 900us.)
> 
> Still, my feeling is that our use case is pretty straightforward, i.e. 
> write data to the disk with any optimisations you are able to do and 
> notify me when the data are physically written to the medium.
> 
> Isn't there a way to achieve this kind of behaviour?
> 
> Martin
> 

A lot depends on what your application requirements are.

Back in a long time ago, before disks had cache RLL and MFM drives used a trick 
called interleave, instead of writing to sector n, n+1,n+2 with a interleave of 
2 would write to n,n+2,n+4 as once they got the message that n was written the 
machine had enough time to setup and send the next write to sector n+2 before 
the head got there, the question with your hardware would be how many sectors 
need to be skipped to be able to write immediately (and this would change with 
hardware changes-and the file would need to be pre-allocated, and may have to 
have some testing done against the given file to quantify the underlying disk 
reality-and reality may change if the disk reallocates sectors), and this 
assumes that can you live with the lower sequential read performance-interleave 
of 2 had 1/2 the read performance, interleave of 3 had 1/3, though with proper 
sector picking and the read cache on the disk, this interleave my not kill the 
read performance if one goes n,n+2,...,n+2*x,n+1,n+3,... correctly knowing that 
n+2*x and n+1 are close in seek time and I don't have any idea what sort of 
interleave one would need to be using with modern hardware.

It would take a fairly intricate program to sort out what reality was, but it 
would seem to be possible to figure out exactly what reality is, and work with 
it.   And the first seek might take a while, but even that could be played 
around with by having marker sectors be written to all of the time so one has 
some idea of what is going to be under the head real soon, of course even if you 
could get all of this correct there are still unknowns of the disk not always 
doing what one expects since they do have a mind of their own, and the unknown 
of can you get the correct sector supplied through everything to the disk fast 
enough every time.

                             Roger

Re: Higher than expected disk write(2) latency

[David Dillow]

On Wed, 2008-07-02 at 20:20 +0200, Martin Sustrik wrote:
> We are using librt, queueing 10240 writes, 512 bytes each.
> 
> We'll retry with libaio. Thanks for advice.

I've gotten good results going direct to the Linux AIO calls, but before
you go too far from your existing code base, are you using a single file
descriptor with the librt aio_*() routines? If so, that may be part of
your problem, as the library will serialize requests to the same fd. I
just pre-dup()'d the descriptor for each of the (max 32) requests I'd
have in flight for a toy stress-tester I wrote. With 10240 requests,
that may be a bit excessive, but it'd point out if that was part of the
problem fairly quickly.

Re: Higher than expected disk write(2) latency

[Andrew Morton]

On Sat, 28 Jun 2008 14:11:32 +0200 Martin Lucina <mato@kotelna.sk> wrote:

> we're getting some rather high figures for write(2) latency when testing
> synchronous writing to disk.  The test I'm running writes 2000 blocks of
> contiguous data to a raw device, using O_DIRECT and various block sizes
> down to a minimum of 512 bytes.  
> 
> The disk is a Seagate ST380817AS SATA connected to an Intel ICH7
> using ata_piix.  Write caching has been explicitly disabled on the
> drive, and there is no other activity that should affect the test
> results (all system filesystems are on a separate drive).  The system is
> running Debian etch, with a 2.6.24 kernel.
> 
> Observed results:
> 
> size=1024, N=2000, took=4.450788 s, thput=3 mb/s seekc=1
> write: avg=8.388851 max=24.998846 min=8.335624 ms
> 8 ms: 1992 cases
> 9 ms: 2 cases
> 10 ms: 1 cases
> 14 ms: 1 cases
> 16 ms: 3 cases
> 24 ms: 1 cases

stoopid question 1: are you writing to a regular file, or to /dev/sda?  If
the former then metadata fetches will introduce glitches.

stoopid question 2: does the same effect happen with reads?

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

[-- Attachment #1: Type: text/plain, Size: 3702 bytes --]

Hi Andrew,

>> we're getting some rather high figures for write(2) latency when testing
>> synchronous writing to disk.  The test I'm running writes 2000 blocks of
>> contiguous data to a raw device, using O_DIRECT and various block sizes
>> down to a minimum of 512 bytes.  
>>
>> The disk is a Seagate ST380817AS SATA connected to an Intel ICH7
>> using ata_piix.  Write caching has been explicitly disabled on the
>> drive, and there is no other activity that should affect the test
>> results (all system filesystems are on a separate drive).  The system is
>> running Debian etch, with a 2.6.24 kernel.
>>
>> Observed results:
>>
>> size=1024, N=2000, took=4.450788 s, thput=3 mb/s seekc=1
>> write: avg=8.388851 max=24.998846 min=8.335624 ms
>> 8 ms: 1992 cases
>> 9 ms: 2 cases
>> 10 ms: 1 cases
>> 14 ms: 1 cases
>> 16 ms: 3 cases
>> 24 ms: 1 cases
> 
> stoopid question 1: are you writing to a regular file, or to /dev/sda?  If
> the former then metadata fetches will introduce glitches.

Not a file, just a raw device.

> stoopid question 2: does the same effect happen with reads?

Dunno. The read is not critical for us. However, I would expect the same 
behaviour (see below).

We've got a satisfying explansation of the behaviour from Roger Heflin:

"You write sector n and n+1, it takes some amount of time for that first 
set of sectors to come under the head, when it does you write it and 
immediately return.   Immediately after that you attempt write sector 
n+2 and n+3 which just a bit ago passed under the head, so you have to 
wait an *ENTIRE* revolution for those sectors to again come under the 
head to be written, another ~8.3ms, and you continue to repeat this with 
each block being written.   If the sector was randomly placed in the 
rotation (ie 50% chance of the disk being off by 1/2 a rotation or 
less-you would have a 4.15 ms average seek time for your test)-but the 
case of sequential sync writes this leaves the sector about as far as 
possible from the head (it just passed under the head)."

Now, the obvious solution was to use AIO to be able to enqueue write 
requests even before the head reaches the end of the sector - thus there 
would be no need for superfluous disk revolvings.

We've actually measured this scenario with kernel AIO (libaio1) and this 
is what we'vew got (see attached graph).

The x axis represents individual write operations, y axis represents 
time. Crosses are operations enqueue times (when write requests were 
issues), circles are times of notifications (when the app was notified 
that the write request was processed).

What we see is that AIO performs rather bad while we are still 
enqueueing more writes (it misses right position on the disk and has to 
do superfluous disk revolvings), however, once we stop enqueueing new 
write request, those already in the queue are processed swiftly.

My guess (I am not a kernel hacker) would be that sync operations on the 
AIO queue are slowing down the retrieval from the queue and thus we miss 
the right place on the disk almost all the time. Once app stops 
enqueueing new write requests there's no contention on the queue and we 
are able to catch up with the speed of disk rotation.

If this is the case, the solution would be straightforward: When 
dequeueing from AIO queue, dequeue *all* the requests in the queue and 
place them into another non-synchronised queue. Getting an element from 
a non-sync queue is matter of few nanoseconds, thus we should be able to 
process it before head missis the right point on the disk. Once the 
non-sync queue is empty, we get *all* the requests from the AIO queue 
again. Etc.

Anyone any opinion on this matter?

Thanks.
Martin

[-- Attachment #2: aio.png --]
[-- Type: image/png, Size: 3628 bytes --]

Re: Higher than expected disk write(2) latency

[Andrew Morton]

On Thu, 10 Jul 2008 10:12:12 +0200 Martin Sustrik <sustrik@fastmq.com> wrote:

> Hi Andrew,
> 
> >> we're getting some rather high figures for write(2) latency when testing
> >> synchronous writing to disk.  The test I'm running writes 2000 blocks of
> >> contiguous data to a raw device, using O_DIRECT and various block sizes
> >> down to a minimum of 512 bytes.  
> >>
> >> The disk is a Seagate ST380817AS SATA connected to an Intel ICH7
> >> using ata_piix.  Write caching has been explicitly disabled on the
> >> drive, and there is no other activity that should affect the test
> >> results (all system filesystems are on a separate drive).  The system is
> >> running Debian etch, with a 2.6.24 kernel.
> >>
> >> Observed results:
> >>
> >> size=1024, N=2000, took=4.450788 s, thput=3 mb/s seekc=1
> >> write: avg=8.388851 max=24.998846 min=8.335624 ms
> >> 8 ms: 1992 cases
> >> 9 ms: 2 cases
> >> 10 ms: 1 cases
> >> 14 ms: 1 cases
> >> 16 ms: 3 cases
> >> 24 ms: 1 cases
> > 
> > stoopid question 1: are you writing to a regular file, or to /dev/sda?  If
> > the former then metadata fetches will introduce glitches.
> 
> Not a file, just a raw device.
> 
> > stoopid question 2: does the same effect happen with reads?
> 
> Dunno. The read is not critical for us. However, I would expect the same 
> behaviour (see below).
> 
> We've got a satisfying explansation of the behaviour from Roger Heflin:
> 
> "You write sector n and n+1, it takes some amount of time for that first 
> set of sectors to come under the head, when it does you write it and 
> immediately return.   Immediately after that you attempt write sector 
> n+2 and n+3 which just a bit ago passed under the head, so you have to 
> wait an *ENTIRE* revolution for those sectors to again come under the 
> head to be written, another ~8.3ms, and you continue to repeat this with 
> each block being written.   If the sector was randomly placed in the 
> rotation (ie 50% chance of the disk being off by 1/2 a rotation or 
> less-you would have a 4.15 ms average seek time for your test)-but the 
> case of sequential sync writes this leaves the sector about as far as 
> possible from the head (it just passed under the head)."
> 
> Now, the obvious solution was to use AIO to be able to enqueue write 
> requests even before the head reaches the end of the sector - thus there 
> would be no need for superfluous disk revolvings.
> 
> We've actually measured this scenario with kernel AIO (libaio1) and this 
> is what we'vew got (see attached graph).
> 
> The x axis represents individual write operations, y axis represents 
> time. Crosses are operations enqueue times (when write requests were 
> issues), circles are times of notifications (when the app was notified 
> that the write request was processed).
> 
> What we see is that AIO performs rather bad while we are still 
> enqueueing more writes (it misses right position on the disk and has to 
> do superfluous disk revolvings), however, once we stop enqueueing new 
> write request, those already in the queue are processed swiftly.
> 
> My guess (I am not a kernel hacker) would be that sync operations on the 
> AIO queue are slowing down the retrieval from the queue and thus we miss 
> the right place on the disk almost all the time. Once app stops 
> enqueueing new write requests there's no contention on the queue and we 
> are able to catch up with the speed of disk rotation.
> 
> If this is the case, the solution would be straightforward: When 
> dequeueing from AIO queue, dequeue *all* the requests in the queue and 
> place them into another non-synchronised queue. Getting an element from 
> a non-sync queue is matter of few nanoseconds, thus we should be able to 
> process it before head missis the right point on the disk. Once the 
> non-sync queue is empty, we get *all* the requests from the AIO queue 
> again. Etc.
> 
> Anyone any opinion on this matter?

Not immediately, but the fine folks on the linux-aio list might be able to
help out.  If you have some simple testcase code which you can share then
that would help things along.  

Re: Higher than expected disk write(2) latency

[Alan Cox]

> What we see is that AIO performs rather bad while we are still 
> enqueueing more writes (it misses right position on the disk and has to 
> do superfluous disk revolvings), however, once we stop enqueueing new 
> write request, those already in the queue are processed swiftly.

Which disk scheduler are you using - some of the disk schedulers
intentionally delay writes to try and get better block merging.

Alan

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

Hi Alan,

>> What we see is that AIO performs rather bad while we are still 
>> enqueueing more writes (it misses right position on the disk and has to 
>> do superfluous disk revolvings), however, once we stop enqueueing new 
>> write request, those already in the queue are processed swiftly.
> 
> Which disk scheduler are you using - some of the disk schedulers
> intentionally delay writes to try and get better block merging.

It's CFQ. Does it delay writes? And if so, what should we use instead?

Thanks.
Martin

Re: Higher than expected disk write(2) latency

[Andrew Morton]

On Thu, 10 Jul 2008 15:17:47 +0200 Martin Sustrik <sustrik@fastmq.com> wrote:

> Hi Alan,
> 
> >> What we see is that AIO performs rather bad while we are still 
> >> enqueueing more writes (it misses right position on the disk and has to 
> >> do superfluous disk revolvings), however, once we stop enqueueing new 
> >> write request, those already in the queue are processed swiftly.
> > 
> > Which disk scheduler are you using - some of the disk schedulers
> > intentionally delay writes to try and get better block merging.
> 
> It's CFQ. Does it delay writes? And if so, what should we use instead?
> 

noop is the simplest scheduler.  deadline is the simplest real scheduler,
and deadline doesn't have any delaying logic.

If CFQ or anticipatory _are_ putting delays into this workload, that'd be
a bug.

Re: Higher than expected disk write(2) latency

[Chris Mason]

On Thu, 2008-07-10 at 01:14 -0700, Andrew Morton wrote:
> On Thu, 10 Jul 2008 10:12:12 +0200 Martin Sustrik <sustrik@fastmq.com> wrote:
> 
> > Hi Andrew,
> > 
> > >> we're getting some rather high figures for write(2) latency when testing
> > >> synchronous writing to disk.  The test I'm running writes 2000 blocks of
> > >> contiguous data to a raw device, using O_DIRECT and various block sizes
> > >> down to a minimum of 512 bytes.  
> > >>
> > >> The disk is a Seagate ST380817AS SATA connected to an Intel ICH7
> > >> using ata_piix.  Write caching has been explicitly disabled on the
> > >> drive, and there is no other activity that should affect the test
> > >> results (all system filesystems are on a separate drive).  The system is
> > >> running Debian etch, with a 2.6.24 kernel.

Is NCQ enabled on the drive?  The basic way to fix this is to have
multiple requests in flight, which isn't going to happen on sata with
the cache off and with ncq off.

So, AIO + NCQ should be fast, as long as your application has multiple
requests in flight through aio (or multiple threads).

-chris

Re: Higher than expected disk write(2) latency

[Martin Lucina]

chris.mason@oracle.com said:
> Is NCQ enabled on the drive?  The basic way to fix this is to have
> multiple requests in flight, which isn't going to happen on sata with
> the cache off and with ncq off.

ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata1.00: ATA-7: Hitachi HDS721616PLA380, P22OAB3A, max UDMA/133
ata1.00: 321672960 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata1.00: configured for UDMA/133

I'm assuming the above indicates NCQ is enabled.

We'll try running the tests tomorrow with different i/o schedulers and
report back.

-mato

Re: Higher than expected disk write(2) latency

[Arjan van de Ven]

On Thu, 10 Jul 2008 15:41:46 +0200
Martin Lucina <mato@kotelna.sk> wrote:

> chris.mason@oracle.com said:
> > Is NCQ enabled on the drive?  The basic way to fix this is to have
> > multiple requests in flight, which isn't going to happen on sata
> > with the cache off and with ncq off.
> 
> ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> ata1.00: ATA-7: Hitachi HDS721616PLA380, P22OAB3A, max UDMA/133
> ata1.00: 321672960 sectors, multi 0: LBA48 NCQ (depth 31/32)
> ata1.00: configured for UDMA/133
> 
> I'm assuming the above indicates NCQ is enabled.
> 
> We'll try running the tests tomorrow with different i/o schedulers and
> report back.


another thing to try is using AHCI mode instead; AHCI tends to be
higher performance

(and.. for fun try to run latencytop during a run, to see if maybe
there are unsuspected delay causes)

-- 
If you want to reach me at my work email, use arjan@linux.intel.com
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

Re: Higher than expected disk write(2) latency

[Chris Mason]

On Thu, 2008-07-10 at 07:01 -0700, Arjan van de Ven wrote:
> On Thu, 10 Jul 2008 15:41:46 +0200
> Martin Lucina <mato@kotelna.sk> wrote:
> 
> > chris.mason@oracle.com said:
> > > Is NCQ enabled on the drive?  The basic way to fix this is to have
> > > multiple requests in flight, which isn't going to happen on sata
> > > with the cache off and with ncq off.
> > 
> > ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
> > ata1.00: ATA-7: Hitachi HDS721616PLA380, P22OAB3A, max UDMA/133
> > ata1.00: 321672960 sectors, multi 0: LBA48 NCQ (depth 31/32)
> > ata1.00: configured for UDMA/133
> > 
> > I'm assuming the above indicates NCQ is enabled.
> > 
> > We'll try running the tests tomorrow with different i/o schedulers and
> > report back.
> 
> 
> another thing to try is using AHCI mode instead; AHCI tends to be
> higher performance
> 
> (and.. for fun try to run latencytop during a run, to see if maybe
> there are unsuspected delay causes)
> 
Any latencies during submit (at least for kernel aio) are probably from
get_request_wait, but the numbers so far look like they are only seeing
one request in flight at a time.

-chris

Re: Higher than expected disk write(2) latency

[Martin Sustrik]

Hi all,

> Which disk scheduler are you using - some of the disk schedulers
> intentionally delay writes to try and get better block merging.

We've run the test with different I/O schedulers. We've found out that 
poor performance we've seen before was due to the short AIO queue size. 
Now, when queue size is big enough to hold all the write requests in the 
test, the results are much better. Have a look here for the code of the 
test and the results in form of graphs:

http://www.zeromq.org/results:aio

There are still at least two problems I see:

1. Enqueueing of writes seems to block every now and then although the 
size of AIO queue is large enough to hold all the requests in the test.

2. We've observed that messages are batched for writes by approximately 
30 per batch. The latency impact of messages 2-30 is almost zero, 
however, the impact of the first message is much higher than expected. I 
would expect latency of one disk revolving (8.3 ms) + optionally latency 
of head movement (say 10 us). What we are seing are latencies of 30-60 ms.

Martin