[clangd] NFC: Add client-side logging for remote index requests

[kbobyrev]

Summary

Figuring out whether the server is responding and debugging issues with remote
index setup is no easy task: add verbose logging for client side RPC requests
to relieve some pain.

[kbobyrev]

Switch Deadline type to const auto.

[sammccall]

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

46–48

(we don't ussually use const for locals)

51

Including the request payload is IMO too much even at --log=verbose, we do this for LSP messages but those are more useful/central. Vlog the request and dlog the payload? (Similar to log/vlog for LSP)

75

"RPC Request" may be a bit jargony for these messages. And "Request" is part of the RequestT name.
It'd be nice to include the server name too, there may be several.

What about Remote index: LookupRequest => 123 results in 18ms. [llvm.clangd-index-staging.org:1234]?

[kbobyrev]

Address review comments.

[kbobyrev]

Rebase on top of master.

[kbobyrev]

Change logging format to be consistent with another patch.

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

 
 #include "Client.h"
 #include "Service.grpc.pb.h"
 #include "index/Index.h"
 #include "marshalling/Marshalling.h"
 #include "support/Logger.h"
 #include "support/Trace.h"
 #include "clang/Basic/Version.h"
+#include "llvm/ADT/SmallString.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Error.h"
 
 #include <chrono>
 
 namespace clang {
 namespace clangd {
 namespace remote {
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;
     Context.AddMetadata("version", clang::getClangToolFullVersion("clangd"));
-    std::chrono::system_clock::time_point Deadline =
-        std::chrono::system_clock::now() + DeadlineWaitingTime;
+    std::chrono::system_clock::time_point StartTime =
+        std::chrono::system_clock::now();
+    auto Deadline = StartTime + DeadlineWaitingTime;
     Context.set_deadline(Deadline);
     auto Reader = (Stub.get()->*RPCCall)(&Context, RPCRequest);
+    dlog("Sending {0}: {1}", RequestT::descriptor()->name(),
+         RPCRequest.DebugString());
     ReplyT Reply;
     unsigned Successful = 0;
     unsigned FailedToParse = 0;
     while (Reader->Read(&Reply)) {
       if (!Reply.has_stream_result()) {
         FinalResult = Reply.final_result().has_more();
         continue;
       }
       auto Response = ProtobufMarshaller->fromProtobuf(Reply.stream_result());
       if (!Response) {
         elog("Received invalid {0}: {1}. Reason: {2}",
              ReplyT::descriptor()->name(), Reply.stream_result().DebugString(),
              Response.takeError());
         ++FailedToParse;
         continue;
       }
       Callback(*Response);
       ++Successful;
     }
+    auto Millis = std::chrono::duration_cast<std::chrono::milliseconds>(
+                      std::chrono::system_clock::now() - StartTime)
+                      .count();
+    vlog("Remote index [{0}]: {1} => {2} results in {3}ms.", ServerAddress,
+         RequestT::descriptor()->name(), Successful, Millis);
     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,
+      llvm::StringRef Address,
       std::chrono::milliseconds DeadlineTime = std::chrono::milliseconds(1000))
       : Stub(remote::v1::SymbolIndex::NewStub(Channel)),
         ProtobufMarshaller(new Marshaller(/*RemoteIndexRoot=*/"",
                                           /*LocalIndexRoot=*/ProjectRoot)),
-        DeadlineWaitingTime(DeadlineTime) {
+        ServerAddress(Address), DeadlineWaitingTime(DeadlineTime) {
     assert(!ProjectRoot.empty());
   }
 
   void lookup(const clangd::LookupRequest &Request,
               llvm::function_ref<void(const clangd::Symbol &)> Callback)
       const override {
     streamRPC(Request, &remote::v1::SymbolIndex::Stub::Lookup, Callback);
   }
public:
   }
 
   // IndexClient does not take any space since the data is stored on the
   // server.
   size_t estimateMemoryUsage() const override { return 0; }
 
 private:
   std::unique_ptr<remote::v1::SymbolIndex::Stub> Stub;
+  llvm::SmallString<256> ServerAddress;
   std::unique_ptr<Marshaller> ProtobufMarshaller;
   // Each request will be terminated if it takes too long.
   std::chrono::milliseconds DeadlineWaitingTime;
 };
 
 } // namespace
 
 std::unique_ptr<clangd::SymbolIndex> getClient(llvm::StringRef Address,
                                                llvm::StringRef ProjectRoot) {
   const auto Channel =
       grpc::CreateChannel(Address.str(), grpc::InsecureChannelCredentials());
   Channel->GetState(true);
   return std::unique_ptr<clangd::SymbolIndex>(
-      new IndexClient(Channel, ProjectRoot));
+      new IndexClient(Channel, ProjectRoot, Address));
 }
 
 } // namespace remote
 } // namespace clangd
 } // namespace clang