raid5 write latency is 10x the drive latency

raid5 write latency is 10x the drive latency

[Alexander Lyakas]

Hi Neil,

We are testing a fully random 8K write IOMETER workload on a raid5 md,
composed of 5 drives. Initial resync is fully completed.

We see that the write latency that the MD device demonstrates is 10
times the latency of individual drives. Typical iostat output is:

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s
avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
dm-28             0.00     0.00  235.05  883.51   940.21  3448.97
7.85    77.88   62.86   50.68   66.10   0.67  75.46
dm-30             0.00     0.00  230.93  881.44   923.71  3440.72
7.85    68.90   55.31   59.45   54.22   0.70  77.94
dm-32             0.00     0.00  185.57  846.39   742.27  3300.52
7.84    59.39   51.10   44.98   52.44   0.56  57.73
dm-33             0.00     0.00  232.99  864.95   931.96  3374.74
7.85    46.72   34.92   31.06   35.96   0.45  49.48
dm-35             0.00     0.00  265.98  895.88  1063.92  3498.45
7.85    62.14   46.43   41.09   48.01   0.56  65.15
md4               0.00     0.00    0.00  263.92     0.00 12338.14
93.50     0.00    0.00    0.00    0.00   0.00   0.00
dm-37             0.00     0.00    0.00  263.92     0.00 12338.14
93.50   128.54  505.81    0.00  505.81   3.89 102.68

dm-28,30,32,33,35 are MD individual devices.
dm-37 is a linear Device Mapper device stacked on top of md4, to see
the MD performance (for some reason MD doesn't show r/w latencies in
iostat).

I understand that with RMW that raid5 is doing, we can expect 2x of
the drive latency (1x to load the stipe-head, 1x to update the
required stripe-head blocks on disk). However, I am trying to
understand where the rest of the latency is coming from.

One thing I see is that with such random workload, raid5d thread is
busy updating the bitmap in stack like this:
[<ffffffff81569f05>] md_super_wait+0x55/0x90
[<ffffffff815709e8>] bitmap_unplug.part.21+0x158/0x160
[<ffffffff81570a12>] bitmap_unplug+0x22/0x30
[<ffffffffa0702f57>] raid5d+0xe7/0x570 [raid456]
[<ffffffff8156344d>] md_thread+0x10d/0x140
[<ffffffff8107f050>] kthread+0xc0/0xd0
[<ffffffff816f61ec>] ret_from_fork+0x7c/0xb0
[<ffffffffffffffff>] 0xffffffffffffffff

So I understand that given a single-threaded nature of raid5, when
raid5d() is doing the bitmap update, it delays the processing of all
stripe-heads.

So I commented out the bitmap_unplug call, just to see if there is
some other problem. Things are better now, but still:
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s
avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
dm-27             0.00     0.00  254.74 1317.89  1018.95  5271.58
8.00   137.68   87.55   92.98   86.50   0.49  77.05
dm-29             0.00     0.00  269.47 1345.26  1077.89  5381.05
8.00   146.44  104.24   81.36  108.82   0.52  83.79
dm-32             0.00     0.00  267.37 1345.26  1069.47  5381.05
8.00   130.10   94.34   73.72   98.44   0.48  76.63
dm-33             0.00     0.00  267.37 1343.16  1069.47  5372.63
8.00    87.61   54.40   52.19   54.84   0.34  55.16
dm-36             0.00     0.00  271.58 1355.79  1086.32  5423.16
8.00   136.33   97.45   81.77  100.59   0.47  76.63
md4               0.00     0.00    0.00  454.74     0.00 21911.58
96.37     0.00    0.00    0.00    0.00   0.00   0.00
dm-37             0.00     0.00    0.00  454.74     0.00 21911.58
96.37   132.05  330.82    0.00  330.82   2.31 105.26

So it looks like about ~100ms are lost somewhere (assuming ~100ms +
~100ms for reading and writing the stripe head).

I tried to profile raid5d looking for some other blocking operation it
might be doing. And I don't see one. Typically - without the bitmap
update - raid5 call takes 400-500us, so I don't understand how the
additional ~100ms of latency is gained. (With the bitmap update,
raid5d is significantly delayed by it, which delayes all the
processing). Do you have an idea why there is a latency difference?

Thanks,
Alex.

Re: raid5 write latency is 10x the drive latency

[Peter Grandi]

> We are testing a fully random 8K write IOMETER workload on a
> raid5 md, composed of 5 drives. [ ... ]

"Doctor, if I stab my hand very hard with a fork it hurts a lot,
what can you do about that?"

> We see that the write latency that the MD device demonstrates

Congratulations on reckoning that write latency matters. People
who think they know better and use parity RAID usually manage to
forget about write latency.

Also congratulations on using a reasonable member count of 4+1.

> is 10 times the latency of individual drives. [ ... ]

The latency of what actually?

That's what 'iostat' reports for "something". The definition of
'await' if that's what you are looking may be interesting.

Also, what does your tool report?

  BTW, why not use 'fio' which along with some versions of
  Garloff's version of 'bonnie' is one of the few reliable
  speed-testing tools (with the right options...).

Also what type of device? Which size of the stripe cache (very
important)?

Which chunk size? Which drive write cache setting? Which use of
barriers? Which filesystem? Which elevator? Which flusher
parameters? Which tool settings? How many threads?

Because some of the numbers look a bit amazing or strange:

* Only 20% of IOPS are reads, which is pretty miraculous.

* 'dm-33' seems significantly faster (seek times) than the other
  members.

* Each drive delivers over 1,000 4kiB IOPS (mixed r/W), which is
  also pretty miraculous if they are disk drives, and terrible if
  they are flash drives.

* That ~50ms full wait-time per IO seems a bit high to me at a
  device utilization of around 70%, and a bit inconsistent with
  the ability of each device to process 1,000 IOPS.

* In your second set of numbers utilization remains the same,the
  per-disk write await doubles to around 90-100ms, average queue
  size nearly doubles too, but 4kiB write IOPS go up to by 50%,
  and the percent of reads goes down to 16.6% almost exactly.
  These numbers tell a story, a pretty strong story.

