Re: AW: WG: Re: read performance much slower than write

"Also sprach Hoffmann Christian:"
> Before I started testing I set the blocksize to 4096 on all server with
> blockdev --setra 4096 /dev/... which I think improved the performance a bit.
> For the tests I also set up the raid5 array new and added chunk-size=4 which
> sets the chuck-size to 4K.

Sounds good.

> I started testing with time dd and got the following results for:
> 
> Local disk on server:
> time dd if=/dev/sdc1 of=/dev/null bs=4K
> 2002092+1 Datens_tze ein
> 2002092+1 Datens_tze aus
> 8200571904 bytes transferred in 51,904124 seconds (157994612 bytes/sec)

So read is 157MB/s on the sever.

> 
> real    0m51.978s
> user    0m0.680s
> sys     0m21.379s
> 
> 
> Enbd Device on client (/dev/nda):

But what is the resurce? The /dev/sdc1.

> time dd if=/dev/nda of=/dev/null bs=4K
> 2002092+0 Datens_tze ein
> 2002092+0 Datens_tze aus
> 8200568832 bytes transferred in 129,429907 seconds (63359150 bytes/sec)

OK, that's 63MB/s reading over enbd.  That sounds good to me. The
holdup looks to be the transport, since as I recall the cpu is not
working very hard (but you need to check both sides). It is likely that
a reactive protocol has problems over Gigabit ethernet, because every
transfer needs a (small, synchronous) ack.

> 
> real    2m9.432s
> user    0m0.889s
> sys     0m9.831s
> 
> 
> Raid Device on client (raid5 /dev/md0):
> time dd if=/dev/md0 of=/dev/null bs=4K
> 6006192+0 Datens_tze ein
> 6006192+0 Datens_tze aus
> 24601362432 bytes transferred in 730,017786 seconds (33699675 bytes/sec)

Not sure what is meant here. Is this a raid over three enbd devices?
Then read is 33MB/s, which is more or less comprehensible... well,
in general terms. With a stripe of 4K and a blocksize of 4K I don't see
how one read can generate more than one read over the wire.

Anyway, it's clear that putting in the raid level decreases read speed by
half.

> 
> real    12m10.027s
> user    0m2.529s
> sys     1m19.665s
> 
> 
> Raid Device on server (local disk 3 partitions /dev/sdc2-4 software raid
> /dev/md5):
>  time dd if=/dev/md5 of=/dev/null bs=4K
> 4004160+0 Datens_tze ein
> 4004160+0 Datens_tze aus
> 16401039360 bytes transferred in 970,346423 seconds (16902252 bytes/sec)

So you are testing only on the server side. Read is at full velocity,
which implies that changing the transport does the trick.

> real    16m10.366s
> user    0m1.999s
> sys     0m34.909s
> 
> For the tests I used no filesystem as you suggested.
> 
> I do not think that software raid is the bottleneck, at least not on local
> discs.

But I am not saying it is! Maybe you do not understand what I am saying
- which is that adding software raid into the mix causes a drop in
speed.

> Here is the output of /proc/nbdinfo:
> 
> Device a:       Open
> [a] State:      verify, rw, merge requests, enabled, validated, show_errs,
> last error 0, lives 4, bp 0
> [a] Queued:     +0R/0W curr (check 0R/0W) +254R/226W max
> [a] Buffersize: 262144  (sectors=512, blocks=64)
> [a] Blocksize:  4096    (log=12)
> [a] Size:       8008368KB
> [a] Blocks:     2002092
> [a] Sockets:    2       (*)     (+)
> [a] Requested:  16.072M (8.20M) (7.87M) 11.81MR/4.255MW max 64
> [a] Despatched: 16.072M (8.20M) (7.87M) 11.81MR/4.255MW md5 16.4KW (12.4K
> eq, 3.99K ne, 0 dn)
> [a] Errored:    2       (1)     (1)     2+0
> [a] Pending:    0       (0)     (0)     0R/0W+0R/0W
> [a] B/s now:    0       (0R+0W)
> [a] B/s ave:    3.78G   (3.67GR+113MW)
> [a] B/s max:    3.45G   (3.29GR+1.85GW)
> [a] Spectrum:   63%1    7%2     17%3    1%16    3%32

OK - well about 2/3 of the the transfers are single block. This will
slow things down over Gigabit ethernet (goodness knows how Ge works at
all!) because every transfer has to be followed by a small ack.


