Index: llvm/lib/Support/TimeProfiler.cpp =================================================================== --- llvm/lib/Support/TimeProfiler.cpp +++ llvm/lib/Support/TimeProfiler.cpp @@ -27,20 +27,35 @@ TimeTraceProfiler *TimeTraceProfilerInstance = nullptr; typedef duration DurationType; +typedef time_point TimePointType; typedef std::pair CountAndDurationType; typedef std::pair NameAndCountAndDurationType; struct Entry { - time_point Start; - DurationType Duration; + TimePointType Start; + TimePointType End; std::string Name; std::string Detail; - Entry(time_point &&S, DurationType &&D, std::string &&N, - std::string &&Dt) - : Start(std::move(S)), Duration(std::move(D)), Name(std::move(N)), + Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt) + : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), Detail(std::move(Dt)){}; + + // Calculate timings for FlameGraph. Cast time points to microsecond precision + // rather than casting duration. This avoid truncation issues causing inner + // scopes overruning outer scopes. + steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const { + return (time_point_cast(Start) - + time_point_cast(StartTime)) + .count(); + } + + steady_clock::rep getFlameGraphDurUs() const { + return (time_point_cast(End) - + time_point_cast(Start)) + .count(); + } }; struct TimeTraceProfiler { @@ -49,17 +64,27 @@ } void begin(std::string Name, llvm::function_ref Detail) { - Stack.emplace_back(steady_clock::now(), DurationType{}, std::move(Name), + Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name), Detail()); } void end() { assert(!Stack.empty() && "Must call begin() first"); auto &E = Stack.back(); - E.Duration = steady_clock::now() - E.Start; + E.End = steady_clock::now(); + + // Check that end times monotonically increase. + assert((Entries.empty() || + (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >= + Entries.back().getFlameGraphStartUs(StartTime) + + Entries.back().getFlameGraphDurUs())) && + "TimeProfiler scope ended earlier than previous scope"); + + // Calculate duration at full precision for overall counts. + DurationType Duration = E.End - E.Start; // Only include sections longer or equal to TimeTraceGranularity msec. - if (duration_cast(E.Duration).count() >= TimeTraceGranularity) + if (duration_cast(Duration).count() >= TimeTraceGranularity) Entries.emplace_back(E); // Track total time taken by each "name", but only the topmost levels of @@ -72,7 +97,7 @@ }) == Stack.rend()) { auto &CountAndTotal = CountAndTotalPerName[E.Name]; CountAndTotal.first++; - CountAndTotal.second += E.Duration; + CountAndTotal.second += Duration; } Stack.pop_back(); @@ -81,6 +106,7 @@ void Write(raw_pwrite_stream &OS) { assert(Stack.empty() && "All profiler sections should be ended when calling Write"); + json::OStream J(OS); J.objectBegin(); J.attributeBegin("traceEvents"); @@ -88,8 +114,8 @@ // Emit all events for the main flame graph. for (const auto &E : Entries) { - auto StartUs = duration_cast(E.Start - StartTime).count(); - auto DurUs = duration_cast(E.Duration).count(); + auto StartUs = E.getFlameGraphStartUs(StartTime); + auto DurUs = E.getFlameGraphDurUs(); J.object([&]{ J.attribute("pid", 1); @@ -154,7 +180,7 @@ SmallVector Stack; SmallVector Entries; StringMap CountAndTotalPerName; - time_point StartTime; + TimePointType StartTime; // Minimum time granularity (in microseconds) unsigned TimeTraceGranularity;