[clangd] Add more logs and attach tracers to remote index server routines

[kbobyrev]

Rebase on top of parent revision, add more logging on the client side.

[sammccall]

Server-side tracing looks nice, but you'll need some flags to allow actually extracting a trace, right?

clang-tools-extra/clangd/index/remote/server/Server.cpp

62

Nit: this is "LookupRequest" on the client side. I'd suggest just the same on the server, or "Recv.LookupRequest" or so? to make it easier to correspond them

63

you don't do this on the client side, but could

63

prefer DebugString over ShortDebugString, the missing newlines can make it hard to follow

98

you don't do this on the client side, but should

[kbobyrev]

Resolve the comments.

[kbobyrev]

clang-tools-extra/clangd/index/remote/server/Server.cpp

63

Do you mean logging RPCRequest there? Done now.

[kbobyrev]

Rebase on top of master

[kbobyrev]

In favor of D84499 with clean diffs.

[kbobyrev]

Reset D83831 to master.

clang-tools-extra/clangd/index/remote/Client.cpp

     bool FinalResult = false;
     trace::Span Tracer(RequestT::descriptor()->name());
     const auto RPCRequest = ProtobufMarshaller->toProtobuf(Request);
+    SPAN_ATTACH(Tracer, "Request", RPCRequest.DebugString());
     grpc::ClientContext Context;
     std::chrono::system_clock::time_point Deadline =
         std::chrono::system_clock::now() + DeadlineWaitingTime;
     Context.set_deadline(Deadline);
     auto Reader = (Stub.get()->*RPCCall)(&Context, RPCRequest);
     ReplyT Reply;
+    unsigned Received = 0;
+    unsigned FailedToParse = 0;
     while (Reader->Read(&Reply)) {
       if (!Reply.has_stream_result()) {
         FinalResult = Reply.final_result();

       auto Response = ProtobufMarshaller->fromProtobuf(Reply.stream_result());
       if (!Response) {
         elog("Received invalid {0}", ReplyT::descriptor()->name());
+        ++FailedToParse;
         continue;
       }
       Callback(*Response);
+      ++Received;
     }
-    SPAN_ATTACH(Tracer, "status", Reader->Finish().ok());
+    SPAN_ATTACH(Tracer, "Status", Reader->Finish().ok());
+    SPAN_ATTACH(Tracer, "Received", Received);
+    SPAN_ATTACH(Tracer, "Failed to parse", FailedToParse);
     return FinalResult;
   }
 

clang-tools-extra/clangd/index/remote/server/Server.cpp

 #include "index/Index.h"
 #include "index/Serialization.h"
 #include "index/remote/marshalling/Marshalling.h"
+#include "support/Logger.h"
+#include "support/Trace.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/Path.h"

 llvm::cl::opt<std::string> IndexRoot(llvm::cl::desc("<PROJECT ROOT>"),
                                      llvm::cl::Positional, llvm::cl::Required);
 
