[clangd] When replying, log the method name and latency.

[sammccall]

Summary

This information is strictly available in the log (you can find the original
call) but it makes the log easier to follow in practice.

[sammccall]

Log now looks something like this:

I[16:47:01.225] <-- textDocument/completion("2")
I[16:47:01.233] Ignored diagnostic. /usr/local/google/home/sammccall/temp/test.cc:7:1:'main' must return 'int'
I[16:47:01.234] Code complete: sema context Statement, query scopes [] (AnyScope=false)
I[16:47:01.234] Code complete: 0 results from Sema, 0 from Index, 0 matched, 0 returned.
I[16:47:01.234] --> reply:textDocument/completion("2") 8 ms

[kadircet]

LG, thanks!

clangd/ClangdLSPServer.cpp

218 ↗

(On Diff #170890)

Move locking below to not lock while copying reply.

221 ↗

(On Diff #170890)

What about also printing vlog after sending out reply? Because for "heavy" replies there is a huge difference between process time and serialization of response to json, sometimes it might help to see how much time is spent for serialization as well.(for example ycmd patch, it takes a few hundred ms to prepare reply, but then a few seconds to dump it)

[sammccall]

clangd/ClangdLSPServer.cpp

221 ↗

(On Diff #170890)

As discussed offline, this is interesting, but only relevant for really huge responses and probably noise the rest of the time.
Let's leave it out for now, but may be worth adding locally when debugging this.

clang-tools-extra/trunk/clangd/ClangdLSPServer.h

private:
   // MessageHandler deals with incoming messages, use call() etc for outgoing.
   clangd::Transport &Transp;
   class MessageHandler;
   std::unique_ptr<MessageHandler> MsgHandler;
   std::atomic<int> NextCallID = {0};
   std::mutex TranspWriter;
   void call(StringRef Method, llvm::json::Value Params);
   void notify(StringRef Method, llvm::json::Value Params);
-  void reply(llvm::json::Value ID, llvm::Expected<llvm::json::Value> Result);
 
   RealFileSystemProvider FSProvider;
   /// Options used for code completion
   clangd::CodeCompleteOptions CCOpts;
   /// Options used for diagnostics.
   ClangdDiagnosticOptions DiagOpts;
   /// The supported kinds of the client.
   SymbolKindBitset SupportedSymbolKinds;

clang-tools-extra/trunk/clangd/ClangdLSPServer.cpp

 private:
   // Function object to reply to an LSP call.
   // Each instance must be called exactly once, otherwise:
   //  - the bug is logged, and (in debug mode) an assert will fire
   //  - if there was no reply, an error reply is sent
   //  - if there were multiple replies, only the first is sent
   class ReplyOnce {
     std::atomic<bool> Replied = {false};
+    std::chrono::steady_clock::time_point Start;
     json::Value ID;
     std::string Method;
     ClangdLSPServer *Server; // Null when moved-from.
     json::Object *TraceArgs;
 
   public:
     ReplyOnce(const json::Value &ID, StringRef Method, ClangdLSPServer *Server,
               json::Object *TraceArgs)
-        : ID(ID), Method(Method), Server(Server), TraceArgs(TraceArgs) {
+        : Start(std::chrono::steady_clock::now()), ID(ID), Method(Method),
+          Server(Server), TraceArgs(TraceArgs) {
       assert(Server);
     }
     ReplyOnce(ReplyOnce &&Other)
-        : Replied(Other.Replied.load()), ID(std::move(Other.ID)),
-          Method(std::move(Other.Method)), Server(Other.Server),
-          TraceArgs(Other.TraceArgs) {
+        : Replied(Other.Replied.load()), Start(Other.Start),
+          ID(std::move(Other.ID)), Method(std::move(Other.Method)),
+          Server(Other.Server), TraceArgs(Other.TraceArgs) {
       Other.Server = nullptr;
     }
     ReplyOnce& operator=(ReplyOnce&&) = delete;
     ReplyOnce(const ReplyOnce &) = delete;
     ReplyOnce& operator=(const ReplyOnce&) = delete;
 
     ~ReplyOnce() {
       if (Server && !Replied) {
         elog("No reply to message {0}({1})", Method, ID);
         assert(false && "must reply to all calls!");
         (*this)(make_error<LSPError>("server failed to reply",
                                      ErrorCode::InternalError));
       }
     }
 
     void operator()(Expected<json::Value> Reply) {
       assert(Server && "moved-from!");
       if (Replied.exchange(true)) {
         elog("Replied twice to message {0}({1})", Method, ID);
         assert(false && "must reply to each call only once!");
         return;
       }
-      if (TraceArgs) {
-        if (Reply)
+      auto Duration = std::chrono::steady_clock::now() - Start;
+      if (Reply) {
+        log("--> reply:{0}({1}) {2:ms}", Method, ID, Duration);
+        if (TraceArgs)
           (*TraceArgs)["Reply"] = *Reply;
-        else {
-          auto Err = Reply.takeError();
+        std::lock_guard<std::mutex> Lock(Server->TranspWriter);
+        Server->Transp.reply(std::move(ID), std::move(Reply));
+      } else {
+        Error Err = Reply.takeError();
+        log("--> reply:{0}({1}) {2:ms}, error: {3}", Method, ID, Duration, Err);
+        if (TraceArgs)
           (*TraceArgs)["Error"] = to_string(Err);
-          Reply = std::move(Err);
-        }
+        std::lock_guard<std::mutex> Lock(Server->TranspWriter);
+        Server->Transp.reply(std::move(ID), std::move(Err));
       }
-      Server->reply(ID, std::move(Reply));
     }
   };
 
   StringMap<std::function<void(json::Value)>> Notifications;
   StringMap<std::function<void(json::Value, ReplyOnce)>> Calls;
 
   // Method calls may be cancelled by ID, so keep track of their state.
   // This needs a mutex: handlers may finish on a different thread, and that's

 }
 
 void ClangdLSPServer::notify(StringRef Method, json::Value Params) {
   log("--> {0}", Method);
   std::lock_guard<std::mutex> Lock(TranspWriter);
   Transp.notify(Method, std::move(Params));
 }
 
-void ClangdLSPServer::reply(json::Value ID, Expected<json::Value> Result) {
-  if (Result) {
-    log("--> reply({0})", ID);
-    std::lock_guard<std::mutex> Lock(TranspWriter);
-    Transp.reply(std::move(ID), std::move(Result));
-  } else {
-    Error Err = Result.takeError();
-    log("--> reply({0}) error: {1}", ID, Err);
-    std::lock_guard<std::mutex> Lock(TranspWriter);
-    Transp.reply(std::move(ID), std::move(Err));
-  }
-}
-
 void ClangdLSPServer::onInitialize(const InitializeParams &Params,
                                    Callback<json::Value> Reply) {
   if (Params.rootUri && *Params.rootUri)
     ClangdServerOpts.WorkspaceRoot = Params.rootUri->file();
   else if (Params.rootPath && !Params.rootPath->empty())
     ClangdServerOpts.WorkspaceRoot = *Params.rootPath;
   if (Server)
     return Reply(make_error<LSPError>("server already initialized",