> [ ... ] with RMW that raid5 is doing, we can expect 2x of the
> drive latency

HAHAHAHAHAHA! HAHAHAHAHAHAHAHAHA! You made my day.

> (1x to load the stipe-head, 1x to update the required
> stripe-head blocks on disk).

Amazing! Send patches! :-)

> raid5d thread is busy updating the bitmap

Using a bitmap and worrying about write latency, I had not even
thought about that as a possibility. Extremely funny!

> commented out the bitmap_unplug call

Ah plugging/unplugging one of the great examples of sheer
"genius" in the Linux code. We can learn a lot from it :-).

> Typically - without the bitmap update - raid5 call takes
> 400-500us, so I don't understand how the additional ~100ms of
> latency is gained

That's really really funny! Thanks! :-)

Re: raid5 write latency is 10x the drive latency

[Peter Grandi]

> [ ... ] Which tool settings? [ ... ]

As to this, how are the 8KiB writes aligned? To 1KiB? 4KiB?
8KiB? To something else?

Is there any other activity on the same physical disks given
that the RAID members seem to be LVs?

Also what's the size of those LV members of the MD set? It may
be quite small...

Re: raid5 write latency is 10x the drive latency

[Alexander Lyakas]

Peter,
Thank you for your response.

On Tue, Mar 4, 2014 at 12:15 AM, Peter Grandi <pg@lxra2.for.sabi.co.uk> wrote:
>> We are testing a fully random 8K write IOMETER workload on a
>> raid5 md, composed of 5 drives. [ ... ]
>
> "Doctor, if I stab my hand very hard with a fork it hurts a lot,
> what can you do about that?"
>
>> We see that the write latency that the MD device demonstrates
>
> Congratulations on reckoning that write latency matters. People
> who think they know better and use parity RAID usually manage to
> forget about write latency.
>
> Also congratulations on using a reasonable member count of 4+1.
Thank you, Peter.


>
>> is 10 times the latency of individual drives. [ ... ]
>
> The latency of what actually?
>
> That's what 'iostat' reports for "something". The definition of
> 'await' if that's what you are looking may be interesting.
>
Yes, r_await and w_await is what I am looking at.

> Also, what does your tool report?
>
>   BTW, why not use 'fio' which along with some versions of
>   Garloff's version of 'bonnie' is one of the few reliable
>   speed-testing tools (with the right options...).
>
> Also what type of device? Which size of the stripe cache (very
> important)?
>
> Which chunk size? Which drive write cache setting? Which use of
> barriers? Which filesystem? Which elevator? Which flusher
> parameters? Which tool settings? How many threads?
As you probably know, each entry in the MD stripe cache is a kind of a
mini-stripe of 4K blocks (this is what is called "struct stripe_head"
in the code). So for example, when using 64K MD chunk size and 8K
write-size, it may be required to load and update 2 stripe-heads to
satisfy the write. With 4K write-size and 4K MD chunk size, for
example, it is needed to load and update a single stripe-head to
satisfy the write.
In my test, MD chunk size is 64K, so yes, it is needed to load more
than one stripe-head each time. With 4K write-size, there is not much
difference, actually, there are still some milliseconds "unaccounted".

As for other parameters you mentioned, I can post all of them, but at
this point, I only care how much write latency MD adds above the write
latency that the drives demonstrate. I am not sure why you find this
funny, BTW.

>
> Because some of the numbers look a bit amazing or strange:
>
> * Only 20% of IOPS are reads, which is pretty miraculous.
>
> * 'dm-33' seems significantly faster (seek times) than the other
>   members.
>
> * Each drive delivers over 1,000 4kiB IOPS (mixed r/W), which is
>   also pretty miraculous if they are disk drives, and terrible if
>   they are flash drives.
>
> * That ~50ms full wait-time per IO seems a bit high to me at a
>   device utilization of around 70%, and a bit inconsistent with
>   the ability of each device to process 1,000 IOPS.
>
> * In your second set of numbers utilization remains the same,the
>   per-disk write await doubles to around 90-100ms, average queue
>   size nearly doubles too, but 4kiB write IOPS go up to by 50%,
>   and the percent of reads goes down to 16.6% almost exactly.
>   These numbers tell a story, a pretty strong story.
>

>> [ ... ] with RMW that raid5 is doing, we can expect 2x of the
>> drive latency
>
> HAHAHAHAHAHA! HAHAHAHAHAHAHAHAHA! You made my day.
>
>> (1x to load the stipe-head, 1x to update the required
>> stripe-head blocks on disk).
>
> Amazing! Send patches! :-)
I studied the raid5 code at some point, and here is the flow for
writing a 4Kb block onto a 2+1 raid5 with 4K chunk size:

add_stripe_bio: bio is attached to the stripe
analyse_stripe
handle_stripe_fill
handle_stripe_dirtying: here the second data drive is marked for "read"
ops_run_io: here it submits the READ bio
raid5_end_read_request: READ bio is completed, raid5d will complete
handling this stripe
analyse_stripe
handle_stripe_dirtying()->schedule_reconstruction()
__raid_run_ops
ops_run_biodrain: here user bio is copied into the stripe-head's block
of the data drive that we didn't read
ops_run_reconstruct5
ops_complete_reconstruct: parity calculation is done, processing will
resume in raid5d
analyse_stripe
handle_stripe: sets R5_Wantwrite on the parity and data r5devs
ops_run_io: schedules the writes
raid5_end_write_request: called two times: on parity and data drive
This completes the flow, and eventually user bio is completed.

So besides loaing and writing out the stripe-head, there is only the
parity calculation, which I don't know at this point how much time
does it take. (In my test, the CPU had a good amount of idle time,
BTW).
Do you agree that this is the flow? Or you see some other places,
where millis can be spent, which I missed?

>
>> raid5d thread is busy updating the bitmap
>
> Using a bitmap and worrying about write latency, I had not even
> thought about that as a possibility. Extremely funny!
Can you please clarify what to do you find so funny here? Should I not
use the bitmap?

