diff --git a/clang-tools-extra/clangd/index/remote/server/Server.cpp b/clang-tools-extra/clangd/index/remote/server/Server.cpp --- a/clang-tools-extra/clangd/index/remote/server/Server.cpp +++ b/clang-tools-extra/clangd/index/remote/server/Server.cpp @@ -94,10 +94,14 @@ } private: + using stopwatch = std::chrono::steady_clock; + grpc::Status Lookup(grpc::ServerContext *Context, const LookupRequest *Request, grpc::ServerWriter *Reply) override { - WithContextValue(CurrentRequest, Context); + auto StartTime = stopwatch::now(); + WithContextValue WithRequestContext(CurrentRequest, Context); + logRequest(*Request); trace::Span Tracer("LookupRequest"); auto Req = ProtobufMarshaller->fromProtobuf(Request); if (!Req) { @@ -116,21 +120,26 @@ } LookupReply NextMessage; *NextMessage.mutable_stream_result() = *SerializedItem; + logResponse(NextMessage); Reply->Write(NextMessage); ++Sent; }); LookupReply LastMessage; LastMessage.mutable_final_result()->set_has_more(true); + logResponse(LastMessage); Reply->Write(LastMessage); SPAN_ATTACH(Tracer, "Sent", Sent); SPAN_ATTACH(Tracer, "Failed to send", FailedToSend); + logRequestSummary("v1/Lookup", Sent, StartTime); return grpc::Status::OK; } grpc::Status FuzzyFind(grpc::ServerContext *Context, const FuzzyFindRequest *Request, grpc::ServerWriter *Reply) override { - WithContextValue(CurrentRequest, Context); + auto StartTime = stopwatch::now(); + WithContextValue WithRequestContext(CurrentRequest, Context); + logRequest(*Request); trace::Span Tracer("FuzzyFindRequest"); auto Req = ProtobufMarshaller->fromProtobuf(Request); if (!Req) { @@ -150,20 +159,25 @@ } FuzzyFindReply NextMessage; *NextMessage.mutable_stream_result() = *SerializedItem; + logResponse(NextMessage); Reply->Write(NextMessage); ++Sent; }); FuzzyFindReply LastMessage; LastMessage.mutable_final_result()->set_has_more(HasMore); + logResponse(LastMessage); Reply->Write(LastMessage); SPAN_ATTACH(Tracer, "Sent", Sent); SPAN_ATTACH(Tracer, "Failed to send", FailedToSend); + logRequestSummary("v1/FuzzyFind", Sent, StartTime); return grpc::Status::OK; } grpc::Status Refs(grpc::ServerContext *Context, const RefsRequest *Request, grpc::ServerWriter *Reply) override { - WithContextValue(CurrentRequest, Context); + auto StartTime = stopwatch::now(); + WithContextValue WithRequestContext(CurrentRequest, Context); + logRequest(*Request); trace::Span Tracer("RefsRequest"); auto Req = ProtobufMarshaller->fromProtobuf(Request); if (!Req) { @@ -182,21 +196,26 @@ } RefsReply NextMessage; *NextMessage.mutable_stream_result() = *SerializedItem; + logResponse(NextMessage); Reply->Write(NextMessage); ++Sent; }); RefsReply LastMessage; LastMessage.mutable_final_result()->set_has_more(HasMore); + logResponse(LastMessage); Reply->Write(LastMessage); SPAN_ATTACH(Tracer, "Sent", Sent); SPAN_ATTACH(Tracer, "Failed to send", FailedToSend); + logRequestSummary("v1/Refs", Sent, StartTime); return grpc::Status::OK; } grpc::Status Relations(grpc::ServerContext *Context, const RelationsRequest *Request, grpc::ServerWriter *Reply) override { - WithContextValue(CurrentRequest, Context); + auto StartTime = stopwatch::now(); + WithContextValue WithRequestContext(CurrentRequest, Context); + logRequest(*Request); trace::Span Tracer("RelationsRequest"); auto Req = ProtobufMarshaller->fromProtobuf(Request); if (!Req) { @@ -217,17 +236,44 @@ } RelationsReply NextMessage; *NextMessage.mutable_stream_result() = *SerializedItem; + logResponse(NextMessage); Reply->Write(NextMessage); ++Sent; }); RelationsReply LastMessage; LastMessage.mutable_final_result()->set_has_more(true); + logResponse(LastMessage); Reply->Write(LastMessage); SPAN_ATTACH(Tracer, "Sent", Sent); SPAN_ATTACH(Tracer, "Failed to send", FailedToSend); + logRequestSummary("v1/Relations", Sent, StartTime); return grpc::Status::OK; } + // Proxy object to allow proto messages to be lazily serialized as text. + struct TextProto { + const google::protobuf::Message &M; + friend llvm::raw_ostream &operator<<(llvm::raw_ostream &OS, + const TextProto &P) { + return OS << P.M.DebugString(); + } + }; + + void logRequest(const google::protobuf::Message &M) { + vlog("<<< {0}\n{1}", M.GetDescriptor()->name(), TextProto{M}); + } + void logResponse(const google::protobuf::Message &M) { + vlog(">>> {0}\n{1}", M.GetDescriptor()->name(), TextProto{M}); + } + void logRequestSummary(llvm::StringLiteral RequestName, unsigned Sent, + stopwatch::time_point StartTime) { + auto Duration = stopwatch::now() - StartTime; + auto Millis = + std::chrono::duration_cast(Duration).count(); + log("[public] request {0} => OK: {1} results in {2}ms", RequestName, Sent, + Millis); + } + std::unique_ptr ProtobufMarshaller; clangd::SymbolIndex &Index; }; diff --git a/clang-tools-extra/clangd/test/remote-index/pipeline_helper.py b/clang-tools-extra/clangd/test/remote-index/pipeline_helper.py --- a/clang-tools-extra/clangd/test/remote-index/pipeline_helper.py +++ b/clang-tools-extra/clangd/test/remote-index/pipeline_helper.py @@ -28,6 +28,8 @@ parser.add_argument('--input-file-name', required=True) parser.add_argument('--project-root', required=True) parser.add_argument('--index-file', required=True) + parser.add_argument('--server-arg', action='append', default=[]) + parser.add_argument('--server-log', nargs='?', type=argparse.FileType('wb'), default=os.devnull) args = parser.parse_args() @@ -40,7 +42,7 @@ index_server_process = subprocess.Popen([ 'clangd-index-server', '--server-address=' + server_address, args.index_file, args.project_root - ], + ] + args.server_arg, stderr=subprocess.PIPE) # This will kill index_server_process if it hangs without printing init @@ -53,7 +55,10 @@ # Wait for the server to warm-up. found_init_message = False while index_server_process.poll() is None: - if b'Server listening' in index_server_process.stderr.readline(): + line = index_server_process.stderr.readline() + args.server_log.write(line) + args.server_log.flush() + if b'Server listening' in line: print('Server initialization complete.', file=sys.stderr) found_init_message = True break @@ -70,12 +75,14 @@ '--project-root=' + args.project_root, '--lit-test', '--sync' ], stdin=in_file) - clangd_process.wait() print( 'Clangd executed successfully, shutting down child processes.', file=sys.stderr) index_server_process.kill() + for line in index_server_process.stderr: + args.server_log.write(line) + args.server_log.flush() if __name__ == '__main__': diff --git a/clang-tools-extra/clangd/test/remote-index/public-log.test b/clang-tools-extra/clangd/test/remote-index/public-log.test new file mode 100644 --- /dev/null +++ b/clang-tools-extra/clangd/test/remote-index/public-log.test @@ -0,0 +1,26 @@ +# RUN: rm -rf %t +# RUN: clangd-indexer %S/Inputs/Source.cpp > %t.idx +# RUN: %python %S/pipeline_helper.py --input-file-name=%s --server-arg=--log=verbose --server-arg=-log-public --server-log=%t.public.log --project-root=%S --index-file=%t.idx > /dev/null +# RUN: %python %S/pipeline_helper.py --input-file-name=%s --server-arg=--log=verbose --server-log=%t.log --project-root=%S --index-file=%t.idx > /dev/null +# RUN: FileCheck --check-prefixes=LOG,LOG-PUBLIC %s < %t.public.log +# RUN: FileCheck --check-prefixes=LOG,LOG-ALL %s < %t.log +# REQUIRES: clangd-remote-index + +# LOG: Server listening on +{"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":123,"rootPath":"clangd","capabilities":{},"trace":"off"}} +--- +# Verify that request and response bodies are included in the verbose logs, +# but not when --log-public is on. +# The request summary should be included in either case. +{"jsonrpc":"2.0","id":1,"method":"workspace/symbol","params":{"query":"gFoo"}} +# LOG-ALL: <<< FuzzyFindRequest +# LOG-ALL: query: "gFoo" +# LOG-ALL: >>> FuzzyFindReply +# LOG-ALL: name: "getFoo" +# LOG-PUBLIC-NOT: gFoo +# LOG-PUBLIC-NOT: getFoo +# LOG: request v1/FuzzyFind => OK: 1 results in {{.*}}ms +--- +{"jsonrpc":"2.0","id":4,"method":"shutdown"} +--- +{"jsonrpc":"2.0","method":"exit"}