> [a] Kthreads:   0       (0 waiting/0 running/2 max)
> [a] Cthreads:   2       (+)     (+)
> [a] Cpids:      2       (3969)  (3970)
> Device b:       Open
> [b] State:      verify, rw, merge requests, enabled, validated, show_errs,
> last error 0, lives 4, bp 0
> [b] Queued:     +0R/0W curr (check 0R/0W) +254R/226W max
> [b] Buffersize: 262144  (sectors=512, blocks=64)
> [b] Blocksize:  4096    (log=12)
> [b] Size:       8008368KB
> [b] Blocks:     2002092
> [b] Sockets:    2       (+)     (*)
> [b] Requested:  14.163M (7.08M) (7.08M) 9.905MR/4.258MW max 64
> [b] Despatched: 14.163M (7.08M) (7.08M) 9.905MR/4.258MW md5 4.11KW (524 eq,
> 3.59K ne, 0 dn)
> [b] Errored:    2       (1)     (1)     2+0
> [b] Pending:    0       (0)     (0)     0R/0W+0R/0W
> [b] B/s now:    0       (0R+0W)
> [b] B/s ave:    1.49G   (1.36GR+132MW)
> [b] B/s max:    1.03G   (3.57GR+1.45GW)
> [b] Spectrum:   63%1    7%2     18%3    1%16    1%32

Exactly the same.

> [b] Kthreads:   0       (0 waiting/0 running/2 max)
> [b] Cthreads:   2       (+)     (+)
> [b] Cpids:      2       (3963)  (3964)
> Device c:       Open
> [c] State:      verify, rw, merge requests, enabled, validated, show_errs,
> last error 0, lives 4, bp 0
> [c] Queued:     +0R/0W curr (check 0R/0W) +254R/229W max

Max 254 requests on the queue at one time. Hmm.

> [c] Buffersize: 262144  (sectors=512, blocks=64)
> [c] Blocksize:  4096    (log=12)
> [c] Size:       8008368KB
> [c] Blocks:     2002092
> [c] Sockets:    2       (+)     (*)
> [c] Requested:  14.163M (7.06M) (7.09M) 9.908MR/4.254MW max 64
> [c] Despatched: 14.163M (7.06M) (7.09M) 9.908MR/4.254MW md5 26.7KW (21.8K
> eq, 4.83K ne, 0 dn)
> [c] Errored:    2       (1)     (1)     2+0
> [c] Pending:    0       (0)     (0)     0R/0W+0R/0W
> [c] B/s now:    0       (0R+0W)
> [c] B/s ave:    1.49G   (1.36GR+129MW)
> [c] B/s max:    3.09G   (3.42GR+3.66GW)
> [c] Spectrum:   63%1    7%2     18%3    1%16    1%32

And again.

> [c] Kthreads:   0       (0 waiting/0 running/2 max)
> [c] Cthreads:   2       (+)     (+)
> [c] Cpids:      2       (3965)  (3968)
> Device d:       Open
> [d] State:      verify, rw, merge requests, enabled, validated, show_errs,
> last error 0, lives 4, bp 0
> [d] Queued:     +0R/0W curr (check 0R/0W) +122R/230W max

Well, it only ever had 122 read requests on the queue at one time. I
think the max is 512.

> [d] Buffersize: 262144  (sectors=512, blocks=64)
> [d] Blocksize:  4096    (log=12)
> [d] Size:       8008368KB
> [d] Blocks:     2002092
> [d] Sockets:    2       (*)     (+)
> [d] Requested:  14.163M (7.09M) (7.06M) 4.552MR/9.610MW max 64
> [d] Despatched: 14.163M (7.09M) (7.06M) 4.552MR/9.610MW md5 3.31MW (3.30M
> eq, 5.44K ne, 0 dn)
> [d] Errored:    2       (1)     (1)     2+0
> [d] Pending:    0       (0)     (0)     0R/0W+0R/0W
> [d] B/s now:    0       (0R+0W)
> [d] B/s ave:    1.49G   (372MR+1.12GW)
> [d] B/s max:    992M    (3.06GR+1.90GW)
> [d] Spectrum:   63%1    7%2     18%3    1%16    1%32
> [d] Kthreads:   0       (0 waiting/0 running/2 max)
> [d] Cthreads:   2       (+)     (+)
> [d] Cpids:      2       (3966)  (3967)
> Device e-p:     Closed
> 
> 
> 
> Hope the results are useful,

Yes - it shows something along the lines of what I imagined - the
interposition of raid at the client side over enbd is causing the kernel
to pass many small requests to enbd, which is bad for transfer over Ge.

There's little one can do about it, because the requests arriving at
the enbd driver are NOT contiguous (thanks to raid), so the driver
cannot aggregate them much.

What I imagine would help is several different request queues for enbd,
so that it can accumulate more requests on each and thus have a greater
chance of doing aggregation on each. I suspect that the way raid
splits up the placements on disk may in general sabotage the elevator
algorithm that is used for aggregation. 

What kernel did you say this was?

I think one could load several enbd drivers, each on a different major,
and use one each for each enbd device of yours. That would separate the
queues. One can load the driver with major=XX. The result might be
better aggregation.

You could try turning of merge_requests, and seeing if the performance
gets worse. If it does, that indicates the theory is correct.


Peter