demangle function names in trace files

[Trass3r]

This improves consistency in the trace files as other entries are demangled too.

@jamieschmeiser @An-DJ

[github-actions]

✅ With the latest revision this PR passed the Python code formatter.

[Trass3r]

This is a bit brute-force as it also runs demangle on cases like [module], see getIRName above around line 200.
Also for SCCs it fails to demangle since getName returns something like (func1[,func2]).
I didn't hit the Loop and MachineFunction cases in the Debugger so not sure about those.

In general those function entries are duplicated a lot in the trace file, maybe one could limit it to certain levels in the flame graph, e.g. only once for PassManager<Function> and not for every single pass beneath it like EarlyCSEPass.

[jamieschmeiser]

getIRName is a locally defined function (see above in this file). In some of the cases, it is desirable to have the mangled name reported because that can be used for filtering. In this case, I don't think that there is filtering available, so demangling the name seems reasonable. However, as you noted, there are names where demangling is not appropriate. I would suggest that you add a parameter to the getIRName function (defaulting to false) to allow demangling of appropriate names and do the demangling there.

[jamieschmeiser]

See comments in response

[jamieschmeiser]

LGTM, thanks

[llvmbot]

@llvm/pr-subscribers-clang-driver

@llvm/pr-subscribers-clang

Author: Trass3r (Trass3r)

Changes

This improves consistency in the trace files as other entries are demangled too.

@jamieschmeiser @An-DJ

---

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

4 Files Affected:

• (modified) clang/test/Driver/ftime-trace-sections.py (+13-2)
• (modified) llvm/lib/IR/LegacyPassManager.cpp (+3-1)
• (modified) llvm/lib/Passes/CMakeLists.txt (+1)
• (modified) llvm/lib/Passes/StandardInstrumentations.cpp (+5-4)

diff --git a/clang/test/Driver/ftime-trace-sections.py b/clang/test/Driver/ftime-trace-sections.py
old mode 100644
new mode 100755
index 02afa4ac54eb7b..eeb3aa24131a39
--- a/clang/test/Driver/ftime-trace-sections.py
+++ b/clang/test/Driver/ftime-trace-sections.py
@@ -19,9 +19,12 @@ def is_before(range1, range2):
 
 log_contents = json.loads(sys.stdin.read())
 events = log_contents["traceEvents"]
-codegens = [event for event in events if event["name"] == "CodeGen Function"]
+
+instants  = [event for event in events if event["name"] == "InstantiateFunction"]
+codegens  = [event for event in events if event["name"] == "CodeGen Function"]
+opts      = [event for event in events if event["name"] == "OptFunction"]
 frontends = [event for event in events if event["name"] == "Frontend"]
-backends = [event for event in events if event["name"] == "Backend"]
+backends  = [event for event in events if event["name"] == "Backend"]
 
 beginning_of_time = log_contents["beginningOfTime"] / 1000000
 seconds_since_epoch = time.time()
@@ -48,3 +51,11 @@ def is_before(range1, range2):
     ]
 ):
     sys.exit("Not all Frontend section are before all Backend sections!")
+
+# Check that entries for foo exist and are in a demangled form.
+if not any(e for e in instants if "foo<int>" in e["args"]["detail"]):
+    sys.exit("Missing Instantiate entry for foo!")
+if not any(e for e in codegens if "foo<int>" in e["args"]["detail"]):
+    sys.exit("Missing CodeGen entry for foo!")
+if not any(e for e in opts if "foo<int>" in e["args"]["detail"]):
+    sys.exit("Missing Optimize entry for foo!")
diff --git a/llvm/lib/IR/LegacyPassManager.cpp b/llvm/lib/IR/LegacyPassManager.cpp
index 953f21ce740590..9e3578954418ad 100644
--- a/llvm/lib/IR/LegacyPassManager.cpp
+++ b/llvm/lib/IR/LegacyPassManager.cpp
@@ -12,6 +12,7 @@
 
 #include "llvm/IR/LegacyPassManager.h"
 #include "llvm/ADT/MapVector.h"
+#include "llvm/Demangle/Demangle.h"
 #include "llvm/IR/DiagnosticInfo.h"
 #include "llvm/IR/IRPrintingPasses.h"
 #include "llvm/IR/LLVMContext.h"
