From dbd95b75321ba866195e817575e0accd2408e9ae Mon Sep 17 00:00:00 2001 From: Igor Canadi Date: Tue, 12 May 2015 15:53:55 -0700 Subject: [PATCH] Add more table properties to EventLogger Summary: Example output: {"time_micros": 1431463794310521, "job": 353, "event": "table_file_creation", "file_number": 387, "file_size": 86937, "table_info": {"data_size": "81801", "index_size": "9751", "filter_size": "0", "raw_key_size": "23448", "raw_average_key_size": "24.000000", "raw_value_size": "990571", "raw_average_value_size": "1013.890481", "num_data_blocks": "245", "num_entries": "977", "filter_policy_name": "", "kDeletedKeys": "0"}} Also fixed a bug where BuildTable() in recovery was passing Env::IOHigh argument into paranoid_checks_file parameter. Test Plan: make check + check out the output in the log Reviewers: sdong, rven, yhchiang Reviewed By: yhchiang Subscribers: dhruba, leveldb Differential Revision: https://reviews.facebook.net/D38343 --- db/builder.cc | 13 +++++---- db/builder.h | 5 +++- db/compaction_job.cc | 12 +++++--- db/db_impl.cc | 28 +++++++++++------- db/event_logger_helpers.cc | 46 ++++++++++++++++++++++++++++++ db/event_logger_helpers.h | 18 ++++++++++++ db/flush_job.cc | 17 +++++++---- src.mk | 1 + table/block_based_table_builder.cc | 33 +++++++-------------- table/block_based_table_builder.h | 5 ++++ table/cuckoo_table_builder.h | 2 ++ table/mock_table.h | 4 +++ table/plain_table_builder.h | 2 ++ table/table_builder.h | 6 ++++ util/event_logger.h | 1 + 15 files changed, 146 insertions(+), 47 deletions(-) create mode 100644 db/event_logger_helpers.cc create mode 100644 db/event_logger_helpers.h diff --git a/db/builder.cc b/db/builder.cc index a8951a98e..a3ed607bf 100644 --- a/db/builder.cc +++ b/db/builder.cc @@ -51,7 +51,7 @@ Status BuildTable( const SequenceNumber earliest_seqno_in_memtable, const CompressionType compression, const CompressionOptions& compression_opts, bool paranoid_file_checks, - const Env::IOPriority io_priority) { + const Env::IOPriority io_priority, TableProperties* table_properties) { Status s; meta->fd.file_size = 0; meta->smallest_seqno = meta->largest_seqno = 0; @@ -199,13 +199,16 @@ Status BuildTable( // Finish and check for builder errors if (s.ok()) { s = builder->Finish(); - if (s.ok()) { - meta->fd.file_size = builder->FileSize(); - assert(meta->fd.GetFileSize() > 0); - } } else { builder->Abandon(); } + if (s.ok()) { + meta->fd.file_size = builder->FileSize(); + assert(meta->fd.GetFileSize() > 0); + if (table_properties) { + *table_properties = builder->GetTableProperties(); + } + } delete builder; // Finish and check for file errors diff --git a/db/builder.h b/db/builder.h index 50c86ab6c..9d2888dee 100644 --- a/db/builder.h +++ b/db/builder.h @@ -7,6 +7,7 @@ // found in the LICENSE file. See the AUTHORS file for names of contributors. #pragma once #include +#include #include #include "db/table_properties_collector.h" #include "rocksdb/comparator.h" @@ -15,6 +16,7 @@ #include "rocksdb/types.h" #include "rocksdb/options.h" #include "rocksdb/immutable_options.h" +#include "rocksdb/table_properties.h" namespace rocksdb { @@ -53,6 +55,7 @@ extern Status BuildTable( const SequenceNumber earliest_seqno_in_memtable, const CompressionType compression, const CompressionOptions& compression_opts, bool paranoid_file_checks, - const Env::IOPriority io_priority = Env::IO_HIGH); + const Env::IOPriority io_priority = Env::IO_HIGH, + TableProperties* table_properties = nullptr); } // namespace rocksdb diff --git a/db/compaction_job.cc b/db/compaction_job.cc index 1575d8d2f..12f35cb0b 100644 --- a/db/compaction_job.cc +++ b/db/compaction_job.cc @@ -22,6 +22,7 @@ #include "db/builder.h" #include "db/db_iter.h" #include "db/dbformat.h" +#include "db/event_logger_helpers.h" #include "db/filename.h" #include "db/log_reader.h" #include "db/log_writer.h" @@ -1010,6 +1011,7 @@ Status CompactionJob::FinishCompactionOutputFile(Iterator* input) { const uint32_t output_path_id = compact_->current_output()->path_id; assert(output_number != 0); + TableProperties table_properties; // Check for iterator errors Status s = input->status(); const uint64_t current_entries = compact_->builder->NumEntries(); @@ -1018,6 +1020,9 @@ Status CompactionJob::FinishCompactionOutputFile(Iterator* input) { } else { compact_->builder->Abandon(); } + if (s.ok()) { + table_properties = compact_->builder->GetTableProperties(); + } const uint64_t current_bytes = compact_->builder->FileSize(); compact_->current_output()->file_size = current_bytes; compact_->total_bytes += current_bytes; @@ -1058,10 +1063,9 @@ Status CompactionJob::FinishCompactionOutputFile(Iterator* input) { " keys, %" PRIu64 " bytes", cfd->GetName().c_str(), job_id_, output_number, current_entries, current_bytes); - event_logger_->Log() << "job" << job_id_ << "event" - << "table_file_creation" - << "file_number" << output_number << "file_size" - << current_bytes; + EventLoggerHelpers::LogTableFileCreation(event_logger_, job_id_, + output_number, current_bytes, + table_properties); } } return s; diff --git a/db/db_impl.cc b/db/db_impl.cc index 6be7d9c53..95df83e10 100644 --- a/db/db_impl.cc +++ b/db/db_impl.cc @@ -31,6 +31,7 @@ #include "db/compaction_job.h" #include "db/db_iter.h" #include "db/dbformat.h" +#include "db/event_logger_helpers.h" #include "db/filename.h" #include "db/job_context.h" #include "db/log_reader.h" @@ -1131,6 +1132,7 @@ Status DBImpl::WriteLevel0TableForRecovery(int job_id, ColumnFamilyData* cfd, ro.total_order_seek = true; Arena arena; Status s; + TableProperties table_properties; { ScopedArenaIterator iter(mem->NewIterator(ro, &arena)); const SequenceNumber newest_snapshot = snapshots_.GetNewest(); @@ -1141,6 +1143,8 @@ Status DBImpl::WriteLevel0TableForRecovery(int job_id, ColumnFamilyData* cfd, " Level-0 table #%" PRIu64 ": started", cfd->GetName().c_str(), meta.fd.GetNumber()); + bool paranoid_file_checks = + cfd->GetLatestMutableCFOptions()->paranoid_file_checks; { mutex_.Unlock(); s = BuildTable( @@ -1148,21 +1152,25 @@ Status DBImpl::WriteLevel0TableForRecovery(int job_id, ColumnFamilyData* cfd, iter.get(), &meta, cfd->internal_comparator(), cfd->int_tbl_prop_collector_factories(), newest_snapshot, earliest_seqno_in_memtable, GetCompressionFlush(*cfd->ioptions()), - cfd->ioptions()->compression_opts, Env::IO_HIGH); + cfd->ioptions()->compression_opts, paranoid_file_checks, Env::IO_HIGH, + &table_properties); LogFlush(db_options_.info_log); mutex_.Lock(); } + } + Log(InfoLogLevel::DEBUG_LEVEL, db_options_.info_log, + "[%s] [WriteLevel0TableForRecovery]" + " Level-0 table #%" PRIu64 ": %" PRIu64 " bytes %s", + cfd->GetName().c_str(), meta.fd.GetNumber(), meta.fd.GetFileSize(), + s.ToString().c_str()); - Log(InfoLogLevel::DEBUG_LEVEL, db_options_.info_log, - "[%s] [WriteLevel0TableForRecovery]" - " Level-0 table #%" PRIu64 ": %" PRIu64 " bytes %s", - cfd->GetName().c_str(), meta.fd.GetNumber(), meta.fd.GetFileSize(), - s.ToString().c_str()); - event_logger_.Log() << "job" << job_id << "event" - << "table_file_creation" - << "file_number" << meta.fd.GetNumber() << "file_size" - << meta.fd.GetFileSize(); + // output to event logger + if (s.ok()) { + EventLoggerHelpers::LogTableFileCreation( + &event_logger_, job_id, meta.fd.GetNumber(), meta.fd.GetFileSize(), + table_properties); } + ReleaseFileNumberFromPendingOutputs(pending_outputs_inserted_elem); // Note that if file_size is zero, the file has been deleted and diff --git a/db/event_logger_helpers.cc b/db/event_logger_helpers.cc new file mode 100644 index 000000000..521b68433 --- /dev/null +++ b/db/event_logger_helpers.cc @@ -0,0 +1,46 @@ +// Copyright (c) 2013, Facebook, Inc. All rights reserved. +// This source code is licensed under the BSD-style license found in the +// LICENSE file in the root directory of this source tree. An additional grant +// of patent rights can be found in the PATENTS file in the same directory. + +#include "db/event_logger_helpers.h" + +namespace rocksdb { + +namespace { +inline double SafeDivide(double a, double b) { return b == 0.0 ? 0 : a / b; } +} // namespace + +void EventLoggerHelpers::LogTableFileCreation( + EventLogger* event_logger, int job_id, uint64_t file_number, + uint64_t file_size, const TableProperties& table_properties) { + auto stream = event_logger->Log(); + stream << "job" << job_id << "event" + << "table_file_creation" + << "file_number" << file_number << "file_size" << file_size + << "table_properties"; + stream.StartObject(); + + // basic properties: + stream << "data_size" << table_properties.data_size + << "index_size" << table_properties.index_size + << "filter_size" << table_properties.filter_size + << "raw_key_size" << table_properties.raw_key_size + << "raw_average_key_size" << SafeDivide(table_properties.raw_key_size, + table_properties.num_entries) + << "raw_value_size" << table_properties.raw_value_size + << "raw_average_value_size" << SafeDivide( + table_properties.raw_value_size, table_properties.num_entries) + << "num_data_blocks" << table_properties.num_data_blocks + << "num_entries" << table_properties.num_entries + << "filter_policy_name" << table_properties.filter_policy_name; + + // user collected properties + for (const auto& prop : table_properties.user_collected_properties) { + stream << prop.first << prop.second; + } + + stream.EndObject(); +} + +} // namespace rocksdb diff --git a/db/event_logger_helpers.h b/db/event_logger_helpers.h new file mode 100644 index 000000000..86e9adca5 --- /dev/null +++ b/db/event_logger_helpers.h @@ -0,0 +1,18 @@ +// Copyright (c) 2013, Facebook, Inc. All rights reserved. +// This source code is licensed under the BSD-style license found in the +// LICENSE file in the root directory of this source tree. An additional grant +// of patent rights can be found in the PATENTS file in the same directory. +#pragma once + +#include "util/event_logger.h" +#include "rocksdb/table_properties.h" + +namespace rocksdb { + +class EventLoggerHelpers { + public: + static void LogTableFileCreation(EventLogger* event_logger, int job_id, + uint64_t file_number, uint64_t file_size, + const TableProperties& table_properties); +}; +} // namespace rocksdb diff --git a/db/flush_job.cc b/db/flush_job.cc index 351713e45..c0745cc64 100644 --- a/db/flush_job.cc +++ b/db/flush_job.cc @@ -20,6 +20,7 @@ #include "db/builder.h" #include "db/db_iter.h" #include "db/dbformat.h" +#include "db/event_logger_helpers.h" #include "db/filename.h" #include "db/log_reader.h" #include "db/log_writer.h" @@ -195,6 +196,7 @@ Status FlushJob::WriteLevel0Table(const autovector& mems, << total_num_entries << "num_deletes" << total_num_deletes << "memory_usage" << total_memory_usage; + TableProperties table_properties; { ScopedArenaIterator iter( NewMergingIterator(&cfd_->internal_comparator(), &memtables[0], @@ -211,17 +213,22 @@ Status FlushJob::WriteLevel0Table(const autovector& mems, cfd_->int_tbl_prop_collector_factories(), newest_snapshot_, earliest_seqno_in_memtable, output_compression_, cfd_->ioptions()->compression_opts, - mutable_cf_options_.paranoid_file_checks, Env::IO_HIGH); + mutable_cf_options_.paranoid_file_checks, Env::IO_HIGH, + &table_properties); LogFlush(db_options_.info_log); } Log(InfoLogLevel::INFO_LEVEL, db_options_.info_log, "[%s] [JOB %d] Level-0 flush table #%" PRIu64 ": %" PRIu64 " bytes %s", cfd_->GetName().c_str(), job_context_->job_id, meta.fd.GetNumber(), meta.fd.GetFileSize(), s.ToString().c_str()); - event_logger_->Log() << "job" << job_context_->job_id << "event" - << "table_file_creation" - << "file_number" << meta.fd.GetNumber() << "file_size" - << meta.fd.GetFileSize(); + + // output to event logger + if (s.ok()) { + EventLoggerHelpers::LogTableFileCreation( + event_logger_, job_context_->job_id, meta.fd.GetNumber(), + meta.fd.GetFileSize(), table_properties); + } + if (!db_options_.disableDataSync && output_file_directory_ != nullptr) { output_file_directory_->Fsync(); } diff --git a/src.mk b/src.mk index c4be8d3f5..303ed9662 100644 --- a/src.mk +++ b/src.mk @@ -14,6 +14,7 @@ LIB_SOURCES = \ db/db_impl_experimental.cc \ db/db_iter.cc \ db/experimental.cc \ + db/event_logger_helpers.cc \ db/file_indexer.cc \ db/filename.cc \ db/flush_job.cc \ diff --git a/table/block_based_table_builder.cc b/table/block_based_table_builder.cc index 7b19574fe..201f1285e 100644 --- a/table/block_based_table_builder.cc +++ b/table/block_based_table_builder.cc @@ -39,6 +39,7 @@ #include "table/meta_blocks.h" #include "table/table_builder.h" +#include "util/string_util.h" #include "util/coding.h" #include "util/compression.h" #include "util/crc32c.h" @@ -830,28 +831,6 @@ Status BlockBasedTableBuilder::Finish() { } } - // Print out the table stats - if (ok()) { - // user collected properties - std::string user_collected; - user_collected.reserve(1024); - for (const auto& collector : r->table_properties_collectors) { - for (const auto& prop : collector->GetReadableProperties()) { - user_collected.append(prop.first); - user_collected.append("="); - user_collected.append(prop.second); - user_collected.append("; "); - } - } - - Log(InfoLogLevel::INFO_LEVEL, r->ioptions.info_log, - "Table was constructed:\n" - " [basic properties]: %s\n" - " [user collected properties]: %s", - r->props.ToString().c_str(), - user_collected.c_str()); - } - return r->status; } @@ -869,6 +848,16 @@ uint64_t BlockBasedTableBuilder::FileSize() const { return rep_->offset; } +TableProperties BlockBasedTableBuilder::GetTableProperties() const { + TableProperties ret = rep_->props; + for (const auto& collector : rep_->table_properties_collectors) { + for (const auto& prop : collector->GetReadableProperties()) { + ret.user_collected_properties.insert(prop); + } + } + return ret; +} + const std::string BlockBasedTable::kFilterBlockPrefix = "filter."; const std::string BlockBasedTable::kFullFilterBlockPrefix = "fullfilter."; } // namespace rocksdb diff --git a/table/block_based_table_builder.h b/table/block_based_table_builder.h index 5b060e074..716a4e9ba 100644 --- a/table/block_based_table_builder.h +++ b/table/block_based_table_builder.h @@ -10,6 +10,8 @@ #pragma once #include #include +#include +#include #include #include "rocksdb/flush_block_policy.h" @@ -68,6 +70,9 @@ class BlockBasedTableBuilder : public TableBuilder { // Finish() call, returns the size of the final generated file. uint64_t FileSize() const override; + // Get table properties + TableProperties GetTableProperties() const override; + private: bool ok() const { return status().ok(); } // Call block's Finish() method and then write the finalize block contents to diff --git a/table/cuckoo_table_builder.h b/table/cuckoo_table_builder.h index 26c94e1bc..6b5a180c2 100644 --- a/table/cuckoo_table_builder.h +++ b/table/cuckoo_table_builder.h @@ -57,6 +57,8 @@ class CuckooTableBuilder: public TableBuilder { // Finish() call, returns the size of the final generated file. uint64_t FileSize() const override; + TableProperties GetTableProperties() const override { return properties_; } + private: struct CuckooBucket { CuckooBucket() diff --git a/table/mock_table.h b/table/mock_table.h index 268249744..ef38575cc 100644 --- a/table/mock_table.h +++ b/table/mock_table.h @@ -125,6 +125,10 @@ class MockTableBuilder : public TableBuilder { uint64_t FileSize() const override { return table_.size(); } + TableProperties GetTableProperties() const override { + return TableProperties(); + } + private: uint32_t id_; MockTableFileSystem* file_system_; diff --git a/table/plain_table_builder.h b/table/plain_table_builder.h index 840a279b0..f542d2f60 100644 --- a/table/plain_table_builder.h +++ b/table/plain_table_builder.h @@ -69,6 +69,8 @@ class PlainTableBuilder: public TableBuilder { // Finish() call, returns the size of the final generated file. uint64_t FileSize() const override; + TableProperties GetTableProperties() const override { return properties_; } + bool SaveIndexInFile() const { return store_index_in_file_; } private: diff --git a/table/table_builder.h b/table/table_builder.h index 8972228b7..19da4c26d 100644 --- a/table/table_builder.h +++ b/table/table_builder.h @@ -9,9 +9,12 @@ #pragma once +#include +#include #include #include "db/table_properties_collector.h" #include "rocksdb/options.h" +#include "rocksdb/table_properties.h" #include "util/mutable_cf_options.h" namespace rocksdb { @@ -78,6 +81,9 @@ class TableBuilder { // Size of the file generated so far. If invoked after a successful // Finish() call, returns the size of the final generated file. virtual uint64_t FileSize() const = 0; + + // Returns table properties + virtual TableProperties GetTableProperties() const = 0; }; } // namespace rocksdb diff --git a/util/event_logger.h b/util/event_logger.h index 9054a6225..806b4e501 100644 --- a/util/event_logger.h +++ b/util/event_logger.h @@ -72,6 +72,7 @@ class JSONWritter { void StartObject() { assert(state_ == kExpectValue); + state_ = kExpectKey; stream_ << "{"; first_element_ = true; }