[clang-doc] add ftime profiling (#97644)

Summary:
this patches adds ftime-tracing option for clang-doc which was what I
used to profile the performance problems we had with clang-doc
generating the llvm docs.
- ftime-trace produces a time profiler json file called
clang-doc-tracing.json

Test Plan: 

Reviewers: 

Subscribers: 

Tasks: 

Tags: 


Differential Revision: https://phabricator.intern.facebook.com/D60251381

Author: PeterChou1

clang-tools-extra/clang-doc/BitcodeReader.cpp

@@ -9,6 +9,7 @@
 #include "BitcodeReader.h"
 #include "llvm/ADT/IndexedMap.h"
 #include "llvm/Support/Error.h"
+#include "llvm/Support/TimeProfiler.h"
 #include "llvm/Support/raw_ostream.h"
 #include <optional>
 
@@ -670,6 +671,7 @@ llvm::Error ClangDocBitcodeReader::readRecord(unsigned ID, T I) {
 
 template <>
 llvm::Error ClangDocBitcodeReader::readRecord(unsigned ID, Reference *I) {
+  llvm::TimeTraceScope("Reducing infos", "readRecord");
   Record R;
   llvm::StringRef Blob;
   llvm::Expected<unsigned> MaybeRecID = Stream.readRecord(ID, R, &Blob);
@@ -681,6 +683,7 @@ llvm::Error ClangDocBitcodeReader::readRecord(unsigned ID, Reference *I) {
 // Read a block of records into a single info.
 template <typename T>
 llvm::Error ClangDocBitcodeReader::readBlock(unsigned ID, T I) {
+  llvm::TimeTraceScope("Reducing infos", "readBlock");
   if (llvm::Error Err = Stream.EnterSubBlock(ID))
     return Err;
 
@@ -711,6 +714,7 @@ llvm::Error ClangDocBitcodeReader::readBlock(unsigned ID, T I) {
 
 template <typename T>
 llvm::Error ClangDocBitcodeReader::readSubBlock(unsigned ID, T I) {
+  llvm::TimeTraceScope("Reducing infos", "readSubBlock");
   switch (ID) {
   // Blocks can only have certain types of sub blocks.
   case BI_COMMENT_BLOCK_ID: {
@@ -817,6 +821,7 @@ llvm::Error ClangDocBitcodeReader::readSubBlock(unsigned ID, T I) {
 
 ClangDocBitcodeReader::Cursor
 ClangDocBitcodeReader::skipUntilRecordOrBlock(unsigned &BlockOrRecordID) {
+  llvm::TimeTraceScope("Reducing infos", "skipUntilRecordOrBlock");
   BlockOrRecordID = 0;
 
   while (!Stream.AtEndOfStream()) {
@@ -878,6 +883,7 @@ llvm::Error ClangDocBitcodeReader::validateStream() {
 }
 
 llvm::Error ClangDocBitcodeReader::readBlockInfoBlock() {
+  llvm::TimeTraceScope("Reducing infos", "readBlockInfoBlock");
   Expected<std::optional<llvm::BitstreamBlockInfo>> MaybeBlockInfo =
       Stream.ReadBlockInfoBlock();
   if (!MaybeBlockInfo)
@@ -894,6 +900,7 @@ llvm::Error ClangDocBitcodeReader::readBlockInfoBlock() {
 template <typename T>
 llvm::Expected<std::unique_ptr<Info>>
 ClangDocBitcodeReader::createInfo(unsigned ID) {
+  llvm::TimeTraceScope("Reducing infos", "createInfo");
   std::unique_ptr<Info> I = std::make_unique<T>();
   if (auto Err = readBlock(ID, static_cast<T *>(I.get())))
     return std::move(Err);
@@ -902,6 +909,7 @@ ClangDocBitcodeReader::createInfo(unsigned ID) {
 
 llvm::Expected<std::unique_ptr<Info>>
 ClangDocBitcodeReader::readBlockToInfo(unsigned ID) {
+  llvm::TimeTraceScope("Reducing infos", "readBlockToInfo");
   switch (ID) {
   case BI_NAMESPACE_BLOCK_ID:
     return createInfo<NamespaceInfo>(ID);

clang-tools-extra/clang-doc/Mapper.cpp

@@ -13,12 +13,17 @@
 #include "clang/Index/USRGeneration.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/Support/Error.h"
+#include "llvm/Support/TimeProfiler.h"
 
 namespace clang {
 namespace doc {
 
 void MapASTVisitor::HandleTranslationUnit(ASTContext &Context) {
+  if (CDCtx.FTimeTrace)
+    llvm::timeTraceProfilerInitialize(200, "clang-doc");
   TraverseDecl(Context.getTranslationUnitDecl());
+  if (CDCtx.FTimeTrace)
+    llvm::timeTraceProfilerFinishThread();
 }
 
 template <typename T> bool MapASTVisitor::mapDecl(const T *D) {
@@ -30,6 +35,7 @@ template <typename T> bool MapASTVisitor::mapDecl(const T *D) {
   if (D->getParentFunctionOrMethod())
     return true;
 
+  llvm::timeTraceProfilerBegin("Mapping declaration", "emit info from astnode");
   llvm::SmallString<128> USR;
   // If there is an error generating a USR for the decl, skip this decl.
   if (index::generateUSRForDecl(D, USR))
@@ -40,7 +46,10 @@ template <typename T> bool MapASTVisitor::mapDecl(const T *D) {
   auto I = serialize::emitInfo(D, getComment(D, D->getASTContext()),
                                getLine(D, D->getASTContext()), File,
                                IsFileInRootDir, CDCtx.PublicOnly);
+  llvm::timeTraceProfilerEnd();
 
+  llvm::timeTraceProfilerBegin("Mapping declaration",
+                               "serialized info into bitcode");
   // A null in place of I indicates that the serializer is skipping this decl
   // for some reason (e.g. we're only reporting public decls).
   if (I.first)
@@ -49,6 +58,7 @@ template <typename T> bool MapASTVisitor::mapDecl(const T *D) {
   if (I.second)
     CDCtx.ECtx->reportResult(llvm::toHex(llvm::toStringRef(I.second->USR)),
                              serialize::serialize(I.second));
+  llvm::timeTraceProfilerEnd();
   return true;
 }
 

clang-tools-extra/clang-doc/Representation.cpp

@@ -368,9 +368,11 @@ ClangDocContext::ClangDocContext(tooling::ExecutionContext *ECtx,
                                  StringRef ProjectName, bool PublicOnly,
                                  StringRef OutDirectory, StringRef SourceRoot,
                                  StringRef RepositoryUrl,
-                                 std::vector<std::string> UserStylesheets)
+                                 std::vector<std::string> UserStylesheets,
+                                 bool FTimeTrace)
     : ECtx(ECtx), ProjectName(ProjectName), PublicOnly(PublicOnly),
-      OutDirectory(OutDirectory), UserStylesheets(UserStylesheets) {
+      OutDirectory(OutDirectory), UserStylesheets(UserStylesheets),
+      FTimeTrace(FTimeTrace) {
   llvm::SmallString<128> SourceRootDir(SourceRoot);
   if (SourceRoot.empty())
     // If no SourceRoot was provided the current path is used as the default

clang-tools-extra/clang-doc/Representation.h

@@ -482,10 +482,13 @@ struct ClangDocContext {
   ClangDocContext(tooling::ExecutionContext *ECtx, StringRef ProjectName,
                   bool PublicOnly, StringRef OutDirectory, StringRef SourceRoot,
                   StringRef RepositoryUrl,
-                  std::vector<std::string> UserStylesheets);
+                  std::vector<std::string> UserStylesheets,
+                  bool FTimeTrace = false);
   tooling::ExecutionContext *ECtx;
   std::string ProjectName; // Name of project clang-doc is documenting.
   bool PublicOnly; // Indicates if only public declarations are documented.
+  bool FTimeTrace; // Indicates if ftime trace is turned on
+  int Granularity; // Granularity of ftime trace
   std::string OutDirectory; // Directory for outputting generated files.
   std::string SourceRoot;   // Directory where processed files are stored. Links
                             // to definition locations will only be generated if

clang-tools-extra/clang-doc/tool/ClangDocMain.cpp

@@ -41,6 +41,7 @@
 #include "llvm/Support/Process.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/ThreadPool.h"
+#include "llvm/Support/TimeProfiler.h"
 #include "llvm/Support/raw_ostream.h"
 #include <atomic>
 #include <mutex>
@@ -99,6 +100,11 @@ URL of repository that hosts code.
 Used for links to definition locations.)"),
                   llvm::cl::cat(ClangDocCategory));
 
+static llvm::cl::opt<bool> FTimeTrace("ftime-trace", llvm::cl::desc(R"(
+Turn on time profiler. Generates clang-doc-tracing.json)"),
+                                      llvm::cl::init(false),
+                                      llvm::cl::cat(ClangDocCategory));
+
 enum OutputFormatTy {
   md,
   yaml,
@@ -229,6 +235,12 @@ Example usage for a project using a compile commands database:
     return 1;
   }
 
+  // turns on ftime trace profiling
+  if (FTimeTrace)
+    llvm::timeTraceProfilerInitialize(200, "clang-doc");
+
+  llvm::TimeTraceScope("main");
+
   // Fail early if an invalid format was provided.
   std::string Format = getFormatString();
   llvm::outs() << "Emiting docs in " << Format << " format.\n";
@@ -252,8 +264,8 @@ Example usage for a project using a compile commands database:
       OutDirectory,
       SourceRoot,
       RepositoryUrl,
-      {UserStylesheets.begin(), UserStylesheets.end()}
-  };
+      {UserStylesheets.begin(), UserStylesheets.end()},
+      FTimeTrace};
 
   if (Format == "html") {
     if (auto Err = getHtmlAssetFiles(argv[0], CDCtx)) {
@@ -262,6 +274,7 @@ Example usage for a project using a compile commands database:
     }
   }
 
+  llvm::timeTraceProfilerBegin("Mapping declaration", "total runtime");
   // Mapping phase
   llvm::outs() << "Mapping decls...\n";
   auto Err =
@@ -276,24 +289,28 @@ Example usage for a project using a compile commands database:
       return 1;
     }
   }
+  llvm::timeTraceProfilerEnd();
 
   // Collect values into output by key.
   // In ToolResults, the Key is the hashed USR and the value is the
   // bitcode-encoded representation of the Info object.
+  llvm::timeTraceProfilerBegin("Collect Info", "total runtime");
   llvm::outs() << "Collecting infos...\n";
   llvm::StringMap<std::vector<StringRef>> USRToBitcode;
   Executor->get()->getToolResults()->forEachResult(
       [&](StringRef Key, StringRef Value) {
         auto R = USRToBitcode.try_emplace(Key, std::vector<StringRef>());
         R.first->second.emplace_back(Value);
       });
+  llvm::timeTraceProfilerEnd();
 
   // Collects all Infos according to their unique USR value. This map is added
   // to from the thread pool below and is protected by the USRToInfoMutex.
   llvm::sys::Mutex USRToInfoMutex;
   llvm::StringMap<std::unique_ptr<doc::Info>> USRToInfo;
 
   // First reducing phase (reduce all decls into one info per decl).
+  llvm::timeTraceProfilerBegin("Reducing infos", "total runtime");
   llvm::outs() << "Reducing " << USRToBitcode.size() << " infos...\n";
   std::atomic<bool> Error;
   Error = false;
@@ -302,8 +319,11 @@ Example usage for a project using a compile commands database:
   llvm::DefaultThreadPool Pool(llvm::hardware_concurrency(ExecutorConcurrency));
   for (auto &Group : USRToBitcode) {
     Pool.async([&]() {
-      std::vector<std::unique_ptr<doc::Info>> Infos;
+      if (FTimeTrace)
+        llvm::timeTraceProfilerInitialize(200, "clang-doc");
 
+      llvm::timeTraceProfilerBegin("Reducing infos", "decoding bitcode");
+      std::vector<std::unique_ptr<doc::Info>> Infos;
       for (auto &Bitcode : Group.getValue()) {
         llvm::BitstreamCursor Stream(Bitcode);
         doc::ClangDocBitcodeReader Reader(Stream);
@@ -316,32 +336,40 @@ Example usage for a project using a compile commands database:
         std::move(ReadInfos->begin(), ReadInfos->end(),
                   std::back_inserter(Infos));
       }
+      llvm::timeTraceProfilerEnd();
 
+      llvm::timeTraceProfilerBegin("Reducing infos", "merging bitcode");
       auto Reduced = doc::mergeInfos(Infos);
       if (!Reduced) {
         llvm::errs() << llvm::toString(Reduced.takeError());
         return;
       }
+      llvm::timeTraceProfilerEnd();
 
       // Add a reference to this Info in the Index
       {
         std::lock_guard<llvm::sys::Mutex> Guard(IndexMutex);
         clang::doc::Generator::addInfoToIndex(CDCtx.Idx, Reduced.get().get());
       }
-
       // Save in the result map (needs a lock due to threaded access).
+
       {
         std::lock_guard<llvm::sys::Mutex> Guard(USRToInfoMutex);
         USRToInfo[Group.getKey()] = std::move(Reduced.get());
       }
+
+      if (CDCtx.FTimeTrace)
+        llvm::timeTraceProfilerFinishThread();
     });
   }
+  llvm::timeTraceProfilerEnd();
 
   Pool.wait();
 
   if (Error)
     return 1;
 
+  llvm::timeTraceProfilerBegin("Writing output", "total runtime");
   // Ensure the root output directory exists.
   if (std::error_code Err = llvm::sys::fs::create_directories(OutDirectory);
       Err != std::error_code()) {
@@ -362,6 +390,16 @@ Example usage for a project using a compile commands database:
   if (Err) {
     llvm::outs() << "warning: " << toString(std::move(Err)) << "\n";
   }
-
+  llvm::timeTraceProfilerEnd();
+
+  if (FTimeTrace) {
+    std::error_code EC;
+    llvm::raw_fd_ostream OS("clang-doc-tracing.json", EC,
+                            llvm::sys::fs::OF_Text);
+    if (!EC)
+      llvm::timeTraceProfilerWrite(OS);
+    else
+      return 1;
+  }
   return 0;
 }