Add request_id in IODebugContext. (#8045)

Summary:
Add request_id in IODebugContext which will be populated by
    underlying FileSystem for IOTracing purposes. Update IOTracer to trace
    request_id in the tracing records. Provided API
    IODebugContext::SetRequestId which will set the request_id and enable
    tracing for request_id. The API hides the implementation and underlying
    file system needs to call this API directly.

Update DB::StartIOTrace API and remove redundant Env* from the
    argument as its not used and DB already has Env that is passed down to
    IOTracer.

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

Test Plan: Update unit test.

Differential Revision: D26899871

Pulled By: akankshamahajan15

fbshipit-source-id: 56adef52ee5af0fb3060b607c3af1ec01635fa2b
main
Akanksha Mahajan 4 years ago committed by Facebook GitHub Bot
parent 5025c7ec09
commit 689b13e639
  1. 1
      HISTORY.md
  2. 2
      db/blob/db_blob_basic_test.cc
  3. 2
      db/db_impl/db_impl.cc
  4. 2
      db/db_impl/db_impl.h
  5. 66
      env/file_system_tracer.cc
  6. 2
      include/rocksdb/db.h
  7. 24
      include/rocksdb/file_system.h
  8. 4
      include/rocksdb/utilities/stackable_db.h
  9. 2
      tools/io_tracer_parser_test.cc
  10. 16
      tools/io_tracer_parser_tool.cc
  11. 53
      trace_replay/io_tracer.cc
  12. 10
      trace_replay/io_tracer.h
  13. 41
      trace_replay/io_tracer_test.cc

@ -15,6 +15,7 @@
### Public API change ### Public API change
* Added `TableProperties::slow_compression_estimated_data_size` and `TableProperties::fast_compression_estimated_data_size`. When `ColumnFamilyOptions::sample_for_compression > 0`, they estimate what `TableProperties::data_size` would have been if the "fast" or "slow" (see `ColumnFamilyOptions::sample_for_compression` API doc for definitions) compression had been used instead. * Added `TableProperties::slow_compression_estimated_data_size` and `TableProperties::fast_compression_estimated_data_size`. When `ColumnFamilyOptions::sample_for_compression > 0`, they estimate what `TableProperties::data_size` would have been if the "fast" or "slow" (see `ColumnFamilyOptions::sample_for_compression` API doc for definitions) compression had been used instead.
* Update DB::StartIOTrace and remove Env object from the arguments as its redundant and DB already has Env object that is passed down to IOTracer::StartIOTrace
## 6.19.0 (03/21/2021) ## 6.19.0 (03/21/2021)
### Bug Fixes ### Bug Fixes

@ -223,7 +223,7 @@ TEST_F(DBBlobBasicTest, GenerateIOTracing) {
std::unique_ptr<TraceWriter> trace_writer; std::unique_ptr<TraceWriter> trace_writer;
ASSERT_OK( ASSERT_OK(
NewFileTraceWriter(env_, EnvOptions(), trace_file, &trace_writer)); NewFileTraceWriter(env_, EnvOptions(), trace_file, &trace_writer));
ASSERT_OK(db_->StartIOTrace(env_, TraceOptions(), std::move(trace_writer))); ASSERT_OK(db_->StartIOTrace(TraceOptions(), std::move(trace_writer)));
constexpr char key[] = "key"; constexpr char key[] = "key";
constexpr char blob_value[] = "blob_value"; constexpr char blob_value[] = "blob_value";

@ -3145,7 +3145,7 @@ SystemClock* DBImpl::GetSystemClock() const {
#ifndef ROCKSDB_LITE #ifndef ROCKSDB_LITE
Status DBImpl::StartIOTrace(Env* /*env*/, const TraceOptions& trace_options, Status DBImpl::StartIOTrace(const TraceOptions& trace_options,
std::unique_ptr<TraceWriter>&& trace_writer) { std::unique_ptr<TraceWriter>&& trace_writer) {
assert(trace_writer != nullptr); assert(trace_writer != nullptr);
return io_tracer_->StartIOTrace(GetSystemClock(), trace_options, return io_tracer_->StartIOTrace(GetSystemClock(), trace_options,

@ -469,7 +469,7 @@ class DBImpl : public DB {
Status EndBlockCacheTrace() override; Status EndBlockCacheTrace() override;
using DB::StartIOTrace; using DB::StartIOTrace;
Status StartIOTrace(Env* env, const TraceOptions& options, Status StartIOTrace(const TraceOptions& options,
std::unique_ptr<TraceWriter>&& trace_writer) override; std::unique_ptr<TraceWriter>&& trace_writer) override;
using DB::EndIOTrace; using DB::EndIOTrace;

@ -20,7 +20,7 @@ IOStatus FileSystemTracingWrapper::NewSequentialFile(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1)); fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -34,7 +34,7 @@ IOStatus FileSystemTracingWrapper::NewRandomAccessFile(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1)); fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -48,7 +48,7 @@ IOStatus FileSystemTracingWrapper::NewWritableFile(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1)); fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -62,7 +62,7 @@ IOStatus FileSystemTracingWrapper::ReopenWritableFile(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1)); fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -78,7 +78,7 @@ IOStatus FileSystemTracingWrapper::ReuseWritableFile(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1)); fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -92,7 +92,7 @@ IOStatus FileSystemTracingWrapper::NewRandomRWFile(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1)); fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -106,7 +106,7 @@ IOStatus FileSystemTracingWrapper::NewDirectory(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
name.substr(name.find_last_of("/\\") + 1)); name.substr(name.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -121,7 +121,7 @@ IOStatus FileSystemTracingWrapper::GetChildren(const std::string& dir,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dir.substr(dir.find_last_of("/\\") + 1)); dir.substr(dir.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -135,7 +135,7 @@ IOStatus FileSystemTracingWrapper::DeleteFile(const std::string& fname,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1)); fname.substr(fname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -149,7 +149,7 @@ IOStatus FileSystemTracingWrapper::CreateDir(const std::string& dirname,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dirname.substr(dirname.find_last_of("/\\") + 1)); dirname.substr(dirname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -162,7 +162,7 @@ IOStatus FileSystemTracingWrapper::CreateDirIfMissing(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dirname.substr(dirname.find_last_of("/\\") + 1)); dirname.substr(dirname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -176,7 +176,7 @@ IOStatus FileSystemTracingWrapper::DeleteDir(const std::string& dirname,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
dirname.substr(dirname.find_last_of("/\\") + 1)); dirname.substr(dirname.find_last_of("/\\") + 1));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -193,7 +193,7 @@ IOStatus FileSystemTracingWrapper::GetFileSize(const std::string& fname,
IOTraceRecord io_record( IOTraceRecord io_record(
clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed,
s.ToString(), fname.substr(fname.find_last_of("/\\") + 1), *file_size); s.ToString(), fname.substr(fname.find_last_of("/\\") + 1), *file_size);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -210,7 +210,7 @@ IOStatus FileSystemTracingWrapper::Truncate(const std::string& fname,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), __func__, elapsed, s.ToString(),
fname.substr(fname.find_last_of("/\\") + 1), size); fname.substr(fname.find_last_of("/\\") + 1), size);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -227,7 +227,7 @@ IOStatus FSSequentialFileTracingWrapper::Read(size_t n,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, __func__, elapsed, s.ToString(), file_name_,
result->size(), 0 /*Offset*/); result->size(), 0 /*Offset*/);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -243,7 +243,7 @@ IOStatus FSSequentialFileTracingWrapper::InvalidateCache(size_t offset,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, length, __func__, elapsed, s.ToString(), file_name_, length,
offset); offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/);
return s; return s;
} }
@ -261,7 +261,7 @@ IOStatus FSSequentialFileTracingWrapper::PositionedRead(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, __func__, elapsed, s.ToString(), file_name_,
result->size(), offset); result->size(), offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -279,7 +279,7 @@ IOStatus FSRandomAccessFileTracingWrapper::Read(uint64_t offset, size_t n,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, n, __func__, elapsed, s.ToString(), file_name_, n,
offset); offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -299,7 +299,7 @@ IOStatus FSRandomAccessFileTracingWrapper::MultiRead(FSReadRequest* reqs,
IOTraceRecord io_record( IOTraceRecord io_record(
clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, latency, clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, latency,
reqs[i].status.ToString(), file_name_, reqs[i].len, reqs[i].offset); reqs[i].status.ToString(), file_name_, reqs[i].len, reqs[i].offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
} }
return s; return s;
} }
@ -317,7 +317,7 @@ IOStatus FSRandomAccessFileTracingWrapper::Prefetch(uint64_t offset, size_t n,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, n, __func__, elapsed, s.ToString(), file_name_, n,
offset); offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -333,7 +333,7 @@ IOStatus FSRandomAccessFileTracingWrapper::InvalidateCache(size_t offset,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, length, __func__, elapsed, s.ToString(), file_name_, length,
static_cast<uint64_t>(offset)); static_cast<uint64_t>(offset));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/);
return s; return s;
} }
@ -349,7 +349,7 @@ IOStatus FSWritableFileTracingWrapper::Append(const Slice& data,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, __func__, elapsed, s.ToString(), file_name_,
data.size(), 0 /*Offset*/); data.size(), 0 /*Offset*/);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -366,7 +366,7 @@ IOStatus FSWritableFileTracingWrapper::PositionedAppend(
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, __func__, elapsed, s.ToString(), file_name_,
data.size(), offset); data.size(), offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -382,7 +382,7 @@ IOStatus FSWritableFileTracingWrapper::Truncate(uint64_t size,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, size, __func__, elapsed, s.ToString(), file_name_, size,
0 /*Offset*/); 0 /*Offset*/);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -395,7 +395,7 @@ IOStatus FSWritableFileTracingWrapper::Close(const IOOptions& options,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_); file_name_);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -409,7 +409,7 @@ uint64_t FSWritableFileTracingWrapper::GetFileSize(const IOOptions& options,
io_op_data |= (1 << IOTraceOp::kIOFileSize); io_op_data |= (1 << IOTraceOp::kIOFileSize);
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, "OK", file_name_, file_size); __func__, elapsed, "OK", file_name_, file_size);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return file_size; return file_size;
} }
@ -425,7 +425,7 @@ IOStatus FSWritableFileTracingWrapper::InvalidateCache(size_t offset,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, length, __func__, elapsed, s.ToString(), file_name_, length,
static_cast<uint64_t>(offset)); static_cast<uint64_t>(offset));
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/);
return s; return s;
} }
@ -442,7 +442,7 @@ IOStatus FSRandomRWFileTracingWrapper::Write(uint64_t offset, const Slice& data,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, __func__, elapsed, s.ToString(), file_name_,
data.size(), offset); data.size(), offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -460,7 +460,7 @@ IOStatus FSRandomRWFileTracingWrapper::Read(uint64_t offset, size_t n,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data,
__func__, elapsed, s.ToString(), file_name_, n, __func__, elapsed, s.ToString(), file_name_, n,
offset); offset);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -473,7 +473,7 @@ IOStatus FSRandomRWFileTracingWrapper::Flush(const IOOptions& options,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_); file_name_);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -486,7 +486,7 @@ IOStatus FSRandomRWFileTracingWrapper::Close(const IOOptions& options,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_); file_name_);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -499,7 +499,7 @@ IOStatus FSRandomRWFileTracingWrapper::Sync(const IOOptions& options,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_); file_name_);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
@ -512,7 +512,7 @@ IOStatus FSRandomRWFileTracingWrapper::Fsync(const IOOptions& options,
IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer,
0 /*io_op_data*/, __func__, elapsed, s.ToString(), 0 /*io_op_data*/, __func__, elapsed, s.ToString(),
file_name_); file_name_);
io_tracer_->WriteIOOp(io_record); io_tracer_->WriteIOOp(io_record, dbg);
return s; return s;
} }
} // namespace ROCKSDB_NAMESPACE } // namespace ROCKSDB_NAMESPACE

