This revision was landed with ongoing or failed builds.
This revision was automatically updated to reflect the committed changes.
Closed by commit rG686d8a0911de: [clangd] Add index server request logging
(authored by sammccall).
Changed prior to commit:
https://reviews.llvm.org/D90654?vs=302423&id=304664#toc
Repository:
rG LLVM Github Monorepo
CHANGES SINCE LAST ACTION
https://reviews.llvm.org/D90654/new/
https://reviews.llvm.org/D90654
Files:
clang-tools-extra/clangd/index/remote/server/Server.cpp
clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
clang-tools-extra/clangd/test/remote-index/public-log.test
Index: clang-tools-extra/clangd/test/remote-index/public-log.test
===================================================================
--- /dev/null
+++ 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"}
Index: clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
===================================================================
--- clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
+++ 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__':
Index: clang-tools-extra/clangd/index/remote/server/Server.cpp
===================================================================
--- clang-tools-extra/clangd/index/remote/server/Server.cpp
+++ 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<LookupReply> *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<FuzzyFindReply> *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<RefsReply> *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<RelationsReply> *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<std::chrono::milliseconds>(Duration).count();
+ log("[public] request {0} => OK: {1} results in {2}ms", RequestName, Sent,
+ Millis);
+ }
+
std::unique_ptr<Marshaller> ProtobufMarshaller;
clangd::SymbolIndex &Index;
};
_______________________________________________
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
