From 689b13e6396011317db4f04a88e72323aead32bd Mon Sep 17 00:00:00 2001 From: Akanksha Mahajan Date: Thu, 1 Apr 2021 13:14:01 -0700 Subject: [PATCH] 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 --- HISTORY.md | 1 + db/blob/db_blob_basic_test.cc | 2 +- db/db_impl/db_impl.cc | 2 +- db/db_impl/db_impl.h | 2 +- env/file_system_tracer.cc | 66 ++++++++++++------------ include/rocksdb/db.h | 2 +- include/rocksdb/file_system.h | 24 +++++++++ include/rocksdb/utilities/stackable_db.h | 4 +- tools/io_tracer_parser_test.cc | 2 +- tools/io_tracer_parser_tool.cc | 16 ++++++ trace_replay/io_tracer.cc | 53 +++++++++++++++++-- trace_replay/io_tracer.h | 10 +++- trace_replay/io_tracer_test.cc | 41 ++++++++++----- 13 files changed, 167 insertions(+), 58 deletions(-) diff --git a/HISTORY.md b/HISTORY.md index 6cb04715a..4e5a350c4 100644 --- a/HISTORY.md +++ b/HISTORY.md @@ -15,6 +15,7 @@ ### 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. +* 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) ### Bug Fixes diff --git a/db/blob/db_blob_basic_test.cc b/db/blob/db_blob_basic_test.cc index a47dd541b..0e099eb8d 100644 --- a/db/blob/db_blob_basic_test.cc +++ b/db/blob/db_blob_basic_test.cc @@ -223,7 +223,7 @@ TEST_F(DBBlobBasicTest, GenerateIOTracing) { std::unique_ptr trace_writer; ASSERT_OK( 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 blob_value[] = "blob_value"; diff --git a/db/db_impl/db_impl.cc b/db/db_impl/db_impl.cc index 7c883683e..a040e8009 100644 --- a/db/db_impl/db_impl.cc +++ b/db/db_impl/db_impl.cc @@ -3145,7 +3145,7 @@ SystemClock* DBImpl::GetSystemClock() const { #ifndef ROCKSDB_LITE -Status DBImpl::StartIOTrace(Env* /*env*/, const TraceOptions& trace_options, +Status DBImpl::StartIOTrace(const TraceOptions& trace_options, std::unique_ptr&& trace_writer) { assert(trace_writer != nullptr); return io_tracer_->StartIOTrace(GetSystemClock(), trace_options, diff --git a/db/db_impl/db_impl.h b/db/db_impl/db_impl.h index 916f15195..65ca3a38a 100644 --- a/db/db_impl/db_impl.h +++ b/db/db_impl/db_impl.h @@ -469,7 +469,7 @@ class DBImpl : public DB { Status EndBlockCacheTrace() override; using DB::StartIOTrace; - Status StartIOTrace(Env* env, const TraceOptions& options, + Status StartIOTrace(const TraceOptions& options, std::unique_ptr&& trace_writer) override; using DB::EndIOTrace; diff --git a/env/file_system_tracer.cc b/env/file_system_tracer.cc index 2a639f152..9a85dd5e0 100644 --- a/env/file_system_tracer.cc +++ b/env/file_system_tracer.cc @@ -20,7 +20,7 @@ IOStatus FileSystemTracingWrapper::NewSequentialFile( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -34,7 +34,7 @@ IOStatus FileSystemTracingWrapper::NewRandomAccessFile( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -48,7 +48,7 @@ IOStatus FileSystemTracingWrapper::NewWritableFile( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -62,7 +62,7 @@ IOStatus FileSystemTracingWrapper::ReopenWritableFile( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -78,7 +78,7 @@ IOStatus FileSystemTracingWrapper::ReuseWritableFile( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -92,7 +92,7 @@ IOStatus FileSystemTracingWrapper::NewRandomRWFile( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -106,7 +106,7 @@ IOStatus FileSystemTracingWrapper::NewDirectory( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), name.substr(name.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -121,7 +121,7 @@ IOStatus FileSystemTracingWrapper::GetChildren(const std::string& dir, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), dir.substr(dir.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -135,7 +135,7 @@ IOStatus FileSystemTracingWrapper::DeleteFile(const std::string& fname, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -149,7 +149,7 @@ IOStatus FileSystemTracingWrapper::CreateDir(const std::string& dirname, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), dirname.substr(dirname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -162,7 +162,7 @@ IOStatus FileSystemTracingWrapper::CreateDirIfMissing( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), dirname.substr(dirname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -176,7 +176,7 @@ IOStatus FileSystemTracingWrapper::DeleteDir(const std::string& dirname, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), dirname.substr(dirname.find_last_of("/\\") + 1)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -193,7 +193,7 @@ IOStatus FileSystemTracingWrapper::GetFileSize(const std::string& fname, IOTraceRecord io_record( clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1), *file_size); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -210,7 +210,7 @@ IOStatus FileSystemTracingWrapper::Truncate(const std::string& fname, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), fname.substr(fname.find_last_of("/\\") + 1), size); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -227,7 +227,7 @@ IOStatus FSSequentialFileTracingWrapper::Read(size_t n, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, result->size(), 0 /*Offset*/); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -243,7 +243,7 @@ IOStatus FSSequentialFileTracingWrapper::InvalidateCache(size_t offset, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, length, offset); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/); return s; } @@ -261,7 +261,7 @@ IOStatus FSSequentialFileTracingWrapper::PositionedRead( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, result->size(), offset); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); 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, __func__, elapsed, s.ToString(), file_name_, n, offset); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -299,7 +299,7 @@ IOStatus FSRandomAccessFileTracingWrapper::MultiRead(FSReadRequest* reqs, IOTraceRecord io_record( clock_->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); + io_tracer_->WriteIOOp(io_record, dbg); } 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, __func__, elapsed, s.ToString(), file_name_, n, offset); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -333,7 +333,7 @@ IOStatus FSRandomAccessFileTracingWrapper::InvalidateCache(size_t offset, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, length, static_cast(offset)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/); return s; } @@ -349,7 +349,7 @@ IOStatus FSWritableFileTracingWrapper::Append(const Slice& data, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, data.size(), 0 /*Offset*/); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -366,7 +366,7 @@ IOStatus FSWritableFileTracingWrapper::PositionedAppend( IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, data.size(), offset); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -382,7 +382,7 @@ IOStatus FSWritableFileTracingWrapper::Truncate(uint64_t size, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, size, 0 /*Offset*/); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -395,7 +395,7 @@ IOStatus FSWritableFileTracingWrapper::Close(const IOOptions& options, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), file_name_); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -409,7 +409,7 @@ uint64_t FSWritableFileTracingWrapper::GetFileSize(const IOOptions& options, io_op_data |= (1 << IOTraceOp::kIOFileSize); IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, "OK", file_name_, file_size); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return file_size; } @@ -425,7 +425,7 @@ IOStatus FSWritableFileTracingWrapper::InvalidateCache(size_t offset, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, io_op_data, __func__, elapsed, s.ToString(), file_name_, length, static_cast(offset)); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, nullptr /*dbg*/); 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, __func__, elapsed, s.ToString(), file_name_, data.size(), offset); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); 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, __func__, elapsed, s.ToString(), file_name_, n, offset); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -473,7 +473,7 @@ IOStatus FSRandomRWFileTracingWrapper::Flush(const IOOptions& options, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), file_name_); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -486,7 +486,7 @@ IOStatus FSRandomRWFileTracingWrapper::Close(const IOOptions& options, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), file_name_); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -499,7 +499,7 @@ IOStatus FSRandomRWFileTracingWrapper::Sync(const IOOptions& options, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), file_name_); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } @@ -512,7 +512,7 @@ IOStatus FSRandomRWFileTracingWrapper::Fsync(const IOOptions& options, IOTraceRecord io_record(clock_->NowNanos(), TraceType::kIOTracer, 0 /*io_op_data*/, __func__, elapsed, s.ToString(), file_name_); - io_tracer_->WriteIOOp(io_record); + io_tracer_->WriteIOOp(io_record, dbg); return s; } } // namespace ROCKSDB_NAMESPACE diff --git a/include/rocksdb/db.h b/include/rocksdb/db.h index 9cfd367bf..b97583a9d 100644 --- a/include/rocksdb/db.h +++ b/include/rocksdb/db.h @@ -1612,7 +1612,7 @@ class DB { } // 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&& /*trace_writer*/) { return Status::NotSupported("StartIOTrace() is not implemented."); } diff --git a/include/rocksdb/file_system.h b/include/rocksdb/file_system.h index c54695983..02e307d0a 100644 --- a/include/rocksdb/file_system.h +++ b/include/rocksdb/file_system.h @@ -132,12 +132,36 @@ struct IODebugContext { // To be set by the FileSystem implementation 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() {} void AddCounter(std::string& name, uint64_t 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::ostringstream ss; ss << file_path << ", "; diff --git a/include/rocksdb/utilities/stackable_db.h b/include/rocksdb/utilities/stackable_db.h index 686452bdd..f798652b4 100644 --- a/include/rocksdb/utilities/stackable_db.h +++ b/include/rocksdb/utilities/stackable_db.h @@ -373,9 +373,9 @@ class StackableDB : public DB { Status EndBlockCacheTrace() override { return db_->EndBlockCacheTrace(); } using DB::StartIOTrace; - Status StartIOTrace(Env* env, const TraceOptions& options, + Status StartIOTrace(const TraceOptions& options, std::unique_ptr&& trace_writer) override { - return db_->StartIOTrace(env, options, std::move(trace_writer)); + return db_->StartIOTrace(options, std::move(trace_writer)); } using DB::EndIOTrace; diff --git a/tools/io_tracer_parser_test.cc b/tools/io_tracer_parser_test.cc index a65d4267e..845d7569b 100644 --- a/tools/io_tracer_parser_test.cc +++ b/tools/io_tracer_parser_test.cc @@ -65,7 +65,7 @@ class IOTracerParserTest : public testing::Test { ASSERT_OK(NewFileTraceWriter(env_, env_options_, trace_file_path_, &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++) { ASSERT_OK(db_->Put(write_opt, "key_" + std::to_string(i), diff --git a/tools/io_tracer_parser_tool.cc b/tools/io_tracer_parser_tool.cc index 3de7fe5bb..01b920f3b 100644 --- a/tools/io_tracer_parser_tool.cc +++ b/tools/io_tracer_parser_tool.cc @@ -73,6 +73,22 @@ void IOTraceRecordParser::PrintHumanReadableIOTraceRecord( // unset the rightmost bit. io_op_data &= (io_op_data - 1); } + + int64_t trace_data = static_cast(record.trace_data); + while (trace_data) { + // Find the rightmost set bit. + uint32_t set_pos = static_cast(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"; fprintf(stdout, "%s", ss.str().c_str()); } diff --git a/trace_replay/io_tracer.cc b/trace_replay/io_tracer.cc index 5d57b8396..a860130f8 100644 --- a/trace_replay/io_tracer.cc +++ b/trace_replay/io_tracer.cc @@ -26,7 +26,8 @@ IOTraceWriter::IOTraceWriter(SystemClock* clock, trace_options_(trace_options), 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(); if (trace_file_size > trace_options_.max_trace_file_size) { return Status::OK(); @@ -71,6 +72,26 @@ Status IOTraceWriter::WriteIOOp(const IOTraceRecord& record) { io_op_data &= (io_op_data - 1); } + int64_t trace_data = 0; + if (dbg) { + trace_data = static_cast(dbg->trace_data); + } + PutFixed64(&trace.payload, trace_data); + while (trace_data) { + // Find the rightmost set bit. + uint32_t set_pos = static_cast(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; TracerHelper::EncodeTrace(trace, &encoded_trace); return trace_writer_->Write(encoded_trace); @@ -213,6 +234,31 @@ Status IOTraceReader::ReadIOOp(IOTraceRecord* record) { // unset the rightmost bit. 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(record->trace_data); + while (trace_data) { + // Find the rightmost set bit. + uint32_t set_pos = static_cast(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(); } @@ -244,8 +290,7 @@ void IOTracer::EndIOTrace() { tracing_enabled = false; } -// TODO: Return status and handle that in file_system_tracer.h -void IOTracer::WriteIOOp(const IOTraceRecord& record) { +void IOTracer::WriteIOOp(const IOTraceRecord& record, IODebugContext* dbg) { if (!writer_.load()) { return; } @@ -253,6 +298,6 @@ void IOTracer::WriteIOOp(const IOTraceRecord& record) { if (!writer_.load()) { return; } - writer_.load()->WriteIOOp(record).PermitUncheckedError(); + writer_.load()->WriteIOOp(record, dbg).PermitUncheckedError(); } } // namespace ROCKSDB_NAMESPACE diff --git a/trace_replay/io_tracer.h b/trace_replay/io_tracer.h index 07355201d..83bcaee9d 100644 --- a/trace_replay/io_tracer.h +++ b/trace_replay/io_tracer.h @@ -9,6 +9,7 @@ #include #include "monitoring/instrumented_mutex.h" +#include "rocksdb/file_system.h" #include "rocksdb/options.h" #include "trace_replay/trace_replay.h" @@ -47,11 +48,16 @@ struct IOTraceRecord { std::string io_status; // Stores file name instead of full path. std::string file_name; + // Fields added to record based on IO operation. uint64_t len = 0; uint64_t offset = 0; uint64_t file_size = 0; + // Additional information passed in IODebugContext. + uint64_t trace_data = 0; + std::string request_id; + IOTraceRecord() {} IOTraceRecord(const uint64_t& _access_timestamp, const TraceType& _trace_type, @@ -102,7 +108,7 @@ class IOTraceWriter { IOTraceWriter(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, // 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; } - void WriteIOOp(const IOTraceRecord& record); + void WriteIOOp(const IOTraceRecord& record, IODebugContext* dbg); private: TraceOptions trace_options_; diff --git a/trace_replay/io_tracer_test.cc b/trace_replay/io_tracer_test.cc index 66ae9b2ad..cc27bb970 100644 --- a/trace_replay/io_tracer_test.cc +++ b/trace_replay/io_tracer_test.cc @@ -63,7 +63,7 @@ class IOTracerTest : public testing::Test { record.file_name = kDummyFile + std::to_string(i); record.len = i; 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; std::unique_ptr trace_writer; + ASSERT_OK(NewFileTraceWriter(env_, env_options_, trace_file_path_, &trace_writer)); IOTracer writer; @@ -100,7 +101,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) { IOTraceRecord record0(0, TraceType::kIOTracer, 0 /*io_op_data*/, GetFileOperation(0), 155 /*latency*/, IOStatus::OK().ToString(), file_name); - writer.WriteIOOp(record0); + writer.WriteIOOp(record0, nullptr); // Write record with FileSize. uint64_t io_op_data = 0; @@ -109,7 +110,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) { GetFileOperation(1), 10 /*latency*/, IOStatus::OK().ToString(), file_name, 256 /*file_size*/); - writer.WriteIOOp(record1); + writer.WriteIOOp(record1, nullptr); // Write record with Length. io_op_data = 0; @@ -118,7 +119,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) { GetFileOperation(2), 10 /*latency*/, IOStatus::OK().ToString(), file_name, 100 /*length*/, 200 /*offset*/); - writer.WriteIOOp(record2); + writer.WriteIOOp(record2, nullptr); // Write record with Length and offset. io_op_data = 0; @@ -128,7 +129,7 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) { GetFileOperation(3), 10 /*latency*/, IOStatus::OK().ToString(), file_name, 120 /*length*/, 17 /*offset*/); - writer.WriteIOOp(record3); + writer.WriteIOOp(record3, nullptr); // Write record with offset. io_op_data = 0; @@ -137,7 +138,17 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) { GetFileOperation(4), 10 /*latency*/, IOStatus::OK().ToString(), file_name, 13 /*length*/, 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_)); } { @@ -186,9 +197,15 @@ TEST_F(IOTracerTest, MultipleRecordsWithDifferentIOOpOptions) { ASSERT_EQ(record4.file_size, 0); ASSERT_EQ(record4.offset, 50); - // Read one more record and it should report error. 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)); IOTracer 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_)); } { @@ -239,7 +256,7 @@ TEST_F(IOTracerTest, AtomicWriteBeforeStartTrace) { IOTracer writer; // The record should not be written to the trace_file since StartIOTrace is // not called. - writer.WriteIOOp(record); + writer.WriteIOOp(record, nullptr); ASSERT_OK(env_->FileExists(trace_file_path_)); } { @@ -267,11 +284,11 @@ TEST_F(IOTracerTest, AtomicNoWriteAfterEndTrace) { &trace_writer)); IOTracer writer; ASSERT_OK(writer.StartIOTrace(clock_, trace_opt, std::move(trace_writer))); - writer.WriteIOOp(record); + writer.WriteIOOp(record, nullptr); writer.EndIOTrace(); // Write the record again. This time the record should not be written since // EndIOTrace is called. - writer.WriteIOOp(record); + writer.WriteIOOp(record, nullptr); ASSERT_OK(env_->FileExists(trace_file_path_)); } {