2020-07-13 23:35:29 +00:00
|
|
|
// Copyright (c) 2019-present, Facebook, Inc. All rights reserved.
|
|
|
|
// This source code is licensed under both the GPLv2 (found in the
|
|
|
|
// COPYING file in the root directory) and Apache 2.0 License
|
|
|
|
// (found in the LICENSE.Apache file in the root directory).
|
|
|
|
|
|
|
|
#include "env/file_system_tracer.h"
|
|
|
|
|
2021-01-26 06:07:26 +00:00
|
|
|
#include "rocksdb/file_system.h"
|
|
|
|
#include "rocksdb/system_clock.h"
|
2021-08-12 02:31:44 +00:00
|
|
|
#include "rocksdb/trace_record.h"
|
2020-07-13 23:35:29 +00:00
|
|
|
|
|
|
|
namespace ROCKSDB_NAMESPACE {
|
|
|
|
|
2020-10-14 17:14:12 +00:00
|
|
|
IOStatus FileSystemTracingWrapper::NewSequentialFile(
|
|
|
|
const std::string& fname, const FileOptions& file_opts,
|
|
|
|
std::unique_ptr<FSSequentialFile>* result, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->NewSequentialFile(fname, file_opts, result, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::NewRandomAccessFile(
|
|
|
|
const std::string& fname, const FileOptions& file_opts,
|
|
|
|
std::unique_ptr<FSRandomAccessFile>* result, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->NewRandomAccessFile(fname, file_opts, result, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
2020-07-13 23:35:29 +00:00
|
|
|
IOStatus FileSystemTracingWrapper::NewWritableFile(
|
|
|
|
const std::string& fname, const FileOptions& file_opts,
|
|
|
|
std::unique_ptr<FSWritableFile>* result, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->NewWritableFile(fname, file_opts, result, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
2020-10-14 17:14:12 +00:00
|
|
|
IOStatus FileSystemTracingWrapper::ReopenWritableFile(
|
|
|
|
const std::string& fname, const FileOptions& file_opts,
|
|
|
|
std::unique_ptr<FSWritableFile>* result, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->ReopenWritableFile(fname, file_opts, result, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::ReuseWritableFile(
|
|
|
|
const std::string& fname, const std::string& old_fname,
|
|
|
|
const FileOptions& file_opts, std::unique_ptr<FSWritableFile>* result,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s =
|
|
|
|
target()->ReuseWritableFile(fname, old_fname, file_opts, result, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::NewRandomRWFile(
|
|
|
|
const std::string& fname, const FileOptions& file_opts,
|
|
|
|
std::unique_ptr<FSRandomRWFile>* result, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->NewRandomRWFile(fname, file_opts, result, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
2020-07-13 23:35:29 +00:00
|
|
|
IOStatus FileSystemTracingWrapper::NewDirectory(
|
|
|
|
const std::string& name, const IOOptions& io_opts,
|
|
|
|
std::unique_ptr<FSDirectory>* result, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->NewDirectory(name, io_opts, result, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
name.substr(name.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::GetChildren(const std::string& dir,
|
|
|
|
const IOOptions& io_opts,
|
|
|
|
std::vector<std::string>* r,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->GetChildren(dir, io_opts, r, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
dir.substr(dir.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::DeleteFile(const std::string& fname,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->DeleteFile(fname, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::CreateDir(const std::string& dirname,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->CreateDir(dirname, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
dirname.substr(dirname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::CreateDirIfMissing(
|
|
|
|
const std::string& dirname, const IOOptions& options, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->CreateDirIfMissing(dirname, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
dirname.substr(dirname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::DeleteDir(const std::string& dirname,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->DeleteDir(dirname, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
dirname.substr(dirname.find_last_of("/\\") + 1));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FileSystemTracingWrapper::GetFileSize(const std::string& fname,
|
|
|
|
const IOOptions& options,
|
|
|
|
uint64_t* file_size,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->GetFileSize(fname, options, file_size, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOFileSize);
|
|
|
|
IOTraceRecord io_record(
|
2021-01-26 06:07:26 +00:00
|
|
|
clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed,
|
2021-01-25 22:35:45 +00:00
|
|
|
s.ToString(), fname.substr(fname.find_last_of("/\\") + 1), *file_size);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
2020-10-14 17:14:12 +00:00
|
|
|
IOStatus FileSystemTracingWrapper::Truncate(const std::string& fname,
|
|
|
|
size_t size,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Truncate(fname, size, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOFileSize);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(),
|
|
|
|
fname.substr(fname.find_last_of("/\\") + 1), size);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
2020-07-13 23:35:29 +00:00
|
|
|
IOStatus FSSequentialFileTracingWrapper::Read(size_t n,
|
|
|
|
const IOOptions& options,
|
|
|
|
Slice* result, char* scratch,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Read(n, options, result, scratch, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_,
|
|
|
|
result->size(), 0 /*Offset*/);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSSequentialFileTracingWrapper::InvalidateCache(size_t offset,
|
|
|
|
size_t length) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->InvalidateCache(offset, length);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_, length,
|
|
|
|
offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSSequentialFileTracingWrapper::PositionedRead(
|
|
|
|
uint64_t offset, size_t n, const IOOptions& options, Slice* result,
|
|
|
|
char* scratch, IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s =
|
|
|
|
target()->PositionedRead(offset, n, options, result, scratch, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_,
|
|
|
|
result->size(), offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomAccessFileTracingWrapper::Read(uint64_t offset, size_t n,
|
|
|
|
const IOOptions& options,
|
|
|
|
Slice* result, char* scratch,
|
|
|
|
IODebugContext* dbg) const {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Read(offset, n, options, result, scratch, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_, n,
|
|
|
|
offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomAccessFileTracingWrapper::MultiRead(FSReadRequest* reqs,
|
|
|
|
size_t num_reqs,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->MultiRead(reqs, num_reqs, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
|
|
|
uint64_t latency = elapsed;
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2020-07-13 23:35:29 +00:00
|
|
|
for (size_t i = 0; i < num_reqs; i++) {
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(
|
|
|
|
clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, latency,
|
|
|
|
reqs[i].status.ToString(), file_name_, reqs[i].len, reqs[i].offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
}
|
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomAccessFileTracingWrapper::Prefetch(uint64_t offset, size_t n,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Prefetch(offset, n, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_, n,
|
|
|
|
offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomAccessFileTracingWrapper::InvalidateCache(size_t offset,
|
|
|
|
size_t length) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->InvalidateCache(offset, length);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_, length,
|
2020-07-13 23:35:29 +00:00
|
|
|
static_cast<uint64_t>(offset));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
Provide support for IOTracing for ReadAsync API (#9833)
Summary:
Same as title
Pull Request resolved: https://github.com/facebook/rocksdb/pull/9833
Test Plan:
Add unit test and manually check the output of tracing logs
For fixed readahead_size it logs as:
```
Access Time : 193352113447923 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 15075 , IO Status: OK, Length: 12288, Offset: 659456
Access Time : 193352113465232 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 14425 , IO Status: OK, Length: 12288, Offset: 671744
Access Time : 193352113481539 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 13062 , IO Status: OK, Length: 12288, Offset: 684032
Access Time : 193352113497692 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 13649 , IO Status: OK, Length: 12288, Offset: 696320
Access Time : 193352113520043 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 19384 , IO Status: OK, Length: 12288, Offset: 708608
Access Time : 193352113538401 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 15406 , IO Status: OK, Length: 12288, Offset: 720896
Access Time : 193352113554855 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 13670 , IO Status: OK, Length: 12288, Offset: 733184
Access Time : 193352113571624 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 13855 , IO Status: OK, Length: 12288, Offset: 745472
Access Time : 193352113587924 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 13953 , IO Status: OK, Length: 12288, Offset: 757760
Access Time : 193352113603285 , File Name: 000026.sst , File Operation: Prefetch , Latency: 59 , IO Status: Not implemented: Prefetch not supported, Length: 8868, Offset: 898349
```
For implicit readahead:
```
Access Time : 193351865156587 , File Name: 000026.sst , File Operation: Prefetch , Latency: 48 , IO Status: Not implemented: Prefetch not supported, Length: 12266, Offset: 391174
Access Time : 193351865160354 , File Name: 000026.sst , File Operation: Prefetch , Latency: 51 , IO Status: Not implemented: Prefetch not supported, Length: 12266, Offset: 395248
Access Time : 193351865164253 , File Name: 000026.sst , File Operation: Prefetch , Latency: 49 , IO Status: Not implemented: Prefetch not supported, Length: 12266, Offset: 399322
Access Time : 193351865165461 , File Name: 000026.sst , File Operation: ReadAsync , Latency: 222871 , IO Status: OK, Length: 135168, Offset: 401408
```
Reviewed By: anand1976
Differential Revision: D35601634
Pulled By: akankshamahajan15
fbshipit-source-id: 5a4f32a850af878efa0767bd5706380152a1f26e
2022-05-26 02:47:03 +00:00
|
|
|
IOStatus FSRandomAccessFileTracingWrapper::ReadAsync(
|
|
|
|
FSReadRequest& req, const IOOptions& opts,
|
|
|
|
std::function<void(const FSReadRequest&, void*)> cb, void* cb_arg,
|
|
|
|
void** io_handle, IOHandleDeleter* del_fn, IODebugContext* dbg) {
|
|
|
|
// Create a callback and populate info.
|
|
|
|
auto read_async_callback =
|
|
|
|
std::bind(&FSRandomAccessFileTracingWrapper::ReadAsyncCallback, this,
|
|
|
|
std::placeholders::_1, std::placeholders::_2);
|
|
|
|
ReadAsyncCallbackInfo* read_async_cb_info = new ReadAsyncCallbackInfo;
|
|
|
|
read_async_cb_info->cb_ = cb;
|
|
|
|
read_async_cb_info->cb_arg_ = cb_arg;
|
|
|
|
read_async_cb_info->start_time_ = clock_->NowNanos();
|
|
|
|
read_async_cb_info->file_op_ = __func__;
|
|
|
|
|
|
|
|
IOStatus s = target()->ReadAsync(req, opts, read_async_callback,
|
|
|
|
read_async_cb_info, io_handle, del_fn, dbg);
|
|
|
|
|
|
|
|
if (!s.ok()) {
|
|
|
|
delete read_async_cb_info;
|
|
|
|
}
|
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
void FSRandomAccessFileTracingWrapper::ReadAsyncCallback(
|
|
|
|
const FSReadRequest& req, void* cb_arg) {
|
|
|
|
ReadAsyncCallbackInfo* read_async_cb_info =
|
|
|
|
static_cast<ReadAsyncCallbackInfo*>(cb_arg);
|
|
|
|
assert(read_async_cb_info);
|
|
|
|
assert(read_async_cb_info->cb_);
|
|
|
|
|
|
|
|
uint64_t elapsed = clock_->NowNanos() - read_async_cb_info->start_time_;
|
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
|
|
|
read_async_cb_info->file_op_, elapsed,
|
|
|
|
req.status.ToString(), file_name_, req.result.size(),
|
|
|
|
req.offset);
|
|
|
|
io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/);
|
|
|
|
|
|
|
|
// call the underlying callback.
|
|
|
|
read_async_cb_info->cb_(req, read_async_cb_info->cb_arg_);
|
|
|
|
delete read_async_cb_info;
|
|
|
|
}
|
|
|
|
|
2020-07-13 23:35:29 +00:00
|
|
|
IOStatus FSWritableFileTracingWrapper::Append(const Slice& data,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Append(data, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_,
|
|
|
|
data.size(), 0 /*Offset*/);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSWritableFileTracingWrapper::PositionedAppend(
|
|
|
|
const Slice& data, uint64_t offset, const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->PositionedAppend(data, offset, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_,
|
|
|
|
data.size(), offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSWritableFileTracingWrapper::Truncate(uint64_t size,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Truncate(size, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_, size,
|
|
|
|
0 /*Offset*/);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSWritableFileTracingWrapper::Close(const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Close(options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
file_name_);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
uint64_t FSWritableFileTracingWrapper::GetFileSize(const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
uint64_t file_size = target()->GetFileSize(options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOFileSize);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, "OK", file_name_, file_size);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return file_size;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSWritableFileTracingWrapper::InvalidateCache(size_t offset,
|
|
|
|
size_t length) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->InvalidateCache(offset, length);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_, length,
|
2020-07-13 23:35:29 +00:00
|
|
|
static_cast<uint64_t>(offset));
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomRWFileTracingWrapper::Write(uint64_t offset, const Slice& data,
|
|
|
|
const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Write(offset, data, options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_,
|
|
|
|
data.size(), offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomRWFileTracingWrapper::Read(uint64_t offset, size_t n,
|
|
|
|
const IOOptions& options,
|
|
|
|
Slice* result, char* scratch,
|
|
|
|
IODebugContext* dbg) const {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-07-13 23:35:29 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Read(offset, n, options, result, scratch, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-25 22:35:45 +00:00
|
|
|
uint64_t io_op_data = 0;
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOLen);
|
|
|
|
io_op_data |= (1 << IOTraceOp::kIOOffset);
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
|
2021-01-25 22:35:45 +00:00
|
|
|
__func__, elapsed, s.ToString(), file_name_, n,
|
|
|
|
offset);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-07-13 23:35:29 +00:00
|
|
|
return s;
|
|
|
|
}
|
2020-10-14 17:14:12 +00:00
|
|
|
|
|
|
|
IOStatus FSRandomRWFileTracingWrapper::Flush(const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Flush(options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
file_name_);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomRWFileTracingWrapper::Close(const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Close(options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
file_name_);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomRWFileTracingWrapper::Sync(const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Sync(options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
file_name_);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
|
|
|
|
|
|
|
IOStatus FSRandomRWFileTracingWrapper::Fsync(const IOOptions& options,
|
|
|
|
IODebugContext* dbg) {
|
2021-01-26 06:07:26 +00:00
|
|
|
StopWatchNano timer(clock_);
|
2020-10-14 17:14:12 +00:00
|
|
|
timer.Start();
|
|
|
|
IOStatus s = target()->Fsync(options, dbg);
|
|
|
|
uint64_t elapsed = timer.ElapsedNanos();
|
2021-01-26 06:07:26 +00:00
|
|
|
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
|
2021-01-25 22:35:45 +00:00
|
|
|
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
|
|
|
|
file_name_);
|
2021-04-01 20:14:01 +00:00
|
|
|
io_tracer_->WriteIOOp(io_record, dbg);
|
2020-10-14 17:14:12 +00:00
|
|
|
return s;
|
|
|
|
}
|
2020-07-13 23:35:29 +00:00
|
|
|
} // namespace ROCKSDB_NAMESPACE
|