core: make the main dout() paths faster and more maintanable #20290

rzarzynski · 2018-02-04T02:31:14Z

Summary

The validation of subsys parameter for dout & company becomes compile-time in almost all cases. The few exceptions are explicitly requested via ceph::dout::need_dynamic.
The level compile-time validation is back and doesn't depend on the VLA extension anymore. It's performed in all cases except those explicitly requested with ceph::dout::need_dynamic.
Memory indirection layer affecting SubsystemMap::should_gather() is gone. That is, the std::vector-typed m_subsys is no longer dereferenced on the main path.
SubsystemMap::should_gather<>() requires one third of comparisons than before.
The message crafting is put outside hot paths to help ICache/ITLB.

Interface changes:

debug_* configurables don't accept negative values anymore -- dout() with level -1 or 0 will be always gathered. Our documentation doesn't say a word about negatives.

Todo

Switch to uint8_t for dout levels.
Handle level -1 in compile-time if possible.
Switch direct ::should_gather() calls to the template variant when possible.
Clean up.
More tests as almost everything is going to be affected.
Resurrect the check on dout's levels where possible.

Performance impact

Environment

1 physial incerta node, 3 OSDs, all NVMe, Xeon E5-2650 v3

Results

random reads on FileStore, debugs set to 0/0.

Reference point: cb396a78d42f034dd61606a327cc703211e49cda

randread,  4 KiB: 167427, 164852, 163403, 162503, 165675,
randread, 64 KiB: 1940050, 1944297, 1933320, 1938220, 1934929,

wip-common-subsystemmap: 7cc9c4152c32403b353ff147b58b6314c3cd46b6

randread,  4 KiB: 168687, 170500, 170551, 171261, 171806,
randread, 64 KiB: 1954171, 1954686, 1962185, 1979382, 1982293,

rzarzynski · 2018-02-04T02:41:56Z

src/log/SubsystemMap.h

+  // The rest. Should be as small as possible to unnecessarily not
+  // enlarge md_config_t and spread it other elements across cache
+  // lines. Access can be slow.
+  std::vector<ceph_subsys_item_t> m_subsys;


No need to carry the size as its already known. std::unique_ptr<std::array> instead?

That sounds good to me.

rzarzynski · 2018-02-04T02:43:27Z

src/log/test.cc

-  subs.add(1, "foosys", 20, 1);
-  subs.add(2, "bar", 20, 2);
-  subs.add(3, "baz", 10, 3);
+  subs.set_log_level(0, 10);


Introduce one method for that.

rzarzynski · 2018-02-04T04:21:19Z

The make check bot fails because of:

/home/jenkins-build/build/workspace/ceph-pull-requests/src/log/test.cc: In member function 'virtual void Log_ReuseBad_Test::TestBody()':
/home/jenkins-build/build/workspace/ceph-pull-requests/src/log/test.cc:59:8: error: 'class ceph::logging::SubsystemMap' has no member named 'add'
   subs.add(1, "foo", 1, 1);

Apparently it rebased the PR on top of freshest master that got a new testcase -- we faced an undetected merge conflict. Not resolving it for now to not lose common reference point with PR #20177.

rzarzynski · 2018-02-04T04:25:23Z

src/common/config.cc

