Basic performance data tracking during indexing

src/command_line.cc

@@ -22,6 +22,7 @@
 #include <functional>
 #include <iostream>
 #include <string>
+#include <sstream>
 #include <unordered_map>
 #include <thread>
 #include <vector>
@@ -49,7 +50,16 @@ std::vector<std::string> kEmptyArgs;
 
 
 
+std::string FormatMicroseconds(long long microseconds) {
+  long long milliseconds = microseconds / 1000;
+  long long remaining = microseconds  - milliseconds;
+  
+  // Only show two digits after the dot.
+  while (remaining >= 100)
+    remaining /= 10;
 
+  return std::to_string(milliseconds) + "." + std::to_string(remaining) + "ms";
+}
 
 
 
@@ -778,18 +788,23 @@ struct Index_DoIdMap {
   std::unique_ptr<IndexFile> previous;
   std::unique_ptr<IndexFile> current;
   optional<std::string> indexed_content;
+  PerformanceImportFile perf;
 
   explicit Index_DoIdMap(std::unique_ptr<IndexFile> current,
-                         optional<std::string> indexed_content)
+                         optional<std::string> indexed_content,
+                         PerformanceImportFile perf)
     : current(std::move(current)),
-      indexed_content(indexed_content) {}
+      indexed_content(indexed_content),
+      perf(perf) {}
 
   explicit Index_DoIdMap(std::unique_ptr<IndexFile> previous,
                          std::unique_ptr<IndexFile> current,
-                         optional<std::string> indexed_content)
+                         optional<std::string> indexed_content,
+                         PerformanceImportFile perf)
     : previous(std::move(previous)),
       current(std::move(current)),
