diff --git a/util/posix_logger.h b/util/posix_logger.h index 1909e61282..a01a4feb54 100644 --- a/util/posix_logger.h +++ b/util/posix_logger.h @@ -8,89 +8,119 @@ #ifndef STORAGE_LEVELDB_UTIL_POSIX_LOGGER_H_ #define STORAGE_LEVELDB_UTIL_POSIX_LOGGER_H_ -#include -#include #include -#include + +#include +#include +#include +#include +#include + #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); + } + + ~PosixLogger() override { + std::fclose(fp_); } - virtual void Logv(const char* format, va_list ap) { + + 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; - - 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(now_tv.tv_usec), - static_cast(thread_id)); - - // 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); - } + // 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(kStackBufferSize), + "sizeof(char) is expected to be 1 in C++"); - // Truncate to available space if necessary - if (p >= limit) { - if (iter == 0) { - continue; // Try again with larger buffer - } else { - p = limit - 1; + 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 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(now_timeval.tv_usec), + thread_id); + + // 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