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

[Jason Dillaman <jdillama@redhat.com>]

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