]>
Commit | Line | Data |
---|---|---|
7c673cae | 1 | // Copyright (c) 2011-present, Facebook, Inc. All rights reserved. |
11fdf7f2 TL |
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). | |
7c673cae | 5 | // |
f67539c2 TL |
6 | #include "logging/auto_roll_logger.h" |
7 | ||
8 | #include <algorithm> | |
1e59de90 | 9 | |
f67539c2 TL |
10 | #include "file/filename.h" |
11 | #include "logging/logging.h" | |
1e59de90 TL |
12 | #include "rocksdb/env.h" |
13 | #include "rocksdb/file_system.h" | |
14 | #include "rocksdb/system_clock.h" | |
7c673cae FG |
15 | #include "util/mutexlock.h" |
16 | ||
f67539c2 | 17 | namespace ROCKSDB_NAMESPACE { |
7c673cae FG |
18 | |
19 | #ifndef ROCKSDB_LITE | |
20 | // -- AutoRollLogger | |
f67539c2 | 21 | |
1e59de90 TL |
22 | AutoRollLogger::AutoRollLogger(const std::shared_ptr<FileSystem>& fs, |
23 | const std::shared_ptr<SystemClock>& clock, | |
24 | const std::string& dbname, | |
f67539c2 TL |
25 | const std::string& db_log_dir, |
26 | size_t log_max_size, | |
27 | size_t log_file_time_to_roll, | |
28 | size_t keep_log_file_num, | |
29 | const InfoLogLevel log_level) | |
30 | : Logger(log_level), | |
31 | dbname_(dbname), | |
32 | db_log_dir_(db_log_dir), | |
1e59de90 TL |
33 | fs_(fs), |
34 | clock_(clock), | |
f67539c2 TL |
35 | status_(Status::OK()), |
36 | kMaxLogFileSize(log_max_size), | |
37 | kLogFileTimeToRoll(log_file_time_to_roll), | |
38 | kKeepLogFileNum(keep_log_file_num), | |
1e59de90 | 39 | cached_now(static_cast<uint64_t>(clock_->NowMicros() * 1e-6)), |
f67539c2 TL |
40 | ctime_(cached_now), |
41 | cached_now_access_count(0), | |
42 | call_NowMicros_every_N_records_(100), | |
43 | mutex_() { | |
1e59de90 TL |
44 | Status s = fs->GetAbsolutePath(dbname, io_options_, &db_absolute_path_, |
45 | &io_context_); | |
f67539c2 TL |
46 | if (s.IsNotSupported()) { |
47 | db_absolute_path_ = dbname; | |
48 | } else { | |
49 | status_ = s; | |
50 | } | |
51 | log_fname_ = InfoLogFileName(dbname_, db_absolute_path_, db_log_dir_); | |
1e59de90 | 52 | if (fs_->FileExists(log_fname_, io_options_, &io_context_).ok()) { |
f67539c2 TL |
53 | RollLogFile(); |
54 | } | |
55 | GetExistingFiles(); | |
20effc67 TL |
56 | s = ResetLogger(); |
57 | if (s.ok() && status_.ok()) { | |
f67539c2 TL |
58 | status_ = TrimOldLogFiles(); |
59 | } | |
60 | } | |
61 | ||
7c673cae FG |
62 | Status AutoRollLogger::ResetLogger() { |
63 | TEST_SYNC_POINT("AutoRollLogger::ResetLogger:BeforeNewLogger"); | |
1e59de90 | 64 | status_ = fs_->NewLogger(log_fname_, io_options_, &logger_, &io_context_); |
7c673cae FG |
65 | TEST_SYNC_POINT("AutoRollLogger::ResetLogger:AfterNewLogger"); |
66 | ||
67 | if (!status_.ok()) { | |
68 | return status_; | |
69 | } | |
f67539c2 TL |
70 | assert(logger_); |
71 | logger_->SetInfoLogLevel(Logger::GetInfoLogLevel()); | |
7c673cae FG |
72 | |
73 | if (logger_->GetLogFileSize() == Logger::kDoNotSupportGetLogFileSize) { | |
74 | status_ = Status::NotSupported( | |
75 | "The underlying logger doesn't support GetLogFileSize()"); | |
76 | } | |
77 | if (status_.ok()) { | |
1e59de90 | 78 | cached_now = static_cast<uint64_t>(clock_->NowMicros() * 1e-6); |
7c673cae FG |
79 | ctime_ = cached_now; |
80 | cached_now_access_count = 0; | |
81 | } | |
82 | ||
83 | return status_; | |
84 | } | |
85 | ||
86 | void AutoRollLogger::RollLogFile() { | |
87 | // This function is called when log is rotating. Two rotations | |
88 | // can happen quickly (NowMicro returns same value). To not overwrite | |
89 | // previous log file we increment by one micro second and try again. | |
1e59de90 | 90 | uint64_t now = clock_->NowMicros(); |
7c673cae FG |
91 | std::string old_fname; |
92 | do { | |
1e59de90 TL |
93 | old_fname = |
94 | OldInfoLogFileName(dbname_, now, db_absolute_path_, db_log_dir_); | |
7c673cae | 95 | now++; |
1e59de90 TL |
96 | } while (fs_->FileExists(old_fname, io_options_, &io_context_).ok()); |
97 | // Wait for logger_ reference count to turn to 1 as it might be pinned by | |
98 | // Flush. Pinned Logger can't be closed till Flush is completed on that | |
99 | // Logger. | |
100 | while (logger_.use_count() > 1) { | |
101 | } | |
102 | // Close the existing logger first to release the existing handle | |
103 | // before renaming the file using the file system. If this call | |
104 | // fails there is nothing much we can do and we will continue with the | |
105 | // rename and hence ignoring the result status. | |
106 | if (logger_) { | |
107 | logger_->Close().PermitUncheckedError(); | |
108 | } | |
109 | Status s = fs_->RenameFile(log_fname_, old_fname, io_options_, &io_context_); | |
20effc67 TL |
110 | if (!s.ok()) { |
111 | // What should we do on error? | |
112 | } | |
f67539c2 TL |
113 | old_log_files_.push(old_fname); |
114 | } | |
115 | ||
116 | void AutoRollLogger::GetExistingFiles() { | |
117 | { | |
118 | // Empty the queue to avoid duplicated entries in the queue. | |
119 | std::queue<std::string> empty; | |
120 | std::swap(old_log_files_, empty); | |
121 | } | |
122 | ||
123 | std::string parent_dir; | |
124 | std::vector<std::string> info_log_files; | |
125 | Status s = | |
1e59de90 | 126 | GetInfoLogFiles(fs_, db_log_dir_, dbname_, &parent_dir, &info_log_files); |
f67539c2 TL |
127 | if (status_.ok()) { |
128 | status_ = s; | |
129 | } | |
130 | // We need to sort the file before enqueing it so that when we | |
131 | // delete file from the front, it is the oldest file. | |
132 | std::sort(info_log_files.begin(), info_log_files.end()); | |
133 | ||
134 | for (const std::string& f : info_log_files) { | |
135 | old_log_files_.push(parent_dir + "/" + f); | |
136 | } | |
137 | } | |
138 | ||
139 | Status AutoRollLogger::TrimOldLogFiles() { | |
1e59de90 | 140 | // Here we directly list info files and delete them through FileSystem. |
f67539c2 TL |
141 | // The deletion isn't going through DB, so there are shortcomes: |
142 | // 1. the deletion is not rate limited by SstFileManager | |
143 | // 2. there is a chance that an I/O will be issued here | |
144 | // Since it's going to be complicated to pass DB object down to | |
145 | // here, we take a simple approach to keep the code easier to | |
146 | // maintain. | |
147 | ||
148 | // old_log_files_.empty() is helpful for the corner case that | |
149 | // kKeepLogFileNum == 0. We can instead check kKeepLogFileNum != 0 but | |
150 | // it's essentially the same thing, and checking empty before accessing | |
151 | // the queue feels safer. | |
152 | while (!old_log_files_.empty() && old_log_files_.size() >= kKeepLogFileNum) { | |
1e59de90 TL |
153 | Status s = |
154 | fs_->DeleteFile(old_log_files_.front(), io_options_, &io_context_); | |
f67539c2 TL |
155 | // Remove the file from the tracking anyway. It's possible that |
156 | // DB cleaned up the old log file, or people cleaned it up manually. | |
157 | old_log_files_.pop(); | |
158 | // To make the file really go away, we should sync parent directory. | |
159 | // Since there isn't any consistency issue involved here, skipping | |
160 | // this part to avoid one I/O here. | |
161 | if (!s.ok()) { | |
162 | return s; | |
163 | } | |
164 | } | |
165 | return Status::OK(); | |
7c673cae FG |
166 | } |
167 | ||
168 | std::string AutoRollLogger::ValistToString(const char* format, | |
169 | va_list args) const { | |
170 | // Any log messages longer than 1024 will get truncated. | |
171 | // The user is responsible for chopping longer messages into multi line log | |
172 | static const int MAXBUFFERSIZE = 1024; | |
173 | char buffer[MAXBUFFERSIZE]; | |
174 | ||
175 | int count = vsnprintf(buffer, MAXBUFFERSIZE, format, args); | |
1e59de90 | 176 | (void)count; |
7c673cae FG |
177 | assert(count >= 0); |
178 | ||
179 | return buffer; | |
180 | } | |
181 | ||
182 | void AutoRollLogger::LogInternal(const char* format, ...) { | |
183 | mutex_.AssertHeld(); | |
f67539c2 TL |
184 | |
185 | if (!logger_) { | |
186 | return; | |
187 | } | |
188 | ||
7c673cae FG |
189 | va_list args; |
190 | va_start(args, format); | |
191 | logger_->Logv(format, args); | |
192 | va_end(args); | |
193 | } | |
194 | ||
195 | void AutoRollLogger::Logv(const char* format, va_list ap) { | |
196 | assert(GetStatus().ok()); | |
f67539c2 TL |
197 | if (!logger_) { |
198 | return; | |
199 | } | |
7c673cae FG |
200 | |
201 | std::shared_ptr<Logger> logger; | |
202 | { | |
203 | MutexLock l(&mutex_); | |
204 | if ((kLogFileTimeToRoll > 0 && LogExpired()) || | |
205 | (kMaxLogFileSize > 0 && logger_->GetLogFileSize() >= kMaxLogFileSize)) { | |
206 | RollLogFile(); | |
207 | Status s = ResetLogger(); | |
f67539c2 TL |
208 | Status s2 = TrimOldLogFiles(); |
209 | ||
7c673cae FG |
210 | if (!s.ok()) { |
211 | // can't really log the error if creating a new LOG file failed | |
212 | return; | |
213 | } | |
214 | ||
215 | WriteHeaderInfo(); | |
f67539c2 TL |
216 | |
217 | if (!s2.ok()) { | |
218 | ROCKS_LOG_WARN(logger.get(), "Fail to trim old info log file: %s", | |
219 | s2.ToString().c_str()); | |
220 | } | |
7c673cae FG |
221 | } |
222 | ||
223 | // pin down the current logger_ instance before releasing the mutex. | |
224 | logger = logger_; | |
225 | } | |
226 | ||
227 | // Another thread could have put a new Logger instance into logger_ by now. | |
228 | // However, since logger is still hanging on to the previous instance | |
229 | // (reference count is not zero), we don't have to worry about it being | |
230 | // deleted while we are accessing it. | |
231 | // Note that logv itself is not mutex protected to allow maximum concurrency, | |
232 | // as thread safety should have been handled by the underlying logger. | |
233 | logger->Logv(format, ap); | |
234 | } | |
235 | ||
236 | void AutoRollLogger::WriteHeaderInfo() { | |
237 | mutex_.AssertHeld(); | |
238 | for (auto& header : headers_) { | |
239 | LogInternal("%s", header.c_str()); | |
240 | } | |
241 | } | |
242 | ||
243 | void AutoRollLogger::LogHeader(const char* format, va_list args) { | |
f67539c2 TL |
244 | if (!logger_) { |
245 | return; | |
246 | } | |
247 | ||
7c673cae FG |
248 | // header message are to be retained in memory. Since we cannot make any |
249 | // assumptions about the data contained in va_list, we will retain them as | |
250 | // strings | |
251 | va_list tmp; | |
252 | va_copy(tmp, args); | |
253 | std::string data = ValistToString(format, tmp); | |
254 | va_end(tmp); | |
255 | ||
256 | MutexLock l(&mutex_); | |
257 | headers_.push_back(data); | |
258 | ||
259 | // Log the original message to the current log | |
260 | logger_->Logv(format, args); | |
261 | } | |
262 | ||
263 | bool AutoRollLogger::LogExpired() { | |
264 | if (cached_now_access_count >= call_NowMicros_every_N_records_) { | |
1e59de90 | 265 | cached_now = static_cast<uint64_t>(clock_->NowMicros() * 1e-6); |
7c673cae FG |
266 | cached_now_access_count = 0; |
267 | } | |
268 | ||
269 | ++cached_now_access_count; | |
270 | return cached_now >= ctime_ + kLogFileTimeToRoll; | |
271 | } | |
272 | #endif // !ROCKSDB_LITE | |
273 | ||
274 | Status CreateLoggerFromOptions(const std::string& dbname, | |
275 | const DBOptions& options, | |
276 | std::shared_ptr<Logger>* logger) { | |
277 | if (options.info_log) { | |
278 | *logger = options.info_log; | |
279 | return Status::OK(); | |
280 | } | |
281 | ||
282 | Env* env = options.env; | |
283 | std::string db_absolute_path; | |
20effc67 | 284 | Status s = env->GetAbsolutePath(dbname, &db_absolute_path); |
1e59de90 | 285 | TEST_SYNC_POINT_CALLBACK("rocksdb::CreateLoggerFromOptions:AfterGetPath", &s); |
20effc67 TL |
286 | if (!s.ok()) { |
287 | return s; | |
288 | } | |
7c673cae FG |
289 | std::string fname = |
290 | InfoLogFileName(dbname, db_absolute_path, options.db_log_dir); | |
291 | ||
1e59de90 TL |
292 | const auto& clock = env->GetSystemClock(); |
293 | // In case it does not exist. | |
294 | s = env->CreateDirIfMissing(dbname); | |
295 | if (!s.ok()) { | |
296 | if (options.db_log_dir.empty()) { | |
297 | return s; | |
298 | } else { | |
299 | // Ignore the error returned during creation of dbname because dbname and | |
300 | // db_log_dir can be on different filesystems in which case dbname will | |
301 | // not exist and error should be ignored. db_log_dir creation will handle | |
302 | // the error in case there is any error in the creation of dbname on same | |
303 | // filesystem. | |
304 | s = Status::OK(); | |
305 | } | |
306 | } | |
307 | assert(s.ok()); | |
308 | ||
309 | if (!options.db_log_dir.empty()) { | |
310 | s = env->CreateDirIfMissing(options.db_log_dir); | |
311 | if (!s.ok()) { | |
312 | return s; | |
313 | } | |
314 | } | |
7c673cae | 315 | #ifndef ROCKSDB_LITE |
1e59de90 | 316 | // Currently we only support roll by time-to-roll and log size |
7c673cae FG |
317 | if (options.log_file_time_to_roll > 0 || options.max_log_file_size > 0) { |
318 | AutoRollLogger* result = new AutoRollLogger( | |
1e59de90 TL |
319 | env->GetFileSystem(), clock, dbname, options.db_log_dir, |
320 | options.max_log_file_size, options.log_file_time_to_roll, | |
321 | options.keep_log_file_num, options.info_log_level); | |
20effc67 | 322 | s = result->GetStatus(); |
7c673cae FG |
323 | if (!s.ok()) { |
324 | delete result; | |
325 | } else { | |
326 | logger->reset(result); | |
327 | } | |
328 | return s; | |
329 | } | |
330 | #endif // !ROCKSDB_LITE | |
331 | // Open a log file in the same directory as the db | |
1e59de90 TL |
332 | s = env->FileExists(fname); |
333 | if (s.ok()) { | |
334 | s = env->RenameFile( | |
335 | fname, OldInfoLogFileName(dbname, clock->NowMicros(), db_absolute_path, | |
336 | options.db_log_dir)); | |
337 | ||
338 | // The operation sequence of "FileExists -> Rename" is not atomic. It's | |
339 | // possible that FileExists returns OK but file gets deleted before Rename. | |
340 | // This can cause Rename to return IOError with subcode PathNotFound. | |
341 | // Although it may be a rare case and applications should be discouraged | |
342 | // to not concurrently modifying the contents of the directories accessed | |
343 | // by the database instance, it is still helpful if we can perform some | |
344 | // simple handling of this case. Therefore, we do the following: | |
345 | // 1. if Rename() returns IOError with PathNotFound subcode, then we check | |
346 | // whether the source file, i.e. LOG, exists. | |
347 | // 2. if LOG exists, it means Rename() failed due to something else. Then | |
348 | // we report error. | |
349 | // 3. if LOG does not exist, it means it may have been removed/renamed by | |
350 | // someone else. Since it does not exist, we can reset Status to OK so | |
351 | // that this caller can try creating a new LOG file. If this succeeds, | |
352 | // we should still allow it. | |
353 | if (s.IsPathNotFound()) { | |
354 | s = env->FileExists(fname); | |
355 | if (s.IsNotFound()) { | |
356 | s = Status::OK(); | |
357 | } | |
358 | } | |
359 | } else if (s.IsNotFound()) { | |
360 | // "LOG" is not required to exist since this could be a new DB. | |
361 | s = Status::OK(); | |
362 | } | |
363 | if (s.ok()) { | |
364 | s = env->NewLogger(fname, logger); | |
365 | } | |
366 | if (s.ok() && logger->get() != nullptr) { | |
7c673cae FG |
367 | (*logger)->SetInfoLogLevel(options.info_log_level); |
368 | } | |
369 | return s; | |
370 | } | |
371 | ||
f67539c2 | 372 | } // namespace ROCKSDB_NAMESPACE |