So, on the cluster that I _expect_ to be slow, it appears that we are waiting on journal commits. I want to make sure that I am reading this correctly:
"received_at": "2014-03-14 12:14:22.659170",
{ "time": "2014-03-14 12:14:22.660191",
"event": "write_thread_in_journal_buffer"},
At this point we have received the write and are attempting to write the transaction to the OSD's journal, yes?
Then:
{ "time": "2014-03-14 12:14:22.900779",
"event": "journaled_completion_queued"},
240ms later we have successfully written to the journal?
I expect this particular slowness due to colocation of journal and data on the same disk (and it's a spinning disk, not an SSD). I expect some of this could be alleviated by migrating journals to SSDs, but I am looking to rebuild in the near future--so am willing to hobble in the meantime.
I am surprised that our all SSD cluster is also underperforming. I am trying colocating the journal on the same disk with all SSDs at the moment and will see if the performance degradation is of the same nature.
On Thu, Mar 13, 2014 at 6:25 PM, Gregory Farnum <greg@xxxxxxxxxxx> wrote:
Right. So which is the interval that's taking all the time? Probably
it's waiting for the journal commit, but maybe there's something else
blocking progress. If it is the journal commit, check out how busy the
disk is (is it just saturated?) and what its normal performance
characteristics are (is it breaking?).
On Thu, Mar 13, 2014 at 5:48 PM, Greg Poirier <greg.poirier@xxxxxxxxxx> wrote:
> Many of the sub ops look like this, with significant lag between received_at
> and commit_sent:
>
> { "description": "osd_op(client.6869831.0:1192491
> rbd_data.67b14a2ae8944a.0000000000009105 [write 507904~3686400] 6.556a4db0
> e660)",
> "received_at": "2014-03-13 20:42:05.811936",
> "age": "46.088198",
> "duration": "0.038328",
> <snip>
> { "time": "2014-03-13 20:42:05.850215",
> "event": "commit_sent"},
> { "time": "2014-03-13 20:42:05.850264",
> "event": "done"}]]},
>
> In this case almost 39ms between received_at and commit_sent.
>
> A particularly egregious example of 80+ms lag between received_at and
> commit_sent:
>
> { "description": "osd_op(client.6869831.0:1190526
> rbd_data.67b14a2ae8944a.0000000000008fac [write 3325952~868352] 6.5255f5fd
> e660)",
> "received_at": "2014-03-13 20:41:40.227813",
> "age": "320.017087",
> "duration": "0.086852",
> <snip>
> { "time": "2014-03-13 20:41:40.314633",
> "event": "commit_sent"},
> { "time": "2014-03-13 20:41:40.314665",
> "event": "done"}]]},
>
>
>
> On Thu, Mar 13, 2014 at 4:17 PM, Gregory Farnum <greg@xxxxxxxxxxx> wrote:
>>
>> On Thu, Mar 13, 2014 at 3:56 PM, Greg Poirier <greg.poirier@xxxxxxxxxx>
>> wrote:
>> > We've been seeing this issue on all of our dumpling clusters, and I'm
>> > wondering what might be the cause of it.
>> >
>> > In dump_historic_ops, the time between op_applied and sub_op_commit_rec
>> > or
>> > the time between commit_sent and sub_op_applied is extremely high. Some
>> > of
>> > the osd_sub_ops are as long as 100 ms. A sample dump_historic_ops is
>> > included at the bottom.
>>
>> It's important to understand what each of those timestamps are reporting.
>>
>> op_applied: the point at which an OSD has applied an operation to its
>> readable backing filesystem in-memory (which for xfs or ext4 will be
>> after it's committed to the journal)
>> sub_op_commit_rec: the point at which an OSD has gotten commits from
>> the replica OSDs
>> commit_sent: the point at which a replica OSD has sent a commit back
>> to its primary
>> sub_op_applied: the point at which a replica OSD has applied a
>> particular operation to its backing filesystem in-memory (again, after
>> the journal if using xfs)
>>
>> Reads are never served from replicas, so a long time between
>> commit_sent and sub_op_applied should not in itself be an issue. A lag
>> time between op_applied and sub_op_commit_rec means that the OSD is
>> waiting on its replicas. A long time there indicates either that the
>> replica is processing slowly, or that there's some issue in the
>> communications stack (all the way from the raw ethernet up to the
>> message handling in the OSD itself).
>> So the first thing to look for are sub ops which have a lag time
>> between the received_at and commit_sent timestamps. If none of those
>> ever turn up, but unusually long waits for sub_op_commit_rec are still
>> present, then it'll take more effort to correlate particular subops on
>> replicas with the op on the primary they correspond to, and see where
>> the time lag is coming into it.
>> -Greg
>> Software Engineer #42 @ http://inktank.com | http://ceph.com
>
>
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