>
>> commented out the bitmap_unplug call
>
> Ah plugging/unplugging one of the great examples of sheer
> "genius" in the Linux code. We can learn a lot from it :-).
Again, can you please clarify? I was only trying to see whether raid5d
does some other blocking operation, besides the bitmap update, and I
learned that it doesn't. I realize that the bitmap update is required,
just wanted to see if there is anything else that was blocking. Do you
see anything wrong with this approach?

>
>> Typically - without the bitmap update - raid5 call takes
>> 400-500us, so I don't understand how the additional ~100ms of
>> latency is gained
>
> That's really really funny! Thanks! :-)
Again, can you please clarify? I am happy to make your day, but if
since you have taken time to comment on my email, I would like to at
least understand what you meant.

Thanks,
Alex.

> --
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: raid5 write latency is 10x the drive latency

[Alexander Lyakas]

On Tue, Mar 4, 2014 at 1:29 AM, Peter Grandi <pg@lxra2.for.sabi.co.uk> wrote:
>> [ ... ] Which tool settings? [ ... ]
>
> As to this, how are the 8KiB writes aligned? To 1KiB? 4KiB?
> 8KiB? To something else?
They were 4Kb aligned. Looking at the code, I don't think it matters
much; if I had them them 8K aligned, it would still be required to
load/update 2 stripe-heads for each write.

>
> Is there any other activity on the same physical disks given
> that the RAID members seem to be LVs?
They are device-mapper devices (but not LVs), and there was no other
activity. The device-mappers lead to drives behind MegaRAID write-back
caching. (Something tells me you will find this funny at best, but as
I mentioned, I am just trying to understand how much write latency MD
can add on top of drives latencies).

>
> Also what's the size of those LV members of the MD set? It may
> be quite small...
Each one is 560GB. The whole MD usable space is ~2.2TB, so with a
random workload over such huge capacity, MD stripe cache cannot help
anyways. You need to load and update new stripe-heads every write.
This was the purpose of the test. In my case, I had 1024 stripe-heads,
while only up to 500 of them were active.

Alex.

> --
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: raid5 write latency is 10x the drive latency

[Peter Grandi]

>> Also what type of device? Which size of the stripe cache
>> (very important)?  Which chunk size? Which drive write cache
>> setting? Which use of barriers? Which filesystem? Which
>> elevator? Which flusher parameters? Which tool settings? How
>> many threads?

> As you probably know, each entry in the MD stripe cache is a
> kind of a mini-stripe of 4K blocks (this is what is called
> "struct stripe_head" in the code).

Agreed, and I have been calling them "stripelet".

So we both share the notion that a 64KiB*(4+1) stripe with a
data capacity of 256KiB is actually made of 16 "mini-stripes" or
"stripelets" of 4KiB*(4+1) "pages". I had asked a specific
question about this some time ago:

  http://sourceforge.net/p/jfs/mailman/message/27438194/

Now it is interesting to note that within a stripe, all
stripelets share the same parity device, but if a write crosses
stripes the parity devices are diffent.

> [ ... ] In my test, MD chunk size is 64K, so yes, it is needed
> to load more than one stripe-head each time. [ ... ]

> As for other parameters you mentioned, I can post all of them,
> but at this point, I only care how much write latency MD adds
> above the write latency that the drives demonstrate. I am not
> sure why you find this funny, BTW.

Because it is so amazingly (euphemism alert) optimistic.

You are wondering about latency, and you seem to consider
caching, barriers, elevator, flusher, etc. irrelevant to that
story, as if they did not have a massive and *variable* impact
on latency. MD RAID is in theory and in practice "just" an IO
remapper (and multiplexer), but the total latency you see is a
product of all the latencies of the components between program
and storage medium.

I have tried to give same very explicit hints as to how this
matters, pointing out very loudly that your overall results are
quite "unexpected":

>> Because some of the numbers look a bit amazing or strange:
>> 
>> * Only 20% of IOPS are reads, which is pretty miraculous.
>> [ ... ]
>> * Each drive delivers over 1,000 4kiB IOPS (mixed r/W), which is
>> also pretty miraculous if they are disk drives, and terrible if
>> they are flash drives.
>> [ ... ]
>> and the percent of reads goes down to 16.6% almost exactly.
>> These numbers tell a story, a pretty strong story.

The story the numbers tell you is: the throughput you are
getting is way too high for 8KiB random writes on a RAID5, and
the number of reads is way too low:

  If writing in each stripelet 2x 4kiB pages out of 4+1,
  the code has to write at least 2x data pages and a
  parity page, and to compute the new value of the parity
  page has two options:
    * read the other 2x data pages, compute new parity page
      from all 4x data pages.
    * read current parity page, the old contents of the 2x data
      pages, subtract them from the parity page.
  Either way it is 2x reads or 3x reads, every 3x writes.

Therefore *obviously* random IOPS are being turned into
sequential ones. We are seeing over 1,000 IOPS per member device
on a purely random test, and disk drives can do at best 100-150
random IOPS. You are not bothering to say what kind of devices
you are using, but it matters a great deal to understanding what
is going on to compare the IOPS observed with the peak ones the
devices are doing. it is amazingly (euphemism alert) optimistic
to assume that "details" like elevator, drive caching, type of
device etc. are irrelevant, because they don't add a *constant*
chunk of latency.

The *obvious* conclusion is that the whole IO subsystem is
trading *massively* latency for throughput. The page cache, the
elevator, the stripe cache, etc. are all there to try and turn
random RMW into sequential pure writes as much as possible.

>>> [ ... ] with RMW that raid5 is doing, we can expect 2x of the
>>> drive latency
>> 
>> HAHAHAHAHAHA! HAHAHAHAHAHAHAHAHA! You made my day.

>>> (1x to load the stipe-head, 1x to update the required
>>> stripe-head blocks on disk).
>> 
>> Amazing! Send patches! :-)

> I studied the raid5 code at some point,

That's irrelevant without a realistic insight on what *must* be
going on.

