Update

[ghstack-poisoned]

db/db_impl/db_impl.cc

@@ -6675,11 +6675,13 @@ Status DBImpl::IngestExternalFile(
 Status DBImpl::IngestExternalFiles(
     const std::vector<IngestExternalFileArg>& args) {
   PERF_TIMER_GUARD(file_ingestion_nanos);
-  // Aggregate end-to-end ingestion latency, one sample per call (not per CF).
-  // StopWatch records on every return path; it is null-safe and self-gating on
-  // stats level, so there is no cost when statistics are disabled.
-  StopWatch ingest_external_file_sw(immutable_db_options_.clock, stats_,
-                                    INGEST_EXTERNAL_FILE_TIME);
+  // Prepare/run ingestion latency, recorded only on success (below).
+  const bool record_ingest_micros =
+      stats_ != nullptr &&
+      stats_->get_stats_level() > StatsLevel::kExceptTimers;
+  const uint64_t ingest_start_micros =
+      record_ingest_micros ? immutable_db_options_.clock->NowMicros() : 0;
+  uint64_t prepare_micros = 0;
   // TODO: plumb Env::IOActivity, Env::IOPriority
   const WriteOptions write_options;
 
@@ -6831,6 +6833,13 @@ Status DBImpl::IngestExternalFiles(
     return status;
   }
 
+  // End of prepare phase; run phase starts here.
+  uint64_t run_start_micros = 0;
+  if (record_ingest_micros) {
+    run_start_micros = immutable_db_options_.clock->NowMicros();
+    prepare_micros = run_start_micros - ingest_start_micros;
+  }
+
   std::vector<SuperVersionContext> sv_ctxs;
   for (size_t i = 0; i != num_cfs; ++i) {
     sv_ctxs.emplace_back(true /* create_superversion */);
@@ -7072,6 +7081,14 @@ Status DBImpl::IngestExternalFiles(
       }
     }
   }
+  // Record latency only for successful ingestions.
+  if (record_ingest_micros && status.ok()) {
+    RecordTimeToHistogram(stats_, INGEST_EXTERNAL_FILE_PREPARE_TIME,
+                          prepare_micros);
+    RecordTimeToHistogram(
+        stats_, INGEST_EXTERNAL_FILE_RUN_TIME,
+        immutable_db_options_.clock->NowMicros() - run_start_micros);
+  }
   return status;
 }
 

db/external_sst_file_test.cc

@@ -310,20 +310,34 @@ TEST_F(ExternalSSTFileTest, IngestionTimingHistogram) {
       /*verify_checksums_before_ingest=*/true, /*ingest_behind=*/false,
       /*sort_data=*/true));
 
-  HistogramData hd;
-  options.statistics->histogramData(INGEST_EXTERNAL_FILE_TIME, &hd);
-  ASSERT_EQ(1, hd.count);
-  ASSERT_GT(hd.max, 0.0);
+  auto hist = [&](Histograms h) {
+    HistogramData hd;
+    options.statistics->histogramData(h, &hd);
+    return hd;
+  };
 
-  // A second call adds exactly one more sample: timing is recorded per
-  // IngestExternalFile(s) call, not per column family.
+  // One sample per call (not per CF) in each phase histogram.
+  HistogramData prepare_hd = hist(INGEST_EXTERNAL_FILE_PREPARE_TIME);
+  HistogramData run_hd = hist(INGEST_EXTERNAL_FILE_RUN_TIME);
+  ASSERT_EQ(1, prepare_hd.count);
+  ASSERT_EQ(1, run_hd.count);
+  ASSERT_GT(prepare_hd.max, 0.0);
+  ASSERT_GT(run_hd.max, 0.0);
+
+  // A second call adds exactly one more sample to each histogram.
   ASSERT_OK(GenerateAndAddExternalFile(
       options, {{"k4", "v4"}, {"k5", "v5"}}, /*file_id=*/-1,
       /*allow_global_seqno=*/true, /*write_global_seqno=*/false,
       /*verify_checksums_before_ingest=*/true, /*ingest_behind=*/false,
       /*sort_data=*/true));
