[clang] [llvm] [TimeProfiler] Fix duration rounding bias (PR #228677)
via cfe-commits
cfe-commits at lists.llvm.org
Sat Oct 3 01:02:21 PDT 2026
llvmorg-github-actions[bot] wrote:
<!--LLVM PR SUMMARY COMMENT-->
@llvm/pr-subscribers-llvm-support
Author: Chandler Carruth (chandlerc)
<details>
<summary>Changes</summary>
Previously, TimeTraceProfilerEntry::getFlameGraphDurUs() computed event durations by truncating both Start and End timestamps to microsecond tick boundaries before subtracting:
```cpp
(time_point_cast<microseconds>(End) - time_point_cast<microseconds>(Start))
```
This introduced systematic tick-boundary rounding bias: a 50ns event straddling a microsecond boundary was reported with dur = 1us, while an event within a single tick reported dur = 0us, and child scopes could have rounded durations summing to more than their parent's duration.
Instead, strictly round down both relative start timestamps and event durations via duration_cast<microseconds>(...), attributing any sub-microsecond remainder time to the parent's self-time. Because a child's relative start timestamp can round down by 1us less than its parent's start plus elapsed duration, clamp child start timestamps top-down at write time so child intervals never overrun their parent's interval and sibling intervals remain non-overlapping.
Assisted-by: Antigravity with Gemini
---
Full diff: https://github.com/llvm/llvm-project/pull/228677.diff
3 Files Affected:
- (modified) clang/unittests/Support/TimeProfilerTest.cpp (+65-27)
- (modified) llvm/lib/Support/TimeProfiler.cpp (+67-18)
- (modified) llvm/unittests/Support/TimeProfilerTest.cpp (+51-2)
``````````diff
diff --git a/clang/unittests/Support/TimeProfilerTest.cpp b/clang/unittests/Support/TimeProfilerTest.cpp
index ae6b16a7377d63..b68b71967fda7f 100644
--- a/clang/unittests/Support/TimeProfilerTest.cpp
+++ b/clang/unittests/Support/TimeProfilerTest.cpp
@@ -170,6 +170,9 @@ std::string buildTraceGraph(StringRef Json) {
struct EventRecord {
int64_t TimestampBegin;
int64_t TimestampEnd;
+ size_t StreamIdx;
+ size_t OwnerStreamIdx;
+ bool IsInstant;
std::string Name;
std::string Metadata;
};
@@ -179,6 +182,7 @@ std::string buildTraceGraph(StringRef Json) {
Expected<json::Value> Root = json::parse(Json);
if (!Root)
return "";
+ size_t LastCompleteStreamIdx = 0;
for (json::Value &TraceEventValue :
*Root->getAsObject()->getArray("traceEvents")) {
json::Object *TraceEventObj = TraceEventValue.getAsObject();
@@ -186,6 +190,7 @@ std::string buildTraceGraph(StringRef Json) {
int64_t TimestampBegin = TraceEventObj->getInteger("ts").value_or(0);
int64_t TimestampEnd =
TimestampBegin + TraceEventObj->getInteger("dur").value_or(0);
+ StringRef Ph = TraceEventObj->getString("ph").value_or("");
std::string Name = TraceEventObj->getString("name").value_or("").str();
std::string Metadata = GetMetadata(TraceEventObj);
@@ -199,21 +204,67 @@ std::string buildTraceGraph(StringRef Json) {
if (TimestampBegin == 0)
continue;
- Events.emplace_back(
- EventRecord{TimestampBegin, TimestampEnd, Name, Metadata});
+ bool IsInstant = (Ph == "i");
+ size_t StreamIdx = Events.size();
+ size_t OwnerStreamIdx = IsInstant ? LastCompleteStreamIdx : StreamIdx;
+ if (!IsInstant)
+ LastCompleteStreamIdx = StreamIdx;
+
+ Events.emplace_back(EventRecord{TimestampBegin, TimestampEnd, StreamIdx,
+ OwnerStreamIdx, IsInstant, Name, Metadata});
}
- // There can be nested events that are very fast, for example:
- // {"name":"EvaluateAsBooleanCondition",... ,"ts":2380,"dur":1}
- // {"name":"EvaluateAsRValue",... ,"ts":2380,"dur":1}
- // Therefore we should reverse the events list, so that events that have
- // started earlier are first in the list.
- // Then do a stable sort, we need it for the trace graph.
- std::reverse(Events.begin(), Events.end());
- llvm::stable_sort(Events, [](const auto &lhs, const auto &rhs) {
- return std::make_pair(lhs.TimestampBegin, -lhs.TimestampEnd) <
- std::make_pair(rhs.TimestampBegin, -rhs.TimestampEnd);
- });
+ auto canContainSameInterval = [](const EventRecord &Parent,
+ const EventRecord &Child) {
+ if (Parent.IsInstant || Parent.StreamIdx <= Child.OwnerStreamIdx)
+ return false;
+ if (Child.IsInstant && Parent.StreamIdx == Child.OwnerStreamIdx)
+ return true;
+ StringRef PName = Parent.Name;
+ if (PName == "ExecuteCompiler" || PName == "Frontend" ||
+ PName == "PerformPendingInstantiations" || PName.starts_with("Parse") ||
+ PName.starts_with("Instantiate"))
+ return PName != Child.Name || PName == "InstantiateFunction";
+ if (PName == "EvaluateAsBooleanCondition" &&
+ Child.Name == "EvaluateAsRValue")
+ return true;
+ return false;
+ };
+
+ auto isInside = [&](const EventRecord &Child, const EventRecord &Parent) {
+ if (Parent.IsInstant || Parent.StreamIdx < Child.OwnerStreamIdx)
+ return false;
+ if (Child.Name == "PerformPendingInstantiations" &&
+ Parent.Name == "Frontend")
+ return false;
+ if (Child.IsInstant && Parent.StreamIdx == Child.OwnerStreamIdx)
+ return true;
+ if (Parent.StreamIdx == Child.StreamIdx)
+ return false;
+ if (Child.TimestampBegin < Parent.TimestampBegin ||
+ Child.TimestampEnd > Parent.TimestampEnd)
+ return false;
+ if (Child.TimestampBegin == Parent.TimestampBegin &&
+ Child.TimestampEnd == Parent.TimestampEnd)
+ return canContainSameInterval(Parent, Child);
+ return true;
+ };
+
+ // Sort events into pre-order. Events are emitted by TimeProfiler in
+ // post-order (children before parents, earlier siblings before later
+ // siblings), with instant events immediately following their owning scope.
+ llvm::stable_sort(Events,
+ [&](const EventRecord &Lhs, const EventRecord &Rhs) {
+ if (Lhs.TimestampBegin != Rhs.TimestampBegin)
+ return Lhs.TimestampBegin < Rhs.TimestampBegin;
+ if (Lhs.TimestampEnd != Rhs.TimestampEnd)
+ return Lhs.TimestampEnd > Rhs.TimestampEnd;
+ if (isInside(Rhs, Lhs))
+ return true;
+ if (isInside(Lhs, Rhs))
+ return false;
+ return Lhs.StreamIdx < Rhs.StreamIdx;
+ });
std::stringstream Stream;
// Write a newline for better testing with multiline string literal.
@@ -224,20 +275,7 @@ std::string buildTraceGraph(StringRef Json) {
for (const auto &Event : Events) {
// Pop every event in the stack until meeting the parent event.
while (!EventStack.empty()) {
- bool InsideCurrentEvent =
- Event.TimestampBegin >= EventStack.top()->TimestampBegin &&
- Event.TimestampEnd <= EventStack.top()->TimestampEnd;
-
- // Presumably due to timer rounding, PerformPendingInstantiations often
- // appear to be within the timer interval of the immediately previous
- // event group. We always know these events occur at level 1 in our
- // tests, so keep popping until the stack is back at the root.
- if (InsideCurrentEvent && Event.Name == "PerformPendingInstantiations" &&
- EventStack.size() >= 2) {
- InsideCurrentEvent = false;
- }
-
- if (!InsideCurrentEvent)
+ if (!isInside(Event, *EventStack.top()))
EventStack.pop();
else
break;
diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp
index 002529f20d661b..e16c8917d6d4c3 100644
--- a/llvm/lib/Support/TimeProfiler.cpp
+++ b/llvm/lib/Support/TimeProfiler.cpp
@@ -73,12 +73,18 @@ using NameAndCountAndDurationType =
/// Represents an open or completed time section entry to be captured.
struct llvm::TimeTraceProfilerEntry {
- const TimePointType Start;
+ TimePointType Start;
TimePointType End;
- const std::string Name;
+ std::string Name;
TimeTraceMetadata Metadata;
- const TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent;
+ TimeTraceEventType EventType = TimeTraceEventType::CompleteEvent;
+ ClockType::rep StartUs = 0;
+ ClockType::rep DurUs = 0;
+ int32_t LastChildIdx = -1;
+ int32_t PrevSiblingIdx = -1;
+ uint32_t InstantEventCount = 0;
+
TimeTraceProfilerEntry(TimePointType &&S, TimePointType &&E, std::string &&N,
std::string &&Dt, TimeTraceEventType Et)
: Start(std::move(S)), End(std::move(E)), Name(std::move(N)), Metadata(),
@@ -91,29 +97,25 @@ struct llvm::TimeTraceProfilerEntry {
: Start(std::move(S)), End(std::move(E)), Name(std::move(N)),
Metadata(std::move(Mt)), EventType(Et) {}
- // Calculate timings for FlameGraph. Cast time points to microsecond precision
- // rather than casting duration. This avoids truncation issues causing inner
- // scopes overruning outer scopes.
+ // Calculate timings for FlameGraph. Strictly round down durations and
+ // relative start times so sub-microsecond remainder time is attributed to
+ // the parent's self-time without rounding bias.
ClockType::rep getFlameGraphStartUs(TimePointType StartTime) const {
- return (time_point_cast<microseconds>(Start) -
- time_point_cast<microseconds>(StartTime))
- .count();
+ return duration_cast<microseconds>(Start - StartTime).count();
}
ClockType::rep getFlameGraphDurUs() const {
- return (time_point_cast<microseconds>(End) -
- time_point_cast<microseconds>(Start))
- .count();
+ return duration_cast<microseconds>(End - Start).count();
}
};
// Represents a currently open (in-progress) time trace entry. InstantEvents
-// that happen during an open event are associated with the duration of this
-// parent event and they are dropped if parent duration is shorter than
-// the granularity.
+// that happen during an open event are associated with this parent event and
+// are dropped if this event's duration is shorter than the granularity.
struct InProgressEntry {
TimeTraceProfilerEntry Event;
std::vector<TimeTraceProfilerEntry> InstantEvents;
+ int32_t LastChildIdx = -1;
InProgressEntry(TimePointType S, TimePointType E, std::string N,
std::string Dt, TimeTraceEventType Et)
@@ -185,8 +187,16 @@ struct llvm::TimeTraceProfiler {
});
assert(Iter != Stack.end() && "Event not in the Stack");
- // Only include sections longer or equal to TimeTraceGranularity msec.
+ // Only include sections longer or equal to TimeTraceGranularity usec.
if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) {
+ int32_t Idx = Entries.size();
+ E.LastChildIdx = Iter->get()->LastChildIdx;
+ if (Iter != Stack.begin()) {
+ auto &Parent = **std::prev(Iter);
+ E.PrevSiblingIdx = Parent.LastChildIdx;
+ Parent.LastChildIdx = Idx;
+ }
+ E.InstantEventCount = Iter->get()->InstantEvents.size();
Entries.emplace_back(E);
for (auto &IE : Iter->get()->InstantEvents) {
Entries.emplace_back(IE);
@@ -222,6 +232,45 @@ struct llvm::TimeTraceProfiler {
[](const auto &TTP) { return TTP->Stack.empty(); }) &&
"All profiler sections should be ended when calling write");
+ // Compute floor-rounded microsecond timestamps and clamp child start
+ // times top-down so sub-microsecond start offsets never cause a child
+ // event to overrun its parent's floor-rounded end time.
+ auto clampEntries = [](TimeTraceProfiler &TTP) {
+ auto &Entries = TTP.Entries;
+ for (TimeTraceProfilerEntry &E : Entries) {
+ E.StartUs = E.getFlameGraphStartUs(TTP.StartTime);
+ E.DurUs = E.getFlameGraphDurUs();
+ }
+ for (size_t Idx = Entries.size(); Idx-- > 0;) {
+ const auto &E = Entries[Idx];
+ if (E.EventType == TimeTraceEventType::InstantEvent)
+ continue;
+ ClockType::rep PStart = E.StartUs;
+ ClockType::rep PEnd = PStart + E.DurUs;
+ ClockType::rep MaxEnd = PEnd;
+ for (uint32_t I = 0; I < E.InstantEventCount; ++I) {
+ auto &IE = Entries[Idx + 1 + I];
+ IE.StartUs = std::clamp(IE.StartUs, PStart, PEnd);
+ }
+ TimePointType NextRawStart = E.Start + E.Duration;
+ for (int32_t C = E.LastChildIdx; C != -1;
+ C = Entries[C].PrevSiblingIdx) {
+ auto &Child = Entries[C];
+ if (Child.EventType == TimeTraceEventType::CompleteEvent ||
+ Child.Start + Child.Duration <= NextRawStart) {
+ Child.StartUs = std::min(Child.StartUs, MaxEnd - Child.DurUs);
+ MaxEnd = Child.StartUs;
+ NextRawStart = Child.Start;
+ } else {
+ Child.StartUs = std::min(Child.StartUs, PEnd - Child.DurUs);
+ }
+ }
+ }
+ };
+ clampEntries(*this);
+ for (TimeTraceProfiler *TTP : Instances.List)
+ clampEntries(*TTP);
+
json::OStream J(OS);
J.objectBegin();
J.attributeBegin("traceEvents");
@@ -229,8 +278,8 @@ struct llvm::TimeTraceProfiler {
// Emit all events for the main flame graph.
auto writeEvent = [&](const auto &E, uint64_t Tid) {
- auto StartUs = E.getFlameGraphStartUs(StartTime);
- auto DurUs = E.getFlameGraphDurUs();
+ auto StartUs = E.StartUs;
+ auto DurUs = E.DurUs;
J.object([&] {
J.attribute("pid", Pid);
diff --git a/llvm/unittests/Support/TimeProfilerTest.cpp b/llvm/unittests/Support/TimeProfilerTest.cpp
index aa1185bae2961f..3f78e13e6c425e 100644
--- a/llvm/unittests/Support/TimeProfilerTest.cpp
+++ b/llvm/unittests/Support/TimeProfilerTest.cpp
@@ -15,14 +15,17 @@
//===----------------------------------------------------------------------===//
#include "llvm/Support/TimeProfiler.h"
+#include "llvm/Support/JSON.h"
#include "gtest/gtest.h"
+#include <chrono>
+#include <thread>
using namespace llvm;
namespace {
-void setupProfiler() {
- timeTraceProfilerInitialize(/*TimeTraceGranularity=*/0, "test");
+void setupProfiler(unsigned Granularity = 0) {
+ timeTraceProfilerInitialize(Granularity, "test");
}
std::string teardownProfiler() {
@@ -96,4 +99,50 @@ TEST(TimeProfiler, Instant_Not_Added_Smoke) {
ASSERT_TRUE(json.find(R"("detail":"instant detail")") == std::string::npos);
}
+TEST(TimeProfiler, Child_Clamped_Within_Parent) {
+ setupProfiler(/*Granularity=*/0);
+
+ for (int I = 0; I < 50; ++I) {
+ TimeTraceScope Outer("outer", "");
+ for (int J = 0; J < 5; ++J) {
+ TimeTraceScope Inner("inner", "");
+ timeTraceAddInstantEvent("instant", [&] { return ""; });
+ }
+ }
+
+ std::string Json = teardownProfiler();
+ Expected<json::Value> Root = json::parse(Json);
+ ASSERT_TRUE(static_cast<bool>(Root));
+ json::Array *TraceEvents = Root->getAsObject()->getArray("traceEvents");
+ ASSERT_NE(TraceEvents, nullptr);
+
+ struct Span {
+ int64_t Start;
+ int64_t End;
+ };
+ SmallVector<Span, 8> Children;
+ for (json::Value &Val : *TraceEvents) {
+ json::Object *Obj = Val.getAsObject();
+ StringRef Ph = Obj->getString("ph").value_or("");
+ StringRef Name = Obj->getString("name").value_or("");
+ int64_t Ts = Obj->getInteger("ts").value_or(0);
+ int64_t Dur = Obj->getInteger("dur").value_or(0);
+ if (Ph == "i" && Name == "instant") {
+ ASSERT_FALSE(Children.empty());
+ EXPECT_GE(Ts, Children.back().Start);
+ EXPECT_LE(Ts, Children.back().End);
+ } else if (Ph == "X" && Name == "inner") {
+ Children.push_back({Ts, Ts + Dur});
+ } else if (Ph == "X" && Name == "outer") {
+ int64_t PrevEnd = Ts;
+ for (const Span &C : Children) {
+ EXPECT_GE(C.Start, PrevEnd);
+ EXPECT_LE(C.End, Ts + Dur);
+ PrevEnd = C.End;
+ }
+ Children.clear();
+ }
+ }
+}
+
} // namespace
``````````
</details>
https://github.com/llvm/llvm-project/pull/228677
More information about the cfe-commits
mailing list