common/log: Speed improvement for log. by aclamk · Pull Request #17938 · ceph/ceph

aclamk · 2017-09-25T08:27:48Z

streambuf and ostream are reused as much as possible.

Signed-off-by: Adam Kupczyk akupczyk@redhat.com

jcsp · 2017-09-25T09:58:24Z

Are there any benchmarks that show the speedup?

Signed-off-by: Adam Kupczyk <akupczyk@redhat.com>

aclamk · 2017-09-26T11:27:32Z

@jcsp
I added test.
Before:
[ RUN ] Log.Speed_gather
[ OK ] Log.Speed_gather (1657 ms)
[ RUN ] Log.Speed_nogather
[ OK ] Log.Speed_nogather (59 ms)
After:
[ RUN ] Log.Speed_gather
[ OK ] Log.Speed_gather (1306 ms)
[ RUN ] Log.Speed_nogather
[ OK ] Log.Speed_nogather (54 ms)

jcsp · 2017-09-28T10:30:13Z

Seems to me like a reasonable use of thread local data to cut down on allocations.

Any other opinions? @liewegas ?

tchaikov · 2017-10-02T03:42:33Z

http://pulpito.ceph.com/kchai-2017-10-01_17:38:10-rados-wip-kefu-testing-2017-10-01-2202-distro-basic-mira/

aclamk · 2017-10-03T07:49:46Z

@tchaikov
Reading from http://pulpito.ceph.com/kchai-2017-10-01_17:38:10-rados-wip-kefu-testing-2017-10-01-2202-distro-basic-mira/ .

1692886 : Failed on: "cbt - Final Pool Health Check."
1692795: Failed to run "osd-scrub-repair.sh"
1692959: "RuntimeError: Scrubbing terminated -- not all pgs were active and clean."

And additional 5 jobs were running happily for 12h before being terminated.

Should I proceed to clean this problems up ?

tchaikov · 2017-10-03T13:25:57Z

@aclamk the reason why i didn't merge your PR is that i wanted to review it before doing so. but neither did i want to to be a blocker of it. so i leave the link to the rados qa tests. because none of the failures is relevant to your PR, so i didn't add a negative review.

cbodley · 2017-10-04T13:30:05Z

hi @aclamk, i'm having trouble figuring out what exactly was slow about current logging, and how this change set addresses it. can you explain a bit more about what you learned from your investigation?

PrebufferedStreambuf is such a simple and useful class on its own, and i worry that these changes are so specific to logging that it would be less useful for other things

cbodley · 2017-10-04T14:51:51Z

src/common/PrebufferedStreambuf.h