@@ -946,7 +939,7 @@ int md_config_t::_get_val(const std::string &key, char **buf, int len) const
  string k(ConfFile::normalize_key_name(key));
  // subsys?
  for (size_t o = 0; o < subsys.get_num(); o++) {
-    std::string as_option = "debug_" + subsys.get_name(o);
+    std::string as_option = std::string("debug_") + subsys.get_name(o);


Hmm, possibly this could be made at compile-time.

rzarzynski · 2018-02-04T04:26:17Z

src/common/config.cc

@@ -178,13 +178,6 @@ void md_config_t::validate_schema()

 void md_config_t::init_subsys()


rzarzynski · 2018-02-04T04:29:34Z

src/common/dout.h

+    }									\
+  }(cct);								\
+									\
+  if (should_gather) {							\


unlikely()? I can see that GCC arranges some dout usages in a way not friendly for static branch prediction.

rzarzynski · 2018-02-04T04:31:51Z

src/log/SubsystemMap.h

@@ -52,16 +66,38 @@ class SubsystemMap {
    return m_subsys[subsys].gather_level;
  }

-  const std::string& get_name(unsigned subsys) const {
+  // TODO(rzarzynski): move to string_view?
+  const char* get_name(unsigned subsys) const {


constexpr.

rzarzynski · 2018-02-04T04:37:26Z

src/log/SubsystemMap.h

 class SubsystemMap {
-  std::vector<Subsystem> m_subsys;
-  unsigned m_max_name_len;
+  // Access the current gathering levels must be *FAST* as they are


FIXME: Access to.

rzarzynski · 2018-02-09T16:59:10Z

src/common/dout.h

+  }(cct);								\
+									\
+  if (unlikely(should_gather)) {					\
+    [&]() __attribute__((noinline,cold)) {				\


This can be controversial as we're using compiler-specific extensions here. However, the befit seems to outweigh the costs. Please take a look on a comparison of KernelDevice::read() translation before and after the change.

TODO: comment the intention behind the lambda and noinline,cold.

TODO: introduce a macro-based abstraction?

rzarzynski · 2018-02-09T17:00:23Z

src/common/dout.h

+    }									\
+  }(cct);								\
+									\
+  if (unlikely(should_gather)) {					\


Maybe we could differentiate the hinting policy basing on e.g. v and the default gathering level. Though, I'm not sure it's really necessary.

adamemerson · 2018-02-14T18:34:13Z

src/common/dout.h

 // generic macros
 #define dout_prefix *_dout

 #define dout_impl(cct, sub, v)						\
  do {									\
-  if (cct->_conf->subsys.should_gather(sub, v)) {			\
+  const bool should_gather = [&](const auto cctX) {			\


This is interesting. I had an idea for replacing the template with a function accepting a lambda at one point but this is a very nice way of moving things to compile time.

adamemerson · 2018-02-14T18:37:10Z

src/common/subsys_types.h

+#define SUBSYS(name, log, gather) \
+  ceph_subsys_##name,
+#define DEFAULT_SUBSYS(log, gather)
+#include "common/subsys.h"


I wonder if it makes sense to keep this Magic Macro stuff instead of just open-coding a data structure

I believe the idea behind subsys.h and the macros is to have subsystems and their log/levels defined only once - a single source of true that is transformed to dependent structures later. Maybe it's possible to perform that via constexpr functions instead of macros but I haven't investigated that.

adamemerson · 2018-02-14T18:56:09Z

src/common/subsys_types.h

+struct ceph_subsys_item_t {
+  const char* name;
+  uint8_t log_level;
+  uint8_t gather_level;


Maybe use uint_fast8_t here, letting the compiler pick another width if it's faster.

Hmm, this might be a good measure to explicitly distinguish the hot path than the comment we have around m_gather_levels. Something targeting more the human's attention than machines. Fom x86's perspective I don't expect any difference. The open questions are: 1) the effect of fast types on ARMs and 2) the proliferation of uint_fast8_t across the codebase. This would be the first occurrence (not counting 3rd party code).

adamemerson · 2018-02-14T18:56:48Z

src/log/SubsystemMap.h

+  // The rest. Should be as small as possible to unnecessarily not
+  // enlarge md_config_t and spread it other elements across cache
+  // lines. Access can be slow.
+  std::vector<ceph_subsys_item_t> m_subsys;


That sounds good to me.

rzarzynski · 2018-02-21T11:46:42Z

Rebased to freshest master and fixed the build failures.

tchaikov

i will take a closer look early tomorrow.

tchaikov · 2018-02-22T15:50:45Z

src/common/dout.h

@@ -43,14 +43,47 @@ class DoutPrefixProvider {
  virtual ~DoutPrefixProvider() {}
 };

+// helpers
+namespace ceph {


nit, we could do

namespace ceph::dout { // ... }

in C++17.

Cool! Thanks for pointing out this feature.

tchaikov · 2018-02-22T16:06:08Z

src/common/subsys_types.h

+/*
+ * Ceph - scalable distributed file system
+ *
+ * Copyright (C) 2004-2006 Sage Weil <sage@newdream.net>


the copyright line should be updated.

tchaikov

lgtm in general.

tchaikov · 2018-02-27T08:58:58Z

src/os/bluestore/BlueStore.cc

@@ -1618,10 +1618,11 @@ bool BlueStore::OnodeSpace::map_any(std::function<bool(OnodeRef)> f)
  return false;
 }

-void BlueStore::OnodeSpace::dump(CephContext *cct, int lvl)
+template <int LogLevelV = 30>


@rzarzynski could you rebase your change against master, as 8471cb4#diff-a9faffcf40600fd57aea5451cef5abe9R6344 in #19843 was merged recently. and your PR changes the function signature of BlueStore::_dump_onode().

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

The idea is to: 1. Do not put the dout()'s crafting stuff on the hot, fall-through path. Cheapest branches are those that are forward and never taken. 2. Move it to separated sections placed far away from the main path to be more friendly to ICache and ITLB. That is, dout_impl constructs a function now. Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

tchaikov · 2018-02-28T01:22:44Z

http://pulpito.ceph.com/kchai-2018-02-27_10:33:49-rados-wip-kefu-testing-2018-02-27-1348-distro-basic-mira/

rzarzynski added core performance labels Feb 4, 2018

rzarzynski requested review from tchaikov and liewegas February 4, 2018 02:31

rzarzynski commented Feb 4, 2018

View reviewed changes

mattbenjamin requested a review from adamemerson February 4, 2018 03:00

rzarzynski commented Feb 4, 2018

View reviewed changes

rzarzynski force-pushed the wip-common-subsystemmap branch from 7cc9c41 to a8de819 Compare February 4, 2018 05:47

rzarzynski commented Feb 9, 2018

View reviewed changes

rzarzynski changed the title ~~[WIP] core: make the main dout() paths faster and more maintanable~~ core: make the main dout() paths faster and more maintanable Feb 13, 2018

adamemerson reviewed Feb 14, 2018

View reviewed changes

rzarzynski force-pushed the wip-common-subsystemmap branch 4 times, most recently from 8e746c6 to 00a2614 Compare February 21, 2018 10:27

tchaikov reviewed Feb 22, 2018

View reviewed changes

tchaikov self-requested a review February 22, 2018 16:12

rzarzynski force-pushed the wip-common-subsystemmap branch from 00a2614 to 4411cac Compare February 23, 2018 00:42

tchaikov approved these changes Feb 23, 2018

View reviewed changes

tchaikov added needs-qa wip-kefu-testing labels Feb 23, 2018

tchaikov requested changes Feb 27, 2018

View reviewed changes

rzarzynski force-pushed the wip-common-subsystemmap branch 3 times, most recently from 676139a to 360f823 Compare February 27, 2018 10:31

rzarzynski added 9 commits February 27, 2018 11:38

core: dout checks ceph_subsys_* in compile time if possible.

b0f94c6

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

common: move subsys-dependant types to a dedicated header.

8a66835

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

osd: remove the PGLog::prefix_provider as it's always nullptr.

5b3c5bb

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

core: make SubsystemMap more statical and optimize should_gather().

d96bf57

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

core: resurrect the old check on dout's levels where possible.

1a3e935

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

ceph: switch to SubsystemMap::should_gather<SubV, LvlV>().

d13e071

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

log: remove SubsystemMap::m_max_name_len.

de5efc8

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

log: prohibit negative values for debug_* configurables.

360f823

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

tchaikov approved these changes Feb 27, 2018

View reviewed changes

tchaikov merged commit 971e3c3 into ceph:master Feb 28, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core: make the main dout() paths faster and more maintanable #20290

core: make the main dout() paths faster and more maintanable #20290

rzarzynski commented Feb 4, 2018 •

edited

rzarzynski Feb 4, 2018

adamemerson Feb 14, 2018

rzarzynski Feb 4, 2018

rzarzynski commented Feb 4, 2018

rzarzynski Feb 4, 2018

rzarzynski Feb 4, 2018

rzarzynski Feb 4, 2018 •

edited

rzarzynski Feb 4, 2018

rzarzynski Feb 4, 2018

rzarzynski Feb 9, 2018

rzarzynski Feb 9, 2018

adamemerson Feb 14, 2018

adamemerson Feb 14, 2018

rzarzynski Feb 21, 2018

adamemerson Feb 14, 2018

rzarzynski Feb 21, 2018

adamemerson Feb 14, 2018

rzarzynski commented Feb 21, 2018

tchaikov left a comment

tchaikov Feb 22, 2018

rzarzynski Feb 22, 2018

rzarzynski Feb 23, 2018

tchaikov Feb 22, 2018

rzarzynski Feb 23, 2018

tchaikov left a comment

tchaikov Feb 27, 2018

rzarzynski Feb 27, 2018

tchaikov commented Feb 28, 2018

		@@ -178,13 +178,6 @@ void md_config_t::validate_schema()

		void md_config_t::init_subsys()

core: make the main dout() paths faster and more maintanable #20290

core: make the main dout() paths faster and more maintanable #20290

Conversation

rzarzynski commented Feb 4, 2018 • edited

Summary

Interface changes:

Todo

Performance impact

Environment

Results

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rzarzynski commented Feb 4, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rzarzynski Feb 4, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rzarzynski commented Feb 21, 2018

tchaikov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tchaikov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tchaikov commented Feb 28, 2018

rzarzynski commented Feb 4, 2018 •

edited

rzarzynski Feb 4, 2018 •

edited