feat: Add support for measuring per-TU indexing time (#152)

Author: varungandhi-src

indexer/CliOptions.h

@@ -28,6 +28,7 @@ struct CliOptions {
   std::string scipClangExecutablePath;
   std::string temporaryOutputDir;
   std::string indexOutputPath;
+  std::string statsFilePath;
 
   std::chrono::seconds receiveTimeout;
   uint32_t numWorkers;
@@ -49,6 +50,8 @@ struct CliOptions {
 
   std::string workerMode;
 
+  bool measureStatistics;
+
   std::string preprocessorHistoryLogPath;
 
   // An opaque ID provided by the driver for a worker to identify the

indexer/Driver.cc

@@ -46,6 +46,7 @@
 #include "indexer/Path.h"
 #include "indexer/RAII.h"
 #include "indexer/ScipExtras.h"
+#include "indexer/Statistics.h"
 #include "indexer/Timer.h"
 
 namespace boost_ip = boost::interprocess;
@@ -116,6 +117,7 @@ struct DriverOptions {
   RootPath projectRootPath;
   AbsolutePath compdbPath;
   AbsolutePath indexOutputPath;
+  AbsolutePath statsFilePath;
   size_t numWorkers;
   std::chrono::seconds receiveTimeout;
   bool deterministic;
@@ -132,7 +134,7 @@ struct DriverOptions {
   explicit DriverOptions(std::string driverId, const CliOptions &cliOpts)
       : workerExecutablePath(),
         projectRootPath(AbsolutePath("/"), RootKind::Project), compdbPath(),
-        indexOutputPath(), numWorkers(cliOpts.numWorkers),
+        indexOutputPath(), statsFilePath(), numWorkers(cliOpts.numWorkers),
         receiveTimeout(cliOpts.receiveTimeout),
         deterministic(cliOpts.deterministic),
         preprocessorRecordHistoryFilterRegex(
@@ -151,12 +153,12 @@ struct DriverOptions {
         RootPath{AbsolutePath{std::move(cwd)}, RootKind::Project};
 
     auto setAbsolutePath = [this](const std::string &path, AbsolutePath &out) {
-      if (llvm::sys::path::is_absolute(path)) {
-        out = AbsolutePath(std::string(path));
-        return;
-      }
-      out = this->projectRootPath.makeAbsolute(
-          RootRelativePathRef(path, RootKind::Project));
+      out = path.empty()
+                ? AbsolutePath()
+                : (llvm::sys::path::is_absolute(path)
+                       ? AbsolutePath(std::string(path))
+                       : this->projectRootPath.makeAbsolute(
+                           RootRelativePathRef(path, RootKind::Project)));
     };
 
     // Strictly speaking, there is a TOCTOU problem here, as scip-clang
@@ -183,6 +185,7 @@ struct DriverOptions {
 
     setAbsolutePath(cliOpts.indexOutputPath, this->indexOutputPath);
     setAbsolutePath(cliOpts.compdbPath, this->compdbPath);
+    setAbsolutePath(cliOpts.statsFilePath, this->statsFilePath);
 
     auto makeDirs = [](const StdPath &path, const char *name) {
       std::error_code error;
@@ -223,6 +226,9 @@ struct DriverOptions {
     if (this->deterministic) {
       args.push_back("--deterministic");
     }
+    if (!this->statsFilePath.asStringRef().empty()) {
+      args.push_back("--measure-statistics");
+    }
     if (!this->preprocessorRecordHistoryFilterRegex.empty()) {
       args.push_back(fmt::format("--preprocessor-record-history-filter={}",
                                  this->preprocessorRecordHistoryFilterRegex));
@@ -346,6 +352,10 @@ class Scheduler final {
 public:
   using Process = boost::process::child;
 
+  const absl::flat_hash_map<JobId, IndexJob> &getJobMap() const {
+    return this->allJobList;
+  }
+
   void checkInvariants() const {
     ENFORCE(
         this->wipJobs.size() + this->idleWorkers.size() == this->workers.size(),
@@ -566,6 +576,7 @@ class Driver {
   Scheduler scheduler;
   FileIndexingPlanner planner;
 
+  std::vector<std::pair<JobId, IndexingStatistics>> allStatistics;
   std::vector<AbsolutePath> indexPartPaths;
 
   /// Total number of commands in the compilation database.
@@ -595,6 +606,36 @@ class Driver {
     }
   }
 
+  void emitStatsFile() {
+    if (this->options.statsFilePath.asStringRef().empty()) {
+      return;
+    }
+    std::vector<std::pair<uint32_t, StatsEntry>> perJobStats{};
+    auto &jobMap = this->scheduler.getJobMap();
+    for (auto &pair : this->allStatistics) {
+      auto &[jobId, stats] = pair;
+      auto semaJobId = JobId::newTask(jobId.taskId());
+      auto it = jobMap.find(semaJobId);
+      ENFORCE(it != jobMap.end());
+      ENFORCE(it->second.kind == IndexJob::Kind::SemanticAnalysis);
+      perJobStats.emplace_back(
+          jobId.taskId(),
+          StatsEntry{it->second.semanticAnalysis.command.Filename,
+                     std::move(stats)});
+    }
+    absl::c_sort(perJobStats, [](const auto &p1, const auto &p2) -> bool {
+      ENFORCE(p1.first != p2.first,
+              "got multiple StatEntry values for the same TU");
+      return p1.first < p2.first;
+    });
+    std::vector<StatsEntry> stats{};
+    for (auto &pair : perJobStats) {
+      stats.emplace_back(std::move(pair.second));
+    }
+    StatsEntry::emitAll(std::move(stats),
+                        this->options.statsFilePath.asStringRef());
+  }
+
   void run() {
     ManualTimer total, indexing, merging;
     unsigned numTus;
@@ -607,6 +648,8 @@ class Driver {
       TIME_IT(merging, this->emitScipIndex());
       spdlog::debug("indexing complete; driver shutting down now, kthxbai");
     });
+    this->emitStatsFile();
+
     using secs = std::chrono::seconds;
     fmt::print("Finished indexing {} translation units in {:.1f}s (indexing: "
                "{:.1f}s, merging: {:.1f}s).\n",
@@ -822,11 +865,17 @@ class Driver {
           }));
       break;
     }
-    case IndexJob::Kind::EmitIndex:
+    case IndexJob::Kind::EmitIndex: {
+      auto &result = response.result.emitIndex;
+      if (!this->options.statsFilePath.asStringRef().empty()) {
+        this->allStatistics.emplace_back(response.jobId,
+                                         std::move(result.statistics));
+      }
       this->indexPartPaths.emplace_back(
           std::move(response.result.emitIndex.indexPartPath));
       break;
     }
+    }
   }
 
   void processOneJobResult() {

indexer/IpcMessages.cc

@@ -147,11 +147,12 @@ bool fromJSON(const llvm::json::Value &jsonValue, HashValue &h,
   return false;
 }
 
-DERIVE_SERIALIZE_1_NEWTYPE(scip_clang::EmitIndexJobResult, indexPartPath)
+DERIVE_SERIALIZE_1_NEWTYPE(scip_clang::IndexingStatistics, totalTimeMicros)
 DERIVE_SERIALIZE_1_NEWTYPE(scip_clang::EmitIndexJobDetails, filesToBeIndexed)
 DERIVE_SERIALIZE_1_NEWTYPE(scip_clang::IpcTestMessage, content)
 DERIVE_SERIALIZE_1_NEWTYPE(scip_clang::SemanticAnalysisJobDetails, command)
 
+DERIVE_SERIALIZE_2(scip_clang::EmitIndexJobResult, statistics, indexPartPath)
 DERIVE_SERIALIZE_2(scip_clang::PreprocessedFileInfo, path, hashValue)
 DERIVE_SERIALIZE_2(scip_clang::PreprocessedFileInfoMulti, path, hashValues)
 DERIVE_SERIALIZE_2(scip_clang::IndexJobRequest, id, job)

indexer/IpcMessages.h

@@ -148,7 +148,13 @@ struct SemanticAnalysisJobResult {
 };
 SERIALIZABLE(SemanticAnalysisJobResult)
 
+struct IndexingStatistics {
+  uint64_t totalTimeMicros;
+};
+SERIALIZABLE(IndexingStatistics)
+
 struct EmitIndexJobResult {
+  IndexingStatistics statistics;
   AbsolutePath indexPartPath;
 };
 SERIALIZABLE(EmitIndexJobResult)

indexer/Statistics.cc

@@ -0,0 +1,35 @@
+#include <string_view>
+#include <vector>
+
+#include "llvm/Support/JSON.h"
+
+#include "indexer/Statistics.h"
+
+namespace scip_clang {
+
+llvm::json::Value toJSON(const StatsEntry &entry) {
+  auto &stats = entry.stats;
+  return llvm::json::Object{
+      {"filepath", entry.path},
+      {"stats",
+       llvm::json::Object{
+           {"total_time_s", double(stats.totalTimeMicros) / 1'000'000.0},
+       }}};
+}
+
+// static
+void StatsEntry::emitAll(std::vector<StatsEntry> &&stats,
+                         std::string_view path) {
+  std::error_code error;
+  llvm::raw_fd_ostream out(path, error);
+  ENFORCE(!error);
+  llvm::json::OStream jsonStream(out);
+  jsonStream.array([&]() {
+    for (auto &statEntry : stats) {
+      jsonStream.value(llvm::json::Value(statEntry));
+    }
+  });
+  jsonStream.flush();
+}
+
+} // namespace scip_clang

indexer/Statistics.h

@@ -0,0 +1,21 @@
+#ifndef SCIP_CLANG_STATISTICS_H
+#define SCIP_CLANG_STATISTICS_H
+
+#include "llvm/Support/JSON.h"
+
+#include "indexer/IpcMessages.h"
+
+namespace scip_clang {
+
+struct StatsEntry {
+  std::string path;
+  IndexingStatistics stats;
+
+  static void emitAll(std::vector<StatsEntry> &&stats, std::string_view path);
+};
+
+llvm::json::Value toJSON(const StatsEntry &entry);
+
+} // namespace scip_clang
+
+#endif

indexer/Worker.cc

@@ -51,6 +51,7 @@
 #include "indexer/Logging.h"
 #include "indexer/Path.h"
 #include "indexer/ScipExtras.h"
+#include "indexer/Statistics.h"
 #include "indexer/SymbolFormatter.h"
 #include "indexer/Timer.h"
 #include "indexer/Worker.h"
@@ -1072,15 +1073,17 @@ WorkerOptions WorkerOptions::fromCliOptions(const CliOptions &cliOptions) {
       RootKind::Project};
   WorkerMode mode;
   IpcOptions ipcOptions;
-  StdPath compdbPath;
+  StdPath compdbPath{};
   StdPath indexOutputPath{};
+  StdPath statsFilePath{};
   if (cliOptions.workerMode == "ipc") {
     mode = WorkerMode::Ipc;
     ipcOptions = cliOptions.ipcOptions();
   } else if (cliOptions.workerMode == "compdb") {
     mode = WorkerMode::Compdb;
     compdbPath = StdPath(cliOptions.compdbPath);
     indexOutputPath = StdPath(cliOptions.indexOutputPath);
+    statsFilePath = StdPath(cliOptions.statsFilePath);
   } else {
     ENFORCE(cliOptions.workerMode == "testing");
     mode = WorkerMode::Testing;
@@ -1090,8 +1093,10 @@ WorkerOptions WorkerOptions::fromCliOptions(const CliOptions &cliOptions) {
                        ipcOptions,
                        compdbPath,
                        indexOutputPath,
+                       statsFilePath,
                        cliOptions.logLevel,
                        cliOptions.deterministic,
+                       cliOptions.measureStatistics,
                        PreprocessorHistoryRecordingOptions{
                            cliOptions.preprocessorRecordHistoryFilterRegex,
                            cliOptions.preprocessorHistoryLogPath, false, ""},
@@ -1101,7 +1106,7 @@ WorkerOptions WorkerOptions::fromCliOptions(const CliOptions &cliOptions) {
 
 Worker::Worker(WorkerOptions &&options)
     : options(std::move(options)), messageQueues(), compileCommands(),
-      commandIndex(0), recorder() {
+      commandIndex(0), recorder(), statistics() {
   switch (this->options.mode) {
   case WorkerMode::Ipc:
     this->messageQueues = std::make_unique<MessageQueuePair>(
@@ -1121,6 +1126,9 @@ Worker::Worker(WorkerOptions &&options)
     break;
   }
 
+  // All initialization unrelated to preprocessor recording should be
+  // completed here.
+
   auto &recordingOptions = this->options.recordingOptions;
   HeaderFilter filter(std::string(recordingOptions.filterRegex));
   if (filter.isIdentity()) {
@@ -1222,6 +1230,9 @@ void Worker::sendResult(JobId requestId, IndexJobResult &&result) {
 
 Worker::ReceiveStatus Worker::processTranslationUnitAndRespond(
     IndexJobRequest &&semanticAnalysisRequest) {
+  ManualTimer indexingTimer{};
+  indexingTimer.start();
+
   SemanticAnalysisJobResult semaResult{};
   auto semaRequestId = semanticAnalysisRequest.id;
   auto tuMainFilePath =
@@ -1281,12 +1292,21 @@ Worker::ReceiveStatus Worker::processTranslationUnitAndRespond(
                                             emitIndexRequestId.taskId(),
                                             this->ipcOptions().workerId));
   this->emitIndex(std::move(scipIndex), outputPath);
+  indexingTimer.stop();
+
+  this->statistics.totalTimeMicros =
+      uint64_t(indexingTimer.value<std::chrono::microseconds>());
 
   if (this->options.mode == WorkerMode::Compdb) {
+    if (!this->options.statsFilePath.empty()) {
+      StatsEntry::emitAll({StatsEntry{tuMainFilePath, this->statistics}},
+                          this->options.statsFilePath.c_str());
+    }
     return ReceiveStatus::OK;
   }
 
-  EmitIndexJobResult emitIndexResult{AbsolutePath{outputPath.string()}};
+  EmitIndexJobResult emitIndexResult{this->statistics,
+                                     AbsolutePath{outputPath.string()}};
 
   this->sendResult(emitIndexRequestId,
                    IndexJobResult{.kind = IndexJob::Kind::EmitIndex,

indexer/Worker.h

@@ -57,9 +57,11 @@ struct WorkerOptions {
   IpcOptions ipcOptions;   // only valid if mode == Ipc
   StdPath compdbPath;      // only valid if mode == Compdb
   StdPath indexOutputPath; // only valid if mode == Compdb
+  StdPath statsFilePath;   // only valid if mode == Compdb
 
   spdlog::level::level_enum logLevel;
   bool deterministic;
+  bool measureStatistics;
   PreprocessorHistoryRecordingOptions recordingOptions;
   StdPath temporaryOutputDir;
   std::string workerFault;
@@ -97,6 +99,8 @@ class Worker final {
                           PreprocessorHistoryRecorder>>
       recorder;
 
+  IndexingStatistics statistics;
+
 public:
   Worker(WorkerOptions &&options);
   void run();

indexer/main.cc

@@ -50,6 +50,13 @@ static scip_clang::CliOptions parseArguments(int argc, char *argv[]) {
     cxxopts::value<std::string>(cliOptions.temporaryOutputDir));
   parser.add_options("")("h,help", "Show help text", cxxopts::value<bool>());
   // TODO(def: add-version): Add a --version flag
+  parser.add_options("Advanced")(
+    "print-statistics-path",
+    "Print indexing related statistics in JSON format."
+    " Caution: Timing information for individual TUs should not be compared"
+    " directly across runs, as non-determinism may affect the number of files"
+    " skipped by individual indexing jobs.",
+    cxxopts::value<std::string>(cliOptions.statsFilePath));
   parser.add_options("Advanced")(
     "receive-timeout-seconds",
     "How long should the driver wait for a worker before marking it as timed out?",
@@ -75,6 +82,10 @@ static scip_clang::CliOptions parseArguments(int argc, char *argv[]) {
     "help-all",
     "Show all command-line flags, including internal ones and ones for testing.",
     cxxopts::value<bool>());
+  parser.add_options("Advanced")(
+    "measure-statistics",
+    "[worker-only] Measure various statistics related to indexing",
+    cxxopts::value<bool>(cliOptions.measureStatistics));
   parser.add_options("Internal")(
     "preprocessor-history-log-path",
     "[worker-only] Path to log preprocessor history, if applicable.",