Fix a time-trace issue of incorrect header hierarchy when a header contains a template function for its last symbol.

[MaggieYi]

Summary

HandleEndOfFile is invoked when the lexer hits the end of the current file. This either returns the EOF token or pops a level off the include stack and
keeps going. If it keeps going, clang parses from one header to another header. This results in incorrect header hierarchy in the time trace.

This patch corrects this, as reported by #56554

Fixes: https://github.com/llvm/llvm-project/issues/56554

[MaggieYi]

A simple test to reproduce the issue:

% cat main.cpp
#include "1.h"
#include "2.h"
int foo();

% cat 1.h
template <typename T> auto Zero() -> T { return T{}; }

%cat 2.h
struct Bla {};

Compile the code with -ftime-trace-granularity=0 -ftime-trace to show the issue:

prospero-clang -ftime-trace-granularity=0 -ftime-trace main.cpp -c -o main.o

[MaggieYi]

Analysis the issue using the above simple example:

When clang parses the first line (#include "1.h") in the main.cpp, a time section entry is created and put on the top of the time-trace stack. Assuming this time section entry is named Source-1.h, which has its name Source and detail 1.h. Then, clang parses the template function Zero defined in the 1.h header file. Clang will create a TimeTraceScope variable in which its name is ParseTemplate and its detail is Zero. A new time section entry named ParseTemplate-Zero is created and put on the top of the time-trace stack. ParseTemplate-Zero has its name ParseTemplate and detail Zero. Now, the top element of the time-trace stack is ParseTemplate-Zero and Source-1.h is under ParseTemplate-Zero.

Please note: since ParseTemplate-Zero is TimeTraceScope type variable. It should be popped out from the time-trace stack once the destructor of TimeTraceScope is called.

Since the template Zero is the last symbol defined in the 1.h header, the LexEndOfFile is called, then LexedFileChanged is called. LexedFileChanged is invoked when the lexer hits the end of the current file. This either returns the EOF token or pops a level off the include stack and keeps going. In our case, it keeps going and notifies the client that we are in a new header file: 2.h. The function of timeTraceProfilerEnd is called to pop the top element out from the time-trace stack and calculate the corresponding compilation time. Source-1.h is expected to pop out from the time-trace stack. However, since ParseTemplate-Zero is still alive and is on the top of the time-trace stack. ParseTemplate-Zero is popped out from the time trace stack instead of Source-1.h, which is wrong. Until now, the top of the time-trace stack is Source-1.h.

After that, a time section entry named Source-2.h is created and put on the top of the time-trace stack. Now, the top element of the time-trace stack is Source-2.h, and then Source-1.h is under Source-2.h. This results in incorrect header hierarchy in the time trace: the 2.h shows up as an inclusion under 1.h.

Currently, two available time profiling APIs cannot deal with this special case. I have modified timeTraceProfilerEnd() to handle the header file specially.

[MaggieYi]

Gentle ping ...

[aras-p]

This is probably obsolete now that D148410 has landed.

clang/lib/Sema/Sema.cpp

case EnterFile: {
             Sema::PragmaAlignPackDiagnoseKind::NonDefaultStateAtInclude,
             IncludeLoc);
       }
       break;
     }
     case ExitFile:
       if (!IncludeStack.empty()) {
         if (llvm::timeTraceProfilerEnabled())
-          llvm::timeTraceProfilerEnd();
+          llvm::timeTraceProfilerEnd(true);
 
         S->DiagnoseNonDefaultPragmaAlignPack(
             Sema::PragmaAlignPackDiagnoseKind::ChangedStateAtExit,
             IncludeStack.pop_back_val());
       }
       break;
     default:
       break;

clang/test/Driver/Inputs/header5.h

+template <typename T> auto Zero() -> T { return T{}; }

clang/test/Driver/Inputs/header6.h

+struct Bla {};

clang/test/Driver/check-time-trace-header-hierarchy.cpp

+// RUN: %clangxx -S -I %S/Inputs -ftime-trace=- -ftime-trace-granularity=0 -o /dev/null %s \
+// RUN:    | %python %S/check-time-trace-header-hierarchy.py
+
+#include "header5.h"
+#include "header6.h"
+int foo();

clang/test/Driver/check-time-trace-header-hierarchy.py

