https://github.com/chandlerc created https://github.com/llvm/llvm-project/pull/228677
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 >From e9c1d757acdbf623fc8125b574c1c59f90740854 Mon Sep 17 00:00:00 2001 From: Chandler Carruth <[email protected]> Date: Fri, 2 Oct 2026 09:16:50 +0000 Subject: [PATCH] [TimeProfiler] Fix duration rounding bias Previously, TimeTraceProfilerEntry::getFlameGraphDurUs() computed event durations by truncating both Start and End timestamps to microsecond tick boundaries before subtracting: (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 --- clang/unittests/Support/TimeProfilerTest.cpp | 92 ++++++++++++++------ llvm/lib/Support/TimeProfiler.cpp | 85 ++++++++++++++---- llvm/unittests/Support/TimeProfilerTest.cpp | 53 ++++++++++- 3 files changed, 183 insertions(+), 47 deletions(-) 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 _______________________________________________ cfe-commits mailing list [email protected] https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
