"debug ms = 0/5" logging ...

"debug ms = 0/5" logging ...

[Jason Dillaman]

While the default messenger logging setting has always been an
impediment to high queue-depth, high IOPS workloads, in Luminous it
appears to have slowed down librbd small block IOPS by an additional 10-
15%. When compared against cases where the messenger logs are disabled,
it's more than a 40% IOPS degradation to have the messenger logs
enabled.

From some quick "perf" runs, the Luminous delta seems to be from from a
few places: (1) hobject_t is now used in the OSD messages, and it's more
expensive to construct[2] and print; (2) log messages are longer in
length; and (3) async messenger is more verbose per message at log level
1 compared to simple messenger.

I'd hate to advocate the sledge-hammer approach to say everyone should
deploy librbd with "debug ms = 0" -- especially since I've relied on
decoding the in-memory log messages from core dumps as a pseudo-librbd
flight recorder in the past.

This seems like an area that could use some team discussion and thought.
Perhaps it would be possible to re-use tracepoint hooks where we keep
the last X traces in-memory so that they can be dumped and/or are
available in the core file. In theory that would at least reduce the
expense of converting these trace-like log messages to expensive human
readable strings.

Thoughts?

[1] http://tracker.ceph.com/issues/21846
[2] http://tracker.ceph.com/issues/21845

--
Jason

Re: "debug ms = 0/5" logging ...

[John Spray]

On Thu, Oct 19, 2017 at 12:47 PM, Jason Dillaman <jdillama@redhat.com> wrote:
> While the default messenger logging setting has always been an
> impediment to high queue-depth, high IOPS workloads, in Luminous it
> appears to have slowed down librbd small block IOPS by an additional 10-
> 15%. When compared against cases where the messenger logs are disabled,
> it's more than a 40% IOPS degradation to have the messenger logs
> enabled.
>
> From some quick "perf" runs, the Luminous delta seems to be from from a
> few places: (1) hobject_t is now used in the OSD messages, and it's more
> expensive to construct[2] and print; (2) log messages are longer in
> length; and (3) async messenger is more verbose per message at log level
> 1 compared to simple messenger.
>
> I'd hate to advocate the sledge-hammer approach to say everyone should
> deploy librbd with "debug ms = 0" -- especially since I've relied on
> decoding the in-memory log messages from core dumps as a pseudo-librbd
> flight recorder in the past.
>
> This seems like an area that could use some team discussion and thought.
> Perhaps it would be possible to re-use tracepoint hooks where we keep
> the last X traces in-memory so that they can be dumped and/or are
> available in the core file. In theory that would at least reduce the
> expense of converting these trace-like log messages to expensive human
> readable strings.

What you suggest with tracepoints seems very sensible to me.

The extreme policy would be to say that all debug logging is really
just tracepoints done inefficiently -- in the case of Ceph we probably
only really care on that OSD IO path though.

John

>
> Thoughts?
>
> [1] http://tracker.ceph.com/issues/21846
> [2] http://tracker.ceph.com/issues/21845
>
> --
> Jason
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: "debug ms = 0/5" logging ...

[Haomai Wang]

On Thu, Oct 19, 2017 at 8:06 PM, John Spray <jspray@redhat.com> wrote:
> On Thu, Oct 19, 2017 at 12:47 PM, Jason Dillaman <jdillama@redhat.com> wrote:
>> While the default messenger logging setting has always been an
>> impediment to high queue-depth, high IOPS workloads, in Luminous it
>> appears to have slowed down librbd small block IOPS by an additional 10-
>> 15%. When compared against cases where the messenger logs are disabled,
>> it's more than a 40% IOPS degradation to have the messenger logs
>> enabled.

As I remembered, luminous will add extra line for each message
compared to jewel.

>>
>> From some quick "perf" runs, the Luminous delta seems to be from from a
>> few places: (1) hobject_t is now used in the OSD messages, and it's more
>> expensive to construct[2] and print; (2) log messages are longer in
>> length; and (3) async messenger is more verbose per message at log level
>> 1 compared to simple messenger.

it's new added.

>>
>> I'd hate to advocate the sledge-hammer approach to say everyone should
>> deploy librbd with "debug ms = 0" -- especially since I've relied on
>> decoding the in-memory log messages from core dumps as a pseudo-librbd
>> flight recorder in the past.
>>
>> This seems like an area that could use some team discussion and thought.
>> Perhaps it would be possible to re-use tracepoint hooks where we keep
>> the last X traces in-memory so that they can be dumped and/or are
>> available in the core file. In theory that would at least reduce the
>> expense of converting these trace-like log messages to expensive human
>> readable strings.
>
> What you suggest with tracepoints seems very sensible to me.
>
> The extreme policy would be to say that all debug logging is really
> just tracepoints done inefficiently -- in the case of Ceph we probably
> only really care on that OSD IO path though.
>
> John
>
>>
>> Thoughts?
>>
>> [1] http://tracker.ceph.com/issues/21846
>> [2] http://tracker.ceph.com/issues/21845
>>
>> --
>> Jason
>> --
>> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: "debug ms = 0/5" logging ...

[Gregory Farnum]

On Thu, Oct 19, 2017 at 6:24 AM, Haomai Wang <haomai@xsky.com> wrote:
> On Thu, Oct 19, 2017 at 8:06 PM, John Spray <jspray@redhat.com> wrote:
>> On Thu, Oct 19, 2017 at 12:47 PM, Jason Dillaman <jdillama@redhat.com> wrote:
>>> While the default messenger logging setting has always been an
>>> impediment to high queue-depth, high IOPS workloads, in Luminous it
>>> appears to have slowed down librbd small block IOPS by an additional 10-
>>> 15%. When compared against cases where the messenger logs are disabled,
>>> it's more than a 40% IOPS degradation to have the messenger logs
>>> enabled.
>
> As I remembered, luminous will add extra line for each message
> compared to jewel.
>
>>>
>>> From some quick "perf" runs, the Luminous delta seems to be from from a
>>> few places: (1) hobject_t is now used in the OSD messages, and it's more
>>> expensive to construct[2] and print; (2) log messages are longer in
>>> length; and (3) async messenger is more verbose per message at log level
>>> 1 compared to simple messenger.
>
> it's new added.

Which extra log messages are we printing out in AsyncMessenger that
aren't in SimpleMessenger? Is it just the log line printing out the
message on _send_message? Is there any reason we can't turn that down
to a lower level like in SimpleMessenger?
-Greg