+  : public std::basic_streambuf<char, std::basic_string<char>::traits_type>
+{
+  prebuffered_data* m_data;
+  std::ostream os;


it seems backwards for the streambuf to contain an ostream, instead of the other way around. why can't this stay on the stack in the dout_impl macro?

It really seems wierd that streambuf specialization has and ostream.
I did it just to avoid specialization of ostream, just to have streambuf in it.

Reusing ostream and streambuf between logs is the gist of this change.

got it. so the ostream and streambuf will both be thread_local and have the same lifetime 👍

cbodley · 2017-10-04T14:59:15Z

src/common/PrebufferedStreambuf.h

-
+  PrebufferedStreambuf(): m_data(nullptr), os(this) {};
+  ~PrebufferedStreambuf();
+  static PrebufferedStreambuf* get_streambuf(prebuffered_data* data);


if this factory function is the only way to construct a valid PrebufferedStreambuf, the constructor and destructor should be made private

this unfortunately means that you can't ever put a PrebufferedStreambuf on the stack. so if you ever want more than one in a thread, you're stuck with dynamic allocation

Thanks. Those should be private.
The dynamic allocation is performed once per thread, and in seldom cases when we log from inside log.

aclamk · 2017-10-05T12:20:23Z

@cbodley
This pull request stemmed from joemarios work on false sharing. ( #9431 )
Initial analysis showed that there is a lot of false sharing on elements of locale. (http://en.cppreference.com/w/cpp/locale/locale)
This was impossible to get rid of, because first element of locale is atomic reference counter, that was modified on creation of every streambuf and ostream.
This false sharing turned out to have little impact on performance, however to prove this, I made this modification to logging, which seems to provide speed up.
The rationale here is to skip creation and destruction of streambuf and ostream, as they are reused in each log.
The additional logic is responsible for creating extra streambuf and ostream, if we happen to call function that produces logs during construction of log.

cbodley · 2017-10-05T13:58:44Z

ok thanks @aclamk! i ran a profiler on the unit test and saw that, without your changes, the std::locale ctor/dtor were each using ~3-5% of the cpu time. so your strategy to reuse them makes sense

would you object to making this a separate class though, like ThreadLocalPrebufferedStreambuf or something? then PrebufferedStreambuf in its current form could be reused for simple things without interfering with logging performance

liewegas · 2017-11-02T15:12:34Z

ping

aclamk · 2017-11-02T15:17:50Z

@cbodley
I have not seen PrebufferedStreambuf used anywhere else, but I agree that making it backward-compatilble would be nicer.
I will do.
@liewegas
Thanks for the ping.

cbodley · 2017-11-03T15:09:53Z

thanks @aclamk, there are a lot of stringstreams in rgw that could take advantage of it someday :)

…usage Signed-off-by: Adam Kupczyk <akupczyk@redhat.com>

tchaikov · 2017-11-22T15:01:42Z

@aclamk i updated your PR, and posted the updated version at #19100. could you please take a look?

Signed-off-by: Adam Kupczyk <akupczyk@redhat.com>

tchaikov

@aclamk please see the comment at #19100 (comment). we can clean this up a little bit before merging it.

tchaikov · 2017-11-27T09:55:32Z

src/common/ThreadLocalPrebufferedStreambuf.h

+  : m_buf(buf), m_buf_len(buf_len), m_pptr(nullptr) {}
+
+  /// return a string copy (inefficiently)
+  std::string get_str() const;


please see https://github.com/ceph/ceph/pull/19100/files#diff-8dcb74089b1227130d768a47852508bdR48, get_str(), size() and snprintf() methods are not needed here.

aclamk · 2017-11-30T08:17:34Z

Closing, because #19100 does it better.

jcsp added cleanup common labels Sep 25, 2017

common/log: Performance test for logging.

39bc0da

Signed-off-by: Adam Kupczyk <akupczyk@redhat.com>

aclamk force-pushed the wip-log-reuse-streambuf branch from d3ae910 to a059e46 Compare September 26, 2017 11:27

jcsp approved these changes Sep 28, 2017

View reviewed changes

tchaikov self-assigned this Sep 28, 2017

markhpc added the performance label Sep 28, 2017

tchaikov added needs-qa wip-kefu-testing labels Oct 1, 2017

tchaikov removed needs-qa wip-kefu-testing labels Oct 2, 2017

cbodley reviewed Oct 4, 2017

View reviewed changes

common/log: Added new version of PrebufferedStreambuf, tuned for log …

8e1a7ea

…usage Signed-off-by: Adam Kupczyk <akupczyk@redhat.com>

aclamk force-pushed the wip-log-reuse-streambuf branch from 5581ced to 8e1a7ea Compare November 5, 2017 20:21

tchaikov mentioned this pull request Nov 22, 2017

common/log: Speed improvement for log #19100

Merged

common/log: plugged in PrebufferedStreamBuf to logging

98453b6

Signed-off-by: Adam Kupczyk <akupczyk@redhat.com>

tchaikov reviewed Nov 27, 2017

View reviewed changes

aclamk closed this Nov 30, 2017

tchaikov mentioned this pull request Aug 24, 2018

log: avoid heap allocations for most log entries #23721

Merged

cbodley mentioned this pull request Jun 24, 2024

rgw: implement S3 additional checksum support #55076

Merged

14 tasks

Conversation

aclamk commented Sep 25, 2017

Uh oh!

jcsp commented Sep 25, 2017

Uh oh!

aclamk commented Sep 26, 2017

Uh oh!

jcsp commented Sep 28, 2017

Uh oh!

tchaikov commented Oct 2, 2017

Uh oh!

aclamk commented Oct 3, 2017

Uh oh!

tchaikov commented Oct 3, 2017

Uh oh!

cbodley commented Oct 4, 2017

Uh oh!

cbodley Oct 4, 2017

Choose a reason for hiding this comment

Uh oh!

aclamk Oct 5, 2017

Choose a reason for hiding this comment

Uh oh!

cbodley Oct 5, 2017

Choose a reason for hiding this comment

Uh oh!

cbodley Oct 4, 2017

Choose a reason for hiding this comment

Uh oh!

aclamk Oct 5, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

aclamk commented Oct 5, 2017

Uh oh!

cbodley commented Oct 5, 2017

Uh oh!

liewegas commented Nov 2, 2017

Uh oh!

aclamk commented Nov 2, 2017

Uh oh!

cbodley commented Nov 3, 2017

Uh oh!

tchaikov commented Nov 22, 2017

Uh oh!

tchaikov left a comment

Choose a reason for hiding this comment

Uh oh!

tchaikov Nov 27, 2017

Choose a reason for hiding this comment

Uh oh!

aclamk commented Nov 30, 2017

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

aclamk Oct 5, 2017 •

edited

Loading