-  options.statistics->histogramData(INGEST_EXTERNAL_FILE_TIME, &hd);
-  ASSERT_EQ(2, hd.count);
+  ASSERT_EQ(2, hist(INGEST_EXTERNAL_FILE_PREPARE_TIME).count);
+  ASSERT_EQ(2, hist(INGEST_EXTERNAL_FILE_RUN_TIME).count);
+
+  // A failed ingestion records nothing (latency is logged only on success).
+  ASSERT_NOK(db_->IngestExternalFile({"/path/does/not/exist.sst"},
+                                     IngestExternalFileOptions()));
+  ASSERT_EQ(2, hist(INGEST_EXTERNAL_FILE_PREPARE_TIME).count);
+  ASSERT_EQ(2, hist(INGEST_EXTERNAL_FILE_RUN_TIME).count);
 }
 
 TEST_F(ExternalSSTFileTest, ComparatorMismatch) {

include/rocksdb/statistics.h

@@ -765,10 +765,15 @@ enum Histograms : uint32_t {
   // blocks for uniform key distribution tracking.
   BLOCK_KEY_DISTRIBUTION_CV,
 
-  // Time (microseconds) spent in a single DB::IngestExternalFile(s) call,
-  // measured end to end. One sample is recorded per call, not per column
-  // family. Requires stats level > kExceptTimers.
-  INGEST_EXTERNAL_FILE_TIME,
+  // Time (microseconds) in the "prepare" phase of an IngestExternalFile(s) call
+  // (validation and reading/linking the files; does not block writes). One
+  // sample per successful call; requires stats level > kExceptTimers.
+  INGEST_EXTERNAL_FILE_PREPARE_TIME,
+
+  // Time (microseconds) in the "run" phase of an IngestExternalFile(s) call
+  // (work under the DB mutex while writes are blocked). One sample per
+  // successful call; requires stats level > kExceptTimers.
+  INGEST_EXTERNAL_FILE_RUN_TIME,
 
   HISTOGRAM_ENUM_MAX
 };

java/rocksjni/portal.h

@@ -5998,8 +5998,10 @@ class HistogramTypeJni {
         return 0x41;
       case ROCKSDB_NAMESPACE::Histograms::BLOCK_KEY_DISTRIBUTION_CV:
         return 0x42;
-      case ROCKSDB_NAMESPACE::Histograms::INGEST_EXTERNAL_FILE_TIME:
+      case ROCKSDB_NAMESPACE::Histograms::INGEST_EXTERNAL_FILE_PREPARE_TIME:
         return 0x43;
+      case ROCKSDB_NAMESPACE::Histograms::INGEST_EXTERNAL_FILE_RUN_TIME:
+        return 0x44;
       case ROCKSDB_NAMESPACE::Histograms::HISTOGRAM_ENUM_MAX:
         // 0x3E is reserved for backwards compatibility on current minor
         // version.
@@ -6154,7 +6156,9 @@ class HistogramTypeJni {
       case 0x42:
         return ROCKSDB_NAMESPACE::Histograms::BLOCK_KEY_DISTRIBUTION_CV;
       case 0x43:
-        return ROCKSDB_NAMESPACE::Histograms::INGEST_EXTERNAL_FILE_TIME;
+        return ROCKSDB_NAMESPACE::Histograms::INGEST_EXTERNAL_FILE_PREPARE_TIME;
+      case 0x44:
+        return ROCKSDB_NAMESPACE::Histograms::INGEST_EXTERNAL_FILE_RUN_TIME;
       case 0x3E:
         // 0x3E is reserved for backwards compatibility on current minor
         // version.

java/src/main/java/org/rocksdb/HistogramType.java

@@ -232,10 +232,14 @@ public enum HistogramType {
   BLOCK_KEY_DISTRIBUTION_CV((byte) 0x42),
 
   /**
-   * Time (microseconds) spent in a single IngestExternalFile(s) call,
-   * measured end to end.
+   * Time (us) in the prepare phase of an IngestExternalFile(s) call.
    */
-  INGEST_EXTERNAL_FILE_TIME((byte) 0x43),
+  INGEST_EXTERNAL_FILE_PREPARE_TIME((byte) 0x43),
+
+  /**
+   * Time (us) in the run phase of an IngestExternalFile(s) call.
+   */
+  INGEST_EXTERNAL_FILE_RUN_TIME((byte) 0x44),
 
   // 0x3E is reserved for backwards compatibility on current minor version.
   HISTOGRAM_ENUM_MAX((byte) 0x3E);

monitoring/statistics.cc

@@ -386,7 +386,9 @@ const std::vector<std::pair<Histograms, std::string>> HistogramsNameMap = {
     {MULTISCAN_PREPARE_MICROS, "rocksdb.multiscan.prepare.micros"},
     {MULTISCAN_BLOCKS_PER_PREPARE, "rocksdb.multiscan.blocks.per.prepare"},
     {BLOCK_KEY_DISTRIBUTION_CV, "rocksdb.block.key.distribution.cv"},
-    {INGEST_EXTERNAL_FILE_TIME, "rocksdb.ingest.external.file.micros"},
+    {INGEST_EXTERNAL_FILE_PREPARE_TIME,
+     "rocksdb.ingest.external.file.prepare.micros"},
+    {INGEST_EXTERNAL_FILE_RUN_TIME, "rocksdb.ingest.external.file.run.micros"},
 };
 
 std::shared_ptr<Statistics> CreateDBStatistics() {

unreleased_history/new_features/ingest_external_file_micros_histogram.md

@@ -1 +0,0 @@
-Added a new stats histogram `rocksdb.ingest.external.file.micros` reporting the end-to-end latency (in microseconds) of each `IngestExternalFile`/`IngestExternalFiles` call.

unreleased_history/new_features/ingest_external_file_phase_histograms.md

@@ -0,0 +1 @@
+Added two stats histograms reporting the per-call latency (in microseconds) of each successful `IngestExternalFile`/`IngestExternalFiles` call, split by phase: `rocksdb.ingest.external.file.prepare.micros` (argument validation and reading/validating/linking the external files, which does not block live writes) and `rocksdb.ingest.external.file.run.micros` (the ingestion performed under the DB mutex while live writes are blocked). Failed ingestions are not recorded.