> and here is the flow for writing a 4Kb block onto a 2+1 raid5
> with 4K chunk size:

That's a bit of a different case and is irrelevant.

> So besides loaing and writing out the stripe-head, there is
> only the parity calculation, which I don't know at this point
> how much time does it take. (In my test, the CPU had a good
> amount of idle time, BTW). Do you agree that this is the flow?
> Or you see some other places, where millis can be spent, which
> I missed?

>>> raid5d thread is busy updating the bitmap
>> 
>> Using a bitmap and worrying about write latency, I had not even
>> thought about that as a possibility. Extremely funny!

> Can you please clarify what to do you find so funny here?

That's so extremely funny I must be disturbing the neighbours
with my guffaws...

The analysis above is based on the peculiar assumption that MD
RAID5 is a "pure" IO remapper and multiplexer, and indeed it is,
from the point of view of logic flow. But from the point of view
of *event* flow, of timing, MD RAID5 must be very careful indeed
to preserve proper semantics, and this means achieving something
like "transactions". This implies very subtle and very costly
(in terms of latency) ordering and locking of reads and writes.

Because MD RAID5 is reading and writing to several devices whose
content is changing all the time, with very different speeds,
and potential different failures, and must give programs the
illusion that they are dealing with a single device with
reliable, consistent behaviour. For example a request to MD can
only complete when all the sequence of transactions involved in
the request have completed, and this for example involves
careful locking and ordering of updates to the parity page, to
the bitmap (if present), to the event counter in the per-device
MD superblock. All those updates must happen in the right order,
without overlapping with those from other transactions, and they
must all complete before an MD write can be considered complete.
Never mind that the current position (seek arm for disks) on
each device could be completely different, and the efforts of
the elevator are extremely time dependent and also massively
skew latency.

RAID5 does not just turn a logical request into a few device
requests and then returns "done"!

Never mind for example the effects using a filesystem type with
a journal, and the type of journal matters a great deal too.

> Should I not use the bitmap?

That is a tradeoff. using the bitmap as your numbers show has
two effects:

* IO patterns on the storage devices become significantly more
  random (if the bitmap is 'internal').
* All MD updates must wait for completion of the bitmap update
  before returning.

Is that worth the faster reconstruction? You choose.

>>> commented out the bitmap_unplug call
>> 
>> Ah plugging/unplugging one of the great examples of sheer
>> "genius" in the Linux code. We can learn a lot from it :-).

> Again, can you please clarify?

Plugging/unplugging is a sheer "genius" idea, aimed at trading
latency for throughput, in a very "genius" way. Nothing to do
with your troubles, it was just an aside to try and give you yet
another massive hint about latency vs. throughput tradeoffs.

> I was only trying to see whether raid5d does some other
> blocking operation, besides the bitmap update, and I learned
> that it doesn't.

Those 'R5_LOCKED' flags must not be present in the version of
code you have seen. There are many hints on how complicated
ordering and locking of RAID5 operations in:

  http://lxr.free-electrons.com/source/drivers/md/raid5.h

The section "Plugging:" (line 343) seems also pretty explicit.
etc. etc. But looking at the code is a bit blind...

> I realize that the bitmap update is required, just wanted to
> see if there is anything else that was blocking. Do you see
> anything wrong with this approach?

>>> Typically - without the bitmap update - raid5 call takes
>>> 400-500us, so I don't understand how the additional ~100ms
>>> of latency is gained

>> That's really really funny! Thanks! :-)

> Again, can you please clarify? I am happy to make your day,
> but if since you have taken time to comment on my email, I
> would like to at least understand what you meant.

Well, you seem to have tuned (by default or explicitly) your
whole IO subsystem to have as much latency as possible, for the
purpose of having higher throughput, and then you act surprised.

>> As to this, how are the 8KiB writes aligned? To 1KiB? 4KiB?
>> 8KiB? To something else?

> They were 4Kb aligned. Looking at the code, I don't think it
> matters much; if I had them them 8K aligned, it would still be
> required to load/update 2 stripe-heads for each write.

There is a small question of whether writes that cross stripe
boundaries are possible and/or frequent.

Also note that writing 8KiB within the same stripe means that
the two stripelets have the same parity drive, across stripes it
means different parity drives.

>> Is there any other activity on the same physical disks given
>> that the RAID members seem to be LVs?

> They are device-mapper devices (but not LVs),

An LV is just a device mapper device. LVM2 is just a frontend to
DM.

> and there was no other activity. The device-mappers lead to
> drives behind MegaRAID write-back caching. (Something tells me
> you will find this funny at best, [ ... ]

Uhmmmm, that is indeed (euphemism alert) not that awesome. More
caching, more strange things in the MegaRAID firmware...

> [ ... ] I am just trying to understand how much write latency
> MD can add on top of drives latencies).

HAHAHA HAHAHAHA. Indeed very funny. :-).

>> Also what's the size of those LV members of the MD set? It may
>> be quite small...

> Each one is 560GB. The whole MD usable space is ~2.2TB, so with a
> random workload over such huge capacity, MD stripe cache cannot help
> anyways.

But then how is it possible that you have such huge latencies
and such low read rates? You have reported 'iostat' output with
1 read every 5 writes, while I would expect 40%/60% or 50%/50%.

From a very similar test on a RAID5 I had created for fun, with
a tiny 'fio' test like this:

  bs=8k
  ioengine=libaio
  iodepth=4
  size=400g
  fsync=4
  runtime=60
  directory=/fs/tmp
  filename=FIO-TEST

  [rand-write]
  rw=randwrite
  stonewall</pre>

I see something like this:

  Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
  sdc2             45.00     6.00   20.00  111.00   260.00   452.00    10.87     1.22    9.34    4.20   10.27   2.32  30.40
  sdd2             48.00     8.00   29.00  117.00   308.00   500.00    11.07     1.34    9.15   12.55    8.31   2.82  41.20
  sde2             42.00     6.00   19.00  109.00   244.00   444.00    10.75     1.14    8.91    7.79    9.10   2.59  33.20
  sdf2             35.00     5.00   22.00  107.00   228.00   464.00    10.73     1.02    7.66    7.27    7.74   2.26  29.20
  sdg2             40.00     7.00   23.00  106.00   252.00   452.00    10.91     1.12    8.47    7.65    8.64   2.39  30.80
  md2               0.00     0.00    0.00  100.00     0.00  1344.00    26.88     0.00    0.00    0.00    0.00   0.00   0.00

