Skip to content

Commit

Permalink
SERVER-5553 Remove a heap allocation from the log event encoder.
Browse files Browse the repository at this point in the history
The goal is to eventually have a logging path that is truly safe to
use in a signal handler.  This patch advances the cause by removing
the heap allocation caused by returning a string in the date formatters.
  • Loading branch information
amschwerin committed Apr 3, 2014
1 parent afd8648 commit 962b4ab
Show file tree
Hide file tree
Showing 6 changed files with 134 additions and 35 deletions.
6 changes: 3 additions & 3 deletions src/mongo/db/server_options_helpers.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -670,13 +670,13 @@ namespace {
using logger::MessageEventDetailsEncoder;
std::string formatterName = params["systemLog.timeStampFormat"].as<string>();
if (formatterName == "ctime") {
MessageEventDetailsEncoder::setDateFormatter(dateToCtimeString);
MessageEventDetailsEncoder::setDateFormatter(outputDateAsCtime);
}
else if (formatterName == "iso8601-utc") {
MessageEventDetailsEncoder::setDateFormatter(dateToISOStringUTC);
MessageEventDetailsEncoder::setDateFormatter(outputDateAsISOStringUTC);
}
else if (formatterName == "iso8601-local") {
MessageEventDetailsEncoder::setDateFormatter(dateToISOStringLocal);
MessageEventDetailsEncoder::setDateFormatter(outputDateAsISOStringLocal);
}
else {
StringBuilder sb;
Expand Down
5 changes: 3 additions & 2 deletions src/mongo/logger/message_event_utf8_encoder.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@
namespace mongo {
namespace logger {

static MessageEventDetailsEncoder::DateFormatter _dateFormatter = dateToISOStringLocal;
static MessageEventDetailsEncoder::DateFormatter _dateFormatter = outputDateAsISOStringLocal;

void MessageEventDetailsEncoder::setDateFormatter(DateFormatter dateFormatter) {
_dateFormatter = dateFormatter;
Expand All @@ -40,7 +40,8 @@ namespace logger {

static const size_t maxLogLine = 10 * 1024;

os << _dateFormatter(event.getDate()) << ' ';
_dateFormatter(os, event.getDate());
os << ' ';
StringData contextName = event.getContextName();
if (!contextName.empty()) {
os << '[' << contextName << "] ";
Expand Down
4 changes: 2 additions & 2 deletions src/mongo/logger/message_event_utf8_encoder.h
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@

#pragma once

#include <string>
#include <iosfwd>

#include "mongo/logger/encoder.h"
#include "mongo/logger/message_event.h"
Expand All @@ -29,7 +29,7 @@ namespace logger {
*/
class MessageEventDetailsEncoder : public Encoder<MessageEventEphemeral> {
public:
typedef std::string (*DateFormatter)(Date_t);
typedef void (*DateFormatter)(std::ostream&, Date_t);

/**
* Sets the date formatter function for all instances of MessageEventDetailsEncoder.
Expand Down
90 changes: 65 additions & 25 deletions src/mongo/util/time_support.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -110,21 +110,29 @@ namespace mongo {
return buf;
}

static inline std::string _dateToISOString(Date_t date, bool local) {
const int bufSize = 32;
char buf[bufSize];
namespace {
struct DateStringBuffer {
static const int dataCapacity = 64;
char data[dataCapacity];
int size;
};

void _dateToISOString(Date_t date, bool local, DateStringBuffer* result) {
static const int bufSize = DateStringBuffer::dataCapacity;
char* const buf = result->data;
struct tm t;
time_t_to_Struct(date.toTimeT(), &t, local);
int pos = strftime(buf, bufSize, MONGO_ISO_DATE_FMT_NO_TZ, &t);
fassert(16981, 0 < pos);
dassert(0 < pos);
char* cur = buf + pos;
int bufRemaining = bufSize - pos;
pos = snprintf(cur, bufRemaining, ".%03d", static_cast<int32_t>(date.asInt64() % 1000));
fassert(16982, bufRemaining > pos && pos > 0);
dassert(bufRemaining > pos && pos > 0);
cur += pos;
bufRemaining -= pos;
if (local) {
fassert(16983, bufRemaining >= 6);
static const int localTzSubstrLen = 5;
dassert(bufRemaining >= localTzSubstrLen + 1);
#ifdef _WIN32
// NOTE(schwerin): The value stored by _get_timezone is the value one adds to local time
// to get UTC. This is opposite of the ISO-8601 meaning of the timezone offset.
Expand All @@ -138,29 +146,74 @@ namespace mongo {
const long tzOffsetSeconds = msTimeZone* (tzIsWestOfUTC ? 1 : -1);
const long tzOffsetHoursPart = tzOffsetSeconds / 3600;
const long tzOffsetMinutesPart = (tzOffsetSeconds / 60) % 60;
snprintf(cur, 6, "%c%02ld%02ld",
snprintf(cur, localTzSubstrLen + 1, "%c%02ld%02ld",
tzIsWestOfUTC ? '-' : '+',
tzOffsetHoursPart,
tzOffsetMinutesPart);
#else
strftime(cur, bufRemaining, "%z", &t);
#endif
cur += localTzSubstrLen;
}
else {
fassert(16984, bufRemaining >= 2);
dassert(bufRemaining >= 2);
*cur = 'Z';
++cur;
*cur = '\0';
}
return buf;
result->size = cur - buf;
dassert(result->size < DateStringBuffer::dataCapacity);
}

void _dateToCtimeString(Date_t date, DateStringBuffer* result) {
static const size_t ctimeSubstrLen = 19;
static const size_t millisSubstrLen = 4;
time_t t = date.toTimeT();
#if defined(_WIN32)
ctime_s(result->data, sizeof(result->data), &t);
#else
ctime_r(&t, result->data);
#endif
char* milliSecStr = result->data + ctimeSubstrLen;
snprintf(milliSecStr, millisSubstrLen + 1, ".%03d", static_cast<int32_t>(date.asInt64() % 1000));
result->size = ctimeSubstrLen + millisSubstrLen;
}
} // namespace

std::string dateToISOStringUTC(Date_t date) {
return _dateToISOString(date, false);
DateStringBuffer buf;
_dateToISOString(date, false, &buf);
return std::string(buf.data, buf.size);
}

std::string dateToISOStringLocal(Date_t date) {
return _dateToISOString(date, true);
DateStringBuffer buf;
_dateToISOString(date, true, &buf);
return std::string(buf.data, buf.size);
}

std::string dateToCtimeString(Date_t date) {
DateStringBuffer buf;
_dateToCtimeString(date, &buf);
return std::string(buf.data, buf.size);
}

void outputDateAsISOStringUTC(std::ostream& os, Date_t date) {
DateStringBuffer buf;
_dateToISOString(date, false, &buf);
os << StringData(buf.data, buf.size);
}

void outputDateAsISOStringLocal(std::ostream& os, Date_t date) {
DateStringBuffer buf;
_dateToISOString(date, true, &buf);
os << StringData(buf.data, buf.size);

}

void outputDateAsCtime(std::ostream& os, Date_t date) {
DateStringBuffer buf;
_dateToCtimeString(date, &buf);
os << StringData(buf.data, buf.size);
}

namespace {
Expand Down Expand Up @@ -629,19 +682,6 @@ namespace {
return millis / 1000;
}

std::string dateToCtimeString(Date_t date) {
time_t t = date.toTimeT();
char buf[64];
#if defined(_WIN32)
ctime_s(buf, sizeof(buf), &t);
#else
ctime_r(&t, buf);
#endif
char* milliSecStr = buf + 19;
snprintf(milliSecStr, 5, ".%03d", static_cast<int32_t>(date.asInt64() % 1000));
return buf;
}

boost::gregorian::date currentDate() {
boost::posix_time::ptime now = boost::posix_time::second_clock::local_time();
return now.date();
Expand Down
16 changes: 16 additions & 0 deletions src/mongo/util/time_support.h
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@

#pragma once

#include <iosfwd>
#include <ctime>
#include <string>
#include <boost/thread/xtime.hpp>
Expand Down Expand Up @@ -91,6 +92,21 @@ namespace mongo {
*/
StatusWith<Date_t> dateFromISOString(const StringData& dateString);

/**
* Like dateToISOStringUTC, except outputs to a std::ostream.
*/
void outputDateAsISOStringUTC(std::ostream& os, Date_t date);

/**
* Like dateToISOStringLocal, except outputs to a std::ostream.
*/
void outputDateAsISOStringLocal(std::ostream& os, Date_t date);

/**
* Like dateToCtimeString, except outputs to a std::ostream.
*/
void outputDateAsCtime(std::ostream& os, Date_t date);

boost::gregorian::date currentDate();

// parses time of day in "hh:mm" format assuming 'hh' is 00-23
Expand Down
48 changes: 45 additions & 3 deletions src/mongo/util/time_support_test.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,7 @@ namespace {
ASSERT_EQUALS(std::string("2013-02-20T18:29:11Z"), timeToISOString(1361384951));
}

TEST(TimeFormatting, DateAsISO8601UTC) {
TEST(TimeFormatting, DateAsISO8601UTCString) {
ASSERT_EQUALS(std::string("1970-01-01T00:00:00.000Z"),
dateToISOStringUTC(Date_t(0)));
ASSERT_EQUALS(std::string("1970-06-30T01:06:40.981Z"),
Expand All @@ -65,7 +65,7 @@ namespace {
dateToISOStringUTC(Date_t(1361384951100ULL)));
}

TEST(TimeFormatting, DateAsISO8601Local) {
TEST(TimeFormatting, DateAsISO8601LocalString) {
ASSERT_EQUALS(std::string("1969-12-31T19:00:00.000-0500"),
dateToISOStringLocal(Date_t(0)));
ASSERT_EQUALS(std::string("1970-06-29T21:06:40.981-0400"),
Expand All @@ -77,7 +77,7 @@ namespace {
dateToISOStringLocal(Date_t(1361384951100ULL)));
}

TEST(TimeFormatting, DateAsCtime) {
TEST(TimeFormatting, DateAsCtimeString) {
ASSERT_EQUALS(std::string("Wed Dec 31 19:00:00.000"), dateToCtimeString(Date_t(0)));
ASSERT_EQUALS(std::string("Mon Jun 29 21:06:40.981"),
dateToCtimeString(Date_t(15556000981ULL)));
Expand All @@ -88,6 +88,48 @@ namespace {
dateToCtimeString(Date_t(1361384951100ULL)));
}

static std::string stringstreamDate(void (*formatter)(std::ostream&, Date_t), Date_t date) {
std::ostringstream os;
formatter(os, date);
return os.str();
}

TEST(TimeFormatting, DateAsISO8601UTCStream) {
ASSERT_EQUALS(std::string("1970-01-01T00:00:00.000Z"),
stringstreamDate(outputDateAsISOStringUTC, Date_t(0)));
ASSERT_EQUALS(std::string("1970-06-30T01:06:40.981Z"),
stringstreamDate(outputDateAsISOStringUTC, Date_t(15556000981ULL)));
if (!isTimeTSmall)
ASSERT_EQUALS(std::string("2058-02-20T18:29:11.100Z"),
stringstreamDate(outputDateAsISOStringUTC, Date_t(2781455351100ULL)));
ASSERT_EQUALS(std::string("2013-02-20T18:29:11.100Z"),
stringstreamDate(outputDateAsISOStringUTC, Date_t(1361384951100ULL)));
}

TEST(TimeFormatting, DateAsISO8601LocalStream) {
ASSERT_EQUALS(std::string("1969-12-31T19:00:00.000-0500"),
stringstreamDate(outputDateAsISOStringLocal, Date_t(0)));
ASSERT_EQUALS(std::string("1970-06-29T21:06:40.981-0400"),
stringstreamDate(outputDateAsISOStringLocal, Date_t(15556000981ULL)));
if (!isTimeTSmall)
ASSERT_EQUALS(std::string("2058-02-20T13:29:11.100-0500"),
stringstreamDate(outputDateAsISOStringLocal, Date_t(2781455351100ULL)));
ASSERT_EQUALS(std::string("2013-02-20T13:29:11.100-0500"),
stringstreamDate(outputDateAsISOStringLocal, Date_t(1361384951100ULL)));
}

TEST(TimeFormatting, DateAsCtimeStream) {
ASSERT_EQUALS(std::string("Wed Dec 31 19:00:00.000"),
stringstreamDate(outputDateAsCtime, Date_t(0)));
ASSERT_EQUALS(std::string("Mon Jun 29 21:06:40.981"),
stringstreamDate(outputDateAsCtime, Date_t(15556000981ULL)));
if (!isTimeTSmall)
ASSERT_EQUALS(std::string("Wed Feb 20 13:29:11.100"),
stringstreamDate(outputDateAsCtime, Date_t(2781455351100ULL)));
ASSERT_EQUALS(std::string("Wed Feb 20 13:29:11.100"),
stringstreamDate(outputDateAsCtime, Date_t(1361384951100ULL)));
}

TEST(TimeParsing, DateAsISO8601UTC) {
// Allowed date format:
// YYYY-MM-DDTHH:MM[:SS[.m[m[m]]]]Z
Expand Down

0 comments on commit 962b4ab

Please sign in to comment.