[clangd] Tracing: name worker threads, and enforce naming scheduled async tasks

Summary:
This has a bit of a blast radius, but I think there's enough value in "forcing"
us to give names to these async tasks for debugging. Guessing about what
multithreaded code is doing is so unfun...

The "file" param attached to the tasks may seem to be redundant with the thread
names, but note that thread names are truncated to 15 chars on linux!
We'll be lucky to get the whole basename...

Reviewers: ilya-biryukov

Subscribers: klimek, jkorous-apple, ioeric, cfe-commits

Differential Revision: https://reviews.llvm.org/D43388

llvm-svn: 325480
This commit is contained in:
Sam McCall 2018-02-19 09:56:28 +00:00
parent ced2fe68f3
commit c901c5db78
9 changed files with 114 additions and 72 deletions

View File

@ -179,9 +179,10 @@ void ClangdServer::codeComplete(
Callback(make_tagged(std::move(Result), std::move(TaggedFS.Tag)));
};
WorkScheduler.runWithPreamble(File, BindWithForward(Task, std::move(Contents),
File.str(),
std::move(Callback)));
WorkScheduler.runWithPreamble("CodeComplete", File,
BindWithForward(Task, std::move(Contents),
File.str(),
std::move(Callback)));
}
void ClangdServer::signatureHelp(
@ -222,7 +223,8 @@ void ClangdServer::signatureHelp(
};
WorkScheduler.runWithPreamble(
File, BindWithForward(Action, File.str(), std::move(Callback)));
"SignatureHelp", File,
BindWithForward(Action, File.str(), std::move(Callback)));
}
llvm::Expected<tooling::Replacements>
@ -307,7 +309,7 @@ void ClangdServer::rename(
};
WorkScheduler.runWithAST(
File,
"Rename", File,
BindWithForward(Action, File.str(), NewName.str(), std::move(Callback)));
}
@ -376,7 +378,8 @@ void ClangdServer::dumpAST(PathRef File,
Callback(Result);
};
WorkScheduler.runWithAST(File, BindWithForward(Action, std::move(Callback)));
WorkScheduler.runWithAST("DumpAST", File,
BindWithForward(Action, std::move(Callback)));
}
void ClangdServer::findDefinitions(
@ -392,7 +395,8 @@ void ClangdServer::findDefinitions(
Callback(make_tagged(std::move(Result), TaggedFS.Tag));
};
WorkScheduler.runWithAST(File, BindWithForward(Action, std::move(Callback)));
WorkScheduler.runWithAST("Definitions", File,
BindWithForward(Action, std::move(Callback)));
}
llvm::Optional<Path> ClangdServer::switchSourceHeader(PathRef Path) {
@ -488,7 +492,8 @@ void ClangdServer::findDocumentHighlights(
Callback(make_tagged(std::move(Result), TaggedFS.Tag));
};
WorkScheduler.runWithAST(File, BindWithForward(Action, std::move(Callback)));
WorkScheduler.runWithAST("Highlights", File,
BindWithForward(Action, std::move(Callback)));
}
void ClangdServer::findHover(
@ -511,7 +516,8 @@ void ClangdServer::findHover(
Callback(make_tagged(std::move(Result), TaggedFS.Tag));
};
WorkScheduler.runWithAST(File, BindWithForward(Action, std::move(Callback)));
WorkScheduler.runWithAST("Hover", File,
BindWithForward(Action, std::move(Callback)));
}
void ClangdServer::scheduleReparseAndDiags(

View File

@ -44,8 +44,10 @@
#include "TUScheduler.h"
#include "Logger.h"
#include "Trace.h"
#include "clang/Frontend/PCHContainerOperations.h"
#include "llvm/Support/Errc.h"
#include "llvm/Support/Path.h"
#include <memory>
#include <queue>
#include <thread>
@ -67,7 +69,8 @@ class ASTWorkerHandle;
/// worker.
class ASTWorker {
friend class ASTWorkerHandle;
ASTWorker(Semaphore &Barrier, CppFile AST, bool RunSync);
ASTWorker(llvm::StringRef File, Semaphore &Barrier, CppFile AST,
bool RunSync);
public:
/// Create a new ASTWorker and return a handle to it.
@ -75,14 +78,15 @@ public:
/// is null, all requests will be processed on the calling thread
/// synchronously instead. \p Barrier is acquired when processing each
/// request, it is be used to limit the number of actively running threads.
static ASTWorkerHandle Create(AsyncTaskRunner *Tasks, Semaphore &Barrier,
CppFile AST);
static ASTWorkerHandle Create(llvm::StringRef File, AsyncTaskRunner *Tasks,
Semaphore &Barrier, CppFile AST);
~ASTWorker();
void update(ParseInputs Inputs,
UniqueFunction<void(llvm::Optional<std::vector<DiagWithFixIts>>)>
OnUpdated);
void runWithAST(UniqueFunction<void(llvm::Expected<InputsAndAST>)> Action);
void runWithAST(llvm::StringRef Name,
UniqueFunction<void(llvm::Expected<InputsAndAST>)> Action);
bool blockUntilIdle(Deadline Timeout) const;
std::shared_ptr<const PreambleData> getPossiblyStalePreamble() const;
@ -96,11 +100,16 @@ private:
/// Signal that run() should finish processing pending requests and exit.
void stop();
/// Adds a new task to the end of the request queue.
void startTask(UniqueFunction<void()> Task, bool isUpdate,
llvm::Optional<CancellationFlag> CF);
void startTask(llvm::StringRef Name, UniqueFunction<void()> Task,
bool isUpdate, llvm::Optional<CancellationFlag> CF);
using RequestWithCtx = std::pair<UniqueFunction<void()>, Context>;
struct Request {
UniqueFunction<void()> Action;
std::string Name;
Context Ctx;
};
std::string File;
const bool RunSync;
Semaphore &Barrier;
// AST and FileInputs are only accessed on the processing thread from run().
@ -114,7 +123,7 @@ private:
std::size_t LastASTSize; /* GUARDED_BY(Mutex) */
// Set to true to signal run() to finish processing.
bool Done; /* GUARDED_BY(Mutex) */
std::queue<RequestWithCtx> Requests; /* GUARDED_BY(Mutex) */
std::queue<Request> Requests; /* GUARDED_BY(Mutex) */
// Only set when last request is an update. This allows us to cancel an update
// that was never read, if a subsequent update comes in.
llvm::Optional<CancellationFlag> LastUpdateCF; /* GUARDED_BY(Mutex) */
@ -163,18 +172,21 @@ private:
std::shared_ptr<ASTWorker> Worker;
};
ASTWorkerHandle ASTWorker::Create(AsyncTaskRunner *Tasks, Semaphore &Barrier,
CppFile AST) {
ASTWorkerHandle ASTWorker::Create(llvm::StringRef File, AsyncTaskRunner *Tasks,
Semaphore &Barrier, CppFile AST) {
std::shared_ptr<ASTWorker> Worker(
new ASTWorker(Barrier, std::move(AST), /*RunSync=*/!Tasks));
new ASTWorker(File, Barrier, std::move(AST), /*RunSync=*/!Tasks));
if (Tasks)
Tasks->runAsync([Worker]() { Worker->run(); });
Tasks->runAsync("worker:" + llvm::sys::path::filename(File),
[Worker]() { Worker->run(); });
return ASTWorkerHandle(std::move(Worker));
}
ASTWorker::ASTWorker(Semaphore &Barrier, CppFile AST, bool RunSync)
: RunSync(RunSync), Barrier(Barrier), AST(std::move(AST)), Done(false) {
ASTWorker::ASTWorker(llvm::StringRef File, Semaphore &Barrier, CppFile AST,
bool RunSync)
: File(File), RunSync(RunSync), Barrier(Barrier), AST(std::move(AST)),
Done(false) {
if (RunSync)
return;
}
@ -212,11 +224,12 @@ void ASTWorker::update(
};
CancellationFlag UpdateCF;
startTask(BindWithForward(Task, UpdateCF, std::move(OnUpdated)),
startTask("Update", BindWithForward(Task, UpdateCF, std::move(OnUpdated)),
/*isUpdate=*/true, UpdateCF);
}
void ASTWorker::runWithAST(
llvm::StringRef Name,
UniqueFunction<void(llvm::Expected<InputsAndAST>)> Action) {
auto Task = [=](decltype(Action) Action) {
ParsedAST *ActualAST = AST.getAST();
@ -233,8 +246,8 @@ void ASTWorker::runWithAST(
LastASTSize = ActualAST->getUsedBytes();
};
startTask(BindWithForward(Task, std::move(Action)), /*isUpdate=*/false,
llvm::None);
startTask(Name, BindWithForward(Task, std::move(Action)),
/*isUpdate=*/false, llvm::None);
}
std::shared_ptr<const PreambleData>
@ -257,13 +270,14 @@ void ASTWorker::stop() {
RequestsCV.notify_all();
}
void ASTWorker::startTask(UniqueFunction<void()> Task, bool isUpdate,
llvm::Optional<CancellationFlag> CF) {
void ASTWorker::startTask(llvm::StringRef Name, UniqueFunction<void()> Task,
bool isUpdate, llvm::Optional<CancellationFlag> CF) {
assert(isUpdate == CF.hasValue() &&
"Only updates are expected to pass CancellationFlag");
if (RunSync) {
assert(!Done && "running a task after stop()");
trace::Span Tracer(Name + ":" + llvm::sys::path::filename(File));
Task();
return;
}
@ -281,14 +295,14 @@ void ASTWorker::startTask(UniqueFunction<void()> Task, bool isUpdate,
} else {
LastUpdateCF = llvm::None;
}
Requests.emplace(std::move(Task), Context::current().clone());
Requests.push({std::move(Task), Name, Context::current().clone()});
} // unlock Mutex.
RequestsCV.notify_all();
}
void ASTWorker::run() {
while (true) {
RequestWithCtx Req;
Request Req;
{
std::unique_lock<std::mutex> Lock(Mutex);
RequestsCV.wait(Lock, [&]() { return Done || !Requests.empty(); });
@ -303,9 +317,12 @@ void ASTWorker::run() {
// Leave it on the queue for now, so waiters don't see an empty queue.
} // unlock Mutex
std::lock_guard<Semaphore> BarrierLock(Barrier);
WithContext Guard(std::move(Req.second));
Req.first();
{
std::lock_guard<Semaphore> BarrierLock(Barrier);
WithContext Guard(std::move(Req.Ctx));
trace::Span Tracer(Req.Name);
Req.Action();
}
{
std::lock_guard<std::mutex> Lock(Mutex);
@ -379,7 +396,7 @@ void TUScheduler::update(
if (!FD) {
// Create a new worker to process the AST-related tasks.
ASTWorkerHandle Worker = ASTWorker::Create(
WorkerThreads ? WorkerThreads.getPointer() : nullptr, Barrier,
File, WorkerThreads ? WorkerThreads.getPointer() : nullptr, Barrier,
CppFile(File, StorePreamblesInMemory, PCHOps, ASTCallback));
FD = std::unique_ptr<FileData>(new FileData{Inputs, std::move(Worker)});
} else {
@ -396,7 +413,8 @@ void TUScheduler::remove(PathRef File) {
}
void TUScheduler::runWithAST(
PathRef File, UniqueFunction<void(llvm::Expected<InputsAndAST>)> Action) {
llvm::StringRef Name, PathRef File,
UniqueFunction<void(llvm::Expected<InputsAndAST>)> Action) {
auto It = Files.find(File);
if (It == Files.end()) {
Action(llvm::make_error<llvm::StringError>(
@ -405,11 +423,11 @@ void TUScheduler::runWithAST(
return;
}
It->second->Worker->runWithAST(std::move(Action));
It->second->Worker->runWithAST(Name, std::move(Action));
}
void TUScheduler::runWithPreamble(
PathRef File,
llvm::StringRef Name, PathRef File,
UniqueFunction<void(llvm::Expected<InputsAndPreamble>)> Action) {
auto It = Files.find(File);
if (It == Files.end()) {
@ -420,6 +438,8 @@ void TUScheduler::runWithPreamble(
}
if (!PreambleTasks) {
trace::Span Tracer(Name);
SPAN_ATTACH(Tracer, "file", File);
std::shared_ptr<const PreambleData> Preamble =
It->second->Worker->getPossiblyStalePreamble();
Action(InputsAndPreamble{It->second->Inputs, Preamble.get()});
@ -428,17 +448,22 @@ void TUScheduler::runWithPreamble(
ParseInputs InputsCopy = It->second->Inputs;
std::shared_ptr<const ASTWorker> Worker = It->second->Worker.lock();
auto Task = [InputsCopy, Worker, this](Context Ctx,
auto Task = [InputsCopy, Worker, this](std::string Name, std::string File,
Context Ctx,
decltype(Action) Action) mutable {
std::lock_guard<Semaphore> BarrierLock(Barrier);
WithContext Guard(std::move(Ctx));
trace::Span Tracer(Name);
SPAN_ATTACH(Tracer, "file", File);
std::shared_ptr<const PreambleData> Preamble =
Worker->getPossiblyStalePreamble();
Action(InputsAndPreamble{InputsCopy, Preamble.get()});
};
PreambleTasks->runAsync(
BindWithForward(Task, Context::current().clone(), std::move(Action)));
"task:" + llvm::sys::path::filename(File),
BindWithForward(Task, std::string(Name), std::string(File),
Context::current().clone(), std::move(Action)));
}
std::vector<std::pair<Path, std::size_t>>

View File

@ -37,7 +37,7 @@ struct InputsAndPreamble {
/// TUScheduler is not thread-safe, only one thread should be providing updates
/// and scheduling tasks.
/// Callbacks are run on a threadpool and it's appropriate to do slow work in
/// them.
/// them. Each task has a name, used for tracing (should be UpperCamelCase).
class TUScheduler {
public:
TUScheduler(unsigned AsyncThreadsCount, bool StorePreamblesInMemory,
@ -65,7 +65,7 @@ public:
/// \p Action is executed.
/// If an error occurs during processing, it is forwarded to the \p Action
/// callback.
void runWithAST(PathRef File,
void runWithAST(llvm::StringRef Name, PathRef File,
UniqueFunction<void(llvm::Expected<InputsAndAST>)> Action);
/// Schedule an async read of the Preamble. Preamble passed to \p Action may
@ -74,7 +74,7 @@ public:
/// If an error occurs during processing, it is forwarded to the \p Action
/// callback.
void runWithPreamble(
PathRef File,
llvm::StringRef Name, PathRef File,
UniqueFunction<void(llvm::Expected<InputsAndPreamble>)> Action);
/// Wait until there are no scheduled or running tasks.

View File

@ -34,7 +34,8 @@ bool AsyncTaskRunner::wait(Deadline D) const {
[&] { return InFlightTasks == 0; });
}
void AsyncTaskRunner::runAsync(UniqueFunction<void()> Action) {
void AsyncTaskRunner::runAsync(llvm::Twine Name,
UniqueFunction<void()> Action) {
{
std::lock_guard<std::mutex> Lock(Mutex);
++InFlightTasks;
@ -51,13 +52,14 @@ void AsyncTaskRunner::runAsync(UniqueFunction<void()> Action) {
});
std::thread(
[](decltype(Action) Action, decltype(CleanupTask)) {
[](std::string Name, decltype(Action) Action, decltype(CleanupTask)) {
llvm::set_thread_name(Name);
Action();
// Make sure function stored by Action is destroyed before CleanupTask
// is run.
Action = nullptr;
},
std::move(Action), std::move(CleanupTask))
Name.str(), std::move(Action), std::move(CleanupTask))
.detach();
}

View File

@ -12,6 +12,7 @@
#include "Context.h"
#include "Function.h"
#include "llvm/ADT/Twine.h"
#include <atomic>
#include <cassert>
#include <condition_variable>
@ -81,7 +82,8 @@ public:
void wait() const { (void) wait(llvm::None); }
LLVM_NODISCARD bool wait(Deadline D) const;
void runAsync(UniqueFunction<void()> Action);
// The name is used for tracing and debugging (e.g. to name a spawned thread).
void runAsync(llvm::Twine Name, UniqueFunction<void()> Action);
private:
mutable std::mutex Mutex;

View File

@ -208,17 +208,19 @@ void log(const Twine &Message) {
}
// Returned context owns Args.
static Context makeSpanContext(llvm::StringRef Name, json::obj *Args) {
static Context makeSpanContext(llvm::Twine Name, json::obj *Args) {
if (!T)
return Context::current().clone();
WithContextValue WithArgs{std::unique_ptr<json::obj>(Args)};
return T->beginSpan(Name, Args);
return T->beginSpan(Name.isSingleStringRef() ? Name.getSingleStringRef()
: llvm::StringRef(Name.str()),
Args);
}
// Span keeps a non-owning pointer to the args, which is how users access them.
// The args are owned by the context though. They stick around until the
// beginSpan() context is destroyed, when the tracing engine will consume them.
Span::Span(llvm::StringRef Name)
Span::Span(llvm::Twine Name)
: Args(T ? new json::obj() : nullptr),
RestoreCtx(makeSpanContext(Name, Args)) {}

View File

@ -82,7 +82,7 @@ void log(const llvm::Twine &Name);
/// SomeJSONExpr is evaluated and copied only if actually needed.
class Span {
public:
Span(llvm::StringRef Name);
Span(llvm::Twine Name);
~Span();
/// Mutable metadata, if this span is interested.

View File

@ -54,31 +54,33 @@ TEST_F(TUSchedulerTests, MissingFiles) {
// Assert each operation for missing file is an error (even if it's available
// in VFS).
S.runWithAST(Missing, [&](llvm::Expected<InputsAndAST> AST) {
S.runWithAST("", Missing, [&](llvm::Expected<InputsAndAST> AST) {
ASSERT_FALSE(bool(AST));
ignoreError(AST.takeError());
});
S.runWithPreamble(Missing, [&](llvm::Expected<InputsAndPreamble> Preamble) {
ASSERT_FALSE(bool(Preamble));
ignoreError(Preamble.takeError());
});
S.runWithPreamble("", Missing,
[&](llvm::Expected<InputsAndPreamble> Preamble) {
ASSERT_FALSE(bool(Preamble));
ignoreError(Preamble.takeError());
});
// remove() shouldn't crash on missing files.
S.remove(Missing);
// Assert there aren't any errors for added file.
S.runWithAST(
Added, [&](llvm::Expected<InputsAndAST> AST) { EXPECT_TRUE(bool(AST)); });
S.runWithPreamble(Added, [&](llvm::Expected<InputsAndPreamble> Preamble) {
S.runWithAST("", Added, [&](llvm::Expected<InputsAndAST> AST) {
EXPECT_TRUE(bool(AST));
});
S.runWithPreamble("", Added, [&](llvm::Expected<InputsAndPreamble> Preamble) {
EXPECT_TRUE(bool(Preamble));
});
S.remove(Added);
// Assert that all operations fail after removing the file.
S.runWithAST(Added, [&](llvm::Expected<InputsAndAST> AST) {
S.runWithAST("", Added, [&](llvm::Expected<InputsAndAST> AST) {
ASSERT_FALSE(bool(AST));
ignoreError(AST.takeError());
});
S.runWithPreamble(Added, [&](llvm::Expected<InputsAndPreamble> Preamble) {
S.runWithPreamble("", Added, [&](llvm::Expected<InputsAndPreamble> Preamble) {
ASSERT_FALSE(bool(Preamble));
ignoreError(Preamble.takeError());
});
@ -143,24 +145,27 @@ TEST_F(TUSchedulerTests, ManyUpdates) {
{
WithContextValue WithNonce(NonceKey, ++Nonce);
S.runWithAST(File, [Inputs, Nonce, &Mut, &TotalASTReads](
llvm::Expected<InputsAndAST> AST) {
EXPECT_THAT(Context::current().get(NonceKey), Pointee(Nonce));
S.runWithAST("CheckAST", File,
[Inputs, Nonce, &Mut,
&TotalASTReads](llvm::Expected<InputsAndAST> AST) {
EXPECT_THAT(Context::current().get(NonceKey),
Pointee(Nonce));
ASSERT_TRUE((bool)AST);
EXPECT_EQ(AST->Inputs.FS, Inputs.FS);
EXPECT_EQ(AST->Inputs.Contents, Inputs.Contents);
ASSERT_TRUE((bool)AST);
EXPECT_EQ(AST->Inputs.FS, Inputs.FS);
EXPECT_EQ(AST->Inputs.Contents, Inputs.Contents);
std::lock_guard<std::mutex> Lock(Mut);
++TotalASTReads;
});
std::lock_guard<std::mutex> Lock(Mut);
++TotalASTReads;
});
}
{
WithContextValue WithNonce(NonceKey, ++Nonce);
S.runWithPreamble(
File, [Inputs, Nonce, &Mut, &TotalPreambleReads](
llvm::Expected<InputsAndPreamble> Preamble) {
"CheckPreamble", File,
[Inputs, Nonce, &Mut, &TotalPreambleReads](
llvm::Expected<InputsAndPreamble> Preamble) {
EXPECT_THAT(Context::current().get(NonceKey), Pointee(Nonce));
ASSERT_TRUE((bool)Preamble);

View File

@ -29,7 +29,7 @@ TEST_F(ThreadingTest, TaskRunner) {
AsyncTaskRunner Tasks;
auto scheduleIncrements = [&]() {
for (int TaskI = 0; TaskI < TasksCnt; ++TaskI) {
Tasks.runAsync([&Counter, &Mutex, IncrementsPerTask]() {
Tasks.runAsync("task", [&Counter, &Mutex, IncrementsPerTask]() {
for (int Increment = 0; Increment < IncrementsPerTask; ++Increment) {
std::lock_guard<std::mutex> Lock(Mutex);
++Counter;