1 // Copyright (c) 2011-present, Facebook, Inc. All rights reserved. 2 // This source code is licensed under both the GPLv2 (found in the 3 // COPYING file in the root directory) and Apache 2.0 License 4 // (found in the LICENSE.Apache file in the root directory). 5 // 6 // Copyright (c) 2011 The LevelDB Authors. All rights reserved. 7 // Use of this source code is governed by a BSD-style license that can be 8 // found in the LICENSE file. See the AUTHORS file for names of contributors. 9 // 10 // Logger implementation that can be shared by all environments 11 // where enough posix functionality is available. 12 13 #pragma once 14 #include <algorithm> 15 #include <stdio.h> 16 #include "port/sys_time.h" 17 #include <time.h> 18 #include <fcntl.h> 19 20 #ifdef OS_LINUX 21 #ifndef FALLOC_FL_KEEP_SIZE 22 #include <linux/falloc.h> 23 #endif 24 #endif 25 26 #include <atomic> 27 #include "env/io_posix.h" 28 #include "monitoring/iostats_context_imp.h" 29 #include "rocksdb/env.h" 30 #include "test_util/sync_point.h" 31 32 namespace ROCKSDB_NAMESPACE { 33 34 class PosixLogger : public Logger { 35 private: PosixCloseHelper()36 Status PosixCloseHelper() { 37 int ret; 38 39 ret = fclose(file_); 40 if (ret) { 41 return IOError("Unable to close log file", "", ret); 42 } 43 return Status::OK(); 44 } 45 FILE* file_; 46 uint64_t (*gettid_)(); // Return the thread id for the current thread 47 std::atomic_size_t log_size_; 48 int fd_; 49 const static uint64_t flush_every_seconds_ = 5; 50 std::atomic_uint_fast64_t last_flush_micros_; 51 Env* env_; 52 std::atomic<bool> flush_pending_; 53 54 protected: CloseImpl()55 virtual Status CloseImpl() override { return PosixCloseHelper(); } 56 57 public: 58 PosixLogger(FILE* f, uint64_t (*gettid)(), Env* env, 59 const InfoLogLevel log_level = InfoLogLevel::ERROR_LEVEL) Logger(log_level)60 : Logger(log_level), 61 file_(f), 62 gettid_(gettid), 63 log_size_(0), 64 fd_(fileno(f)), 65 last_flush_micros_(0), 66 env_(env), 67 flush_pending_(false) {} ~PosixLogger()68 virtual ~PosixLogger() { 69 if (!closed_) { 70 closed_ = true; 71 PosixCloseHelper().PermitUncheckedError(); 72 } 73 } Flush()74 virtual void Flush() override { 75 TEST_SYNC_POINT("PosixLogger::Flush:Begin1"); 76 TEST_SYNC_POINT("PosixLogger::Flush:Begin2"); 77 if (flush_pending_) { 78 flush_pending_ = false; 79 fflush(file_); 80 } 81 last_flush_micros_ = env_->NowMicros(); 82 } 83 84 using Logger::Logv; Logv(const char * format,va_list ap)85 virtual void Logv(const char* format, va_list ap) override { 86 IOSTATS_TIMER_GUARD(logger_nanos); 87 88 const uint64_t thread_id = (*gettid_)(); 89 90 // We try twice: the first time with a fixed-size stack allocated buffer, 91 // and the second time with a much larger dynamically allocated buffer. 92 char buffer[500]; 93 for (int iter = 0; iter < 2; iter++) { 94 char* base; 95 int bufsize; 96 if (iter == 0) { 97 bufsize = sizeof(buffer); 98 base = buffer; 99 } else { 100 bufsize = 65536; 101 base = new char[bufsize]; 102 } 103 char* p = base; 104 char* limit = base + bufsize; 105 106 struct timeval now_tv; 107 gettimeofday(&now_tv, nullptr); 108 const time_t seconds = now_tv.tv_sec; 109 struct tm t; 110 localtime_r(&seconds, &t); 111 p += snprintf(p, limit - p, 112 "%04d/%02d/%02d-%02d:%02d:%02d.%06d %llx ", 113 t.tm_year + 1900, 114 t.tm_mon + 1, 115 t.tm_mday, 116 t.tm_hour, 117 t.tm_min, 118 t.tm_sec, 119 static_cast<int>(now_tv.tv_usec), 120 static_cast<long long unsigned int>(thread_id)); 121 122 // Print the message 123 if (p < limit) { 124 va_list backup_ap; 125 va_copy(backup_ap, ap); 126 p += vsnprintf(p, limit - p, format, backup_ap); 127 va_end(backup_ap); 128 } 129 130 // Truncate to available space if necessary 131 if (p >= limit) { 132 if (iter == 0) { 133 continue; // Try again with larger buffer 134 } else { 135 p = limit - 1; 136 } 137 } 138 139 // Add newline if necessary 140 if (p == base || p[-1] != '\n') { 141 *p++ = '\n'; 142 } 143 144 assert(p <= limit); 145 const size_t write_size = p - base; 146 147 #ifdef ROCKSDB_FALLOCATE_PRESENT 148 const int kDebugLogChunkSize = 128 * 1024; 149 150 // If this write would cross a boundary of kDebugLogChunkSize 151 // space, pre-allocate more space to avoid overly large 152 // allocations from filesystem allocsize options. 153 const size_t log_size = log_size_; 154 const size_t last_allocation_chunk = 155 ((kDebugLogChunkSize - 1 + log_size) / kDebugLogChunkSize); 156 const size_t desired_allocation_chunk = 157 ((kDebugLogChunkSize - 1 + log_size + write_size) / 158 kDebugLogChunkSize); 159 if (last_allocation_chunk != desired_allocation_chunk) { 160 fallocate( 161 fd_, FALLOC_FL_KEEP_SIZE, 0, 162 static_cast<off_t>(desired_allocation_chunk * kDebugLogChunkSize)); 163 } 164 #endif 165 166 size_t sz = fwrite(base, 1, write_size, file_); 167 flush_pending_ = true; 168 if (sz > 0) { 169 log_size_ += write_size; 170 } 171 uint64_t now_micros = static_cast<uint64_t>(now_tv.tv_sec) * 1000000 + 172 now_tv.tv_usec; 173 if (now_micros - last_flush_micros_ >= flush_every_seconds_ * 1000000) { 174 Flush(); 175 } 176 if (base != buffer) { 177 delete[] base; 178 } 179 break; 180 } 181 } GetLogFileSize()182 size_t GetLogFileSize() const override { return log_size_; } 183 }; 184 185 } // namespace ROCKSDB_NAMESPACE 186