Here the numbers are as expected: around 100-110 random IOPS per
device and a plausible ratio of reads to writes, plausible
transfer rates, with device latencies that look very much like
typical seek latencies, and MD latencies reported by 'fio'
between 20-50ms.

  Note: 7200RPM 1TB contemporary SATA drives, except for 'sdd2'
  which is a bit slower, IIRC default MD stripe cache, much
  tigther than default flusher parameters, 'deadline' elevator,
  barriers, ...).

Re: raid5 write latency is 10x the drive latency

[Peter Grandi]

[ ... ]
>>> Because some of the numbers look a bit amazing or strange:
>>> 
>>> * Only 20% of IOPS are reads, which is pretty miraculous.
>>> [ ... ]
>>> * Each drive delivers over 1,000 4kiB IOPS (mixed r/W), which is
>>> also pretty miraculous if they are disk drives, and terrible if
>>> they are flash drives.
>>> [ ... ]
>>> and the percent of reads goes down to 16.6% almost exactly.
>>> These numbers tell a story, a pretty strong story.
[ ... ]
> From a very similar test on a RAID5 I had created for fun, [ ... ]
>  Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
>  sdc2             45.00     6.00   20.00  111.00   260.00   452.00    10.87     1.22    9.34    4.20   10.27   2.32  30.40
>  sdd2             48.00     8.00   29.00  117.00   308.00   500.00    11.07     1.34    9.15   12.55    8.31   2.82  41.20
>  sde2             42.00     6.00   19.00  109.00   244.00   444.00    10.75     1.14    8.91    7.79    9.10   2.59  33.20
>  sdf2             35.00     5.00   22.00  107.00   228.00   464.00    10.73     1.02    7.66    7.27    7.74   2.26  29.20
>  sdg2             40.00     7.00   23.00  106.00   252.00   452.00    10.91     1.12    8.47    7.65    8.64   2.39  30.80
>  md2               0.00     0.00    0.00  100.00     0.00  1344.00    26.88     0.00    0.00    0.00    0.00   0.00   0.00

I have redone the test with more details. Same hardware, a
contemporary PC with an ADM 6100 CPU, 8GiB of RAM, several
7200RPM 1TB contemporary SATA drives, entirely quiet. The MD
RAID set was created out of 112GiB partitions in the outer (but
not outermost) cylinders. One drive slower than the other 4.

------------------------------------------------------------------------
  #  mdadm -C /dev/md2 -f -c 64 -l 5 -n 5 /dev/sd{c,d,e,f}2 missing
  mdadm: array /dev/md2 started.
  #  echo 200000 >| /sys/block/md2/md/sync_speed_min 
  #  echo 500000 >| /sys/block/md2/md/sync_speed_max
  #  mdadm /dev/md2 --add /dev/sdg2
  mdadm: added /dev/sdg2
  #  grep -A2 md2 /proc/mdstat 
  md2 : active raid5 sdg2[5] sdc2[0] sdf2[3] sde2[2] sdd2[1]
	486538752 blocks super 1.0 level 5, 64k chunk, algorithm 2 [5/4] [UUUU_]
	[>....................]  recovery =  3.7% (4581684/121634688) finish=26.1min speed=74591K/sec</li>
  #  grep -A2 md2 /proc/mdstat 
  md2 : active raid5 sdg2[5] sdc2[0] sdf2[3] sde2[2] sdd2[1]
	486538752 blocks super 1.0 level 5, 64k chunk, algorithm 2 [5/5] [UUUUU]
------------------------------------------------------------------------
  #  mkfs.xfs -f -s size=4096 -i size=512,attr=2 -l size=64m,su=256k -L tmp /dev/md2
  meta-data=/dev/md2               isize=512    agcount=16, agsize=7602160 blks
	   =                       sectsz=4096  attr=2, projid32bit=0
  data     =                       bsize=4096   blocks=121634560, imaxpct=25
	   =                       sunit=16     swidth=64 blks
  naming   =version 2              bsize=4096   ascii-ci=0
  log      =internal log           bsize=4096   blocks=16384, version=2
	   =                       sectsz=4096  sunit=64 blks, lazy-count=1
  realtime =none                   extsz=4096   blocks=0, rtextents=0
  #  mount -t xfs -o defaults,inode64,barrier /dev/md2 /fs/tmp
  #  echo 32000 >| /sys/block/md2/md/stripe_cache_size
------------------------------------------------------------------------

At this point I started 'iostat -dkxz sd{c,d,e,f,g}2 md2' in
another window, and manually created the file for 'fio', having
raised the 'stripe_cache' to speed that up a bit, as 256 is a
bit too low:

------------------------------------------------------------------------
  #  dd bs=1M count=420000 if=/dev/zero conv=fsync of=/fs/tmp/FIO-TEST
  420000+0 records in
  420000+0 records out
  440401920000 bytes (440 GB) copied, 1128.98 s, 390 MB/s
  #  filefrag /fs/tmp/FIO-TEST 
  /fs/tmp/FIO-TEST: 27 extents found
------------------------------------------------------------------------

During the 'dd' to create the file 'iostat' reported something
like:

  Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
  sdc2             16.00 25583.00   10.00  238.00   104.00 103656.00   836.77     3.99   16.13   32.40   15.45   3.32  82.40
  sdd2             30.00 25569.00    9.00  242.00   160.00 103616.00   826.90     3.03   12.13   17.78   11.92   3.03  76.00
  sde2              9.00 25569.00    2.00  238.00    44.00 102076.00   851.00     4.71   18.43  104.00   17.71   3.60  86.40
  sdf2             21.00 25564.00    3.00  248.00    96.00 103620.00   826.42     9.88   39.39   58.67   39.16   3.90  98.00
  sdg2             17.00 25553.00    5.00  256.00    88.00 103620.00   794.70    10.74   41.18   72.80   40.56   3.75  98.00
  md2               0.00     0.00    0.00 6349.00     0.00 404176.00   127.32     0.00    0.00    0.00    0.00   0.00   0.00