@ -1612,7 +1612,7 @@ class DB {
} }
// IO Tracing operations. Use EndIOTrace() to stop tracing. // IO Tracing operations. Use EndIOTrace() to stop tracing.
virtual Status StartIOTrace(Env* /*env*/, const TraceOptions& /*options*/, virtual Status StartIOTrace(const TraceOptions& /*options*/,
std::unique_ptr<TraceWriter>&& /*trace_writer*/) { std::unique_ptr<TraceWriter>&& /*trace_writer*/) {
return Status::NotSupported("StartIOTrace() is not implemented."); return Status::NotSupported("StartIOTrace() is not implemented.");
} }

@ -132,12 +132,36 @@ struct IODebugContext {
// To be set by the FileSystem implementation // To be set by the FileSystem implementation
std::string msg; std::string msg;
// To be set by the underlying FileSystem implementation.
std::string request_id;
// In order to log required information in IO tracing for different
// operations, Each bit in trace_data stores which corresponding info from
// IODebugContext will be added in the trace. Foreg, if trace_data = 1, it
// means bit at position 0 is set so TraceData::kRequestID (request_id) will
// be logged in the trace record.
//
enum TraceData : char {
// The value of each enum represents the bitwise position for
// that information in trace_data which will be used by IOTracer for
// tracing. Make sure to add them sequentially.
kRequestID = 0,
};
uint64_t trace_data = 0;
IODebugContext() {} IODebugContext() {}
void AddCounter(std::string& name, uint64_t value) { void AddCounter(std::string& name, uint64_t value) {
counters.emplace(name, value); counters.emplace(name, value);
} }
// Called by underlying file system to set request_id and log request_id in
// IOTracing.
void SetRequestId(const std::string& _request_id) {
request_id = _request_id;
trace_data |= (1 << TraceData::kRequestID);
}
std::string ToString() { std::string ToString() {
std::ostringstream ss; std::ostringstream ss;
ss << file_path << ", "; ss << file_path << ", ";

@ -373,9 +373,9 @@ class StackableDB : public DB {
Status EndBlockCacheTrace() override { return db_->EndBlockCacheTrace(); } Status EndBlockCacheTrace() override { return db_->EndBlockCacheTrace(); }
using DB::StartIOTrace; using DB::StartIOTrace;
Status StartIOTrace(Env* env, const TraceOptions& options, Status StartIOTrace(const TraceOptions& options,
std::unique_ptr<TraceWriter>&& trace_writer) override { std::unique_ptr<TraceWriter>&& trace_writer) override {
return db_->StartIOTrace(env, options, std::move(trace_writer)); return db_->StartIOTrace(options, std::move(trace_writer));
} }
using DB::EndIOTrace; using DB::EndIOTrace;

@ -65,7 +65,7 @@ class IOTracerParserTest : public testing::Test {
ASSERT_OK(NewFileTraceWriter(env_, env_options_, trace_file_path_, ASSERT_OK(NewFileTraceWriter(env_, env_options_, trace_file_path_,
&trace_writer)); &trace_writer));
ASSERT_OK(db_->StartIOTrace(env_, trace_opt, std::move(trace_writer))); ASSERT_OK(db_->StartIOTrace(trace_opt, std::move(trace_writer)));
for (int i = 0; i < 10; i++) { for (int i = 0; i < 10; i++) {
ASSERT_OK(db_->Put(write_opt, "key_" + std::to_string(i), ASSERT_OK(db_->Put(write_opt, "key_" + std::to_string(i),

@ -73,6 +73,22 @@ void IOTraceRecordParser::PrintHumanReadableIOTraceRecord(
// unset the rightmost bit. // unset the rightmost bit.
io_op_data &= (io_op_data - 1); io_op_data &= (io_op_data - 1);
} }
int64_t trace_data = static_cast<int64_t>(record.trace_data);
while (trace_data) {
// Find the rightmost set bit.
uint32_t set_pos = static_cast<uint32_t>(log2(trace_data & -trace_data));
switch (set_pos) {
case IODebugContext::TraceData::kRequestID:
ss << ", Request Id: " << record.request_id;
break;
default:
assert(false);
}
// unset the rightmost bit.
trace_data &= (trace_data - 1);
}
ss << "\n"; ss << "\n";
fprintf(stdout, "%s", ss.str().c_str()); fprintf(stdout, "%s", ss.str().c_str());
} }

@ -26,7 +26,8 @@ IOTraceWriter::IOTraceWriter(SystemClock* clock,
trace_options_(trace_options), trace_options_(trace_options),
trace_writer_(std::move(trace_writer)) {} trace_writer_(std::move(trace_writer)) {}
Status IOTraceWriter::WriteIOOp(const IOTraceRecord& record) { Status IOTraceWriter::WriteIOOp(const IOTraceRecord& record,
IODebugContext* dbg) {
uint64_t trace_file_size = trace_writer_->GetFileSize(); uint64_t trace_file_size = trace_writer_->GetFileSize();
if (trace_file_size > trace_options_.max_trace_file_size) { if (trace_file_size > trace_options_.max_trace_file_size) {
return Status::OK(); return Status::OK();
@ -71,6 +72,26 @@ Status IOTraceWriter::WriteIOOp(const IOTraceRecord& record) {
io_op_data &= (io_op_data - 1); io_op_data &= (io_op_data - 1);
} }
int64_t trace_data = 0;
if (dbg) {
trace_data = static_cast<int64_t>(dbg->trace_data);
}
PutFixed64(&trace.payload, trace_data);
while (trace_data) {
// Find the rightmost set bit.
uint32_t set_pos = static_cast<uint32_t>(log2(trace_data & -trace_data));
switch (set_pos) {
case IODebugContext::TraceData::kRequestID: {
Slice request_id(dbg->request_id);
PutLengthPrefixedSlice(&trace.payload, request_id);
} break;
default:
assert(false);
}
// unset the rightmost bit.
trace_data &= (trace_data - 1);
}
std::string encoded_trace; std::string encoded_trace;
TracerHelper::EncodeTrace(trace, &encoded_trace); TracerHelper::EncodeTrace(trace, &encoded_trace);
return trace_writer_->Write(encoded_trace); return trace_writer_->Write(encoded_trace);
@ -213,6 +234,31 @@ Status IOTraceReader::ReadIOOp(IOTraceRecord* record) {
// unset the rightmost bit. // unset the rightmost bit.
io_op_data &= (io_op_data - 1); io_op_data &= (io_op_data - 1);
} }
if (!GetFixed64(&enc_slice, &record->trace_data)) {
return Status::Incomplete(
"Incomplete access record: Failed to read trace op.");
}
int64_t trace_data = static_cast<int64_t>(record->trace_data);
while (trace_data) {
// Find the rightmost set bit.
uint32_t set_pos = static_cast<uint32_t>(log2(trace_data & -trace_data));
switch (set_pos) {
case IODebugContext::TraceData::kRequestID: {
Slice request_id;
if (!GetLengthPrefixedSlice(&enc_slice, &request_id)) {
return Status::Incomplete(
"Incomplete access record: Failed to request id.");
}
record->request_id = request_id.ToString();
} break;
default:
assert(false);
}
// unset the rightmost bit.
trace_data &= (trace_data - 1);
}
return Status::OK(); return Status::OK();
} }
@ -244,8 +290,7 @@ void IOTracer::EndIOTrace() {
tracing_enabled = false; tracing_enabled = false;
} }
// TODO: Return status and handle that in file_system_tracer.h void IOTracer::WriteIOOp(const IOTraceRecord& record, IODebugContext* dbg) {
void IOTracer::WriteIOOp(const IOTraceRecord& record) {
if (!writer_.load()) { if (!writer_.load()) {
return; return;
} }
@ -253,6 +298,6 @@ void IOTracer::WriteIOOp(const IOTraceRecord& record) {
if (!writer_.load()) { if (!writer_.load()) {
return; return;
} }
writer_.load()->WriteIOOp(record).PermitUncheckedError(); writer_.load()->WriteIOOp(record, dbg).PermitUncheckedError();
} }
} // namespace ROCKSDB_NAMESPACE } // namespace ROCKSDB_NAMESPACE

@ -9,6 +9,7 @@
#include <fstream> #include <fstream>
#include "monitoring/instrumented_mutex.h" #include "monitoring/instrumented_mutex.h"
#include "rocksdb/file_system.h"
#include "rocksdb/options.h" #include "rocksdb/options.h"
#include "trace_replay/trace_replay.h" #include "trace_replay/trace_replay.h"
@ -47,11 +48,16 @@ struct IOTraceRecord {
std::string io_status; std::string io_status;
// Stores file name instead of full path. // Stores file name instead of full path.
std::string file_name; std::string file_name;
// Fields added to record based on IO operation. // Fields added to record based on IO operation.
uint64_t len = 0; uint64_t len = 0;
uint64_t offset = 0; uint64_t offset = 0;
uint64_t file_size = 0; uint64_t file_size = 0;
// Additional information passed in IODebugContext.
uint64_t trace_data = 0;
std::string request_id;
IOTraceRecord() {} IOTraceRecord() {}
IOTraceRecord(const uint64_t& _access_timestamp, const TraceType& _trace_type, IOTraceRecord(const uint64_t& _access_timestamp, const TraceType& _trace_type,
@ -102,7 +108,7 @@ class IOTraceWriter {
IOTraceWriter(IOTraceWriter&&) = delete; IOTraceWriter(IOTraceWriter&&) = delete;
IOTraceWriter& operator=(IOTraceWriter&&) = delete; IOTraceWriter& operator=(IOTraceWriter&&) = delete;
Status WriteIOOp(const IOTraceRecord& record); Status WriteIOOp(const IOTraceRecord& record, IODebugContext* dbg);
// Write a trace header at the beginning, typically on initiating a trace, // Write a trace header at the beginning, typically on initiating a trace,
// with some metadata like a magic number and RocksDB version. // with some metadata like a magic number and RocksDB version.
@ -175,7 +181,7 @@ class IOTracer {
TSAN_SUPPRESSION bool is_tracing_enabled() const { return tracing_enabled; } TSAN_SUPPRESSION bool is_tracing_enabled() const { return tracing_enabled; }
void WriteIOOp(const IOTraceRecord& record); void WriteIOOp(const IOTraceRecord& record, IODebugContext* dbg);
private: private:
TraceOptions trace_options_; TraceOptions trace_options_;

@ -63,7 +63,7 @@ class IOTracerTest : public testing::Test {
record.file_name = kDummyFile + std::to_string(i); record.file_name = kDummyFile + std::to_string(i);
record.len = i; record.len = i;
record.offset = i + 20; record.offset = i + 20;
EXPECT_OK(writer->WriteIOOp(record)); EXPECT_OK(writer->WriteIOOp(record, nullptr));
} }
} }
@ -91,6 +91,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) {
{ {
TraceOptions trace_opt; TraceOptions trace_opt;
std::unique_ptr<TraceWriter> trace_writer; std::unique_ptr<TraceWriter> trace_writer;
ASSERT_OK(NewFileTraceWriter(env_, env_options_, trace_file_path_, ASSERT_OK(NewFileTraceWriter(env_, env_options_, trace_file_path_,
&trace_writer)); &trace_writer));
IOTracer writer; IOTracer writer;
@ -100,7 +101,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) {
IOTraceRecord record0(0, TraceType::kIOTracer, 0 /*io_op_data*/, IOTraceRecord record0(0, TraceType::kIOTracer, 0 /*io_op_data*/,
GetFileOperation(0), 155 /*latency*/, GetFileOperation(0), 155 /*latency*/,
IOStatus::OK().ToString(), file_name); IOStatus::OK().ToString(), file_name);
writer.WriteIOOp(record0); writer.WriteIOOp(record0, nullptr);
// Write record with FileSize. // Write record with FileSize.
uint64_t io_op_data = 0; uint64_t io_op_data = 0;
@ -109,7 +110,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) {
GetFileOperation(1), 10 /*latency*/, GetFileOperation(1), 10 /*latency*/,
IOStatus::OK().ToString(), file_name, IOStatus::OK().ToString(), file_name,
256 /*file_size*/); 256 /*file_size*/);
writer.WriteIOOp(record1); writer.WriteIOOp(record1, nullptr);
// Write record with Length. // Write record with Length.
io_op_data = 0; io_op_data = 0;
@ -118,7 +119,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) {
GetFileOperation(2), 10 /*latency*/, GetFileOperation(2), 10 /*latency*/,
IOStatus::OK().ToString(), file_name, 100 /*length*/, IOStatus::OK().ToString(), file_name, 100 /*length*/,
200 /*offset*/); 200 /*offset*/);
writer.WriteIOOp(record2); writer.WriteIOOp(record2, nullptr);
// Write record with Length and offset. // Write record with Length and offset.
io_op_data = 0; io_op_data = 0;
@ -128,7 +129,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) {
GetFileOperation(3), 10 /*latency*/, GetFileOperation(3), 10 /*latency*/,
IOStatus::OK().ToString(), file_name, 120 /*length*/, IOStatus::OK().ToString(), file_name, 120 /*length*/,
17 /*offset*/); 17 /*offset*/);
writer.WriteIOOp(record3); writer.WriteIOOp(record3, nullptr);
// Write record with offset. // Write record with offset.
io_op_data = 0; io_op_data = 0;
@ -137,7 +138,17 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) {
GetFileOperation(4), 10 /*latency*/, GetFileOperation(4), 10 /*latency*/,
IOStatus::OK().ToString(), file_name, 13 /*length*/, IOStatus::OK().ToString(), file_name, 13 /*length*/,
50 /*offset*/); 50 /*offset*/);
writer.WriteIOOp(record4); writer.WriteIOOp(record4, nullptr);
// Write record with IODebugContext.
io_op_data = 0;
IODebugContext dbg;
dbg.SetRequestId("request_id_1");
IOTraceRecord record5(0, TraceType::kIOTracer, io_op_data,
GetFileOperation(5), 10 /*latency*/,
IOStatus::OK().ToString(), file_name);
writer.WriteIOOp(record5, &dbg);
ASSERT_OK(env_->FileExists(trace_file_path_)); ASSERT_OK(env_->FileExists(trace_file_path_));
} }
{ {
@ -186,9 +197,15 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) {
ASSERT_EQ(record4.file_size, 0); ASSERT_EQ(record4.file_size, 0);
ASSERT_EQ(record4.offset, 50); ASSERT_EQ(record4.offset, 50);
// Read one more record and it should report error.
IOTraceRecord record5; IOTraceRecord record5;
ASSERT_NOK(reader.ReadIOOp(&record5)); ASSERT_OK(reader.ReadIOOp(&record5));
ASSERT_EQ(record5.len, 0);
ASSERT_EQ(record5.file_size, 0);
ASSERT_EQ(record5.offset, 0);
ASSERT_EQ(record5.request_id, "request_id_1");
// Read one more record and it should report error.
IOTraceRecord record6;
ASSERT_NOK(reader.ReadIOOp(&record6));
} }
} }
@ -204,7 +221,7 @@ TEST_F(IOTracerTest, AtomicWrite) {
&trace_writer)); &trace_writer));
IOTracer writer; IOTracer writer;
ASSERT_OK(writer.StartIOTrace(clock_, trace_opt, std::move(trace_writer))); ASSERT_OK(writer.StartIOTrace(clock_, trace_opt, std::move(trace_writer)));
writer.WriteIOOp(record); writer.WriteIOOp(record, nullptr);
ASSERT_OK(env_->FileExists(trace_file_path_)); ASSERT_OK(env_->FileExists(trace_file_path_));
} }
{ {
@ -239,7 +256,7 @@ TEST_F(IOTracerTest, AtomicWriteBeforeStartTrace) {
IOTracer writer; IOTracer writer;
// The record should not be written to the trace_file since StartIOTrace is // The record should not be written to the trace_file since StartIOTrace is
// not called. // not called.
writer.WriteIOOp(record); writer.WriteIOOp(record, nullptr);
ASSERT_OK(env_->FileExists(trace_file_path_)); ASSERT_OK(env_->FileExists(trace_file_path_));
} }
{ {
@ -267,11 +284,11 @@ TEST_F(IOTracerTest, AtomicNoWriteAfterEndTrace) {
&trace_writer)); &trace_writer));
IOTracer writer; IOTracer writer;
ASSERT_OK(writer.StartIOTrace(clock_, trace_opt, std::move(trace_writer))); ASSERT_OK(writer.StartIOTrace(clock_, trace_opt, std::move(trace_writer)));
writer.WriteIOOp(record); writer.WriteIOOp(record, nullptr);
writer.EndIOTrace(); writer.EndIOTrace();
// Write the record again. This time the record should not be written since // Write the record again. This time the record should not be written since
// EndIOTrace is called. // EndIOTrace is called.
writer.WriteIOOp(record); writer.WriteIOOp(record, nullptr);
ASSERT_OK(env_->FileExists(trace_file_path_)); ASSERT_OK(env_->FileExists(trace_file_path_));
} }
{ {

Loading…
Cancel
Save