-      indexed_content(indexed_content) {}
+      indexed_content(indexed_content),
+      perf(perf) {}
 };
 
 struct Index_OnIdMapped {
@@ -798,18 +813,25 @@ struct Index_OnIdMapped {
   std::unique_ptr<IdMap> previous_id_map;
   std::unique_ptr<IdMap> current_id_map;
   optional<std::string> indexed_content;
+  PerformanceImportFile perf;
 
-  Index_OnIdMapped(const optional<std::string>& indexed_content)
+  Index_OnIdMapped(const optional<std::string>& indexed_content,
-    : indexed_content(indexed_content) {}
+                   PerformanceImportFile perf)
+    : indexed_content(indexed_content),
+      perf(perf) {}
 };
 
 struct Index_OnIndexed {
   IndexUpdate update;
   // Map is file path to file content.
   std::unordered_map<std::string, std::string> indexed_content;
+  PerformanceImportFile perf;
 
-  explicit Index_OnIndexed(IndexUpdate& update, const optional<std::string>& indexed_content)
+  explicit Index_OnIndexed(
-    : update(update) {
+      IndexUpdate& update,
+      const optional<std::string>& indexed_content,
+      PerformanceImportFile perf)
+    : update(update), perf(perf) {
     if (indexed_content) {
       assert(update.files_def_update.size() == 1);
       this->indexed_content[update.files_def_update[0].path] = *indexed_content;
@@ -962,11 +984,11 @@ bool ImportCachedIndex(IndexerConfig* config,
                        const std::string& tu_path,
                        const optional<std::string>& indexed_content) {
   // TODO: only load cache if command line arguments are the same.
-
+  PerformanceImportFile tu_perf;
   Timer time;
 
   std::unique_ptr<IndexFile> cache = LoadCachedIndex(config, tu_path);
-  time.ResetAndPrint("Reading cached index from disk " + tu_path);
+  tu_perf.index_load_cached = time.ElapsedMicrosecondsAndReset();
   if (!cache)
     return true;
 
@@ -974,14 +996,17 @@ bool ImportCachedIndex(IndexerConfig* config,
 
   // Import all dependencies.
   for (auto& dependency_path : cache->dependencies) {
-    std::cerr << "- Got dependency " << dependency_path << std::endl;
+    //std::cerr << "- Got dependency " << dependency_path << std::endl;
+    PerformanceImportFile perf;
+    time.Reset();
     std::unique_ptr<IndexFile> cache = LoadCachedIndex(config, dependency_path);
+    perf.index_load_cached = time.ElapsedMicrosecondsAndReset();
     if (cache && GetLastModificationTime(cache->path) == cache->last_modification_time)
       file_consumer_shared->Mark(cache->path);
     else
       needs_reparse = true;
     if (cache)
-      queue_do_id_map->Enqueue(Index_DoIdMap(std::move(cache), nullopt));
+      queue_do_id_map->Enqueue(Index_DoIdMap(std::move(cache), nullopt, perf));
   }
 
   // Import primary file.
@@ -989,7 +1014,7 @@ bool ImportCachedIndex(IndexerConfig* config,
     file_consumer_shared->Mark(tu_path);
   else
     needs_reparse = true;
-  queue_do_id_map->Enqueue(Index_DoIdMap(std::move(cache), indexed_content));
+  queue_do_id_map->Enqueue(Index_DoIdMap(std::move(cache), indexed_content, tu_perf));
 
   return needs_reparse;
 }
@@ -999,21 +1024,22 @@ void ParseFile(IndexerConfig* config,
                Index_DoIdMapQueue* queue_do_id_map,
                const Project::Entry& entry,
                const optional<std::string>& indexed_content) {
-  Timer time;
 
   std::unique_ptr<IndexFile> cache_for_args = LoadCachedIndex(config, entry.filename);
 
   std::string tu_path = cache_for_args ? cache_for_args->import_file : entry.filename;
   const std::vector<std::string>& tu_args = entry.args;
 
+  PerformanceImportFile perf;
+
   std::vector<std::unique_ptr<IndexFile>> indexes = Parse(
     config, file_consumer_shared,
     tu_path, tu_args,
-    entry.filename, indexed_content);
+    entry.filename, indexed_content,
-  time.ResetAndPrint("Parsing/indexing " + tu_path);
+    &perf);
 
   for (std::unique_ptr<IndexFile>& new_index : indexes) {
-    std::cerr << "Got index for " << new_index->path << std::endl;
+    Timer time;
 
     // Load the cached index.
     std::unique_ptr<IndexFile> cached_index;
@@ -1024,7 +1050,8 @@ void ParseFile(IndexerConfig* config,
     // TODO: Enable this assert when we are no longer forcibly indexing the primary file.
     //assert(!cached_index || GetLastModificationTime(new_index->path) != cached_index->last_modification_time);
 
-    time.ResetAndPrint("Loading cached index");
+    // Note: we are reusing the parent perf.
+    perf.index_load_cached = time.ElapsedMicrosecondsAndReset();
 
     // Publish diagnostics.
     if (!new_index->diagnostics.empty() || (cached_index && !cached_index->diagnostics.empty())) {
@@ -1052,11 +1079,12 @@ void ParseFile(IndexerConfig* config,
 
     // Cache the newly indexed file. This replaces the existing cache.
     // TODO: Run this as another import pipeline stage.
+    time.Reset();
     WriteToCache(config, new_index->path, *new_index, content);
-    time.ResetAndPrint("Cache index update to disk");
+    perf.index_save_to_disk = time.ElapsedMicrosecondsAndReset();
 
     // Dispatch IdMap creation request, which will happen on querydb thread.
-    Index_DoIdMap response(std::move(cached_index), std::move(new_index), content);
+    Index_DoIdMap response(std::move(cached_index), std::move(new_index), content, perf);
     queue_do_id_map->Enqueue(std::move(response));
   }
 
@@ -1066,9 +1094,8 @@ bool ResetStaleFiles(IndexerConfig* config,
                      FileConsumer::SharedState* file_consumer_shared,
                      const std::string& tu_path) {
   Timer time;
-
   std::unique_ptr<IndexFile> cache = LoadCachedIndex(config, tu_path);
-  time.ResetAndPrint("Reading cached index from disk " + tu_path);
+
   if (!cache) {
     std::cerr << "[indexer] Unable to load existing index from file when freshening (dependences will not be freshened)" << std::endl;
     file_consumer_shared->Mark(tu_path);
@@ -1079,7 +1106,6 @@ bool ResetStaleFiles(IndexerConfig* config,
 
   // Check dependencies
   for (auto& dependency_path : cache->dependencies) {
-    std::cerr << "- Got dependency " << dependency_path << std::endl;
     std::unique_ptr<IndexFile> cache = LoadCachedIndex(config, dependency_path);
     if (GetLastModificationTime(cache->path) != cache->last_modification_time) {
       needs_reparse = true;
@@ -1157,10 +1183,32 @@ bool IndexMain_DoCreateIndexUpdate(
   Timer time;
   IndexUpdate update = IndexUpdate::CreateDelta(response->previous_id_map.get(), response->current_id_map.get(),
     response->previous_index.get(), response->current_index.get());
-  time.ResetAndPrint("[indexer] Creating delta IndexUpdate");
+  response->perf.index_make_delta = time.ElapsedMicrosecondsAndReset();
-  Index_OnIndexed reply(update, response->indexed_content);
+
+#define PRINT_SECTION(name) \
+  if (response->perf.name) {\
+    total += response->perf.name; \
+    long long milliseconds = response->perf.name / 1000; \
+    long long remaining = response->perf.name - milliseconds; \
+    output << " " << #name << ": " << FormatMicroseconds(response->perf.name); \
+  }
+  std::stringstream output;
+  long long total = 0;
+  output << "[perf]";
+  PRINT_SECTION(index_parse);
+  PRINT_SECTION(index_build);
+  PRINT_SECTION(index_save_to_disk);
+  PRINT_SECTION(index_load_cached);
+  PRINT_SECTION(querydb_id_map);
+  PRINT_SECTION(index_make_delta);
+  output << "\n       total: " << FormatMicroseconds(total);
+  output << " path: " << response->current_index->path;
+  output << std::endl;
+  std::cerr << output.rdbuf();
+#undef PRINT_SECTION
+
+  Index_OnIndexed reply(update, response->indexed_content, response->perf);
   queue_on_indexed->Enqueue(std::move(reply));
-  time.ResetAndPrint("[indexer] Sending update to server");
 
   return true;
 }
@@ -1678,7 +1726,7 @@ bool QueryDbMainLoop(
           response.result.activeSignature = 0;
           for (size_t i = 0; i < response.result.signatures.size(); ++i) {
             if (active_param < response.result.signatures.size()) {
-              response.result.activeSignature = i;
+              response.result.activeSignature = (int)i;
               break;
             }
           }
@@ -2061,7 +2109,7 @@ bool QueryDbMainLoop(
 
     did_work = true;
 
-    Index_OnIdMapped response(request->indexed_content);
+    Index_OnIdMapped response(request->indexed_content, request->perf);
     Timer time;
     
     if (request->previous) {
@@ -2071,8 +2119,8 @@ bool QueryDbMainLoop(
 
     assert(request->current);
     response.current_id_map = MakeUnique<IdMap>(db, request->current->id_cache);
-    time.ResetAndPrint("[querydb] Create IdMap " + request->current->path);
     response.current_index = std::move(request->current);
+    response.perf.querydb_id_map = time.ElapsedMicrosecondsAndReset();
 
     queue_on_id_mapped->Enqueue(std::move(response));
   }
@@ -2109,7 +2157,7 @@ bool QueryDbMainLoop(
     }
 
     db->ApplyIndexUpdate(&response->update);
-    time.ResetAndPrint("[querydb] Applying index update");
+    //time.ResetAndPrint("[querydb] Applying index update");
   }
 
   return did_work;

src/indexer.cc

@@ -6,6 +6,7 @@
 #include "libclangmm/Utility.h"
 #include "platform.h"
 #include "serializer.h"
+#include "timer.h"
 
 #include <algorithm>
 #include <chrono>
@@ -1382,6 +1383,7 @@ std::vector<std::unique_ptr<IndexFile>> Parse(
     std::vector<std::string> args,
     const std::string& file_contents_path,
     const optional<std::string>& file_contents,
+    PerformanceImportFile* perf,
     bool dump_ast) {
 
   if (!config->enableIndexing)
@@ -1389,6 +1391,8 @@ std::vector<std::unique_ptr<IndexFile>> Parse(
 
   file = NormalizePath(file);
 
+  Timer timer;
+
   clang::Index index(0 /*excludeDeclarationsFromPCH*/,
                      0 /*displayDiagnostics*/);
   std::vector<CXUnsavedFile> unsaved_files;
@@ -1401,6 +1405,8 @@ std::vector<std::unique_ptr<IndexFile>> Parse(
   }
   clang::TranslationUnit tu(index, file, args, unsaved_files, CXTranslationUnit_KeepGoing);
 
+  perf->index_parse = timer.ElapsedMicrosecondsAndReset();
+
   if (dump_ast)
     Dump(tu.document_cursor());
 
@@ -1418,13 +1424,15 @@ std::vector<std::unique_ptr<IndexFile>> Parse(
   bool is_first_ownership;
   param.primary_file = file_consumer.TryConsumeFile(cx_file, &is_first_ownership);
 
-  std::cerr << "!! [START] Indexing " << file << std::endl;
+  //std::cerr << "!! [START] Indexing " << file << std::endl;
   CXIndexAction index_action = clang_IndexAction_create(index.cx_index);
   clang_indexTranslationUnit(index_action, &param, callbacks, sizeof(callbacks),
                              CXIndexOpt_IndexFunctionLocalSymbols | CXIndexOpt_SkipParsedBodiesInSession | CXIndexOpt_IndexImplicitTemplateInstantiations,
                              tu.cx_tu);
   clang_IndexAction_dispose(index_action);
-  std::cerr << "!! [END] Indexing " << file << std::endl;
+  //std::cerr << "!! [END] Indexing " << file << std::endl;
+
+  perf->index_build = timer.ElapsedMicrosecondsAndReset();
 
   auto result = param.file_consumer->TakeLocalState();
   for (auto& entry : result) {

src/indexer.h

@@ -6,6 +6,7 @@
 #include "utils.h"
 #include "language_server_api.h"
 #include "libclangmm/Utility.h"
+#include "performance.h"
 
 #include <optional.h>
 #include <rapidjson/writer.h>
@@ -508,5 +509,6 @@ std::vector<std::unique_ptr<IndexFile>> Parse(
     std::vector<std::string> args,
     const std::string& file_contents_path,
     const optional<std::string>& file_contents,
+    PerformanceImportFile* perf,
     bool dump_ast = false);
 void IndexInit();

src/libclangmm/TranslationUnit.cc

@@ -23,7 +23,7 @@ TranslationUnit::TranslationUnit(Index& index,
   for (const auto& arg : platform_args)
     args.push_back(arg.c_str());
 
-  std::cerr << "Parsing " << filepath << " with args " << StringJoin(args) << std::endl;
+  //std::cerr << "Parsing " << filepath << " with args " << StringJoin(args) << std::endl;
 
   //CXErrorCode error_code = clang_parseTranslationUnit2FullArgv(
   CXErrorCode error_code = clang_parseTranslationUnit2(

src/performance.h

@@ -0,0 +1,24 @@
+#pragma once
+
+// Contains timing information for the entire pipeline for importing a file
+// into the querydb.
+struct PerformanceImportFile {
+  // All units are in microseconds.
+
+  // [indexer] clang parsing the file
+  long long index_parse = 0;
+  // [indexer] build the IndexFile object from clang parse
+  long long index_build = 0;
+  // [querydb] create IdMap object from IndexFile
+  long long querydb_id_map = 0;
+  // [indexer] save the IndexFile to disk
+  long long index_save_to_disk = 0;
+  // [indexer] loading previously cached index
+  long long index_load_cached = 0;
+  // [indexer] create delta IndexUpdate object
+  long long index_make_delta = 0;
+  // [querydb] update WorkingFile indexed file state
+  //long long querydb_update_working_file = 0;
+  // [querydb] apply IndexUpdate
+  //long long querydb_apply_index_update = 0;
+};

src/timer.cc

@@ -6,6 +6,18 @@ Timer::Timer() {
   Reset();
 }
 
+long long Timer::ElapsedMicroseconds() const {
+  std::chrono::time_point<Clock> end = Clock::now();
+  return std::chrono::duration_cast<std::chrono::microseconds>(end - start).count();
+}
+
+long long Timer::ElapsedMicrosecondsAndReset() {
+  std::chrono::time_point<Clock> end = Clock::now();
+  long long microseconds = std::chrono::duration_cast<std::chrono::microseconds>(end - start).count();
+  Reset();
+  return microseconds;
+}
+
 void Timer::Reset() {
   start = Clock::now();
 }

src/timer.h

@@ -9,6 +9,10 @@ struct Timer {
   // Creates a new timer. A timer is always running.
   Timer();
 
+  // Returns elapsed microseconds.
+  long long ElapsedMicroseconds() const;
+  // Returns elapsed microseconds and restarts/resets the timer.
+  long long ElapsedMicrosecondsAndReset();
   // Restart/reset the timer.
   void Reset();
   // Resets timer and prints a message like "<foo> took 5ms"