| File: | build/llvm-toolchain-snapshot-15~++20220420111733+e13d2efed663/clang-tools-extra/clangd/support/Trace.cpp |
| Warning: | line 107, column 11 Value stored to 'OriginTime' is never read |
Press '?' to see keyboard shortcuts
Keyboard shortcuts:
| 1 | //===--- Trace.cpp - Performance tracing facilities -----------------------===// |
| 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 | #include "support/Trace.h" |
| 10 | #include "support/Context.h" |
| 11 | #include "llvm/ADT/DenseSet.h" |
| 12 | #include "llvm/ADT/Optional.h" |
| 13 | #include "llvm/ADT/ScopeExit.h" |
| 14 | #include "llvm/ADT/StringRef.h" |
| 15 | #include "llvm/Support/Chrono.h" |
| 16 | #include "llvm/Support/FormatVariadic.h" |
| 17 | #include "llvm/Support/Threading.h" |
| 18 | #include <atomic> |
| 19 | #include <chrono> |
| 20 | #include <memory> |
| 21 | #include <mutex> |
| 22 | |
| 23 | namespace clang { |
| 24 | namespace clangd { |
| 25 | namespace trace { |
| 26 | |
| 27 | namespace { |
| 28 | // The current implementation is naive: each thread writes to Out guarded by Mu. |
| 29 | // Perhaps we should replace this by something that disturbs performance less. |
| 30 | class JSONTracer : public EventTracer { |
| 31 | public: |
| 32 | JSONTracer(llvm::raw_ostream &OS, bool Pretty) |
| 33 | : Out(OS, Pretty ? 2 : 0), Start(std::chrono::system_clock::now()) { |
| 34 | // The displayTimeUnit must be ns to avoid low-precision overlap |
| 35 | // calculations! |
| 36 | Out.objectBegin(); |
| 37 | Out.attribute("displayTimeUnit", "ns"); |
| 38 | Out.attributeBegin("traceEvents"); |
| 39 | Out.arrayBegin(); |
| 40 | rawEvent("M", llvm::json::Object{ |
| 41 | {"name", "process_name"}, |
| 42 | {"args", llvm::json::Object{{"name", "clangd"}}}, |
| 43 | }); |
| 44 | } |
| 45 | |
| 46 | ~JSONTracer() { |
| 47 | Out.arrayEnd(); |
| 48 | Out.attributeEnd(); |
| 49 | Out.objectEnd(); |
| 50 | Out.flush(); |
| 51 | } |
| 52 | |
| 53 | // We stash a Span object in the context. It will record the start/end, |
| 54 | // and this also allows us to look up the parent Span's information. |
| 55 | Context beginSpan( |
| 56 | llvm::StringRef Name, |
| 57 | llvm::function_ref<void(llvm::json::Object *)> AttachDetails) override { |
| 58 | auto JS = std::make_unique<JSONSpan>(this, Name); |
| 59 | AttachDetails(&JS->Args); |
| 60 | return Context::current().derive(SpanKey, std::move(JS)); |
| 61 | } |
| 62 | |
| 63 | // Trace viewer requires each thread to properly stack events. |
| 64 | // So we need to mark only duration that the span was active on the thread. |
| 65 | // (Hopefully any off-thread activity will be connected by a flow event). |
| 66 | // Record the end time here, but don't write the event: Args aren't ready yet. |
| 67 | void endSpan() override { |
| 68 | Context::current().getExisting(SpanKey)->markEnded(); |
| 69 | } |
| 70 | |
| 71 | void instant(llvm::StringRef Name, llvm::json::Object &&Args) override { |
| 72 | captureThreadMetadata(); |
| 73 | jsonEvent("i", |
| 74 | llvm::json::Object{{"name", Name}, {"args", std::move(Args)}}); |
| 75 | } |
| 76 | |
| 77 | // Record an event on the current thread. ph, pid, tid, ts are set. |
| 78 | // Contents must be a list of the other JSON key/values. |
| 79 | void jsonEvent(llvm::StringRef Phase, llvm::json::Object &&Contents, |
| 80 | uint64_t TID = llvm::get_threadid(), double Timestamp = 0) { |
| 81 | Contents["ts"] = Timestamp ? Timestamp : timestamp(); |
| 82 | Contents["tid"] = int64_t(TID); |
| 83 | std::lock_guard<std::mutex> Lock(Mu); |
| 84 | rawEvent(Phase, Contents); |
| 85 | } |
| 86 | |
| 87 | private: |
| 88 | class JSONSpan { |
| 89 | public: |
| 90 | JSONSpan(JSONTracer *Tracer, llvm::StringRef Name) |
| 91 | : StartTime(Tracer->timestamp()), EndTime(0), Name(Name), |
| 92 | TID(llvm::get_threadid()), Tracer(Tracer) { |
| 93 | // ~JSONSpan() may run in a different thread, so we need to capture now. |
| 94 | Tracer->captureThreadMetadata(); |
| 95 | |
| 96 | // We don't record begin events here (and end events in the destructor) |
| 97 | // because B/E pairs have to appear in the right order, which is awkward. |
| 98 | // Instead we send the complete (X) event in the destructor. |
| 99 | |
| 100 | // If our parent was on a different thread, add an arrow to this span. |
| 101 | auto *Parent = Context::current().get(SpanKey); |
| 102 | if (Parent && *Parent && (*Parent)->TID != TID) { |
| 103 | // If the parent span ended already, then show this as "following" it. |
| 104 | // Otherwise show us as "parallel". |
| 105 | double OriginTime = (*Parent)->EndTime; |
| 106 | if (!OriginTime) |
| 107 | OriginTime = (*Parent)->StartTime; |
Value stored to 'OriginTime' is never read | |
| 108 | |
| 109 | auto FlowID = nextID(); |
| 110 | Tracer->jsonEvent( |
| 111 | "s", |
| 112 | llvm::json::Object{{"id", FlowID}, |
| 113 | {"name", "Context crosses threads"}, |
| 114 | {"cat", "mock_cat"}}, |
| 115 | (*Parent)->TID, (*Parent)->StartTime); |
| 116 | Tracer->jsonEvent( |
| 117 | "f", |
| 118 | llvm::json::Object{{"id", FlowID}, |
| 119 | {"bp", "e"}, |
| 120 | {"name", "Context crosses threads"}, |
| 121 | {"cat", "mock_cat"}}, |
| 122 | TID); |
| 123 | } |
| 124 | } |
| 125 | |
| 126 | ~JSONSpan() { |
| 127 | // Finally, record the event (ending at EndTime, not timestamp())! |
| 128 | Tracer->jsonEvent("X", |
| 129 | llvm::json::Object{{"name", std::move(Name)}, |
| 130 | {"args", std::move(Args)}, |
| 131 | {"dur", EndTime - StartTime}}, |
| 132 | TID, StartTime); |
| 133 | } |
| 134 | |
| 135 | // May be called by any thread. |
| 136 | void markEnded() { EndTime = Tracer->timestamp(); } |
| 137 | |
| 138 | llvm::json::Object Args; |
| 139 | |
| 140 | private: |
| 141 | static int64_t nextID() { |
| 142 | static std::atomic<int64_t> Next = {0}; |
| 143 | return Next++; |
| 144 | } |
| 145 | |
| 146 | double StartTime; |
| 147 | std::atomic<double> EndTime; // Filled in by markEnded(). |
| 148 | std::string Name; |
| 149 | uint64_t TID; |
| 150 | JSONTracer *Tracer; |
| 151 | }; |
| 152 | static Key<std::unique_ptr<JSONSpan>> SpanKey; |
| 153 | |
| 154 | // Record an event. ph and pid are set. |
| 155 | // Contents must be a list of the other JSON key/values. |
| 156 | void rawEvent(llvm::StringRef Phase, |
| 157 | const llvm::json::Object &Event) /*REQUIRES(Mu)*/ { |
| 158 | // PID 0 represents the clangd process. |
| 159 | Out.object([&] { |
| 160 | Out.attribute("pid", 0); |
| 161 | Out.attribute("ph", Phase); |
| 162 | for (const auto &KV : Event) |
| 163 | Out.attribute(KV.first, KV.second); |
| 164 | }); |
| 165 | } |
| 166 | |
| 167 | // If we haven't already, emit metadata describing this thread. |
| 168 | void captureThreadMetadata() { |
| 169 | uint64_t TID = llvm::get_threadid(); |
| 170 | std::lock_guard<std::mutex> Lock(Mu); |
| 171 | if (ThreadsWithMD.insert(TID).second) { |
| 172 | llvm::SmallString<32> Name; |
| 173 | llvm::get_thread_name(Name); |
| 174 | if (!Name.empty()) { |
| 175 | rawEvent("M", llvm::json::Object{ |
| 176 | {"tid", int64_t(TID)}, |
| 177 | {"name", "thread_name"}, |
| 178 | {"args", llvm::json::Object{{"name", Name}}}, |
| 179 | }); |
| 180 | } |
| 181 | } |
| 182 | } |
| 183 | |
| 184 | double timestamp() { |
| 185 | using namespace std::chrono; |
| 186 | return duration<double, std::micro>(system_clock::now() - Start).count(); |
| 187 | } |
| 188 | |
| 189 | std::mutex Mu; |
| 190 | llvm::json::OStream Out /*GUARDED_BY(Mu)*/; |
| 191 | llvm::DenseSet<uint64_t> ThreadsWithMD /*GUARDED_BY(Mu)*/; |
| 192 | const llvm::sys::TimePoint<> Start; |
| 193 | }; |
| 194 | |
| 195 | // We emit CSV as specified in RFC 4180: https://www.ietf.org/rfc/rfc4180.txt. |
| 196 | // \r\n line endings are used, cells with \r\n," are quoted, quotes are doubled. |
| 197 | class CSVMetricTracer : public EventTracer { |
| 198 | public: |
| 199 | CSVMetricTracer(llvm::raw_ostream &Out) : Out(Out) { |
| 200 | Start = std::chrono::steady_clock::now(); |
| 201 | |
| 202 | Out.SetUnbuffered(); // We write each line atomically. |
| 203 | Out << "Kind,Metric,Label,Value,Timestamp\r\n"; |
| 204 | } |
| 205 | |
| 206 | void record(const Metric &Metric, double Value, |
| 207 | llvm::StringRef Label) override { |
| 208 | assert(!needsQuote(Metric.Name))(static_cast <bool> (!needsQuote(Metric.Name)) ? void ( 0) : __assert_fail ("!needsQuote(Metric.Name)", "clang-tools-extra/clangd/support/Trace.cpp" , 208, __extension__ __PRETTY_FUNCTION__)); |
| 209 | std::string QuotedLabel; |
| 210 | if (needsQuote(Label)) |
| 211 | Label = QuotedLabel = quote(Label); |
| 212 | uint64_t Micros = std::chrono::duration_cast<std::chrono::microseconds>( |
| 213 | std::chrono::steady_clock::now() - Start) |
| 214 | .count(); |
| 215 | std::lock_guard<std::mutex> Lock(Mu); |
| 216 | Out << llvm::formatv("{0},{1},{2},{3:e},{4}.{5:6}\r\n", |
| 217 | typeName(Metric.Type), Metric.Name, Label, Value, |
| 218 | Micros / 1000000, Micros % 1000000); |
| 219 | } |
| 220 | |
| 221 | private: |
| 222 | llvm::StringRef typeName(Metric::MetricType T) { |
| 223 | switch (T) { |
| 224 | case Metric::Value: |
| 225 | return "v"; |
| 226 | case Metric::Counter: |
| 227 | return "c"; |
| 228 | case Metric::Distribution: |
| 229 | return "d"; |
| 230 | } |
| 231 | llvm_unreachable("Unknown Metric::MetricType enum")::llvm::llvm_unreachable_internal("Unknown Metric::MetricType enum" , "clang-tools-extra/clangd/support/Trace.cpp", 231); |
| 232 | } |
| 233 | |
| 234 | static bool needsQuote(llvm::StringRef Text) { |
| 235 | // https://www.ietf.org/rfc/rfc4180.txt section 2.6 |
| 236 | return Text.find_first_of(",\"\r\n") != llvm::StringRef::npos; |
| 237 | } |
| 238 | |
| 239 | std::string quote(llvm::StringRef Text) { |
| 240 | std::string Result = "\""; |
| 241 | for (char C : Text) { |
| 242 | Result.push_back(C); |
| 243 | if (C == '"') |
| 244 | Result.push_back('"'); |
| 245 | } |
| 246 | Result.push_back('"'); |
| 247 | return Result; |
| 248 | } |
| 249 | |
| 250 | private: |
| 251 | std::mutex Mu; |
| 252 | llvm::raw_ostream &Out /*GUARDED_BY(Mu)*/; |
| 253 | std::chrono::steady_clock::time_point Start; |
| 254 | }; |
| 255 | |
| 256 | Key<std::unique_ptr<JSONTracer::JSONSpan>> JSONTracer::SpanKey; |
| 257 | |
| 258 | EventTracer *T = nullptr; |
| 259 | } // namespace |
| 260 | |
| 261 | Session::Session(EventTracer &Tracer) { |
| 262 | assert(!T && "Resetting global tracer is not allowed.")(static_cast <bool> (!T && "Resetting global tracer is not allowed." ) ? void (0) : __assert_fail ("!T && \"Resetting global tracer is not allowed.\"" , "clang-tools-extra/clangd/support/Trace.cpp", 262, __extension__ __PRETTY_FUNCTION__)); |
| 263 | T = &Tracer; |
| 264 | } |
| 265 | |
| 266 | Session::~Session() { T = nullptr; } |
| 267 | |
| 268 | std::unique_ptr<EventTracer> createJSONTracer(llvm::raw_ostream &OS, |
| 269 | bool Pretty) { |
| 270 | return std::make_unique<JSONTracer>(OS, Pretty); |
| 271 | } |
| 272 | |
| 273 | std::unique_ptr<EventTracer> createCSVMetricTracer(llvm::raw_ostream &OS) { |
| 274 | return std::make_unique<CSVMetricTracer>(OS); |
| 275 | } |
| 276 | |
| 277 | void log(const llvm::Twine &Message) { |
| 278 | if (!T) |
| 279 | return; |
| 280 | T->instant("Log", llvm::json::Object{{"Message", Message.str()}}); |
| 281 | } |
| 282 | |
| 283 | bool enabled() { return T != nullptr; } |
| 284 | |
| 285 | // The JSON object is event args (owned by context), if the tracer wants them. |
| 286 | static std::pair<Context, llvm::json::Object *> |
| 287 | makeSpanContext(llvm::Twine Name, const Metric &LatencyMetric) { |
| 288 | if (!T) |
| 289 | return std::make_pair(Context::current().clone(), nullptr); |
| 290 | llvm::Optional<WithContextValue> WithLatency; |
| 291 | using Clock = std::chrono::high_resolution_clock; |
| 292 | WithLatency.emplace(llvm::make_scope_exit( |
| 293 | [StartTime = Clock::now(), Name = Name.str(), &LatencyMetric] { |
| 294 | LatencyMetric.record( |
| 295 | std::chrono::duration_cast<std::chrono::milliseconds>(Clock::now() - |
| 296 | StartTime) |
| 297 | .count(), |
| 298 | Name); |
| 299 | })); |
| 300 | llvm::json::Object *Args = nullptr; |
| 301 | Context Ctx = T->beginSpan( |
| 302 | Name.isSingleStringRef() ? Name.getSingleStringRef() |
| 303 | : llvm::StringRef(Name.str()), |
| 304 | [&](llvm::json::Object *A) { |
| 305 | assert(A && A->empty() && "Invalid AttachDetails() placeholder!")(static_cast <bool> (A && A->empty() && "Invalid AttachDetails() placeholder!") ? void (0) : __assert_fail ("A && A->empty() && \"Invalid AttachDetails() placeholder!\"" , "clang-tools-extra/clangd/support/Trace.cpp", 305, __extension__ __PRETTY_FUNCTION__)); |
| 306 | Args = A; |
| 307 | }); |
| 308 | return std::make_pair(std::move(Ctx), Args); |
| 309 | } |
| 310 | |
| 311 | // Fallback metric that measures latencies for spans without an explicit latency |
| 312 | // metric. Labels are span names. |
| 313 | constexpr Metric SpanLatency("span_latency", Metric::Distribution, "span_name"); |
| 314 | |
| 315 | // Span keeps a non-owning pointer to the args, which is how users access them. |
| 316 | // The args are owned by the context though. They stick around until the |
| 317 | // beginSpan() context is destroyed, when the tracing engine will consume them. |
| 318 | Span::Span(llvm::Twine Name) : Span(Name, SpanLatency) {} |
| 319 | Span::Span(llvm::Twine Name, const Metric &LatencyMetric) |
| 320 | : Span(makeSpanContext(Name, LatencyMetric)) {} |
| 321 | Span::Span(std::pair<Context, llvm::json::Object *> Pair) |
| 322 | : Args(Pair.second), RestoreCtx(std::move(Pair.first)) {} |
| 323 | |
| 324 | Span::~Span() { |
| 325 | if (T) |
| 326 | T->endSpan(); |
| 327 | } |
| 328 | |
| 329 | void Metric::record(double Value, llvm::StringRef Label) const { |
| 330 | if (!T) |
| 331 | return; |
| 332 | assert((LabelName.empty() == Label.empty()) &&(static_cast <bool> ((LabelName.empty() == Label.empty( )) && "recording a measurement with inconsistent labeling" ) ? void (0) : __assert_fail ("(LabelName.empty() == Label.empty()) && \"recording a measurement with inconsistent labeling\"" , "clang-tools-extra/clangd/support/Trace.cpp", 333, __extension__ __PRETTY_FUNCTION__)) |
| 333 | "recording a measurement with inconsistent labeling")(static_cast <bool> ((LabelName.empty() == Label.empty( )) && "recording a measurement with inconsistent labeling" ) ? void (0) : __assert_fail ("(LabelName.empty() == Label.empty()) && \"recording a measurement with inconsistent labeling\"" , "clang-tools-extra/clangd/support/Trace.cpp", 333, __extension__ __PRETTY_FUNCTION__)); |
| 334 | T->record(*this, Value, Label); |
| 335 | } |
| 336 | |
| 337 | Context EventTracer::beginSpan( |
| 338 | llvm::StringRef Name, |
| 339 | llvm::function_ref<void(llvm::json::Object *)> AttachDetails) { |
| 340 | return Context::current().clone(); |
| 341 | } |
| 342 | } // namespace trace |
| 343 | } // namespace clangd |
| 344 | } // namespace clang |