@@ -1421,7 +1422,8 @@ bool FPPassManager::runOnFunction(Function &F) {
 
   // Store name outside of loop to avoid redundant calls.
   const StringRef Name = F.getName();
-  llvm::TimeTraceScope FunctionScope("OptFunction", Name);
+  llvm::TimeTraceScope FunctionScope(
+      "OptFunction", [&F]() { return demangle(F.getName().str()); });
 
   for (unsigned Index = 0; Index < getNumContainedPasses(); ++Index) {
     FunctionPass *FP = getContainedPass(Index);
diff --git a/llvm/lib/Passes/CMakeLists.txt b/llvm/lib/Passes/CMakeLists.txt
index 6425f4934b2103..b5224327d79216 100644
--- a/llvm/lib/Passes/CMakeLists.txt
+++ b/llvm/lib/Passes/CMakeLists.txt
@@ -21,6 +21,7 @@ add_llvm_component_library(LLVMPasses
   CodeGen
   Core
   Coroutines
+  Demangle
   HipStdPar
   IPO
   InstCombine
diff --git a/llvm/lib/Passes/StandardInstrumentations.cpp b/llvm/lib/Passes/StandardInstrumentations.cpp
index 697988b3fc7c0b..0faf865cd013c8 100644
--- a/llvm/lib/Passes/StandardInstrumentations.cpp
+++ b/llvm/lib/Passes/StandardInstrumentations.cpp
@@ -20,6 +20,7 @@
 #include "llvm/Analysis/LazyCallGraph.h"
 #include "llvm/Analysis/LoopInfo.h"
 #include "llvm/CodeGen/MachineFunction.h"
+#include "llvm/Demangle/Demangle.h"
 #include "llvm/IR/Constants.h"
 #include "llvm/IR/Function.h"
 #include "llvm/IR/Module.h"
@@ -215,12 +216,12 @@ void printIR(raw_ostream &OS, const Loop *L) {
   printLoop(const_cast<Loop &>(*L), OS);
 }
 
-std::string getIRName(Any IR) {
+std::string getIRName(Any IR, bool demangled = false) {
   if (unwrapIR<Module>(IR))
     return "[module]";
 
   if (const auto *F = unwrapIR<Function>(IR))
-    return F->getName().str();
+    return demangled ? demangle(F->getName()) : F->getName().str();
 
   if (const auto *C = unwrapIR<LazyCallGraph::SCC>(IR))
     return C->getName();
@@ -229,7 +230,7 @@ std::string getIRName(Any IR) {
     return L->getName().str();
 
   if (const auto *MF = unwrapIR<MachineFunction>(IR))
-    return MF->getName().str();
+    return demangled ? demangle(MF->getName()) : MF->getName().str();
 
   llvm_unreachable("Unknown wrapped IR type");
 }
@@ -1495,7 +1496,7 @@ void TimeProfilingPassesHandler::registerCallbacks(
 }
 
 void TimeProfilingPassesHandler::runBeforePass(StringRef PassID, Any IR) {
-  timeTraceProfilerBegin(PassID, getIRName(IR));
+  timeTraceProfilerBegin(PassID, getIRName(IR, true));
 }
 
 void TimeProfilingPassesHandler::runAfterPass() { timeTraceProfilerEnd(); }

[Trass3r]

Thank you @jamieschmeiser, how to proceed? Should I rebase to solve the conflict? Should I apply the clang-fornat diff (which makes things less readable IMHO)?

[jamieschmeiser]

Yes, the way to proceed is to rebase and resolve the conflicts. As far as the formatting changes, I think you should go with what the formatter wants. Everyone has different opinions about things like spacing, line length, etc and will never agree. The formatter keeps things consistent, which I think everyone will agree is good.

[Trass3r]

Ok done

[jamieschmeiser]

Thanks, I looked over things and they still look good.

[jamieschmeiser]

You may want to look at #90756

[Trass3r]

I haven't seen a Loop entry in a trace file yet.
Do we want to change it anyway, @jamieschmeiser?

[Trass3r]

@jamieschmeiser ping

[jamieschmeiser]

@Trass3r, sorry, I didn't realize that you were waiting on me... I had already approved this so you can go ahead and merge it. I was just pointing you at possibly related work that might interest you. Even if you decide to expand this work, I would suggest delivering this as is and doing that as a separate piece.

[jamieschmeiser]

To directly answer your question: No, deliver this. If you find loop entries in the future, then consider expanding it. Also, the link to that here may help others should they decide to expand this work.

[Trass3r]

Ok thanks, I don't have commit rights, could you merge it please? :)

[rnk]

Are we sure we want this behavior? Demangling is really expensive. A user noticed a significant (10%) compile time regression from this change. We could skip the demangling and do it offline. It's also worth pointing out that we have to redo this work every time we optimize the same function over and over. There is a fair amount of room for improvement in efficiency here.

[jamieschmeiser]

@rnk It is just a convenience to make things easier to read and should be removed if it is causing compile time issues. I just happened to see this comment now but will be unavailable for about 2 weeks. I will take care of it when I return (I'm not ignoring this...) If you wish to pull it in the mean-time, please go ahead. Sorry for any inconvenience.

[rnk]

I think I'll leave this change in and file an issue about it. A 10% compile time regression with -ftime-trace isn't great, but it doesn't feel revert-worthy.