Index: clangd/CMakeLists.txt =================================================================== --- clangd/CMakeLists.txt +++ clangd/CMakeLists.txt @@ -13,6 +13,7 @@ Logger.cpp Protocol.cpp ProtocolHandlers.cpp + Trace.cpp LINK_LIBS clangAST Index: clangd/ClangdServer.cpp =================================================================== --- clangd/ClangdServer.cpp +++ clangd/ClangdServer.cpp @@ -15,6 +15,8 @@ #include "llvm/ADT/ArrayRef.h" #include "llvm/Support/Errc.h" #include "llvm/Support/FileSystem.h" +#include "llvm/Support/FormatProviders.h" +#include "llvm/Support/FormatVariadic.h" #include "llvm/Support/Path.h" #include "llvm/Support/raw_ostream.h" #include @@ -98,7 +100,8 @@ Workers.reserve(AsyncThreadsCount); for (unsigned I = 0; I < AsyncThreadsCount; ++I) { - Workers.push_back(std::thread([this]() { + Workers.push_back(std::thread([this, I]() { + llvm::set_thread_name(llvm::formatv("scheduler/{0}", I)); while (true) { UniqueFunction Request; Index: clangd/ClangdUnit.cpp =================================================================== --- clangd/ClangdUnit.cpp +++ clangd/ClangdUnit.cpp @@ -10,6 +10,7 @@ #include "ClangdUnit.h" #include "Logger.h" +#include "Trace.h" #include "clang/Frontend/CompilerInstance.h" #include "clang/Frontend/CompilerInvocation.h" #include "clang/Frontend/FrontendActions.h" @@ -1285,6 +1286,7 @@ return OldPreamble; } + trace::Span Tracer(llvm::Twine("Preamble: ") + That->FileName); std::vector PreambleDiags; StoreDiagsConsumer PreambleDiagnosticsConsumer(/*ref*/ PreambleDiags); IntrusiveRefCntPtr PreambleDiagsEngine = @@ -1330,9 +1332,13 @@ } // Compute updated AST. - llvm::Optional NewAST = - ParsedAST::Build(std::move(CI), PreambleForAST, SerializedPreambleDecls, - std::move(ContentsBuffer), PCHs, VFS, That->Logger); + llvm::Optional NewAST; + { + trace::Span Tracer(llvm::Twine("Build: ") + That->FileName); + NewAST = ParsedAST::Build( + std::move(CI), PreambleForAST, SerializedPreambleDecls, + std::move(ContentsBuffer), PCHs, VFS, That->Logger); + } if (NewAST) { Diagnostics.insert(Diagnostics.end(), NewAST->getDiagnostics().begin(), Index: clangd/JSONRPCDispatcher.cpp =================================================================== --- clangd/JSONRPCDispatcher.cpp +++ clangd/JSONRPCDispatcher.cpp @@ -9,6 +9,7 @@ #include "JSONRPCDispatcher.h" #include "ProtocolHandlers.h" +#include "Trace.h" #include "llvm/ADT/SmallString.h" #include "llvm/Support/SourceMgr.h" #include "llvm/Support/YAMLParser.h" @@ -32,6 +33,7 @@ } void JSONOutput::log(const Twine &Message) { + trace::log(Message); std::lock_guard Guard(StreamMutex); Logs << Message; Logs.flush(); @@ -75,8 +77,10 @@ llvm::yaml::MappingNode *Params, const JSONRPCDispatcher::Handler &UnknownHandler, JSONOutput &Out) { llvm::SmallString<64> MethodStorage; - auto I = Handlers.find(Method->getValue(MethodStorage)); + llvm::StringRef MethodStr = Method->getValue(MethodStorage); + auto I = Handlers.find(MethodStr); auto &Handler = I != Handlers.end() ? I->second : UnknownHandler; + trace::Span Tracer(MethodStr); Handler(RequestContext(Out, Id ? Id->getRawValue() : ""), Params); } @@ -206,21 +210,27 @@ } if (ContentLength > 0) { - // Now read the JSON. Insert a trailing null byte as required by the YAML - // parser. std::vector JSON(ContentLength + 1, '\0'); - In.read(JSON.data(), ContentLength); - Out.mirrorInput(StringRef(JSON.data(), In.gcount())); - - // If the stream is aborted before we read ContentLength bytes, In - // will have eofbit and failbit set. - if (!In) { - Out.log("Input was aborted. Read only " + std::to_string(In.gcount()) + - " bytes of expected " + std::to_string(ContentLength) + ".\n"); - break; + llvm::StringRef JSONRef; + { + trace::Span Tracer("Reading request"); + // Now read the JSON. Insert a trailing null byte as required by the + // YAML parser. + In.read(JSON.data(), ContentLength); + Out.mirrorInput(StringRef(JSON.data(), In.gcount())); + + // If the stream is aborted before we read ContentLength bytes, In + // will have eofbit and failbit set. + if (!In) { + Out.log("Input was aborted. Read only " + + std::to_string(In.gcount()) + " bytes of expected " + + std::to_string(ContentLength) + ".\n"); + break; + } + + JSONRef = StringRef(JSON.data(), ContentLength); } - llvm::StringRef JSONRef(JSON.data(), ContentLength); // Log the message. Out.log("<-- " + JSONRef + "\n"); Index: clangd/ProtocolHandlers.cpp =================================================================== --- clangd/ProtocolHandlers.cpp +++ clangd/ProtocolHandlers.cpp @@ -11,6 +11,7 @@ #include "ClangdLSPServer.h" #include "ClangdServer.h" #include "DraftStore.h" +#include "Trace.h" using namespace clang; using namespace clang::clangd; @@ -30,7 +31,10 @@ auto *Callbacks = this->Callbacks; Dispatcher.registerHandler( Method, [=](RequestContext C, llvm::yaml::MappingNode *RawParams) { - if (auto P = std::decay::type::parse(RawParams, *Out)) { + if (auto P = [&] { + trace::Span Tracer("Parse"); + return std::decay::type::parse(RawParams, *Out); + }()) { (Callbacks->*Handler)(std::move(C), *P); } else { Out->log("Failed to decode " + Method + " request.\n"); Index: clangd/Trace.h =================================================================== --- /dev/null +++ clangd/Trace.h @@ -0,0 +1,61 @@ +//===--- Trace.h - Performance tracing facilities ---------------*- C++ -*-===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +// Supports writing performance traces describing clangd's behavior. +// Traces are written in the Trace Event format supported by chrome's trace +// viewer (chrome://tracing). +// +// The format is documented here: +// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview +// +// All APIs are no-ops unless a Session is active (created by ClangdMain). +// +//===----------------------------------------------------------------------===// + +#ifndef LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_ +#define LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_ + +#include "llvm/ADT/Twine.h" +#include "llvm/Support/raw_ostream.h" + +namespace clang { +namespace clangd { +namespace trace { + +// A session directs the output of trace events. Only one Session can exist. +// It should be created before clangd threads are spawned, and destroyed after +// they exit. +// TODO: we may want to add pluggable support for other tracing backends. +class Session { +public: + // Starts a sessions capturing trace events and writing Trace Event JSON. + static std::unique_ptr start(llvm::raw_ostream &OS); + ~Session(); + +private: + Session() = default; +}; + +// Records a single instant event, associated with the current thread. +void log(const llvm::Twine &Name); + +// Records an event whose duration is the lifetime of the Span object. +class Span { +public: + Span(const llvm::Twine &Name); + ~Span(); + +private: +}; + +} // namespace trace +} // namespace clangd +} // namespace clang + +#endif // LLVM_CLANG_TOOLS_EXTRA_CLANGD_TRACE_H_ Index: clangd/Trace.cpp =================================================================== --- /dev/null +++ clangd/Trace.cpp @@ -0,0 +1,121 @@ +//===--- Trace.cpp - Performance tracing facilities -----------------------===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// + +#include "Trace.h" + +#include "llvm/ADT/DenseSet.h" +#include "llvm/Support/Chrono.h" +#include "llvm/Support/FormatProviders.h" +#include "llvm/Support/FormatVariadic.h" +#include "llvm/Support/Threading.h" +#include "llvm/Support/YAMLParser.h" +#include + +namespace clang { +namespace clangd { +namespace trace { +using namespace llvm; + +namespace { +// The current implementation is naive: each thread writes to Out guarded by Mu. +// Perhaps we should replace this by something that disturbs performance less. +class Tracer { +public: + Tracer(raw_ostream &Out) + : Out(Out), Sep(""), Start(std::chrono::system_clock::now()) { + // The displayTimeUnit must be ns to avoid low-precision overlap + // calculations! + Out << R"({"displayTimeUnit":"ns","traceEvents":[)" + << "\n"; + rawEvent("M", R"("name": "process_name", "args":{"name":"clangd"})"); + } + + ~Tracer() { + Out << "\n]}"; + Out.flush(); + } + + // Record an event on the current thread. ph, pid, tid, ts are set. + // Contents must be a list of the other JSON key/values. + template void event(StringRef Phase, const T &Contents) { + uint64_t TID = get_threadid(); + std::lock_guard Lock(Mu); + // If we haven't already, emit metadata describing this thread. + if (ThreadsWithMD.insert(TID).second) { + SmallString<32> Name; + get_thread_name(Name); + if (!Name.empty()) { + rawEvent( + "M", + formatv( + R"("tid": {0}, "name": "thread_name", "args":{"name":"{1}"})", + TID, StringRef(&Name[0], Name.size()))); + } + } + rawEvent(Phase, formatv(R"("ts":{0}, "tid":{1}, {2})", timestamp(), TID, + Contents)); + } + +private: + // Record an event. ph and pid are set. + // Contents must be a list of the other JSON key/values. + template + void rawEvent(StringRef Phase, const T &Contents) /*REQUIRES(Mu)*/ { + // PID 0 represents the clangd process. + Out << Sep << R"({"pid":0, "ph":")" << Phase << "\", " << Contents << "}"; + Sep = ",\n"; + } + + double timestamp() { + using namespace std::chrono; + return duration(system_clock::now() - Start).count(); + } + + std::mutex Mu; + raw_ostream &Out /*GUARDED_BY(Mu)*/; + const char *Sep /*GUARDED_BY(Mu)*/; + DenseSet ThreadsWithMD /*GUARDED_BY(Mu)*/; + const sys::TimePoint<> Start; +}; + +static Tracer *T = nullptr; +} // namespace + +std::unique_ptr Session::createJSON(raw_ostream &OS) { + assert(!T && "A session is already active"); + T = new Tracer(OS); + return std::unique_ptr(new Session()); +} + +Session::~Session() { + delete T; + T = nullptr; +} + +void log(const Twine &Message) { + if (!T) + return; + T->event("i", formatv(R"("name":"{0}")", yaml::escape(Message.str()))); +} + +Span::Span(const Twine &Text) { + if (!T) + return; + T->event("B", formatv(R"("name":"{0}")", yaml::escape(Text.str()))); +} + +Span::~Span() { + if (!T) + return; + T->event("E", R"("_":0)" /* Dummy property to ensure valid JSON */); +} + +} // namespace trace +} // namespace clangd +} // namespace clang Index: clangd/tool/ClangdMain.cpp =================================================================== --- clangd/tool/ClangdMain.cpp +++ clangd/tool/ClangdMain.cpp @@ -10,6 +10,7 @@ #include "ClangdLSPServer.h" #include "JSONRPCDispatcher.h" #include "Path.h" +#include "Trace.h" #include "llvm/Support/CommandLine.h" #include "llvm/Support/FileSystem.h" #include "llvm/Support/Path.h" @@ -56,6 +57,12 @@ "Mirror all LSP input to the specified file. Useful for debugging."), llvm::cl::init(""), llvm::cl::Hidden); +static llvm::cl::opt TraceFile( + "trace", + llvm::cl::desc( + "Trace internal events and timestamps in chrome://tracing JSON format"), + llvm::cl::init(""), llvm::cl::Hidden); + int main(int argc, char *argv[]) { llvm::cl::ParseCommandLineOptions(argc, argv, "clangd"); @@ -81,6 +88,18 @@ << EC.message(); } } + llvm::Optional TraceStream; + std::unique_ptr TraceSession; + if (!TraceFile.empty()) { + std::error_code EC; + TraceStream.emplace(TraceFile, /*ref*/ EC, llvm::sys::fs::F_RW); + if (EC) { + TraceFile.reset(); + llvm::errs() << "Error while opening trace file: " << EC.message(); + } else { + TraceSession = trace::Session::create(*TraceStream); + } + } llvm::raw_ostream &Outs = llvm::outs(); llvm::raw_ostream &Logs = llvm::errs(); @@ -113,7 +132,7 @@ // Initialize and run ClangdLSPServer. ClangdLSPServer LSPServer(Out, WorkerThreadsCount, EnableSnippets, ResourceDirRef, CompileCommandsDirPath); - constexpr int NoShutdownRequestErrorCode = 1; + llvm::set_thread_name("clangd.main"); return LSPServer.run(std::cin) ? 0 : NoShutdownRequestErrorCode; } Index: test/clangd/trace.test =================================================================== --- /dev/null +++ test/clangd/trace.test @@ -0,0 +1,16 @@ +# RUN: clangd -run-synchronously -trace %t < %s && FileCheck %s < %t +# It is absolutely vital that this file has CRLF line endings. +# +Content-Length: 125 + +{"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":123,"rootPath":"clangd","capabilities":{},"trace":"off"}} +# +Content-Length: 152 + +{"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocument":{"uri":"file:///foo.c","languageId":"c","version":1,"text":"void main() {}"}}} +# CHECK: "textDocument/didOpen" +# CHECK: "Preamble: /foo.c" +# CHECK: "Build: /foo.c" +Content-Length: 44 + +{"jsonrpc":"2.0","id":5,"method":"shutdown"} Index: unittests/clangd/CMakeLists.txt =================================================================== --- unittests/clangd/CMakeLists.txt +++ unittests/clangd/CMakeLists.txt @@ -10,6 +10,7 @@ add_extra_unittest(ClangdTests ClangdTests.cpp + TraceTests.cpp ) target_link_libraries(ClangdTests Index: unittests/clangd/TraceTests.cpp =================================================================== --- /dev/null +++ unittests/clangd/TraceTests.cpp @@ -0,0 +1,119 @@ +//===-- TraceTests.cpp - Tracing unit tests ---------------------*- C++ -*-===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// + +#include "Trace.h" + +#include "llvm/ADT/DenseMap.h" +#include "llvm/ADT/SmallString.h" +#include "llvm/Support/SourceMgr.h" +#include "llvm/Support/YAMLParser.h" +#include "gmock/gmock.h" +#include "gtest/gtest.h" + +namespace clang { +namespace clangd { +namespace { +using namespace llvm; + +MATCHER_P(StringNode, Val, "") { + if (arg->getType() != yaml::Node::NK_Scalar) { + *result_listener << "is a " << arg->getVerbatimTag(); + return false; + } + SmallString<32> S; + return Val == static_cast(arg)->getValue(S); +} + +// Checks that N is a Mapping (JS object) with the expected scalar properties. +// The object must have all the Expected properties, but may have others. +bool VerifyObject(yaml::Node &N, std::map Expected) { + auto *M = dyn_cast(&N); + if (!M) { + ADD_FAILURE() << "Not an object"; + return false; + } + bool Match = true; + SmallString<32> Tmp; + for (auto Prop : *M) { + auto *K = dyn_cast_or_null(Prop.getKey()); + if (!K) + continue; + std::string KS = K->getValue(Tmp).str(); + auto I = Expected.find(KS); + if (I == Expected.end()) + continue; // Ignore properties with no assertion. + + auto *V = dyn_cast_or_null(Prop.getValue()); + if (!V) { + ADD_FAILURE() << KS << " is not a string"; + Match = false; + } + std::string VS = V->getValue(Tmp).str(); + if (VS != I->second) { + ADD_FAILURE() << KS << " expected " << I->second << " but actual " << VS; + Match = false; + } + Expected.erase(I); + } + for (const auto &P : Expected) { + ADD_FAILURE() << P.first << " missing, expected " << P.second; + Match = false; + } + return Match; +} + +TEST(TraceTest, SmokeTest) { + // Capture some events. + std::string JSON; + raw_string_ostream OS(JSON); + trace::start(OS); + { + trace::Span S("A"); + trace::log("B"); + } + trace::stop(); + + // Get the root JSON object using the YAML parser. + SourceMgr SM; + yaml::Stream Stream(JSON, SM); + auto Doc = Stream.begin(); + ASSERT_NE(Doc, Stream.end()); + auto *Root = dyn_cast_or_null(Doc->getRoot()); + ASSERT_NE(Root, nullptr) << "Root should be an object"; + + // We expect in order: + // displayTimeUnit: "ns" + // traceEvents: [process name, thread name, start span, log, end span] + // (The order doesn't matter, but the YAML parser is awkward to use otherwise) + auto Prop = Root->begin(); + ASSERT_NE(Prop, Root->end()) << "Expected displayTimeUnit property"; + ASSERT_THAT(Prop->getKey(), StringNode("displayTimeUnit")); + EXPECT_THAT(Prop->getValue(), StringNode("ns")); + ASSERT_NE(++Prop, Root->end()) << "Expected traceEvents property"; + EXPECT_THAT(Prop->getKey(), StringNode("traceEvents")); + auto *Events = dyn_cast_or_null(Prop->getValue()); + ASSERT_NE(Events, nullptr) << "traceEvents should be an array"; + auto Event = Events->begin(); + ASSERT_NE(Event, Events->end()) << "Expected process name"; + EXPECT_TRUE(VerifyObject(*Event, {{"ph", "M"}, {"name", "process_name"}})); + ASSERT_NE(++Event, Events->end()) << "Expected thread name"; + EXPECT_TRUE(VerifyObject(*Event, {{"ph", "M"}, {"name", "thread_name"}})); + ASSERT_NE(++Event, Events->end()) << "Expected span start"; + EXPECT_TRUE(VerifyObject(*Event, {{"ph", "B"}, {"name", "A"}})); + ASSERT_NE(++Event, Events->end()) << "Expected log message"; + EXPECT_TRUE(VerifyObject(*Event, {{"ph", "i"}, {"name", "B"}})); + ASSERT_NE(++Event, Events->end()) << "Expected span end"; + EXPECT_TRUE(VerifyObject(*Event, {{"ph", "E"}})); + ASSERT_EQ(++Event, Events->end()); + ASSERT_EQ(++Prop, Root->end()); +} + +} // namespace +} // namespace clangd +} // namespace clang