log: Use the coarse real time clock in log timestamps #18141

adamemerson · 2017-10-05T23:27:21Z

With an option to use the higher resolution clock if we want to.

This address a Trello Card or whatever.

liewegas

Yay! This looks good.

I don't suppose there's a way to annotate the time_point so that we know whether it's coarse or not? Then we could output only 3 decimal places of precision for coarse stamps and 6 for fine...

tchaikov

i failed to find a caller of _get_val<>().

tchaikov · 2017-10-06T15:34:31Z

src/common/config.h

@@ -162,6 +162,7 @@ struct md_config_t {
  int _get_val(const std::string &key, char **buf, int len) const;
  Option::value_t get_val_generic(const std::string &key) const;
  template<typename T> T get_val(const std::string &key) const;
+  template<typename T> T _get_val(const std::string &key) const;


do we have a caller of this function now?

+ if (changed.find("log_coarse_timestamps") != changed.end()) { + log->set_coarse_timestamps(conf->_get_val("log_coarse_timestamps")); + }

tchaikov · 2017-10-06T17:54:59Z

src/common/config.h

+template<typename T> T md_config_t::_get_val(const std::string &key) const {
+  Option::value_t generic_val = this->get_val_generic(key);
+  get_typed_value_visitor<T> gtv;
+  return boost::apply_visitor(gtv, generic_val);


it's identical to

template<typename T> T md_config_t::get_val(const std::string &key) const

why shall we use it instead of md_config_t::get_val() ?

Thanks for catching this. It was SUPPOSED to _get_val() instead of get_value_generic since _get_val desn't take a lock. I'll push an update in a moment.

~~@adamemerson it's not changed. am i missing something?~~

scratch that.

tchaikov

no need to introduce _get_val().

We create a new time type to support using coarse timestamps (for performance) by default while still allowing the user to switch to fine timestamps. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

The tests should, really, get their time from the same source as the log, and also probably use the same interface to creating entries that other people do. So add an optional message argument and have the tests use that rather than using the new operator directly. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

adamemerson · 2017-10-06T21:30:16Z

@liewegas Times are marked as coarse or fine and print three or six digits depending.

When notified by a config observer, the config lock is already held, create a _get_val template to manipulate newstyle options when notified. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

And set up an observer in CephContext to coarsen/refine time stamps as requested. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

Have each timestamp know whether it's coarse or fine. Print six figures for fine stamps and three for coarse. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

tchaikov · 2017-10-08T16:49:06Z

src/common/config.h

+template<typename T> T md_config_t::_get_val(const std::string &key) const {
+  Option::value_t generic_val = this->_get_val(key);
+  get_typed_value_visitor<T> gtv;
+  return boost::apply_visitor(gtv, generic_val);


@jcsp @adamemerson why don't we just use boost::get<> ?

tchaikov · 2017-10-09T01:35:17Z

jcsp · 2017-10-10T17:00:49Z

src/common/config.cc

+  // An alternative might be to pass a std::unique_lock to
+  // handle_conf_change and have a version of get_var that can take it
+  // by reference and lock as appropriate.
+  Mutex::Locker l(lock);


I am late reviewing this, but this looks scary. Holding md_config_t::lock while calling into handle_conf_change of observers: then the observers can't use get_val (it takes the lock) to react to the changes!

The comment in config.h is referring to the old struct-based config, where holding the lock would be a good thing because it would render it safe to read that struct, rather than in the get_val world where holding the lock is a recipe for deadlocks

I did look through the rest of the file as a sanity check. It seems that we acquire the lock in apply_changes before calling _apply_changes which calls handle_conf_change.

So we had observers being called with the lock held in one path and without the lock held in the other path. I wouldn't be against swinging the change in the other direction and releasing the lock before calling the observers from _apply_changes if you think that would be safer.

We need the lock to cover the handle_conf_change methods until all of the strings are gone from legacy_config_opts.h. Since injectargs etc already hold the lock this change seems correct.

The larger/more annoying issue is that the get_val() calls in handle_conf_change. Maybe we can fix those just by marking the mutex recursive?

That was why I added the _get_val template. A recursive mutex would work, too, as would passing a unique_lock reference into handle_conf_change that can be passed to get_val which can just look to see whether to acquire it or not.

The unique_lock approach seems fragile: we'd have to update all current implementations that use get_val(), and going forward developers have to remember that all future calls to get_val() have to pass the unique_lock ref along to a get_val() variant that takes it. And if they don't they'll only notice if they test changing the config option online and deadlock the config update thread.

My vote is recursive mutex, with a plan to remove it if/when legacy_config_opts ever gets emptied out...

Huh. Looks like it already is recursive. I didn't realize that when I was worried about deadlock before. In that case all we really need to do is back out my _get_val change and just call get_val as normal.

adamemerson requested a review from liewegas October 5, 2017 23:27

adamemerson added common core feature needs-qa performance labels Oct 5, 2017

liewegas changed the title ~~Use the coarse real time clock in log timestamps~~ log: Use the coarse real time clock in log timestamps Oct 6, 2017

liewegas approved these changes Oct 6, 2017

View reviewed changes

tchaikov requested changes Oct 6, 2017

View reviewed changes

tchaikov approved these changes Oct 6, 2017

View reviewed changes

tchaikov reviewed Oct 6, 2017

View reviewed changes

tchaikov requested changes Oct 6, 2017

View reviewed changes

liewegas added the wip-sage-testing label Oct 6, 2017

adamemerson added 3 commits October 6, 2017 17:29

log: Create log_clock to replace use of utime_t

7b0168c

We create a new time type to support using coarse timestamps (for performance) by default while still allowing the user to switch to fine timestamps. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

log: Use log_clock, defaulting to coarse time

31de198

Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

adamemerson force-pushed the wip-log-time branch from 3609ac4 to 1c00492 Compare October 6, 2017 21:29

adamemerson added 3 commits October 6, 2017 20:49

config: Add templated _get_val for use in observers

a0a4c48

When notified by a config observer, the config lock is already held, create a _get_val template to manipulate newstyle options when notified. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

log: Add log_coarse_timestamps option

0f8606b

And set up an observer in CephContext to coarsen/refine time stamps as requested. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

log: Mark timestamps for coarseness and print appropriately

afaf48a

Have each timestamp know whether it's coarse or fine. Print six figures for fine stamps and three for coarse. Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

adamemerson force-pushed the wip-log-time branch from 1c00492 to afaf48a Compare October 7, 2017 00:50

tchaikov approved these changes Oct 7, 2017

View reviewed changes

liewegas removed the wip-sage-testing label Oct 7, 2017

tchaikov added the wip-kefu-testing label Oct 7, 2017

tchaikov reviewed Oct 8, 2017

View reviewed changes

tchaikov merged commit 3b9564f into ceph:master Oct 9, 2017

adamemerson deleted the wip-log-time branch October 9, 2017 15:42

jcsp reviewed Oct 10, 2017

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

log: Use the coarse real time clock in log timestamps #18141

log: Use the coarse real time clock in log timestamps #18141

adamemerson commented Oct 5, 2017

liewegas left a comment

tchaikov left a comment

tchaikov Oct 6, 2017

liewegas Oct 6, 2017

tchaikov Oct 6, 2017 •

edited

adamemerson Oct 6, 2017

tchaikov Oct 7, 2017 •

edited

tchaikov left a comment

adamemerson commented Oct 6, 2017

tchaikov Oct 8, 2017

tchaikov commented Oct 9, 2017

jcsp Oct 10, 2017

adamemerson Oct 10, 2017 •

edited

liewegas Oct 10, 2017

adamemerson Oct 10, 2017

liewegas Oct 10, 2017

adamemerson Oct 10, 2017

log: Use the coarse real time clock in log timestamps #18141

log: Use the coarse real time clock in log timestamps #18141

Conversation

adamemerson commented Oct 5, 2017

liewegas left a 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 Oct 6, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tchaikov Oct 7, 2017 • edited

Choose a reason for hiding this comment

tchaikov left a comment

Choose a reason for hiding this comment

adamemerson commented Oct 6, 2017

Choose a reason for hiding this comment

tchaikov commented Oct 9, 2017

Choose a reason for hiding this comment

adamemerson Oct 10, 2017 • 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

tchaikov Oct 6, 2017 •

edited

tchaikov Oct 7, 2017 •

edited

adamemerson Oct 10, 2017 •

edited