[clang-tools-extra] 686d8a0 - [clangd] Add index server request logging
Sam McCall via cfe-commits
cfe-commits at lists.llvm.org
Wed Nov 11 14:58:34 PST 2020
Author: Sam McCall
Date: 2020-11-11T23:58:18+01:00
New Revision: 686d8a0911de7d9b13617c5aef66f6cebde05d5b
URL: https://github.com/llvm/llvm-project/commit/686d8a0911de7d9b13617c5aef66f6cebde05d5b
DIFF: https://github.com/llvm/llvm-project/commit/686d8a0911de7d9b13617c5aef66f6cebde05d5b.diff
LOG: [clangd] Add index server request logging
- Add verbose logging of payloads
- Add public logging of request summaries
- fix non-logging of messages in request scopes (oops!)
- add test for public/non-public logging, extending pipeline_helper a bit.
We've accumulated quite a lot of duplication in the request handlers by now.
I should factor that out, but not in this patch...
Differential Revision: https://reviews.llvm.org/D90654
Added:
clang-tools-extra/clangd/test/remote-index/public-log.test
Modified:
clang-tools-extra/clangd/index/remote/server/Server.cpp
clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
Removed:
################################################################################
diff --git a/clang-tools-extra/clangd/index/remote/server/Server.cpp b/clang-tools-extra/clangd/index/remote/server/Server.cpp
index fac1bd98ad5f..20b140e00787 100644
--- a/clang-tools-extra/clangd/index/remote/server/Server.cpp
+++ b/clang-tools-extra/clangd/index/remote/server/Server.cpp
@@ -94,10 +94,14 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
}
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 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
}
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 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
}
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 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
}
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 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
}
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;
};
diff --git a/clang-tools-extra/clangd/test/remote-index/pipeline_helper.py b/clang-tools-extra/clangd/test/remote-index/pipeline_helper.py
index b823b5b8cbeb..859792d448f5 100644
--- 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 @@ def main():
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 @@ def main():
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 @@ def main():
# 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 @@ def main():
'--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
index 000000000000..06c8c28d9dc9
--- /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"}
More information about the cfe-commits
mailing list