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

[kbobyrev]

The first iteration is D83831 but the diffs are clobbered and I can't change the history there :( So, creating a new one is maybe the best solution.

[kbobyrev]

Abstract out the client request into a single function call.

[kbobyrev]

Tracer messages for sent and failed to parse items are not correct. Have to figure out how to print them _after_ the callback.

[kbobyrev]

Fix (un)successful message numbers reporting.

[kadircet]

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

61

shouldn't we increment this before the continue above ? (or rename this to successful rather than received ?)

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

42

i think TraceFile is more appropriate here.

48

is it only for pretty printing trace files? do we expect to have any other components this will interact in future? (if not maybe state that in the comments)

49

this sounds like a debug feature, do we really want it to be true by default?

94

all of this trickery is really nice. but i am not sure if it improves readability at all, from the perspective of call sites the amount of code is almost the same. moreover it was some trivial lambda before and instead it is lots of template parameters now.

maybe just have templated function to replace the lambda body instead? e.g.

template <typename StreamType, typenameResultType>
void IndexCallback(Marshaller &M, StreamType &Item) {
      trace::Span Tracer....;
      auto SerializedSymbol = M.toProtobuf(Item);
      // log the events and much more ...
}

then call it in the callbacks. WDYT?

[kbobyrev]

Resolve most review comments.

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

61

Makes sense, I didn't think of "received" in terms of "overall" :P

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

42

TracerFile is what ClangdMain.cpp has; I'm not against this, but I think it'd be better to have them the same for consistency. WDYT?

48

Yeah, right now it's only for trace files. It's quite possible that there will be something else that could be pretty-printed in the future, but not right now, so I changed description (specified trace files).

94

