From 2b407e0bce3c9c3febec4672adb74e0a02ea9f2a Mon Sep 17 00:00:00 2001 From: Jacob Dufault Date: Wed, 17 May 2017 00:08:45 -0700 Subject: [PATCH] Basic performance data tracking during indexing --- src/command_line.cc | 108 +++++++++++++++++++++--------- src/indexer.cc | 12 +++- src/indexer.h | 2 + src/libclangmm/TranslationUnit.cc | 2 +- src/performance.h | 24 +++++++ src/timer.cc | 12 ++++ src/timer.h | 4 ++ 7 files changed, 131 insertions(+), 33 deletions(-) create mode 100644 src/performance.h diff --git a/src/command_line.cc b/src/command_line.cc index dc0e981f..072cfada 100644 --- a/src/command_line.cc +++ b/src/command_line.cc @@ -22,6 +22,7 @@ #include #include #include +#include #include #include #include @@ -49,7 +50,16 @@ std::vector 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 previous; std::unique_ptr current; optional indexed_content; + PerformanceImportFile perf; explicit Index_DoIdMap(std::unique_ptr current, - optional indexed_content) + optional indexed_content, + PerformanceImportFile perf) : current(std::move(current)), - indexed_content(indexed_content) {} + indexed_content(indexed_content), + perf(perf) {} explicit Index_DoIdMap(std::unique_ptr previous, std::unique_ptr current, - optional indexed_content) + optional 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 previous_id_map; std::unique_ptr current_id_map; optional indexed_content; + PerformanceImportFile perf; - Index_OnIdMapped(const optional& indexed_content) - : indexed_content(indexed_content) {} + Index_OnIdMapped(const optional& 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 indexed_content; + PerformanceImportFile perf; - explicit Index_OnIndexed(IndexUpdate& update, const optional& indexed_content) - : update(update) { + explicit Index_OnIndexed( + IndexUpdate& update, + const optional& 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& indexed_content) { // TODO: only load cache if command line arguments are the same. - + PerformanceImportFile tu_perf; Timer time; std::unique_ptr 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 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& indexed_content) { - Timer time; std::unique_ptr cache_for_args = LoadCachedIndex(config, entry.filename); std::string tu_path = cache_for_args ? cache_for_args->import_file : entry.filename; const std::vector& tu_args = entry.args; + PerformanceImportFile perf; + std::vector> indexes = Parse( config, file_consumer_shared, tu_path, tu_args, - entry.filename, indexed_content); - time.ResetAndPrint("Parsing/indexing " + tu_path); + entry.filename, indexed_content, + &perf); for (std::unique_ptr& new_index : indexes) { - std::cerr << "Got index for " << new_index->path << std::endl; + Timer time; // Load the cached index. std::unique_ptr 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 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 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"); - Index_OnIndexed reply(update, response->indexed_content); + response->perf.index_make_delta = time.ElapsedMicrosecondsAndReset(); + +#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(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; diff --git a/src/indexer.cc b/src/indexer.cc index 6045828a..d5f66a4b 100644 --- a/src/indexer.cc +++ b/src/indexer.cc @@ -6,6 +6,7 @@ #include "libclangmm/Utility.h" #include "platform.h" #include "serializer.h" +#include "timer.h" #include #include @@ -1382,6 +1383,7 @@ std::vector> Parse( std::vector args, const std::string& file_contents_path, const optional& file_contents, + PerformanceImportFile* perf, bool dump_ast) { if (!config->enableIndexing) @@ -1389,6 +1391,8 @@ std::vector> Parse( file = NormalizePath(file); + Timer timer; + clang::Index index(0 /*excludeDeclarationsFromPCH*/, 0 /*displayDiagnostics*/); std::vector unsaved_files; @@ -1401,6 +1405,8 @@ std::vector> 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> 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, ¶m, 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) { diff --git a/src/indexer.h b/src/indexer.h index fd71ff36..6c06a5de 100644 --- a/src/indexer.h +++ b/src/indexer.h @@ -6,6 +6,7 @@ #include "utils.h" #include "language_server_api.h" #include "libclangmm/Utility.h" +#include "performance.h" #include #include @@ -508,5 +509,6 @@ std::vector> Parse( std::vector args, const std::string& file_contents_path, const optional& file_contents, + PerformanceImportFile* perf, bool dump_ast = false); void IndexInit(); diff --git a/src/libclangmm/TranslationUnit.cc b/src/libclangmm/TranslationUnit.cc index 3c6ed5be..cc8ed990 100644 --- a/src/libclangmm/TranslationUnit.cc +++ b/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( diff --git a/src/performance.h b/src/performance.h new file mode 100644 index 00000000..7b8bc376 --- /dev/null +++ b/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; +}; \ No newline at end of file diff --git a/src/timer.cc b/src/timer.cc index a7c30dc4..d9c3a7b8 100644 --- a/src/timer.cc +++ b/src/timer.cc @@ -6,6 +6,18 @@ Timer::Timer() { Reset(); } +long long Timer::ElapsedMicroseconds() const { + std::chrono::time_point end = Clock::now(); + return std::chrono::duration_cast(end - start).count(); +} + +long long Timer::ElapsedMicrosecondsAndReset() { + std::chrono::time_point end = Clock::now(); + long long microseconds = std::chrono::duration_cast(end - start).count(); + Reset(); + return microseconds; +} + void Timer::Reset() { start = Clock::now(); } diff --git a/src/timer.h b/src/timer.h index 8a7638d2..15c68e90 100644 --- a/src/timer.h +++ b/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 " took 5ms"