Clean up posix_logger.h.

General cleanup principles:
* Use override when applicable.
* Use const on class members where possible.
* Renames where clarity can be improved.
* Qualify standard library names with std:: when possible, to
  distinguish from POSIX names.
* Qualify POSIX names with the global namespace (::) when possible, to
  distinguish from standard library names.

This also revamps the logic for putting together a message into the
in-memory buffer before that is passed to fwrite(). While correct in
practice, the current implementation advances a char pointer past the
size of its buffer, which is technically undefined behavior.

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=211472570
This commit is contained in:
costan 2018-09-04 09:50:50 -07:00 committed by Victor Costan
parent 89af27bde5
commit 7b945f2003

View File

@ -8,89 +8,119 @@
#ifndef STORAGE_LEVELDB_UTIL_POSIX_LOGGER_H_
#define STORAGE_LEVELDB_UTIL_POSIX_LOGGER_H_
#include <algorithm>
#include <stdio.h>
#include <sys/time.h>
#include <time.h>
#include <cassert>
#include <cinttypes>
#include <cstdarg>
#include <cstdio>
#include <ctime>
#include "leveldb/env.h"
namespace leveldb {
class PosixLogger : public Logger {
private:
FILE* file_;
uint64_t (*gettid_)(); // Return the thread id for the current thread
class PosixLogger final : public Logger {
public:
PosixLogger(FILE* f, uint64_t (*gettid)()) : file_(f), gettid_(gettid) { }
virtual ~PosixLogger() {
fclose(file_);
PosixLogger(FILE* fp, uint64_t (*gettid)()) : fp_(fp), gettid_(gettid) {
assert(fp != nullptr);
}
virtual void Logv(const char* format, va_list ap) {
~PosixLogger() override {
std::fclose(fp_);
}
void Logv(const char* format, va_list arguments) override {
// Record the time as close to the Logv() call as possible.
struct ::timeval now_timeval;
::gettimeofday(&now_timeval, nullptr);
const std::time_t now_seconds = now_timeval.tv_sec;
struct std::tm now_components;
::localtime_r(&now_seconds, &now_components);
const uint64_t thread_id = (*gettid_)();
// We try twice: the first time with a fixed-size stack allocated buffer,
// and the second time with a much larger dynamically allocated buffer.
char buffer[500];
for (int iter = 0; iter < 2; iter++) {
char* base;
int bufsize;
if (iter == 0) {
bufsize = sizeof(buffer);
base = buffer;
} else {
bufsize = 30000;
base = new char[bufsize];
}
char* p = base;
char* limit = base + bufsize;
// We first attempt to print into a stack-allocated buffer. If this attempt
// fails, we make a second attempt with a dynamically allocated buffer.
constexpr const int kStackBufferSize = 512;
char stack_buffer[kStackBufferSize];
static_assert(sizeof(stack_buffer) == static_cast<size_t>(kStackBufferSize),
"sizeof(char) is expected to be 1 in C++");
struct timeval now_tv;
gettimeofday(&now_tv, nullptr);
const time_t seconds = now_tv.tv_sec;
struct tm t;
localtime_r(&seconds, &t);
p += snprintf(p, limit - p,
"%04d/%02d/%02d-%02d:%02d:%02d.%06d %llx ",
t.tm_year + 1900,
t.tm_mon + 1,
t.tm_mday,
t.tm_hour,
t.tm_min,
t.tm_sec,
static_cast<int>(now_tv.tv_usec),
static_cast<long long unsigned int>(thread_id));
int dynamic_buffer_size = 0; // Computed in the first iteration.
for (int iteration = 0; iteration < 2; ++iteration) {
const int buffer_size =
(iteration == 0) ? kStackBufferSize : dynamic_buffer_size;
char* const buffer =
(iteration == 0) ? stack_buffer : new char[dynamic_buffer_size];
// Print the message
if (p < limit) {
va_list backup_ap;
va_copy(backup_ap, ap);
p += vsnprintf(p, limit - p, format, backup_ap);
va_end(backup_ap);
}
// Print the header into the buffer.
int buffer_offset = snprintf(
buffer, buffer_size,
"%04d/%02d/%02d-%02d:%02d:%02d.%06d %" PRIx64 " ",
now_components.tm_year + 1900,
now_components.tm_mon + 1,
now_components.tm_mday,
now_components.tm_hour,
now_components.tm_min,
now_components.tm_sec,
static_cast<int>(now_timeval.tv_usec),
thread_id);
// Truncate to available space if necessary
if (p >= limit) {
if (iter == 0) {
continue; // Try again with larger buffer
} else {
p = limit - 1;
// The header can be at most 48 characters (10 date + 15 time + 3 spacing
// + 20 thread ID), which should fit comfortably into the static buffer.
assert(buffer_offset <= 48);
static_assert(48 < kStackBufferSize,
"stack-allocated buffer may not fit the message header");
assert(buffer_offset < buffer_size);
// Print the message into the buffer.
std::va_list arguments_copy;
va_copy(arguments_copy, arguments);
buffer_offset += std::vsnprintf(buffer + buffer_offset,
buffer_size - buffer_offset, format,
arguments_copy);
va_end(arguments_copy);
// The code below may append a newline at the end of the buffer, which
// requires an extra character.
if (buffer_offset >= buffer_size - 1) {
// The message did not fit into the buffer.
if (iteration == 0) {
// Re-run the loop and use a dynamically-allocated buffer. The buffer
// will be large enough for the log message, an extra newline and a
// null terminator.
dynamic_buffer_size = buffer_offset + 2;
continue;
}
// The dynamically-allocated buffer was incorrectly sized. This should
// not happen, assuming a correct implementation of (v)snprintf. Fail
// in tests, recover by truncating the log message in production.
assert(false);
buffer_offset = buffer_size - 1;
}
// Add newline if necessary
if (p == base || p[-1] != '\n') {
*p++ = '\n';
// Add a newline if necessary.
if (buffer[buffer_offset - 1] != '\n') {
buffer[buffer_offset] = '\n';
++buffer_offset;
}
assert(p <= limit);
fwrite(base, 1, p - base, file_);
fflush(file_);
if (base != buffer) {
delete[] base;
assert(buffer_offset <= buffer_size);
std::fwrite(buffer, 1, buffer_offset, fp_);
std::fflush(fp_);
if (iteration != 0) {
delete[] buffer;
}
break;
}
}
private:
std::FILE* const fp_;
uint64_t (* const gettid_)(); // Return the thread id for the current thread.
};
} // namespace leveldb