+llvm::cl::opt<std::string> TracerFile(
+    "tracer-file",
+    llvm::cl::desc("Path to the file where tracer logs will be stored"));
+
+llvm::cl::opt<bool> PrettyPrint{
+    "pretty",
+    llvm::cl::desc("Pretty-print JSON output"),
+    llvm::cl::init(true),
+};
+
 llvm::cl::opt<std::string> ServerAddress(
     "server-address", llvm::cl::init("0.0.0.0:50051"),
     llvm::cl::desc("Address of the invoked server. Defaults to 0.0.0.0:50051"));

   grpc::Status Lookup(grpc::ServerContext *Context,
                       const LookupRequest *Request,
                       grpc::ServerWriter<LookupReply> *Reply) override {
+    trace::Span Tracer("LookupRequest");
+    SPAN_ATTACH(Tracer, "Request", Request->DebugString());
     clangd::LookupRequest Req;
     for (const auto &ID : Request->ids()) {
       auto SID = SymbolID::fromStr(StringRef(ID));
-      if (!SID)
+      if (!SID) {
+        elog("Lookup request cancelled: invalid SymbolID {1}", SID.takeError());
         return grpc::Status::CANCELLED;
+      }
       Req.IDs.insert(*SID);
     }
+    unsigned Sent = 0;
+    unsigned FailedToSend = 0;
     Index->lookup(Req, [&](const clangd::Symbol &Sym) {
       auto SerializedSymbol = ProtobufMarshaller->toProtobuf(Sym);
-      if (!SerializedSymbol)
+      if (!SerializedSymbol) {
+        ++FailedToSend;
         return;
+      }
       LookupReply NextMessage;
       *NextMessage.mutable_stream_result() = *SerializedSymbol;
       Reply->Write(NextMessage);
+      ++Sent;
     });
     LookupReply LastMessage;
     LastMessage.set_final_result(true);
     Reply->Write(LastMessage);
+    SPAN_ATTACH(Tracer, "Sent", Sent);
+    SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
     return grpc::Status::OK;
   }
 
   grpc::Status FuzzyFind(grpc::ServerContext *Context,
                          const FuzzyFindRequest *Request,
                          grpc::ServerWriter<FuzzyFindReply> *Reply) override {
+    trace::Span Tracer("FuzzyFind");
+    SPAN_ATTACH(Tracer, "Request", Request->DebugString());
     const auto Req = ProtobufMarshaller->fromProtobuf(Request);
+    unsigned Sent = 0;
+    unsigned FailedToSend = 0;
     bool HasMore = Index->fuzzyFind(Req, [&](const clangd::Symbol &Sym) {
       auto SerializedSymbol = ProtobufMarshaller->toProtobuf(Sym);
-      if (!SerializedSymbol)
+      if (!SerializedSymbol) {
+        ++FailedToSend;
         return;
+      }
       FuzzyFindReply NextMessage;
       *NextMessage.mutable_stream_result() = *SerializedSymbol;
       Reply->Write(NextMessage);
+      ++Sent;
     });
     FuzzyFindReply LastMessage;
     LastMessage.set_final_result(HasMore);
     Reply->Write(LastMessage);
+    SPAN_ATTACH(Tracer, "Sent", Sent);
+    SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
     return grpc::Status::OK;
   }
 
   grpc::Status Refs(grpc::ServerContext *Context, const RefsRequest *Request,
                     grpc::ServerWriter<RefsReply> *Reply) override {
+    trace::Span Tracer("Refs");
+    SPAN_ATTACH(Tracer, "Request", Request->DebugString());
     clangd::RefsRequest Req;
     for (const auto &ID : Request->ids()) {
       auto SID = SymbolID::fromStr(StringRef(ID));
-      if (!SID)
+      if (!SID) {
+        elog("Refs request cancelled: invalid SymbolID {1}", SID.takeError());
         return grpc::Status::CANCELLED;
+      }
       Req.IDs.insert(*SID);
     }
+    unsigned Sent = 0;
+    unsigned FailedToSend = 0;
     bool HasMore = Index->refs(Req, [&](const clangd::Ref &Reference) {
       auto SerializedRef = ProtobufMarshaller->toProtobuf(Reference);
-      if (!SerializedRef)
+      if (!SerializedRef) {
+        ++FailedToSend;
         return;
+      }
       RefsReply NextMessage;
       *NextMessage.mutable_stream_result() = *SerializedRef;
       Reply->Write(NextMessage);
+      ++Sent;
     });
     RefsReply LastMessage;
     LastMessage.set_final_result(HasMore);
     Reply->Write(LastMessage);
+    SPAN_ATTACH(Tracer, "Sent", Sent);
+    SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
     return grpc::Status::OK;
   }
 

     return -1;
   }
 
+  llvm::Optional<llvm::raw_fd_ostream> TracerStream;
+  std::unique_ptr<clang::clangd::trace::EventTracer> Tracer;
+  if (!TracerFile.empty()) {
+    std::error_code EC;
+    TracerStream.emplace(TracerFile, EC,
+                         llvm::sys::fs::FA_Read | llvm::sys::fs::FA_Write);
+    if (EC) {
+      TracerStream.reset();
+      llvm::errs() << "Error while opening trace file " << TracerFile << ": "
+                   << EC.message();
+    } else {
+      // FIXME(kirillbobyrev): Also create metrics tracer to track latency and
+      // accumulate other request statistics.
+      Tracer =
+          clang::clangd::trace::createJSONTracer(*TracerStream, PrettyPrint);
+      llvm::outs() << "Successfully created a tracer.\n";
+    }
+  }
+
+  llvm::Optional<clang::clangd::trace::Session> TracingSession;
+  if (Tracer)
+    TracingSession.emplace(*Tracer);
+
   std::unique_ptr<clang::clangd::SymbolIndex> Index = openIndex(IndexPath);
 
   if (!Index) {