Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

log/Log.cc: speed optimizations. Merged 3 writes into 1. #6307

Merged
merged 1 commit into from Oct 25, 2015
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
41 changes: 40 additions & 1 deletion src/common/PrebufferedStreambuf.cc
@@ -1,6 +1,6 @@

#include "common/PrebufferedStreambuf.h"

#include <string.h>
PrebufferedStreambuf::PrebufferedStreambuf(char *buf, size_t len)
: m_buf(buf), m_buf_len(len)
{
Expand Down Expand Up @@ -61,3 +61,42 @@ std::string PrebufferedStreambuf::get_str() const
return std::string(m_buf, this->pptr() - m_buf);
}
}
// returns current size of content
size_t PrebufferedStreambuf::size() const
{
if(m_overflow.size() == 0) {
return this->pptr() - m_buf;
} else {
return m_buf_len + m_overflow.size();
}
}

// extracts up to avail chars of content
int PrebufferedStreambuf::snprintf(char* dst, size_t avail) const
{
size_t o_size=m_overflow.size();
size_t len_a;
size_t len_b;
if(o_size>0){
len_a = m_buf_len;
len_b = o_size;
} else {
len_a = this->pptr() - m_buf;
len_b = 0;
}
if(avail > len_a + len_b ) {
memcpy(dst, m_buf, len_a);
memcpy(dst + m_buf_len, m_overflow.c_str(), len_b);
dst[len_a + len_b] = 0;
} else {
if(avail > len_a ) {
memcpy(dst, m_buf, len_a);
memcpy(dst + m_buf_len, m_overflow.c_str(), avail - len_a - 1);
dst[avail - 1] = 0;
} else {
memcpy(dst, m_buf, avail - 1);
dst[avail - 1] = 0;
}
}
return len_a + len_b;
}
8 changes: 7 additions & 1 deletion src/common/PrebufferedStreambuf.h
Expand Up @@ -37,6 +37,12 @@ class PrebufferedStreambuf

/// return a string copy (inefficiently)
std::string get_str() const;
};

// returns current size of content
size_t size() const;

// extracts up to avail chars of content
int snprintf(char* dst, size_t avail) const;
};

#endif
12 changes: 11 additions & 1 deletion src/include/utime.h
Expand Up @@ -239,12 +239,22 @@ class utime_t {
time_t tt = sec();
localtime_r(&tt, &bdt);

return snprintf(out, outlen,
return ::snprintf(out, outlen,
"%04d-%02d-%02d %02d:%02d:%02d.%06ld",
bdt.tm_year + 1900, bdt.tm_mon + 1, bdt.tm_mday,
bdt.tm_hour, bdt.tm_min, bdt.tm_sec, usec());
}

static int snprintf(char *out, int outlen, time_t tt) {
struct tm bdt;
localtime_r(&tt, &bdt);

return ::snprintf(out, outlen,
"%04d-%02d-%02d %02d:%02d:%02d",
bdt.tm_year + 1900, bdt.tm_mon + 1, bdt.tm_mday,
bdt.tm_hour, bdt.tm_min, bdt.tm_sec);
}

static int parse_date(const string& date, uint64_t *epoch, uint64_t *nsec,
string *out_date=NULL, string *out_time=NULL) {
struct tm tm;
Expand Down
10 changes: 10 additions & 0 deletions src/log/Entry.h
Expand Up @@ -48,6 +48,16 @@ struct Entry {
std::string get_str() const {
return m_streambuf.get_str();
}

// returns current size of content
size_t size() const {
return m_streambuf.size();
}

// extracts up to avail chars of content
int snprintf(char* dst, size_t avail) const {
return m_streambuf.snprintf(dst, avail);
}
};

}
Expand Down
30 changes: 14 additions & 16 deletions src/log/Log.cc
Expand Up @@ -209,7 +209,6 @@ void Log::flush()
void Log::_flush(EntryQueue *t, EntryQueue *requeue, bool crash)
{
Entry *e;
char buf[80];
while ((e = t->dequeue()) != NULL) {
unsigned sub = e->m_subsys;

Expand All @@ -219,33 +218,32 @@ void Log::_flush(EntryQueue *t, EntryQueue *requeue, bool crash)
bool do_stderr = m_stderr_crash >= e->m_prio && should_log;

if (do_fd || do_syslog || do_stderr) {
int buflen = 0;
size_t buflen = 0;
char buf[80 + e->size()];

if (crash)
buflen += snprintf(buf, sizeof(buf), "%6d> ", -t->m_len);
buflen += e->m_stamp.sprintf(buf + buflen, sizeof(buf)-buflen);
buflen += snprintf(buf + buflen, sizeof(buf)-buflen, " %lx %2d ",
(unsigned long)e->m_thread, e->m_prio);

// FIXME: this is slow
string s = e->get_str();

if (do_fd) {
int r = safe_write(m_fd, buf, buflen);
if (r >= 0)
r = safe_write(m_fd, s.data(), s.size());
if (r >= 0)
r = write(m_fd, "\n", 1);
if (r < 0)
cerr << "problem writing to " << m_log_file << ": " << cpp_strerror(r) << std::endl;
}
buflen += e->snprintf(buf + buflen, sizeof(buf) - buflen - 1 );
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch! I bet we can do even better with something that looks like pwritev(2)... then we avoid doing a memcpy into buf entirely, and instead construct an iovec array (there should be a max of 3 or 4 distinct inputs). The write or pwritev syscall is doing another copy anyway, so the one into buf shouldn't be necessary.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have tried using writev but it is actually slower.
Below using writev vs using memcpy to make 1 buffer.
size= 6 IOVS=3 time=107768usec
size= 6 WRITE time=84712usec
size= 12 IOVS=3 time=131376usec
size= 12 WRITE time=120907usec
size= 24 IOVS=3 time=183488usec
size= 24 WRITE time=172170usec
size= 48 IOVS=3 time=271790usec
size= 48 WRITE time=271460usec
size= 96 IOVS=3 time=674332usec
size= 96 WRITE time=424097usec
size=192 IOVS=3 time=769107usec
size=192 WRITE time=784972usec
size=384 IOVS=3 time=2253296usec
size=384 WRITE time=1509636usec
size=768 IOVS=3 time=2977487usec
size=768 WRITE time=2974786usec

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It make sense to me that very small vector will result in bad performance. I guess most of logs should be small enough

if(buflen > sizeof(buf) - 1 ) //paranoid check, buf was declared to hold everything
buflen = sizeof(buf) - 1;

if (do_syslog) {
syslog(LOG_USER, "%s%s", buf, s.c_str());
syslog(LOG_USER, "%s", buf);
}

if (do_stderr) {
cerr << buf << s << std::endl;
cerr << buf << std::endl;
}
if (do_fd) {
buf[buflen-1]='\n';
buf[buflen]='\0';
int r=safe_write(m_fd, buf, buflen+1);
if (r < 0)
cerr << "problem writing to " << m_log_file << ": " << cpp_strerror(r) << std::endl;
}
}

Expand Down