[clang-doc] add ftime profiling

[PeterChou1]

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

[llvmbot]

@llvm/pr-subscribers-clang-tools-extra

Author: None (PeterChou1)

Changes

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.

It introduces two option --ftime-trace and --ftime-gran

• ftime-trace produces a time profiler json file called clang-doc-tracing.json
• ftime-gran allows the user to specify the granularity of the profiling

---

Full diff: https://github.com/llvm/llvm-project/pull/97644.diff

5 Files Affected:

• (modified) clang-tools-extra/clang-doc/BitcodeReader.cpp (+8)
• (modified) clang-tools-extra/clang-doc/Mapper.cpp (+12-1)
• (modified) clang-tools-extra/clang-doc/Representation.cpp (+2)
• (modified) clang-tools-extra/clang-doc/Representation.h (+4-1)
• (modified) clang-tools-extra/clang-doc/tool/ClangDocMain.cpp (+49-2)

diff --git a/clang-tools-extra/clang-doc/BitcodeReader.cpp b/clang-tools-extra/clang-doc/BitcodeReader.cpp
index bfb04e7407b38..2fa228dd7b180 100644
--- a/clang-tools-extra/clang-doc/BitcodeReader.cpp
+++ b/clang-tools-extra/clang-doc/BitcodeReader.cpp
@@ -10,6 +10,7 @@
 #include "llvm/ADT/IndexedMap.h"
 #include "llvm/Support/Error.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/TimeProfiler.h"
 #include <optional>
 
 namespace clang {
@@ -670,6 +671,7 @@ llvm::Error ClangDocBitcodeReader::readRecord(unsigned ID, T I) {
 
 template <>
 llvm::Error ClangDocBitcodeReader::readRecord(unsigned ID, Reference *I) {
+  llvm::TimeTraceScope("clang-doc", "readRecord Reference");
   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("readBlock", "ClangDocBitcodeReader");
   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("readSubBlock", "ClangDocBitcodeReader");
   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("skipUntilRecordOrBlock", "ClangDocBitcodeReader");
   BlockOrRecordID = 0;
 
   while (!Stream.AtEndOfStream()) {
@@ -878,6 +883,7 @@ llvm::Error ClangDocBitcodeReader::validateStream() {
 }
 
 llvm::Error ClangDocBitcodeReader::readBlockInfoBlock() {
+  llvm::TimeTraceScope("readBlockInfoBlock", "ClangDocBitcodeReader");
   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("createInfo", "ClangDocBitcodeReader");
   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("readBlockToInfo", "ClangDocBitcodeReader");
   switch (ID) {
   case BI_NAMESPACE_BLOCK_ID:
     return createInfo<NamespaceInfo>(ID);
diff --git a/clang-tools-extra/clang-doc/Mapper.cpp b/clang-tools-extra/clang-doc/Mapper.cpp
index bb8b7952980ac..d56546dbfa73f 100644
--- a/clang-tools-extra/clang-doc/Mapper.cpp
+++ b/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(CDCtx.Granularity, "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("emit info phase", "emit info");
   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,9 @@ 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("serializing info", "serializing");
   // 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 +57,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;
 }
 
@@ -56,7 +65,9 @@ bool MapASTVisitor::VisitNamespaceDecl(const NamespaceDecl *D) {
   return mapDecl(D);
 }
 
-bool MapASTVisitor::VisitRecordDecl(const RecordDecl *D) { return mapDecl(D); }
+bool MapASTVisitor::VisitRecordDecl(const RecordDecl *D) {
+  return mapDecl(D);
+}
 
 bool MapASTVisitor::VisitEnumDecl(const EnumDecl *D) { return mapDecl(D); }
 
diff --git a/clang-tools-extra/clang-doc/Representation.cpp b/clang-tools-extra/clang-doc/Representation.cpp
index d08afbb962189..23e739a675789 100644
--- a/clang-tools-extra/clang-doc/Representation.cpp
+++ b/clang-tools-extra/clang-doc/Representation.cpp
@@ -366,10 +366,12 @@ void Index::sort() {
 
 ClangDocContext::ClangDocContext(tooling::ExecutionContext *ECtx,
                                  StringRef ProjectName, bool PublicOnly,
+                                 bool FTimeTrace, int Granularity,
                                  StringRef OutDirectory, StringRef SourceRoot,
                                  StringRef RepositoryUrl,
                                  std::vector<std::string> UserStylesheets)
     : ECtx(ECtx), ProjectName(ProjectName), PublicOnly(PublicOnly),
+      FTimeTrace(FTimeTrace), Granularity(Granularity),
       OutDirectory(OutDirectory), UserStylesheets(UserStylesheets) {
   llvm::SmallString<128> SourceRootDir(SourceRoot);
   if (SourceRoot.empty())
diff --git a/clang-tools-extra/clang-doc/Representation.h b/clang-tools-extra/clang-doc/Representation.h
index d70c279f7a2bd..619fa34da8779 100644
--- a/clang-tools-extra/clang-doc/Representation.h
+++ b/clang-tools-extra/clang-doc/Representation.h
@@ -480,12 +480,15 @@ mergeInfos(std::vector<std::unique_ptr<Info>> &Values);
 struct ClangDocContext {
   ClangDocContext() = default;
   ClangDocContext(tooling::ExecutionContext *ECtx, StringRef ProjectName,
-                  bool PublicOnly, StringRef OutDirectory, StringRef SourceRoot,
+                  bool PublicOnly, bool FTimeTrace, int Granularity,
+                  StringRef OutDirectory, StringRef SourceRoot,
                   StringRef RepositoryUrl,
                   std::vector<std::string> UserStylesheets);
   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
diff --git a/clang-tools-extra/clang-doc/tool/ClangDocMain.cpp b/clang-tools-extra/clang-doc/tool/ClangDocMain.cpp
index 6198a6e0cdcc3..4cd4a845629fa 100644
--- a/clang-tools-extra/clang-doc/tool/ClangDocMain.cpp
+++ b/clang-tools-extra/clang-doc/tool/ClangDocMain.cpp
@@ -42,6 +42,7 @@
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/ThreadPool.h"
 #include "llvm/Support/raw_ostream.h"
+#include "llvm/Support/TimeProfiler.h"
 #include <atomic>
 #include <mutex>
 #include <string>
@@ -99,6 +100,16 @@ 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));
+
+static llvm::cl::opt<int> FTimeGranularity(
+    "ftime-gran", llvm::cl::desc(R"(
+Specify granularity for ftime-trace defaults to 200)"),
+    llvm::cl::init(200), llvm::cl::cat(ClangDocCategory));
+
 enum OutputFormatTy {
   md,
   yaml,
@@ -229,6 +240,12 @@ Example usage for a project using a compile commands database:
     return 1;
   }
 
+  // turns on ftime trace profiling
+  if (FTimeTrace)
+    llvm::timeTraceProfilerInitialize(FTimeGranularity, "clang-doc");
+
+  llvm::TimeTraceScope("clang-doc", "main");
+
   // Fail early if an invalid format was provided.
   std::string Format = getFormatString();
   llvm::outs() << "Emiting docs in " << Format << " format.\n";
@@ -249,6 +266,8 @@ Example usage for a project using a compile commands database:
       Executor->get()->getExecutionContext(),
       ProjectName,
       PublicOnly,
+      FTimeTrace,
+      FTimeGranularity,
       OutDirectory,
       SourceRoot,
       RepositoryUrl,
@@ -262,6 +281,7 @@ Example usage for a project using a compile commands database:
     }
   }
 
+  llvm::timeTraceProfilerBegin("mapping phase", "mapping");
   // Mapping phase
   llvm::outs() << "Mapping decls...\n";
   auto Err =
@@ -276,10 +296,12 @@ 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("clang-doc", "collection phase");
   llvm::outs() << "Collecting infos...\n";
   llvm::StringMap<std::vector<StringRef>> USRToBitcode;
   Executor->get()->getToolResults()->forEachResult(
@@ -287,6 +309,7 @@ Example usage for a project using a compile commands database:
         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.
@@ -294,6 +317,7 @@ Example usage for a project using a compile commands database:
   llvm::StringMap<std::unique_ptr<doc::Info>> USRToInfo;
 
   // First reducing phase (reduce all decls into one info per decl).
+  llvm::timeTraceProfilerBegin("reduction phase", "reducing");
   llvm::outs() << "Reducing " << USRToBitcode.size() << " infos...\n";
   std::atomic<bool> Error;
   Error = false;
@@ -302,8 +326,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(FTimeGranularity, "clang-doc");
 
+      llvm::timeTraceProfilerBegin("decoding bitcode phase", "decoding");
+      std::vector<std::unique_ptr<doc::Info>> Infos;
       for (auto &Bitcode : Group.getValue()) {
         llvm::BitstreamCursor Stream(Bitcode);
         doc::ClangDocBitcodeReader Reader(Stream);
@@ -316,12 +343,16 @@ Example usage for a project using a compile commands database:
         std::move(ReadInfos->begin(), ReadInfos->end(),
                   std::back_inserter(Infos));
       }
+      llvm::timeTraceProfilerEnd();
 
+      llvm::timeTraceProfilerBegin("merging bitcode phase", "merging");
       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
       {
@@ -334,14 +365,20 @@ Example usage for a project using a compile commands database:
         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("generating phase", "generating");
   // Ensure the root output directory exists.
   if (std::error_code Err = llvm::sys::fs::create_directories(OutDirectory);
       Err != std::error_code()) {
@@ -362,6 +399,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 {
+      llvm::errs() << "Error opening file: " << EC.message() << "\n";
+    }
+  }
   return 0;
 }

[github-actions]

✅ With the latest revision this PR passed the C/C++ code formatter.

[ilovepi]

Actually, looking at these, I'm not sure I follow the organizational structure of these. How did you decide what's the Name and what's the Detail? is there some logic to this?

[PeterChou1]

there's really no logic I've updated the pr, so that it follow the convention of naming it after the scope or method the timescope is in

[ilovepi]

Have you looked at the profile with the new names? Is it easy to follow? I’d expect it’s a bit harder now, since you’ve dropped some info.

From what I can see, the typical usage of the name is something like “parse input files”. Mostly within our tools we seem to try to capture how long some task is taking, e.g. parsing files, constructing the ast, generating call graphs, writing out files, etc.

I’d consider structuring these more around the tasks your tracking, and perhaps use the details to track more specific bits within a larger task or phase.

[PeterChou1]

I renamed most the labels to follow the convention of [task we are tracking] -> [details]

[ilovepi]

Why here and not say in the lambda in clang-doc main, or in the constructor for the visitor?

[PeterChou1]

I thought it would be more clear since we also use llvm::timeTraceProfilerFinishThread in the method

[ilovepi]

There’s lots of ways to initialize/teardown things so I’m fine with it the way it is, but I wanted to know if there was a reason it wasn’t in those other places.

I’d take another look at how this gets used in other tools, and follow whatever seems to be common.

[ilovepi]

nit: try to be consistent w/ the logging style and capitalization of your messages. It seems to be all over the place.

More concretely, though, what does emit info mean/imply here?

[PeterChou1]

emit info was originally meant to mean the code path where the mapper serialized the ASTNode into clang-docs Info record

[ilovepi]

LGTM modulo a small nit in the naming, we can always add more instrumentation if we need it, but this is a good start.

[ilovepi]

I know this is terminology already in clang-doc, but lets come up w/ something a bit more informative than "Reducing Infos". TBH, the whole "Infos" bit has always rubbed me the wrong way, so even just Reducing Results is better IMO. Use your judgement, but I think we can find a better name for these than Infos.