rocksdb/env/file_system_tracer.cc
Akanksha Mahajan 1d226018af In IOTracing, add filename with each operation in trace file. (#7885)
Summary:
1. In IOTracing, add filename with each IOTrace record. Filename is stored in file object (Tracing Wrappers).
         2. Change the logic of figuring out which additional information (file_size,
            length, offset etc) needs to be store with each operation
            which is different for different operations.
            When new information will be added in future (depends on operation),
            this change would make the future additions simple.

Logic: In IOTraceRecord, io_op_data is added and its
         bitwise positions represent which additional information need
         to added in the record from enum IOTraceOp. Values in IOTraceOp represent bitwise positions.
         So if length and offset needs to be stored (IOTraceOp::kIOLen
         is 1 and IOTraceOp::kIOOffset is 2), position 1 and 2 (from rightmost bit) will be set
         and io_op_data will contain 110.

Pull Request resolved: https://github.com/facebook/rocksdb/pull/7885

Test Plan: Updated io_tracer_test and verified the trace file manually.

Reviewed By: anand1976

Differential Revision: D25982353

Pulled By: akankshamahajan15

fbshipit-source-id: ebfc5539cc0e231d7794a6b42b73f5403e360b22
2021-01-25 14:37:35 -08:00

518 lines
21 KiB
C++

// 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"
#include "rocksdb/env.h"
namespace ROCKSDB_NAMESPACE {
IOStatus FileSystemTracingWrapper::NewSequentialFile(
const std::string& fname, const FileOptions& file_opts,
std::unique_ptr<FSSequentialFile>* result, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->NewSequentialFile(fname, file_opts, result, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::NewRandomAccessFile(
const std::string& fname, const FileOptions& file_opts,
std::unique_ptr<FSRandomAccessFile>* result, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->NewRandomAccessFile(fname, file_opts, result, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::NewWritableFile(
const std::string& fname, const FileOptions& file_opts,
std::unique_ptr<FSWritableFile>* result, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->NewWritableFile(fname, file_opts, result, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::ReopenWritableFile(
const std::string& fname, const FileOptions& file_opts,
std::unique_ptr<FSWritableFile>* result, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->ReopenWritableFile(fname, file_opts, result, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
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) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s =
target()->ReuseWritableFile(fname, old_fname, file_opts, result, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::NewRandomRWFile(
const std::string& fname, const FileOptions& file_opts,
std::unique_ptr<FSRandomRWFile>* result, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->NewRandomRWFile(fname, file_opts, result, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::NewDirectory(
const std::string& name, const IOOptions& io_opts,
std::unique_ptr<FSDirectory>* result, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->NewDirectory(name, io_opts, result, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
name.substr(name.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::GetChildren(const std::string& dir,
const IOOptions& io_opts,
std::vector<std::string>* r,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->GetChildren(dir, io_opts, r, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dir.substr(dir.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::DeleteFile(const std::string& fname,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->DeleteFile(fname, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::CreateDir(const std::string& dirname,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->CreateDir(dirname, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dirname.substr(dirname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::CreateDirIfMissing(
const std::string& dirname, const IOOptions& options, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->CreateDirIfMissing(dirname, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dirname.substr(dirname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::DeleteDir(const std::string& dirname,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->DeleteDir(dirname, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dirname.substr(dirname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::GetFileSize(const std::string& fname,
const IOOptions& options,
uint64_t* file_size,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->GetFileSize(fname, options, file_size, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOFileSize);
IOTraceRecord io_record(
env_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed,
s.ToString(), fname.substr(fname.find_last_of("/\\") + 1), *file_size);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FileSystemTracingWrapper::Truncate(const std::string& fname,
size_t size,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Truncate(fname, size, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOFileSize);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1), size);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSSequentialFileTracingWrapper::Read(size_t n,
const IOOptions& options,
Slice* result, char* scratch,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Read(n, options, result, scratch, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_,
result->size(), 0 /*Offset*/);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSSequentialFileTracingWrapper::InvalidateCache(size_t offset,
size_t length) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->InvalidateCache(offset, length);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, length,
offset);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSSequentialFileTracingWrapper::PositionedRead(
uint64_t offset, size_t n, const IOOptions& options, Slice* result,
char* scratch, IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s =
target()->PositionedRead(offset, n, options, result, scratch, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_,
result->size(), offset);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomAccessFileTracingWrapper::Read(uint64_t offset, size_t n,
const IOOptions& options,
Slice* result, char* scratch,
IODebugContext* dbg) const {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Read(offset, n, options, result, scratch, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, n,
offset);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomAccessFileTracingWrapper::MultiRead(FSReadRequest* reqs,
size_t num_reqs,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->MultiRead(reqs, num_reqs, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t latency = elapsed;
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
for (size_t i = 0; i < num_reqs; i++) {
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, latency, reqs[i].status.ToString(),
file_name_, reqs[i].len, reqs[i].offset);
io_tracer_->WriteIOOp(io_record);
}
return s;
}
IOStatus FSRandomAccessFileTracingWrapper::Prefetch(uint64_t offset, size_t n,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Prefetch(offset, n, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, n,
offset);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomAccessFileTracingWrapper::InvalidateCache(size_t offset,
size_t length) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->InvalidateCache(offset, length);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, length,
static_cast<uint64_t>(offset));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSWritableFileTracingWrapper::Append(const Slice& data,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Append(data, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_,
data.size(), 0 /*Offset*/);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSWritableFileTracingWrapper::PositionedAppend(
const Slice& data, uint64_t offset, const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->PositionedAppend(data, offset, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_,
data.size(), offset);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSWritableFileTracingWrapper::Truncate(uint64_t size,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Truncate(size, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, size,
0 /*Offset*/);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSWritableFileTracingWrapper::Close(const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Close(options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_);
io_tracer_->WriteIOOp(io_record);
return s;
}
uint64_t FSWritableFileTracingWrapper::GetFileSize(const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
uint64_t file_size = target()->GetFileSize(options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOFileSize);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, "OK", file_name_, file_size);
io_tracer_->WriteIOOp(io_record);
return file_size;
}
IOStatus FSWritableFileTracingWrapper::InvalidateCache(size_t offset,
size_t length) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->InvalidateCache(offset, length);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, length,
static_cast<uint64_t>(offset));
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomRWFileTracingWrapper::Write(uint64_t offset, const Slice& data,
const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Write(offset, data, options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_,
data.size(), offset);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomRWFileTracingWrapper::Read(uint64_t offset, size_t n,
const IOOptions& options,
Slice* result, char* scratch,
IODebugContext* dbg) const {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Read(offset, n, options, result, scratch, dbg);
uint64_t elapsed = timer.ElapsedNanos();
uint64_t io_op_data = 0;
io_op_data |= (1 << IOTraceOp::kIOLen);
io_op_data |= (1 << IOTraceOp::kIOOffset);
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, n,
offset);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomRWFileTracingWrapper::Flush(const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Flush(options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomRWFileTracingWrapper::Close(const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Close(options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomRWFileTracingWrapper::Sync(const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Sync(options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_);
io_tracer_->WriteIOOp(io_record);
return s;
}
IOStatus FSRandomRWFileTracingWrapper::Fsync(const IOOptions& options,
IODebugContext* dbg) {
StopWatchNano timer(env_);
timer.Start();
IOStatus s = target()->Fsync(options, dbg);
uint64_t elapsed = timer.ElapsedNanos();
IOTraceRecord io_record(env_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_);
io_tracer_->WriteIOOp(io_record);
return s;
}
} // namespace ROCKSDB_NAMESPACE