+#!/usr/bin/env python
+
+import json, sys, time
+
+def is_inside(range1, range2):
+    a = range1["ts"]; b = a + range1["dur"]
+    c = range2["ts"]; d = c + range2["dur"]
+    return (c <= a <= d) and (c <= b <= d)
+
+def is_before(range1, range2):
+    b = range1["ts"] + range1["dur"]; c = range2["ts"]
+    return b <= c
+
+log_contents = json.loads(sys.stdin.read())
+events = log_contents["traceEvents"]
+
+count = 0;
+header5 = header6 = parsetemplate = parseclass = None
+for event in events:
+    if event["name"] == "Source" and "header5.h" in event["args"]["detail"]:
+        header5 = event
+        count += 1
+    elif event["name"] == "Source" and "header6.h" in event["args"]["detail"]:
+        header6 = event
+        count += 1
+    elif event["name"] == "ParseTemplate" and event["args"]["detail"] == "Zero":
+        parsetemplate = event
+        count += 1
+    elif event["name"] == "ParseClass" and event["args"]["detail"] == "Bla":
+        parseclass = event
+        count += 1
+    elif count == 4:
+        break
+
+beginning_of_time = log_contents["beginningOfTime"] / 1000000
+seconds_since_epoch = time.time()
+
+# Make sure that the 'beginningOfTime' is not later than now.
+if beginning_of_time > seconds_since_epoch:
+    sys.exit("'beginningOfTime' should represent the absolute time when the "
+             "process has started")
+
+if not is_inside(parsetemplate, header5):
+    sys.exit("ParseTemplate `Zero` is NOT inside header5!")
+
+if not is_inside(parseclass, header6):
+    sys.exit("ParseClass `Bla` is NOT inside header6!")
+
+if not is_before(header5, header6):
+    sys.exit("header5 is NOT before header6!")

llvm/include/llvm/Support/TimeProfiler.h

 /// Manually begin a time section, with the given \p Name and \p Detail.
 /// Profiler copies the string data, so the pointers can be given into
 /// temporaries. Time sections can be hierarchical; every Begin must have a
 /// matching End pair but they can nest.
 void timeTraceProfilerBegin(StringRef Name, StringRef Detail);
 void timeTraceProfilerBegin(StringRef Name,
                             llvm::function_ref<std::string()> Detail);
 
-/// Manually end the last time section.
-void timeTraceProfilerEnd();
+/// Manually end the last time section, with the given \p IsSource.
+/// Pass true to \p IsSource if the name of the last time section is
+/// "Source". By default, \p IsSource is false.
+void timeTraceProfilerEnd(bool IsSource = false);
 
 /// The TimeTraceScope is a helper class to call the begin and end functions
 /// of the time trace profiler.  When the object is constructed, it begins
 /// the section; and when it is destroyed, it stops it. If the time profiler
 /// is not initialized, the overhead is a single branch.
 struct TimeTraceScope {
 
   TimeTraceScope() = delete;

llvm/lib/Support/TimeProfiler.cpp

TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
     llvm::get_thread_name(ThreadName);
   }
 
   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
     Stack.emplace_back(ClockType::now(), TimePointType(), std::move(Name),
                        Detail());
   }
 
-  void end() {
+  void element_end() {
     assert(!Stack.empty() && "Must call begin() first");
     TimeTraceProfilerEntry &E = Stack.back();
     E.End = ClockType::now();
 
     // Check that end times monotonically increase.
     assert((Entries.empty() ||
             (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >=
              Entries.back().getFlameGraphStartUs(StartTime) +
if (llvm::none_of(llvm::drop_begin(llvm::reverse(Stack)),
       auto &CountAndTotal = CountAndTotalPerName[E.Name];
       CountAndTotal.first++;
       CountAndTotal.second += Duration;
     }
 
     Stack.pop_back();
   }
 
+  void end(bool IsSource = false) {
+    bool TopElementIsSource = Stack.back().Name == "Source";
+    // If time trace profiler is ended by exiting a file (IsSource=true), we
+    // expect the top of Stack is time section entry with name "Source".
+    // If IsSource is false, the last time section should not be "Source". In
+    // these two cases, only pop the top element of the Stack.
+    if ((IsSource && TopElementIsSource) ||
+        (!IsSource && !TopElementIsSource)) {
+      element_end();
+      return;
+    }
+
+    // If the last time section entry is "Source" but time trace profiler is not
+    // ended by exiting a file (IsSource=false), we don't need to do anything
+    // since the time section entry has been popped out when exiting the
+    // previous 'Source' time section entry.
+    if (!IsSource && TopElementIsSource)
+      return;
+
+    // If the last time section entry is not "Source" but time trace profiler is
+    // ended by exiting a file (IsSource=true), we will pop time sections from
+    // the top of Stack until the 'Source' time section.
+    while (Stack.back().Name != "Source")
+      element_end();
+    element_end();
+  }
+
   // Write events from this TimeTraceProfilerInstance and
   // ThreadTimeTraceProfilerInstances.
   void write(raw_pwrite_stream &OS) {
     // Acquire Mutex as reading ThreadTimeTraceProfilerInstances.
     auto &Instances = getTimeTraceProfilerInstances();
     std::lock_guard<std::mutex> Lock(Instances.Lock);
     assert(Stack.empty() &&
            "All profiler sections should be ended when calling write");

 }
 
 void llvm::timeTraceProfilerBegin(StringRef Name,
                                   llvm::function_ref<std::string()> Detail) {
   if (TimeTraceProfilerInstance != nullptr)
     TimeTraceProfilerInstance->begin(std::string(Name), Detail);
 }
 
-void llvm::timeTraceProfilerEnd() {
+void llvm::timeTraceProfilerEnd(bool IsSource) {
   if (TimeTraceProfilerInstance != nullptr)
-    TimeTraceProfilerInstance->end();
+    TimeTraceProfilerInstance->end(IsSource);
 }