The I run the random RW test with what I regard as
semi-plausible options:

------------------------------------------------------------------------
  #  cat /root/fio-randomw.ini
  [global]
  bs=8k
  ioengine=libaio
  iodepth=2
  size=400g
  fsync=4
  runtime=60
  directory=/fs/tmp
  filename=FIO-TEST

  [rand-write]
  rw=randwrite
  stonewall
------------------------------------------------------------------------
  #  fio /root/fio-randomw.ini
  rand-write: (g=0): rw=randwrite, bs=8K-8K/8K-8K, ioengine=libaio, iodepth=2
  fio 1.59
  Starting 1 process
  Jobs: 1 (f=1): [w] [100.0% done] [0K/261K /s] [0 /31  iops] [eta 00m:00s]
  rand-write: (groupid=0, jobs=1): err= 0: pid=32227
    write: io=16192KB, bw=276269 B/s, iops=33 , runt= 60016msec
      slat (usec): min=12 , max=73 , avg=18.28, stdev= 7.31
      clat (usec): min=16 , max=394656 , avg=29652.40, stdev=53335.77
       lat (usec): min=29 , max=394669 , avg=29671.12, stdev=53333.29
      bw (KB/s) : min=  156, max=  338, per=100.31%, avg=269.84, stdev=34.30
    cpu          : usr=0.02%, sys=0.34%, ctx=4717, majf=0, minf=23
    IO depths    : 1=0.1%, 2=100.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
       submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
       complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
       issued r/w/d: total=0/2024/0, short=0/0/0
       lat (usec): 20=43.73%, 50=31.23%, 100=0.05%
       lat (msec): 100=6.27%, 250=18.68%, 500=0.05%

  Run status group 0 (all jobs):
    WRITE: io=16192KB, aggrb=269KB/s, minb=276KB/s, maxb=276KB/s, mint=60016msec, maxt=60016msec

  Disk stats (read/write):
    md2: ios=0/4279, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, aggrios=1111/13535, aggrmerge=3096/738, aggrticks=15718/142220, aggrin_queue=157931, aggrutil=52.91%
      sdd: ios=1140/13698, merge=3162/742, ticks=20808/158072, in_queue=178864, util=52.91%
      sde: ios=1064/13477, merge=2893/694, ticks=16804/128884, in_queue=145680, util=41.19%
      sdf: ios=1059/13479, merge=2864/738, ticks=11832/117780, in_queue=129604, util=35.02%
      sdc: ios=1178/13773, merge=3377/773, ticks=13316/125512, in_queue=138828, util=38.35%
      sdg: ios=1117/13251, merge=3186/745, ticks=15832/180852, in_queue=196680, util=45.99%
------------------------------------------------------------------------

The above seems pretty clear to me. During the above a typical
'iostat' report looks like:

  Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
  sdc2             12.00    12.00   15.00  207.00   108.00   876.00     8.86     2.08    9.39   15.20    8.97   1.08  24.00
  sdd2             13.00    13.00   14.00  158.00   108.00   684.00     9.21     2.45   14.26   26.86   13.14   1.91  32.80
  sde2             12.00    12.00   14.00  158.00   104.00   680.00     9.12     2.08   12.09   19.43   11.44   1.60  27.60
  sdf2             12.00    12.00   13.00  151.00   100.00   652.00     9.17     1.68   10.24   15.08    9.83   1.44  23.60
  sdg2             11.00    11.00   12.00  181.00    92.00   704.00     8.25     4.81   29.58   16.33   30.45   2.16  41.60
  md2               0.00     0.00    0.00   64.00     0.00  2112.00    66.00     0.00    0.00    0.00    0.00   0.00   0.00

Which seems entirely plausible to me. Having rerun the same
test with a stripe cache size of 256 I get:

  Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
  sdc2            119.00    14.00   22.00  191.00   564.00   820.00    13.00     2.39   11.23    9.64   11.41   1.37  29.20
  sdd2            103.00    13.00   30.00  187.00   532.00   800.00    12.28     2.29   10.54   17.60    9.41   1.95  42.40
  sde2             70.00    10.00   15.00  164.00   340.00   696.00    11.58     1.76    9.83   12.53    9.59   1.43  25.60
  sdf2             66.00     7.00   15.00  138.00   324.00   580.00    11.82     1.63   10.67    6.93   11.07   1.23  18.80
  sdg2             93.00    14.00   25.00  171.00   472.00   740.00    12.37     2.59   13.22   15.52   12.89   1.86  36.40
  md2               0.00     0.00    0.00   69.00     0.00  2304.00    66.78     0.00    0.00    0.00    0.00   0.00   0.00

By varying 'iodepth' and 'fsync' I get interesting variation;
larger device latencies and much larger MD latencies (hundreds
of ms) happen with many threads, which is (euphemism alert)
unsurprising.

>>>> [ ... ] is 10 times the latency of individual drives. [ ... ]

>>> The latency of what actually? [ ... ] The definition of
>>> 'await' if that's what you are looking may be interesting.
>>> [ ... ] Because some of the numbers look a bit amazing or
>>> strange: [ ... ] Which tool settings? How many threads? [
>>> ... ]

Apposite :-).

>> Also what's the size of those LV members of the MD set? It
>> may be quite small...

Guessing wildly, the strange 'iostat' reports might indicate
that the IOMETER test has been run "inadvertently" against a
very small file/area compared to the number of threads, and
their strangeness should have raised "concerns".

Re: raid5 write latency is 10x the drive latency

[NeilBrown]

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

On Mon, 3 Mar 2014 15:28:02 +0200 Alexander Lyakas <alex.bolshoy@gmail.com>
wrote:

