Hello,
On Wed, 01 Feb 2017 11:43:02 +0100 Eugen Block wrote:
> Hi,
>
> I haven't tracked the slow requests yet, but I ran some performance
> tests. Although I'm not an expert, I believe the results are quite
> unsatisfying.
>
You've told us absolutely nothing about your cluster that would be
relevant to determine if your results are actually to be expected or not.
Anything, and I mean anything is relevant, from OS, kernel, Ceph versions
to a detailed description of ALL HW in there, CPU, RAM, SSD, HDD, network,
topology, etc.
> I ran a couple of rados bench tests in a pool, with different
> replication sizes (1 to 3). The tests were executed on one of the ceph
> nodes, which also is a monitor.
>
Benchmarks, including rados bench run from a cluster node that also hosts
OSDs will give you skewed results.
> Results for size 1:
>
> Total time run: 20.428947
> Total writes made: 639
> Write size: 4194304
> Bandwidth (MB/sec): 125.117
>
This and the following results would be on par with a smallish, 1Gb/s
network HDD based cluster.
But we don't know if that's what you're running or not...
> Results for size 2:
>
> Total time run: 20.741990
> Total writes made: 454
> Write size: 4194304
> Bandwidth (MB/sec): 87.552
>
> Still looks nice, at least we would be totally fine with this throughput.
>
As mentioned countless times here, throughput is most likely your least
worry with Ceph, IOPS are more likely to be your bottleneck.
> Results for size 3:
>
> Total time run: 22.934567
> Total writes made: 252
> Write size: 4194304
> Bandwidth (MB/sec): 43.951
>
> I guess this is still ok for a replication size of 3. But the real
> problem seems to be the client throughput.
>
> Running fio on a Xen-VM inside rbd:
>
Since when does Xen support Ceph?
As in, how are you running a Xen VM that uses Ceph?
> Run status group 0 (all jobs):
> WRITE: io=1024.0MB, aggrb=21776KB/s, minb=21776KB/s,
> maxb=21776KB/s, mint=48151msec, maxt=48151msec
>
> And this is one of the better results, we often have values of 12MB/s
> or even lower, e.g. on a KVM-VM:
>
> Run status group 0 (all jobs):
> WRITE: io=512000KB, aggrb=6425KB/s, minb=6425KB/s, maxb=6425KB/s,
> mint=79683msec, maxt=79683msec
>
Fio results w/o the full command line parameters are basically worthless,
I'm afraid.
> This unacceptable!
>
> I use almost all defaults in our ceph.conf,
What did you change that could be relevant then?
> I've been reading
> everything I could find on Google, but I don't understand why the
> clients are so slow. Is it a valid assumption, that the slow requests
> could be caused by our slow clients?
>
Slow requests are caused typically when your cluster is not capable of
keeping up.
> One of the things I tried was
>
> vm1:~ # echo 4096 > /sys/block/xvda/queue/read_ahead_kb
>
Only affects reads.
> but this had no effect. I tried it with different numbers of PGs, but
> that also didn't have any effect.
>
Again, w/o knowing your cluster and these numbers, that information is of
little value.
> What else can I do to increase the performance of my instances or to
> analyse the bottleneck?
>
Understand your HW/cluster.
Monitor the nodes with atop etc, use collectd and graphite, etc, to keep
records of what happened when and to visualize things.
Christian
> Regards,
> Eugen
>
>
> Zitat von Brad Hubbard <bhubbard@xxxxxxxxxx>:
>
> > Check the latency figures in a "perf dump". High numbers in a
> > particular area may help you nail it.
> >
> > I suspect though, that it may come down to enabling debug logging and
> > tracking a slow request through the logs.
> >
> > On Thu, Jan 12, 2017 at 8:41 PM, Eugen Block <eblock@xxxxxx> wrote:
> >> Hi,
> >>
> >>> Looking at the output of dump_historic_ops and dump_ops_in_flight
> >>
> >>
> >> I waited for new slow request messages and dumped the historic_ops into a
> >> file. The reporting OSD shows lots of "waiting for rw locks" messages and a
> >> duration of more than 30 secs:
> >>
> >> "age": 366.044746,
> >> "duration": 32.491506,
> >> "type_data": [
> >> "commit sent; apply or cleanup",
> >> {
> >> "client": "client.9664429",
> >> "tid": 130439910
> >> },
> >> [
> >> {
> >> "time": "2017-01-12 10:38:15.227649",
> >> "event": "initiated"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:15.232310",
> >> "event": "reached_pg"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:15.232341",
> >> "event": "waiting for rw locks"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:15.268819",
> >> "event": "reached_pg"
> >> },
> >> [
> >> .
> >> .
> >> .
> >> ]
> >> {
> >> "time": "2017-01-12 10:38:45.515055",
> >> "event": "waiting for rw locks"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:46.921095",
> >> "event": "reached_pg"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:46.921157",
> >> "event": "started"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:46.921342",
> >> "event": "waiting for subops from 9,15"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:46.921724",
> >> "event": "commit_queued_for_journal_write"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:46.922186",
> >> "event": "write_thread_in_journal_buffer"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:46.931103",
> >> "event": "sub_op_commit_rec"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:46.968730",
> >> "event": "sub_op_commit_rec"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:47.717770",
> >> "event": "journaled_completion_queued"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:47.718280",
> >> "event": "op_commit"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:47.718359",
> >> "event": "commit_sent"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:47.718890",
> >> "event": "op_applied"
> >> },
> >> {
> >> "time": "2017-01-12 10:38:47.719154",
> >> "event": "done"
> >> }
> >>
> >>
> >> There were about 70 events "waiting for rw locks", I truncated the output.
> >> Based on the message "waiting for subops from 9,15" I also dumped the
> >> historic_ops for these two OSDs.
> >>
> >> Duration on OSD.9
> >>
> >> "initiated_at": "2017-01-12 10:38:29.258221",
> >> "age": 54.069919,
> >> "duration": 20.831568,
> >>
> >> Duration on OSD.15
> >>
> >> "initiated_at": "2017-01-12 10:38:23.695098",
> >> "age": 112.118210,
> >> "duration": 26.452526,
> >>
> >> They also contain many "waiting for rw locks" messages, but not as much as
> >> the dump from the reporting OSD.
> >> To me it seems that because two OSDs take a lot of time to process their
> >> requests (only slightly less than 30 secs), it sums up to more than 30 secs
> >> on the reporting (primary?) OSD. Is the reporting OSD always the primary?
> >>
> >> How can I debug this further? I searched the web for "waiting for rw locks",
> >> I also found Wido's blog [1] about my exact problem, but I'm not sure how to
> >> continue. Our admin says our network should be fine, but what can I do to
> >> rule that out?
> >>
> >> I don't think I have provided information about our cluster yet:
> >>
> >> 4 nodes, 3 mons, 20 OSDs on
> >> ceph version 0.94.7-84-g8e6f430 (8e6f430683e4d8293e31fd4eb6cb09be96960cfa)
> >>
> >> [1]
> >> https://blog.widodh.nl/2016/01/slow-requests-with-ceph-waiting-for-rw-locks/
> >>
> >> Thanks!
> >> Eugen
> >>
> >>
> >> Zitat von Brad Hubbard <bhubbard@xxxxxxxxxx>:
> >>
> >>
> >>> On Thu, Jan 12, 2017 at 2:19 AM, Eugen Block <eblock@xxxxxx> wrote:
> >>>>
> >>>> Hi,
> >>>>
> >>>> I simply grepped for "slow request" in ceph.log. What exactly do you mean
> >>>> by
> >>>> "effective OSD"?
> >>>>
> >>>> If I have this log line:
> >>>> 2017-01-11 [...] osd.16 [...] cluster [WRN] slow request 32.868141
> >>>> seconds
> >>>> old, received at 2017-01-11 [...] ack+ondisk+write+known_if_redirected
> >>>> e12440) currently waiting for subops from 0,12
> >>>>
> >>>> I assumed that osd.16 is the one causing problems.
> >>>
> >>>
> >>> 0 and/or 12 in this case. 16 is just waiting. Looking at the output of
> >>> dump_historic_ops and dump_ops_in_flight on the implicated osds may
> >>> help to narrow down what the issue is.
> >>>
> >>>> But now that you mention
> >>>> the subops, I only noticed them yesterday, but didn't have the time yet
> >>>> to
> >>>> investigate further. I'll have a look into the subops messages and report
> >>>> back.
> >>>>
> >>>> Thanks!
> >>>> Eugen
> >>>>
> >>>> Zitat von Burkhard Linke
> >>>> <Burkhard.Linke@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>:
> >>>>
> >>>>
> >>>>> Hi,
> >>>>>
> >>>>>
> >>>>> just for clarity:
> >>>>>
> >>>>>
> >>>>> Did you parse the slow request messages and use the effective OSD in the
> >>>>> statistics? Some message may refer to other OSDs, e.g. "waiting for sub
> >>>>> op
> >>>>> on OSD X,Y". The reporting OSD is not the root cause in that case, but
> >>>>> one
> >>>>> of the mentioned OSDs (and I'm currently not aware of a method to
> >>>>> determine
> >>>>> which of the both OSD is the cause in case of 3 replicates.....).
> >>>>>
> >>>>>
> >>>>> Regards,
> >>>>>
> >>>>> Burkhard
> >>>>>
> >>>>>
> >>>>> _______________________________________________
> >>>>> ceph-users mailing list
> >>>>> ceph-users@xxxxxxxxxxxxxx
> >>>>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
> >>>>
> >>>>
> >>>>
> >>>>
> >>>>
> >>>> --
> >>>> Eugen Block voice : +49-40-559 51 75
> >>>> NDE Netzdesign und -entwicklung AG fax : +49-40-559 51 77
> >>>> Postfach 61 03 15
> >>>> D-22423 Hamburg e-mail : eblock@xxxxxx
> >>>>
> >>>> Vorsitzende des Aufsichtsrates: Angelika Mozdzen
> >>>> Sitz und Registergericht: Hamburg, HRB 90934
> >>>> Vorstand: Jens-U. Mozdzen
> >>>> USt-IdNr. DE 814 013 983
> >>>>
> >>>> _______________________________________________
> >>>> ceph-users mailing list
> >>>> ceph-users@xxxxxxxxxxxxxx
> >>>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
> >>>
> >>>
> >>>
> >>>
> >>> --
> >>> Cheers,
> >>> Brad
> >>
> >>
> >>
> >>
> >> --
> >> Eugen Block voice : +49-40-559 51 75
> >> NDE Netzdesign und -entwicklung AG fax : +49-40-559 51 77
> >> Postfach 61 03 15
> >> D-22423 Hamburg e-mail : eblock@xxxxxx
> >>
> >> Vorsitzende des Aufsichtsrates: Angelika Mozdzen
> >> Sitz und Registergericht: Hamburg, HRB 90934
> >> Vorstand: Jens-U. Mozdzen
> >> USt-IdNr. DE 814 013 983
> >>
> >
> >
> >
> > --
> > Cheers,
> > Brad
>
>
>
--
Christian Balzer Network/Systems Engineer
chibi@xxxxxxx Global OnLine Japan/Rakuten Communications
http://www.gol.com/
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
