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

@@ -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

db/builder.h

@@ -7,6 +7,7 @@
 // found in the LICENSE file. See the AUTHORS file for names of contributors.
 #pragma once
 #include <string>
+#include <utility>
 #include <vector>
 #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

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"
+      EventLoggerHelpers::LogTableFileCreation(event_logger_, job_id_,
-                           << "table_file_creation"
+                                               output_number, current_bytes,
-                           << "file_number" << output_number << "file_size"
+                                               table_properties);
-                           << current_bytes;
     }
   }
   return s;

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,
+  // output to event logger
-        "[%s] [WriteLevel0TableForRecovery]"
+  if (s.ok()) {
-        " Level-0 table #%" PRIu64 ": %" PRIu64 " bytes %s",
+    EventLoggerHelpers::LogTableFileCreation(
-        cfd->GetName().c_str(), meta.fd.GetNumber(), meta.fd.GetFileSize(),
+        &event_logger_, job_id, meta.fd.GetNumber(), meta.fd.GetFileSize(),
-        s.ToString().c_str());
+        table_properties);
-    event_logger_.Log() << "job" << job_id << "event"
-                        << "table_file_creation"
-                        << "file_number" << meta.fd.GetNumber() << "file_size"
-                        << meta.fd.GetFileSize();
   }
+
   ReleaseFileNumberFromPendingOutputs(pending_outputs_inserted_elem);
 
   // Note that if file_size is zero, the file has been deleted and

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

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

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<MemTable*>& 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<MemTable*>& 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"
+    // output to event logger
-                         << "file_number" << meta.fd.GetNumber() << "file_size"
+    if (s.ok()) {
-                         << meta.fd.GetFileSize();
+      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();
     }

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                                               \

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

table/block_based_table_builder.h

@@ -10,6 +10,8 @@
 #pragma once
 #include <stdint.h>
 #include <limits>
+#include <string>
+#include <utility>
 #include <vector>
 
 #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

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()

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_;

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:

table/table_builder.h

@@ -9,9 +9,12 @@
 
 #pragma once
 
+#include <string>
+#include <utility>
 #include <vector>
 #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

util/event_logger.h

@@ -72,6 +72,7 @@ class JSONWritter {
 
   void StartObject() {
     assert(state_ == kExpectValue);
+    state_ = kExpectKey;
     stream_ << "{";
     first_element_ = true;
   }