> Hi Neil,
> 
> We are testing a fully random 8K write IOMETER workload on a raid5 md,
> composed of 5 drives. Initial resync is fully completed.
> 
> We see that the write latency that the MD device demonstrates is 10
> times the latency of individual drives. Typical iostat output is:
> 
> Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s
> avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
> dm-28             0.00     0.00  235.05  883.51   940.21  3448.97
> 7.85    77.88   62.86   50.68   66.10   0.67  75.46
> dm-30             0.00     0.00  230.93  881.44   923.71  3440.72
> 7.85    68.90   55.31   59.45   54.22   0.70  77.94
> dm-32             0.00     0.00  185.57  846.39   742.27  3300.52
> 7.84    59.39   51.10   44.98   52.44   0.56  57.73
> dm-33             0.00     0.00  232.99  864.95   931.96  3374.74
> 7.85    46.72   34.92   31.06   35.96   0.45  49.48
> dm-35             0.00     0.00  265.98  895.88  1063.92  3498.45
> 7.85    62.14   46.43   41.09   48.01   0.56  65.15
> md4               0.00     0.00    0.00  263.92     0.00 12338.14
> 93.50     0.00    0.00    0.00    0.00   0.00   0.00
> dm-37             0.00     0.00    0.00  263.92     0.00 12338.14
> 93.50   128.54  505.81    0.00  505.81   3.89 102.68
> 
> dm-28,30,32,33,35 are MD individual devices.
> dm-37 is a linear Device Mapper device stacked on top of md4, to see
> the MD performance (for some reason MD doesn't show r/w latencies in
> iostat).
> 
> I understand that with RMW that raid5 is doing, we can expect 2x of
> the drive latency (1x to load the stipe-head, 1x to update the
> required stripe-head blocks on disk). However, I am trying to
> understand where the rest of the latency is coming from.
> 
> One thing I see is that with such random workload, raid5d thread is
> busy updating the bitmap in stack like this:
> [<ffffffff81569f05>] md_super_wait+0x55/0x90
> [<ffffffff815709e8>] bitmap_unplug.part.21+0x158/0x160
> [<ffffffff81570a12>] bitmap_unplug+0x22/0x30
> [<ffffffffa0702f57>] raid5d+0xe7/0x570 [raid456]
> [<ffffffff8156344d>] md_thread+0x10d/0x140
> [<ffffffff8107f050>] kthread+0xc0/0xd0
> [<ffffffff816f61ec>] ret_from_fork+0x7c/0xb0
> [<ffffffffffffffff>] 0xffffffffffffffff
> 
> So I understand that given a single-threaded nature of raid5, when
> raid5d() is doing the bitmap update, it delays the processing of all
> stripe-heads.
> 
> So I commented out the bitmap_unplug call, just to see if there is
> some other problem. Things are better now, but still:
> Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s
> avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
> dm-27             0.00     0.00  254.74 1317.89  1018.95  5271.58
> 8.00   137.68   87.55   92.98   86.50   0.49  77.05
> dm-29             0.00     0.00  269.47 1345.26  1077.89  5381.05
> 8.00   146.44  104.24   81.36  108.82   0.52  83.79
> dm-32             0.00     0.00  267.37 1345.26  1069.47  5381.05
> 8.00   130.10   94.34   73.72   98.44   0.48  76.63
> dm-33             0.00     0.00  267.37 1343.16  1069.47  5372.63
> 8.00    87.61   54.40   52.19   54.84   0.34  55.16
> dm-36             0.00     0.00  271.58 1355.79  1086.32  5423.16
> 8.00   136.33   97.45   81.77  100.59   0.47  76.63
> md4               0.00     0.00    0.00  454.74     0.00 21911.58
> 96.37     0.00    0.00    0.00    0.00   0.00   0.00
> dm-37             0.00     0.00    0.00  454.74     0.00 21911.58
> 96.37   132.05  330.82    0.00  330.82   2.31 105.26

Peter already hinted something along these lines, but to make it explicit:

Consider the wkB/s column:  The number for md4 is about the same as the sum
 of any 4 numbers for dm-27..dm-36.  This is expected as the writes will be
 spread evenly and parity writes will be added.
Now consider the rkB/s column in comparison.  We see about 1/5 the reads to
writes.  For a read-modify-write cycle you would see equal numbers.  The 1:5
ratio suggests that on average one device is read for each whole-stripe write.

Now look at w/s.  Each device sees about 1300 write requests.  md4 sees about
450.  So the array sees 4 times the kB/sec, but 1/3 the ops per sec.  This
averages out at the operations seen by the array being 12 times the
size of the requests seen by the devices.  The device requests are at least
4K, so the array requests are at least 48K.
A 48K write to a 5-drive raid5 with 8k chunks will fill 1.5 full stripes.  No
wonder most of the writes don't require a read.

I don't really know how to interpret the *await fields.  When I care about
latency I prefer to run blktrace and extract out the actual events I'm
interested in.  Then find the latency for each and graph them,

By the way, commenting out bitmap_unplug effectively removes the bitmap
protection.  It allows data to be written while the bit is still clear in the
bitmap so in the case of a crash the resync might not fix everything.

NeilBrown



> 
> So it looks like about ~100ms are lost somewhere (assuming ~100ms +
> ~100ms for reading and writing the stripe head).
> 
> I tried to profile raid5d looking for some other blocking operation it
> might be doing. And I don't see one. Typically - without the bitmap
> update - raid5 call takes 400-500us, so I don't understand how the
> additional ~100ms of latency is gained. (With the bitmap update,
> raid5d is significantly delayed by it, which delayes all the
> processing). Do you have an idea why there is a latency difference?
> 
> Thanks,
> Alex.


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: raid5 write latency is 10x the drive latency

[Alexander Lyakas]

Thank you, Neil and Peter, for your comments.

