[clangd] Trace queue state for each TUScheduler action.

[sammccall]

Summary

The new trace event includes what's already in the queue when adding.
For tracers that follow contexts, the trace event will span the time that the action
spends in the queue.
For tracers that follow threads, the trace will be a tiny span on the enqueuing thread.

[kadircet]

clang-tools-extra/clangd/TUScheduler.cpp

511

TIL: queue doesn't allow iteration :shrug:

1054–1055

what if we just pushed the span here and kept it alive in the queue? it is move-able at the moment.

our tracing contract seem to be saying beginSpan/endSpan calls would always form a proper stack, i am not sure about its importance to the jsontracer, but I don't think rest of our tracers cares (and i think it would be nice for that trace to actually span the whole time in queue).

[sammccall]

clang-tools-extra/clangd/TUScheduler.cpp

1054–1055

what if we just pushed the span here and kept it alive in the queue?

Mechanically it's a little more complicated than that, but I get what you're saying - unfortunately it doesn't quite work.

it is move-able at the moment.

(in fact not: it has a WithContext member whose move operators are deleted)

our tracing contract seem to be saying beginSpan/endSpan calls would always form a proper stack

Yes - this is in fact documented as the *only* point of endSpan - it marks the strictly-stacking lifetimes of stack-allocated trace::Spans objects themselves. Tracers that don't need this strict stacking are supposed to watch for the destruction of the context frames created by beginSpan instead. This extends the span over context-propagation, at the cost of no longer strictly stacking.

i am not sure about its importance to the jsontracer

The chrome trace viewer (which jsontracer targets) really does require strict stacking. I'm not 100% sure, but I think the behavior was just to silently discard events that don't nest properly.

I don't think rest of our tracers cares (and i think it would be nice for that trace to actually span the whole time in queue).

Right, so our private out-of-tree tracer follows request/context timelines rather than thread ones, and doesn't require strict nesting. It completely ignores endSpan(), and ends events when the context gets destroyed instead. That's why we bundle up the QueueCtx into the request and then destroy it as soon as we dequeue - it makes that trace actually span the whole time in queue :-)

(Happy to chat more about this or add some comments/diagrams/something if we should make this more clear)

[kadircet]

LGTM!

clang-tools-extra/clangd/TUScheduler.cpp

1054–1055

thanks makes sense.

The chrome trace viewer (which jsontracer targets) really does require strict stacking. I'm not 100% sure, but I think the behavior was just to silently discard events that don't nest properly.

I was expecting this to be the case, but wanted to be sure.

clang-tools-extra/clangd/TUScheduler.cpp

private:
   /// Should the first task in the queue be skipped instead of run?
   bool shouldSkipHeadLocked() const;
 
   struct Request {
     llvm::unique_function<void()> Action;
     std::string Name;
     steady_clock::time_point AddTime;
     Context Ctx;
+    llvm::Optional<Context> QueueCtx;
     llvm::Optional<UpdateType> Update;
     TUScheduler::ASTActionInvalidation InvalidationPolicy;
     Canceler Invalidate;
   };
 
   /// Handles retention of ASTs.
   TUScheduler::ASTCache &IdleASTs;
   const bool RunSync;
private:
   /// Signalled whenever a new request has been scheduled or processing of a
   /// request has completed.
   mutable std::condition_variable RequestsCV;
   std::shared_ptr<const ASTSignals> LatestASTSignals; /* GUARDED_BY(Mutex) */
   /// Latest build preamble for current TU.
   /// None means no builds yet, null means there was an error while building.
   /// Only written by ASTWorker's thread.
   llvm::Optional<std::shared_ptr<const PreambleData>> LatestPreamble;
-  std::queue<Request> PreambleRequests; /* GUARDED_BY(Mutex) */
+  std::deque<Request> PreambleRequests; /* GUARDED_BY(Mutex) */
   /// Signaled whenever LatestPreamble changes state or there's a new
   /// PreambleRequest.
   mutable std::condition_variable PreambleCV;
   /// Guards the callback that publishes results of AST-related computations
   /// (diagnostics, highlightings) and file statuses.
   std::mutex PublishMu;
   // Used to prevent remove document + add document races that lead to
   // out-of-order callbacks for publishing results of onMainAST callback.
