[clangd] Add requests logging to clangd-index-server

[kbobyrev]

Summary

This will allow us to track metrics of the server usage.

[kbobyrev]

In favor of D90526

[kbobyrev]

Actually, maybe I should just postone and build on top of that.

[kbobyrev]

Closed in favor of D90654.

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 "Service.grpc.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/Shutdown.h"
 #include "support/ThreadsafeFS.h"
ProtobufMarshaller = std::unique_ptr<Marshaller>(new Marshaller(
         /*LocalIndexRoot=*/""));
   }
 
 private:
   grpc::Status Lookup(grpc::ServerContext *Context,
                       const LookupRequest *Request,
                       grpc::ServerWriter<LookupReply> *Reply) override {
     trace::Span Tracer("LookupRequest");
+    const auto TimerStart = std::chrono::high_resolution_clock::now();
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
       elog("Can not parse LookupRequest from protobuf: {0}", Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
     Index.lookup(*Req, [&](const clangd::Symbol &Item) {
Index.lookup(*Req, [&](const clangd::Symbol &Item) {
       Reply->Write(NextMessage);
       ++Sent;
     });
     LookupReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(true);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    const auto TimerStop = std::chrono::high_resolution_clock::now();
+    const auto Duration = std::chrono::duration_cast<std::chrono::milliseconds>(
+        TimerStop - TimerStart);
+    log("LookupRequest finished in {1:ms+n}", Duration);
     return grpc::Status::OK;
   }
 
   grpc::Status FuzzyFind(grpc::ServerContext *Context,
                          const FuzzyFindRequest *Request,
                          grpc::ServerWriter<FuzzyFindReply> *Reply) override {
     trace::Span Tracer("FuzzyFindRequest");
+    const auto TimerStart = std::chrono::high_resolution_clock::now();
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
       elog("Can not parse FuzzyFindRequest from protobuf: {0}",
            Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
bool HasMore = Index.fuzzyFind(*Req, [&](const clangd::Symbol &Item) {
       Reply->Write(NextMessage);
       ++Sent;
     });
     FuzzyFindReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(HasMore);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    const auto TimerStop = std::chrono::high_resolution_clock::now();
+    const auto Duration = std::chrono::duration_cast<std::chrono::milliseconds>(
+        TimerStop - TimerStart);
+    log("FuzzyFindRequest finished in {1:ms+n}", Duration);
     return grpc::Status::OK;
   }
 
   grpc::Status Refs(grpc::ServerContext *Context, const RefsRequest *Request,
                     grpc::ServerWriter<RefsReply> *Reply) override {
     trace::Span Tracer("RefsRequest");
+    const auto TimerStart = std::chrono::high_resolution_clock::now();
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
       elog("Can not parse RefsRequest from protobuf: {0}", Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
     bool HasMore = Index.refs(*Req, [&](const clangd::Ref &Item) {
bool HasMore = Index.refs(*Req, [&](const clangd::Ref &Item) {
       Reply->Write(NextMessage);
       ++Sent;
     });
     RefsReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(HasMore);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    const auto TimerStop = std::chrono::high_resolution_clock::now();
+    const auto Duration = std::chrono::duration_cast<std::chrono::milliseconds>(
+        TimerStop - TimerStart);
+    log("RefsRequest finished in {1:ms+n}", Duration);
     return grpc::Status::OK;
   }
 
   grpc::Status Relations(grpc::ServerContext *Context,
                          const RelationsRequest *Request,
                          grpc::ServerWriter<RelationsReply> *Reply) override {
     trace::Span Tracer("RelationsRequest");
+    const auto TimerStart = std::chrono::high_resolution_clock::now();
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
       elog("Can not parse RelationsRequest from protobuf: {0}",
            Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
Index.relations(
           Reply->Write(NextMessage);
           ++Sent;
         });
     RelationsReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(true);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    const auto TimerStop = std::chrono::high_resolution_clock::now();
+    const auto Duration = std::chrono::duration_cast<std::chrono::milliseconds>(
+        TimerStop - TimerStart);
+    log("RelationsRequest finished in {1:ms+n}", Duration);
     return grpc::Status::OK;
   }
 
   std::unique_ptr<Marshaller> ProtobufMarshaller;
   clangd::SymbolIndex &Index;
 };
 
 // Detect changes in \p IndexPath file and load new versions of the index