On Wed, Mar 5, 2014 at 6:58 AM, NeilBrown <neilb@suse.de> wrote:
> On Mon, 3 Mar 2014 15:28:02 +0200 Alexander Lyakas <alex.bolshoy@gmail.com>
> wrote:
>
>> Hi Neil,
>>
>> We are testing a fully random 8K write IOMETER workload on a raid5 md,
>> composed of 5 drives. Initial resync is fully completed.
>>
>> We see that the write latency that the MD device demonstrates is 10
>> times the latency of individual drives. Typical iostat output is:
>>
>> Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s
>> avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
>> dm-28             0.00     0.00  235.05  883.51   940.21  3448.97
>> 7.85    77.88   62.86   50.68   66.10   0.67  75.46
>> dm-30             0.00     0.00  230.93  881.44   923.71  3440.72
>> 7.85    68.90   55.31   59.45   54.22   0.70  77.94
>> dm-32             0.00     0.00  185.57  846.39   742.27  3300.52
>> 7.84    59.39   51.10   44.98   52.44   0.56  57.73
>> dm-33             0.00     0.00  232.99  864.95   931.96  3374.74
>> 7.85    46.72   34.92   31.06   35.96   0.45  49.48
>> dm-35             0.00     0.00  265.98  895.88  1063.92  3498.45
>> 7.85    62.14   46.43   41.09   48.01   0.56  65.15
>> md4               0.00     0.00    0.00  263.92     0.00 12338.14
>> 93.50     0.00    0.00    0.00    0.00   0.00   0.00
>> dm-37             0.00     0.00    0.00  263.92     0.00 12338.14
>> 93.50   128.54  505.81    0.00  505.81   3.89 102.68
>>
>> dm-28,30,32,33,35 are MD individual devices.
>> dm-37 is a linear Device Mapper device stacked on top of md4, to see
>> the MD performance (for some reason MD doesn't show r/w latencies in
>> iostat).
>>
>> I understand that with RMW that raid5 is doing, we can expect 2x of
>> the drive latency (1x to load the stipe-head, 1x to update the
>> required stripe-head blocks on disk). However, I am trying to
>> understand where the rest of the latency is coming from.
>>
>> One thing I see is that with such random workload, raid5d thread is
>> busy updating the bitmap in stack like this:
>> [<ffffffff81569f05>] md_super_wait+0x55/0x90
>> [<ffffffff815709e8>] bitmap_unplug.part.21+0x158/0x160
>> [<ffffffff81570a12>] bitmap_unplug+0x22/0x30
>> [<ffffffffa0702f57>] raid5d+0xe7/0x570 [raid456]
>> [<ffffffff8156344d>] md_thread+0x10d/0x140
>> [<ffffffff8107f050>] kthread+0xc0/0xd0
>> [<ffffffff816f61ec>] ret_from_fork+0x7c/0xb0
>> [<ffffffffffffffff>] 0xffffffffffffffff
>>
>> So I understand that given a single-threaded nature of raid5, when
>> raid5d() is doing the bitmap update, it delays the processing of all
>> stripe-heads.
>>
>> So I commented out the bitmap_unplug call, just to see if there is
>> some other problem. Things are better now, but still:
>> Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s
>> avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
>> dm-27             0.00     0.00  254.74 1317.89  1018.95  5271.58
>> 8.00   137.68   87.55   92.98   86.50   0.49  77.05
>> dm-29             0.00     0.00  269.47 1345.26  1077.89  5381.05
>> 8.00   146.44  104.24   81.36  108.82   0.52  83.79
>> dm-32             0.00     0.00  267.37 1345.26  1069.47  5381.05
>> 8.00   130.10   94.34   73.72   98.44   0.48  76.63
>> dm-33             0.00     0.00  267.37 1343.16  1069.47  5372.63
>> 8.00    87.61   54.40   52.19   54.84   0.34  55.16
>> dm-36             0.00     0.00  271.58 1355.79  1086.32  5423.16
>> 8.00   136.33   97.45   81.77  100.59   0.47  76.63
>> md4               0.00     0.00    0.00  454.74     0.00 21911.58
>> 96.37     0.00    0.00    0.00    0.00   0.00   0.00
>> dm-37             0.00     0.00    0.00  454.74     0.00 21911.58
>> 96.37   132.05  330.82    0.00  330.82   2.31 105.26
>
> Peter already hinted something along these lines, but to make it explicit:
>
> Consider the wkB/s column:  The number for md4 is about the same as the sum
>  of any 4 numbers for dm-27..dm-36.  This is expected as the writes will be
>  spread evenly and parity writes will be added.
> Now consider the rkB/s column in comparison.  We see about 1/5 the reads to
> writes.  For a read-modify-write cycle you would see equal numbers.  The 1:5
> ratio suggests that on average one device is read for each whole-stripe write.
>
> Now look at w/s.  Each device sees about 1300 write requests.  md4 sees about
> 450.  So the array sees 4 times the kB/sec, but 1/3 the ops per sec.  This
> averages out at the operations seen by the array being 12 times the
> size of the requests seen by the devices.  The device requests are at least
> 4K, so the array requests are at least 48K.
> A 48K write to a 5-drive raid5 with 8k chunks will fill 1.5 full stripes.  No
> wonder most of the writes don't require a read.
>
> I don't really know how to interpret the *await fields.  When I care about
> latency I prefer to run blktrace and extract out the actual events I'm
> interested in.  Then find the latency for each and graph them,
>
> By the way, commenting out bitmap_unplug effectively removes the bitmap
> protection.  It allows data to be written while the bit is still clear in the
> bitmap so in the case of a crash the resync might not fix everything.
>
> NeilBrown
>
>
>
>>
>> So it looks like about ~100ms are lost somewhere (assuming ~100ms +
>> ~100ms for reading and writing the stripe head).
>>
>> I tried to profile raid5d looking for some other blocking operation it
>> might be doing. And I don't see one. Typically - without the bitmap
>> update - raid5 call takes 400-500us, so I don't understand how the
>> additional ~100ms of latency is gained. (With the bitmap update,
>> raid5d is significantly delayed by it, which delayes all the
>> processing). Do you have an idea why there is a latency difference?
>>
>> Thanks,
>> Alex.
>