1 //===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===// 2 // 3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions. 4 // See https://llvm.org/LICENSE.txt for license information. 5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception 6 // 7 //===----------------------------------------------------------------------===// 8 // 9 // This file implements hierarchical time profiler. 10 // 11 //===----------------------------------------------------------------------===// 12 13 #include "llvm/Support/TimeProfiler.h" 14 #include "llvm/ADT/STLExtras.h" 15 #include "llvm/ADT/StringMap.h" 16 #include "llvm/Support/CommandLine.h" 17 #include "llvm/Support/JSON.h" 18 #include "llvm/Support/Path.h" 19 #include "llvm/Support/Process.h" 20 #include "llvm/Support/Threading.h" 21 #include <algorithm> 22 #include <cassert> 23 #include <chrono> 24 #include <mutex> 25 #include <string> 26 #include <vector> 27 28 using namespace std::chrono; 29 using namespace llvm; 30 31 static std::mutex Mu; 32 // List of all instances 33 static ManagedStatic<std::vector<TimeTraceProfiler *>> 34 ThreadTimeTraceProfilerInstances; // GUARDED_BY(Mu) 35 // Per Thread instance 36 static LLVM_THREAD_LOCAL TimeTraceProfiler *TimeTraceProfilerInstance = nullptr; 37 38 TimeTraceProfiler *llvm::getTimeTraceProfilerInstance() { 39 return TimeTraceProfilerInstance; 40 } 41 42 typedef duration<steady_clock::rep, steady_clock::period> DurationType; 43 typedef time_point<steady_clock> TimePointType; 44 typedef std::pair<size_t, DurationType> CountAndDurationType; 45 typedef std::pair<std::string, CountAndDurationType> 46 NameAndCountAndDurationType; 47 48 namespace { 49 struct Entry { 50 const TimePointType Start; 51 TimePointType End; 52 const std::string Name; 53 const std::string Detail; 54 55 Entry(TimePointType &&S, TimePointType &&E, std::string &&N, std::string &&Dt) 56 : Start(std::move(S)), End(std::move(E)), Name(std::move(N)), 57 Detail(std::move(Dt)) {} 58 59 // Calculate timings for FlameGraph. Cast time points to microsecond precision 60 // rather than casting duration. This avoid truncation issues causing inner 61 // scopes overruning outer scopes. 62 steady_clock::rep getFlameGraphStartUs(TimePointType StartTime) const { 63 return (time_point_cast<microseconds>(Start) - 64 time_point_cast<microseconds>(StartTime)) 65 .count(); 66 } 67 68 steady_clock::rep getFlameGraphDurUs() const { 69 return (time_point_cast<microseconds>(End) - 70 time_point_cast<microseconds>(Start)) 71 .count(); 72 } 73 }; 74 } // namespace 75 76 struct llvm::TimeTraceProfiler { 77 TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "") 78 : BeginningOfTime(system_clock::now()), StartTime(steady_clock::now()), 79 ProcName(ProcName), Pid(sys::Process::getProcessId()), 80 Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity) { 81 llvm::get_thread_name(ThreadName); 82 } 83 84 void begin(std::string Name, llvm::function_ref<std::string()> Detail) { 85 Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name), 86 Detail()); 87 } 88 89 void end() { 90 assert(!Stack.empty() && "Must call begin() first"); 91 Entry &E = Stack.back(); 92 E.End = steady_clock::now(); 93 94 // Check that end times monotonically increase. 95 assert((Entries.empty() || 96 (E.getFlameGraphStartUs(StartTime) + E.getFlameGraphDurUs() >= 97 Entries.back().getFlameGraphStartUs(StartTime) + 98 Entries.back().getFlameGraphDurUs())) && 99 "TimeProfiler scope ended earlier than previous scope"); 100 101 // Calculate duration at full precision for overall counts. 102 DurationType Duration = E.End - E.Start; 103 104 // Only include sections longer or equal to TimeTraceGranularity msec. 105 if (duration_cast<microseconds>(Duration).count() >= TimeTraceGranularity) 106 Entries.emplace_back(E); 107 108 // Track total time taken by each "name", but only the topmost levels of 109 // them; e.g. if there's a template instantiation that instantiates other 110 // templates from within, we only want to add the topmost one. "topmost" 111 // happens to be the ones that don't have any currently open entries above 112 // itself. 113 if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) { 114 return Val.Name == E.Name; 115 }) == Stack.rend()) { 116 auto &CountAndTotal = CountAndTotalPerName[E.Name]; 117 CountAndTotal.first++; 118 CountAndTotal.second += Duration; 119 } 120 121 Stack.pop_back(); 122 } 123 124 // Write events from this TimeTraceProfilerInstance and 125 // ThreadTimeTraceProfilerInstances. 126 void write(raw_pwrite_stream &OS) { 127 // Acquire Mutex as reading ThreadTimeTraceProfilerInstances. 128 std::lock_guard<std::mutex> Lock(Mu); 129 assert(Stack.empty() && 130 "All profiler sections should be ended when calling write"); 131 assert(llvm::all_of(*ThreadTimeTraceProfilerInstances, 132 [](const auto &TTP) { return TTP->Stack.empty(); }) && 133 "All profiler sections should be ended when calling write"); 134 135 json::OStream J(OS); 136 J.objectBegin(); 137 J.attributeBegin("traceEvents"); 138 J.arrayBegin(); 139 140 // Emit all events for the main flame graph. 141 auto writeEvent = [&](const auto &E, uint64_t Tid) { 142 auto StartUs = E.getFlameGraphStartUs(StartTime); 143 auto DurUs = E.getFlameGraphDurUs(); 144 145 J.object([&] { 146 J.attribute("pid", Pid); 147 J.attribute("tid", int64_t(Tid)); 148 J.attribute("ph", "X"); 149 J.attribute("ts", StartUs); 150 J.attribute("dur", DurUs); 151 J.attribute("name", E.Name); 152 if (!E.Detail.empty()) { 153 J.attributeObject("args", [&] { J.attribute("detail", E.Detail); }); 154 } 155 }); 156 }; 157 for (const Entry &E : Entries) 158 writeEvent(E, this->Tid); 159 for (const TimeTraceProfiler *TTP : *ThreadTimeTraceProfilerInstances) 160 for (const Entry &E : TTP->Entries) 161 writeEvent(E, TTP->Tid); 162 163 // Emit totals by section name as additional "thread" events, sorted from 164 // longest one. 165 // Find highest used thread id. 166 uint64_t MaxTid = this->Tid; 167 for (const TimeTraceProfiler *TTP : *ThreadTimeTraceProfilerInstances) 168 MaxTid = std::max(MaxTid, TTP->Tid); 169 170 // Combine all CountAndTotalPerName from threads into one. 171 StringMap<CountAndDurationType> AllCountAndTotalPerName; 172 auto combineStat = [&](const auto &Stat) { 173 StringRef Key = Stat.getKey(); 174 auto Value = Stat.getValue(); 175 auto &CountAndTotal = AllCountAndTotalPerName[Key]; 176 CountAndTotal.first += Value.first; 177 CountAndTotal.second += Value.second; 178 }; 179 for (const auto &Stat : CountAndTotalPerName) 180 combineStat(Stat); 181 for (const TimeTraceProfiler *TTP : *ThreadTimeTraceProfilerInstances) 182 for (const auto &Stat : TTP->CountAndTotalPerName) 183 combineStat(Stat); 184 185 std::vector<NameAndCountAndDurationType> SortedTotals; 186 SortedTotals.reserve(AllCountAndTotalPerName.size()); 187 for (const auto &Total : AllCountAndTotalPerName) 188 SortedTotals.emplace_back(std::string(Total.getKey()), Total.getValue()); 189 190 llvm::sort(SortedTotals, [](const NameAndCountAndDurationType &A, 191 const NameAndCountAndDurationType &B) { 192 return A.second.second > B.second.second; 193 }); 194 195 // Report totals on separate threads of tracing file. 196 uint64_t TotalTid = MaxTid + 1; 197 for (const NameAndCountAndDurationType &Total : SortedTotals) { 198 auto DurUs = duration_cast<microseconds>(Total.second.second).count(); 199 auto Count = AllCountAndTotalPerName[Total.first].first; 200 201 J.object([&] { 202 J.attribute("pid", Pid); 203 J.attribute("tid", int64_t(TotalTid)); 204 J.attribute("ph", "X"); 205 J.attribute("ts", 0); 206 J.attribute("dur", DurUs); 207 J.attribute("name", "Total " + Total.first); 208 J.attributeObject("args", [&] { 209 J.attribute("count", int64_t(Count)); 210 J.attribute("avg ms", int64_t(DurUs / Count / 1000)); 211 }); 212 }); 213 214 ++TotalTid; 215 } 216 217 auto writeMetadataEvent = [&](const char *Name, uint64_t Tid, 218 StringRef arg) { 219 J.object([&] { 220 J.attribute("cat", ""); 221 J.attribute("pid", Pid); 222 J.attribute("tid", int64_t(Tid)); 223 J.attribute("ts", 0); 224 J.attribute("ph", "M"); 225 J.attribute("name", Name); 226 J.attributeObject("args", [&] { J.attribute("name", arg); }); 227 }); 228 }; 229 230 writeMetadataEvent("process_name", Tid, ProcName); 231 writeMetadataEvent("thread_name", Tid, ThreadName); 232 for (const TimeTraceProfiler *TTP : *ThreadTimeTraceProfilerInstances) 233 writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName); 234 235 J.arrayEnd(); 236 J.attributeEnd(); 237 238 // Emit the absolute time when this TimeProfiler started. 239 // This can be used to combine the profiling data from 240 // multiple processes and preserve actual time intervals. 241 J.attribute("beginningOfTime", 242 time_point_cast<microseconds>(BeginningOfTime) 243 .time_since_epoch() 244 .count()); 245 246 J.objectEnd(); 247 } 248 249 SmallVector<Entry, 16> Stack; 250 SmallVector<Entry, 128> Entries; 251 StringMap<CountAndDurationType> CountAndTotalPerName; 252 const time_point<system_clock> BeginningOfTime; 253 const TimePointType StartTime; 254 const std::string ProcName; 255 const sys::Process::Pid Pid; 256 SmallString<0> ThreadName; 257 const uint64_t Tid; 258 259 // Minimum time granularity (in microseconds) 260 const unsigned TimeTraceGranularity; 261 }; 262 263 void llvm::timeTraceProfilerInitialize(unsigned TimeTraceGranularity, 264 StringRef ProcName) { 265 assert(TimeTraceProfilerInstance == nullptr && 266 "Profiler should not be initialized"); 267 TimeTraceProfilerInstance = new TimeTraceProfiler( 268 TimeTraceGranularity, llvm::sys::path::filename(ProcName)); 269 } 270 271 // Removes all TimeTraceProfilerInstances. 272 // Called from main thread. 273 void llvm::timeTraceProfilerCleanup() { 274 delete TimeTraceProfilerInstance; 275 std::lock_guard<std::mutex> Lock(Mu); 276 for (auto TTP : *ThreadTimeTraceProfilerInstances) 277 delete TTP; 278 ThreadTimeTraceProfilerInstances->clear(); 279 } 280 281 // Finish TimeTraceProfilerInstance on a worker thread. 282 // This doesn't remove the instance, just moves the pointer to global vector. 283 void llvm::timeTraceProfilerFinishThread() { 284 std::lock_guard<std::mutex> Lock(Mu); 285 ThreadTimeTraceProfilerInstances->push_back(TimeTraceProfilerInstance); 286 TimeTraceProfilerInstance = nullptr; 287 } 288 289 void llvm::timeTraceProfilerWrite(raw_pwrite_stream &OS) { 290 assert(TimeTraceProfilerInstance != nullptr && 291 "Profiler object can't be null"); 292 TimeTraceProfilerInstance->write(OS); 293 } 294 295 Error llvm::timeTraceProfilerWrite(StringRef PreferredFileName, 296 StringRef FallbackFileName) { 297 assert(TimeTraceProfilerInstance != nullptr && 298 "Profiler object can't be null"); 299 300 std::string Path = PreferredFileName.str(); 301 if (Path.empty()) { 302 Path = FallbackFileName == "-" ? "out" : FallbackFileName.str(); 303 Path += ".time-trace"; 304 } 305 306 std::error_code EC; 307 raw_fd_ostream OS(Path, EC, sys::fs::OF_TextWithCRLF); 308 if (EC) 309 return createStringError(EC, "Could not open " + Path); 310 311 timeTraceProfilerWrite(OS); 312 return Error::success(); 313 } 314 315 void llvm::timeTraceProfilerBegin(StringRef Name, StringRef Detail) { 316 if (TimeTraceProfilerInstance != nullptr) 317 TimeTraceProfilerInstance->begin(std::string(Name), 318 [&]() { return std::string(Detail); }); 319 } 320 321 void llvm::timeTraceProfilerBegin(StringRef Name, 322 llvm::function_ref<std::string()> Detail) { 323 if (TimeTraceProfilerInstance != nullptr) 324 TimeTraceProfilerInstance->begin(std::string(Name), Detail); 325 } 326 327 void llvm::timeTraceProfilerEnd() { 328 if (TimeTraceProfilerInstance != nullptr) 329 TimeTraceProfilerInstance->end(); 330 } 331