auto Task = [this, Preamble = std::move(Preamble), CI = std::move(CI),
     generateDiagnostics(std::move(CI), std::move(PI), std::move(CIDiags));
   };
   if (RunSync) {
     Task();
     return;
   }
   {
     std::lock_guard<std::mutex> Lock(Mutex);
-    PreambleRequests.push({std::move(Task), std::move(TaskName),
+    PreambleRequests.push_back({std::move(Task), std::move(TaskName),
                                 steady_clock::now(), Context::current().clone(),
-                           llvm::None, TUScheduler::NoInvalidation, nullptr});
+                                llvm::None, llvm::None,
+                                TUScheduler::NoInvalidation, nullptr});
   }
   PreambleCV.notify_all();
   RequestsCV.notify_all();
 }
 
 void ASTWorker::updateASTSignals(ParsedAST &AST) {
   auto Signals = std::make_shared<const ASTSignals>(ASTSignals::derive(AST));
   // Existing readers of ASTSignals will have their copy preserved until the
if (RunSync) {
     // Allow this request to be cancelled if invalidated.
     Context Ctx = Context::current().derive(kFileBeingProcessed, FileName);
     Canceler Invalidate = nullptr;
     if (Invalidation) {
       WithContext WC(std::move(Ctx));
       std::tie(Ctx, Invalidate) = cancelableTask(
           /*Reason=*/static_cast<int>(ErrorCode::ContentModified));
     }
+    // Trace the time the request spends in the queue, and the requests that
+    // it's going to wait for.
+    llvm::Optional<Context> QueueCtx;
+    if (trace::enabled()) {
+      // Tracers that follow threads and need strict nesting will see a tiny
+      // instantaneous event "we're enqueueing", and sometime later it runs.
+      WithContext WC(Ctx.clone());
+      trace::Span Tracer("Queued:" + Name);
+      if (Tracer.Args) {
+        if (CurrentRequest)
+          SPAN_ATTACH(Tracer, "CurrentRequest", CurrentRequest->Name);
+        llvm::json::Array PreambleRequestsNames;
+        for (const auto &Req : PreambleRequests)
+          PreambleRequestsNames.push_back(Req.Name);
+        SPAN_ATTACH(Tracer, "PreambleRequestsNames",
+                    std::move(PreambleRequestsNames));
+        llvm::json::Array RequestsNames;
+        for (const auto &Req : Requests)
+          RequestsNames.push_back(Req.Name);
+        SPAN_ATTACH(Tracer, "RequestsNames", std::move(RequestsNames));
+      }
+      // For tracers that follow contexts, keep the trace span's context alive
+      // until we dequeue the request, so they see the full duration.
+      QueueCtx = Context::current().clone();
+    }
     Requests.push_back({std::move(Task), std::string(Name), steady_clock::now(),
-                        std::move(Ctx), Update, Invalidation,
-                        std::move(Invalidate)});
+                        std::move(Ctx), std::move(QueueCtx), Update,
+                        Invalidation, std::move(Invalidate)});
   }
   RequestsCV.notify_all();
 }
 
 void ASTWorker::run() {
   while (true) {
     {
       std::unique_lock<std::mutex> Lock(Mutex);
while (true) {
         }
 
         wait(Lock, RequestsCV, Wait);
       }
       // Any request in ReceivedPreambles is at least as old as the
       // Requests.front(), so prefer them first to preserve LSP order.
       if (!PreambleRequests.empty()) {
         CurrentRequest = std::move(PreambleRequests.front());
-        PreambleRequests.pop();
+        PreambleRequests.pop_front();
       } else {
         CurrentRequest = std::move(Requests.front());
         Requests.pop_front();
       }
     } // unlock Mutex
 
+    // Inform tracing that the request was dequeued.
+    CurrentRequest->QueueCtx.reset();
+
     // It is safe to perform reads to CurrentRequest without holding the lock as
     // only writer is also this thread.
     {
       std::unique_lock<Semaphore> Lock(Barrier, std::try_to_lock);
       if (!Lock.owns_lock()) {
         Status.update([&](TUStatus &Status) {
           Status.ASTActivity.K = ASTAction::Queued;
           Status.ASTActivity.Name = CurrentRequest->Name;