I think this is a good idea but I can't think of a nice way to do that, too. IndexCallback would have to update Sent and FailedToSend (Tracer should be outside of the callback, right?), and the callback signature if fixed so I wouldn't be able to pass these parameters by reference :( I could probably make those two fields of the class but this doesn't look very nice, or pass member function (templated one) to the callback in each index request, but this also doesn't look very nice.

I think the reason was initially to improve readability but then it's more about code deduplication: right now there are 3 pieces of code that do exactly the same, there will be a fourth one (relations request). Maybe readability even decreases but I really think that having 4 pieces of code with different types is not very nice. Also, D84525 compliments this and there will be practically only no functional code in the functions themselves.

I can understand your argument and I partially support it but I really think we're unfortunately choosing between bad and worse.

[sammccall]

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

42

(driveby, sorry)
TracerFile is the local variable name in ClangdMain, but the public interface (an environment variable there rather than a flag) is CLANGD_TRACE, and it's more important to be consistent with that.

So my vote would be --trace or --trace-file or env CLANGD_TRACE=...

49

This option is not worth having at all, IMO.

73

you don't need both RequestT and ClangdRequest as template params:

• the things you're currently doing are all available through protobuf::Message base class
• but why not move the request fromProtobuf call in here so you only need to pass a single parameter?

74

StreamType doesn't need to be a type param as you can make the lambda param auto

75

can't the return type just be auto?
Then I think you don't need CallbackT as a template param.

94

FWIW, I find the template to be very hard to read, and would prefer the version that is duplicated 4 times.

I've left some suggestions for how to simplify (mostly, eliminating template parameters) but I'm still not sure it's worth it.

96

I don't think you need forward here... just take the param by const reference?

[kbobyrev]

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

49

Why not? It's relatively hard to read trace files otherwise. Do you think they should be pretty-printed by default?

96

How do I do that? The problem is that some functions return bool and one void, so I can't really assign the result to variable and then return it.

[sammccall]

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

49

FWIW, I've never had to read them except when initially developing/debugging the trace feature.
(The most I have to do is fix up a broken end-of-file, and events are one-per-line in non-pretty anyway...)

I think either always-on or always-off is better than having a flag.

96

Currently you have

template <typename IndexCall>(IndexCall&& Call) {
  forward<IndexCall>(Call);
}

but I think this would work fine here:

template <typename IndexCall>(const IndexCall& Call) {
  IndexCall(Call);
}

(nothing particularly wrong with this use of forward, but "more template goop" feels particularly expensive here.

[kbobyrev]

Need to resolve remaining comments and improve readability.

[kbobyrev]

Resolve most review comments.

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

73

but why not move the request fromProtobuf call in here so you only need to pass a single parameter?

Yeah this is the idea; I have D84525 for extending fromProtobuf so that it can be moved here.

75

Ah, I thought LLVM is still C++ 11, not 14. Good to know, thanks!

96

Ah, you meant passing the callback by const reference. I see, thanks for the suggestion!

[kbobyrev]

As discussed in PM, should move back to duplicated code 😢

[kbobyrev]

Move back to duplicated code.

[kbobyrev]

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

73

Not doing this because of getting back to code duplication.

[kbobyrev]

Fix code.

[kadircet]

thanks, LGTM apart from templated-lambdas.

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

84

usage of auto in here results in a templated-lambda. I don't think we want that (please let me know if I am missing something) maybe go back to using clangd::Symbol ? (same for other lambdas)

94

I think this is a good idea but I can't think of a nice way to do that, too. IndexCallback would have to update Sent and FailedToSend (Tracer should be outside of the callback, right?), and the callback signature if fixed so I wouldn't be able to pass these parameters by reference :( I could probably make those two fields of the class but this doesn't look very nice, or pass member function (templated one) to the callback in each index request, but this also doesn't look very nice.

right, i've missed that bit. but I was suggesting you to call IndexCallback inside the lambda, e.g. callsites would look like this:

Index->lookup(Req, [&](const auto &Item) {
    IndexCallback(*ProtobufMarshaller, Item);
});

so in theory you could pass in Sent and FailedToSend as parameters to IndexCallback and mutate them in there.

but not really relevant anymore.

206

any reasons for not using elog in here (and in other places using llvm::errs() ?

[kbobyrev]

Resolve all but 1 post-LGTM comment and rebase on top of master.

[kbobyrev]

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

206

I think we tend to use llvm::errs() instead of logs in CLI tools (ClangdMain.cpp and particularly TraceFile handling were the inspiration and it uses llvm::errs() although there are many elogs there, too) and I'm a little confused about when to use either of those. Could you explain how those are chosen in each case?

[kbobyrev]

Switch from llvm::errs() to elog()

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

class IndexClient : public clangd::SymbolIndex {
   template <typename RequestT, typename ReplyT, typename ClangdRequestT,
             typename CallbackT>
   bool streamRPC(ClangdRequestT Request,
                  StreamingCall<RequestT, ReplyT> RPCCall,
                  CallbackT Callback) const {
     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 Successful = 0;
+    unsigned FailedToParse = 0;
     while (Reader->Read(&Reply)) {
       if (!Reply.has_stream_result()) {
         FinalResult = Reply.final_result();
         continue;
       }
       auto Response = ProtobufMarshaller->fromProtobuf(Reply.stream_result());
       if (!Response) {
         elog("Received invalid {0}", ReplyT::descriptor()->name());
+        ++FailedToParse;
         continue;
       }
       Callback(*Response);
+      ++Successful;
     }
-    SPAN_ATTACH(Tracer, "status", Reader->Finish().ok());
+    SPAN_ATTACH(Tracer, "Status", Reader->Finish().ok());
+    SPAN_ATTACH(Tracer, "Successful", Successful);
+    SPAN_ATTACH(Tracer, "Failed to parse", FailedToParse);
     return FinalResult;
   }
 
 public:
   IndexClient(
       std::shared_ptr<grpc::Channel> Channel, llvm::StringRef ProjectRoot,
       std::chrono::milliseconds DeadlineTime = std::chrono::milliseconds(1000))
       : Stub(remote::SymbolIndex::NewStub(Channel)),

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

 //===--- Server.cpp - gRPC-based Remote Index Server  ---------------------===//
 //
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 
+#include "Index.pb.h"
 #include "index/Index.h"
 #include "index/Serialization.h"
+#include "index/Symbol.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"
 #include "llvm/Support/Signals.h"
 
 #include <grpc++/grpc++.h>
 #include <grpc++/health_check_service_interface.h>
 

 )";
 
 llvm::cl::opt<std::string> IndexPath(llvm::cl::desc("<INDEX FILE>"),
                                      llvm::cl::Positional, llvm::cl::Required);
 
 llvm::cl::opt<std::string> IndexRoot(llvm::cl::desc("<PROJECT ROOT>"),
                                      llvm::cl::Positional, llvm::cl::Required);
 
+llvm::cl::opt<std::string> TraceFile(
+    "trace-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 in the trace"),
+    llvm::cl::init(false),
+};
+
 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"));
 
 std::unique_ptr<clangd::SymbolIndex> openIndex(llvm::StringRef Index) {
   return loadIndex(Index, /*UseIndex=*/true);
 }
 
 class RemoteIndexServer final : public SymbolIndex::Service {
 public:
   RemoteIndexServer(std::unique_ptr<clangd::SymbolIndex> Index,
                     llvm::StringRef IndexRoot)
       : Index(std::move(Index)) {
     llvm::SmallString<256> NativePath = IndexRoot;
     llvm::sys::path::native(NativePath);
     ProtobufMarshaller = std::unique_ptr<Marshaller>(new Marshaller(
         /*RemoteIndexRoot=*/llvm::StringRef(NativePath),
         /*LocalIndexRoot=*/""));
   }
 
 private:
   grpc::Status Lookup(grpc::ServerContext *Context,
                       const LookupRequest *Request,
                       grpc::ServerWriter<LookupReply> *Reply) override {
+    trace::Span Tracer(LookupRequest::descriptor()->name());
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
       elog("Can not parse LookupRequest from protobuf: {0}", Req.takeError());
       return grpc::Status::CANCELLED;
     }
-    Index->lookup(*Req, [&](const clangd::Symbol &Sym) {
-      auto SerializedSymbol = ProtobufMarshaller->toProtobuf(Sym);
-      if (!SerializedSymbol)
+    unsigned Sent = 0;
+    unsigned FailedToSend = 0;
+    Index->lookup(*Req, [&](const auto &Item) {
+      auto SerializedItem = ProtobufMarshaller->toProtobuf(Item);
+      if (!SerializedItem) {
+        ++FailedToSend;
         return;
+      }
       LookupReply NextMessage;
-      *NextMessage.mutable_stream_result() = *SerializedSymbol;
+      *NextMessage.mutable_stream_result() = *SerializedItem;
       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(FuzzyFindRequest::descriptor()->name());
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
       elog("Can not parse FuzzyFindRequest from protobuf: {0}",
            Req.takeError());
       return grpc::Status::CANCELLED;
     }
-    bool HasMore = Index->fuzzyFind(*Req, [&](const clangd::Symbol &Sym) {
-      auto SerializedSymbol = ProtobufMarshaller->toProtobuf(Sym);
-      if (!SerializedSymbol)
+    unsigned Sent = 0;
+    unsigned FailedToSend = 0;
+    bool HasMore = Index->fuzzyFind(*Req, [&](const auto &Item) {
+      auto SerializedItem = ProtobufMarshaller->toProtobuf(Item);
+      if (!SerializedItem) {
+        ++FailedToSend;
         return;
+      }
       FuzzyFindReply NextMessage;
-      *NextMessage.mutable_stream_result() = *SerializedSymbol;
+      *NextMessage.mutable_stream_result() = *SerializedItem;
       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(RefsRequest::descriptor()->name());
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
       elog("Can not parse RefsRequest from protobuf: {0}", Req.takeError());
       return grpc::Status::CANCELLED;
     }
-    bool HasMore = Index->refs(*Req, [&](const clangd::Ref &Reference) {
-      auto SerializedRef = ProtobufMarshaller->toProtobuf(Reference);
-      if (!SerializedRef)
+    unsigned Sent = 0;
+    unsigned FailedToSend = 0;
+    bool HasMore = Index->refs(*Req, [&](const auto &Item) {
+      auto SerializedItem = ProtobufMarshaller->toProtobuf(Item);
+      if (!SerializedItem) {
+        ++FailedToSend;
         return;
+      }
       RefsReply NextMessage;
-      *NextMessage.mutable_stream_result() = *SerializedRef;
+      *NextMessage.mutable_stream_result() = *SerializedItem;
       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;
   }
 
   std::unique_ptr<clangd::SymbolIndex> Index;
   std::unique_ptr<Marshaller> ProtobufMarshaller;
 };
 
 void runServer(std::unique_ptr<clangd::SymbolIndex> Index,
void runServer(std::unique_ptr<clangd::SymbolIndex> Index,
   Server->Wait();
 }
 
 } // namespace
 } // namespace remote
 } // namespace clangd
 } // namespace clang
 
+using clang::clangd::elog;
+
 int main(int argc, char *argv[]) {
   using namespace clang::clangd::remote;
   llvm::cl::ParseCommandLineOptions(argc, argv, Overview);
   llvm::sys::PrintStackTraceOnErrorSignal(argv[0]);
 
   if (!llvm::sys::path::is_absolute(IndexRoot)) {
-    llvm::errs() << "Index root should be an absolute path.\n";
+    elog("Index root should be an absolute path.");
     return -1;
   }
 
+  llvm::Optional<llvm::raw_fd_ostream> TracerStream;
+  std::unique_ptr<clang::clangd::trace::EventTracer> Tracer;
+  if (!TraceFile.empty()) {
+    std::error_code EC;
+    TracerStream.emplace(TraceFile, EC,
+                         llvm::sys::fs::FA_Read | llvm::sys::fs::FA_Write);
+    if (EC) {
+      TracerStream.reset();
+      elog("Error while opening trace file {0}: {1}", TraceFile, EC.message());
+    } else {
+      // FIXME(kirillbobyrev): Also create metrics tracer to track latency and
+      // accumulate other request statistics.
+      Tracer = clang::clangd::trace::createJSONTracer(*TracerStream,
+                                                      /*PrettyPrint=*/false);
+      clang::clangd::vlog("Successfully created a tracer.");
+    }
+  }
+
+  llvm::Optional<clang::clangd::trace::Session> TracingSession;
+  if (Tracer)
+    TracingSession.emplace(*Tracer);
+
   std::unique_ptr<clang::clangd::SymbolIndex> Index = openIndex(IndexPath);
 
   if (!Index) {
-    llvm::errs() << "Failed to open the index.\n";
+    elog("Failed to open the index.");
     return -1;
   }
 
   runServer(std::move(Index), ServerAddress);
 }