Commit da355ecd authored by Harshit Saokar's avatar Harshit Saokar Committed by Facebook GitHub Bot

Instrument time spent by fiber in running state and log it for SR eventbase threads

Summary:
We often run into cases where system CPU util is low but SR eventbase threads are backing up. During S213134 debugging, it took us a while to figure out that requests with http transport were expensive and causing issues on intern-rpc clients and later realized it was a known issue for http transport to be CPU intensive. We got lucky that http transport requests used different stack we could see in strobelight, but this will likely not be the case for other similar issues.

For ease of debugging these issues, one idea is to log SR Eventbase cost of each request to SR scuba. **The closest proxy for this is the wall clock time spent by SR's request-dispatch task in fiber, excluding all the preemptions.** This metric does have couple of drawbacks:

- It wont capture all the work a request does via runInMainContext. This should be Ok since SR tries not to do lot of work in mainContext of fiber manager.
- If system context switching the threads a lot and if eventbase thread is preempted by OS, we will count that time as time spent in task. I am hoping that new metric will still be useful even with this caveat.

Design: Allow fiberManager.AddTask() to optionally take in a bool `logRunningTime` to decide whether it can log the running time of the task. If `logRunningTime` is set, fiber will keep track of elapsed time since most recent run in  `currStartTime_` and track the running time of all previous runs together in  `prevDuration_`.

I looked into using ExecutionObserver for this purpose. I did not go that route because
1. ExecutionObserver's callbacks return fiber IDs, we want a callback to return function/task ID that we can tie back to Sr request.  See here https://fburl.com/diffusion/qh9ioeq3
2. Caller (SR) will need to maintain the separate cache of all outstanding tasks with their running_times and manage their lifetime, which feels more complex than current approach.

I have a way to turn off this change using new killswitch I added in SR.

Reviewed By: yfeldblum

Differential Revision: D24823396

fbshipit-source-id: 62f79b8c340cc48a22684c9cb3cdddadc260a0ab
parent ceee59a7
......@@ -22,10 +22,11 @@ namespace folly {
namespace fibers {
template <typename F>
void Fiber::setFunction(F&& func) {
void Fiber::setFunction(F&& func, TaskOptions taskOptions) {
assert(state_ == INVALID);
func_ = std::forward<F>(func);
state_ = NOT_STARTED;
taskOptions_ = std::move(taskOptions);
}
template <typename F, typename G>
......@@ -34,6 +35,7 @@ void Fiber::setFunctionFinally(F&& resultFunc, G&& finallyFunc) {
resultFunc_ = std::forward<F>(resultFunc);
finallyFunc_ = std::forward<G>(finallyFunc);
state_ = NOT_STARTED;
taskOptions_ = TaskOptions();
}
inline void* Fiber::getUserBuffer() {
......
......@@ -135,6 +135,10 @@ void Fiber::recordStackPosition() {
DCHECK_EQ(state_, NOT_STARTED);
threadId_ = localThreadId();
if (taskOptions_.logRunningTime) {
prevDuration_ = std::chrono::microseconds(0);
currStartTime_ = std::chrono::steady_clock::now();
}
state_ = RUNNING;
try {
......@@ -176,14 +180,23 @@ void Fiber::preempt(State state) {
CHECK_EQ(fiberManager_.numUncaughtExceptions_, uncaught_exceptions());
}
if (taskOptions_.logRunningTime) {
auto now = std::chrono::steady_clock::now();
prevDuration_ += now - currStartTime_;
currStartTime_ = now;
}
state_ = state;
recordStackPosition();
fiberManager_.deactivateFiber(this);
// Resumed from preemption
DCHECK_EQ(fiberManager_.activeFiber_, this);
DCHECK_EQ(state_, READY_TO_RUN);
if (taskOptions_.logRunningTime) {
currStartTime_ = std::chrono::steady_clock::now();
}
state_ = RUNNING;
};
......
......@@ -36,6 +36,15 @@ namespace fibers {
class Baton;
class FiberManager;
struct TaskOptions {
TaskOptions() {}
/**
* Should log the running time of the task? Refer to
* getCurrentTaskRunningTime() for details.
*/
bool logRunningTime = false;
};
/**
* @class Fiber
* @brief Fiber object used by FiberManager to execute tasks.
......@@ -88,7 +97,7 @@ class Fiber {
void init(bool recordStackUsed);
template <typename F>
void setFunction(F&& func);
void setFunction(F&& func, TaskOptions taskOptions);
template <typename F, typename G>
void setFunctionFinally(F&& func, G&& finally);
......@@ -118,6 +127,8 @@ class Fiber {
folly::Function<void()> func_; /**< task function */
bool recordStackUsed_{false};
bool stackFilledWithMagic_{false};
std::chrono::steady_clock::time_point currStartTime_;
std::chrono::steady_clock::duration prevDuration_{0};
/**
* Points to next fiber in remote ready list
......@@ -131,6 +142,7 @@ class Fiber {
folly::Function<void()> resultFunc_;
folly::Function<void()> finallyFunc_;
TaskOptions taskOptions_;
class LocalData {
public:
......
......@@ -158,6 +158,7 @@ inline void FiberManager::runReadyFiber(Fiber* fiber) {
// running at this point.
fiber->func_ = nullptr;
fiber->resultFunc_ = nullptr;
fiber->taskOptions_ = TaskOptions();
if (fiber->finallyFunc_) {
try {
fiber->finallyFunc_();
......@@ -285,7 +286,7 @@ inline void FiberManager::loopUntilNoReadyImpl() {
}
fiber->rcontext_ = std::move(task->rcontext);
fiber->setFunction(std::move(task->func));
fiber->setFunction(std::move(task->func), TaskOptions());
if (observer_) {
observer_->runnable(reinterpret_cast<uintptr_t>(fiber));
}
......@@ -357,7 +358,7 @@ struct FiberManager::AddTaskHelper {
};
template <typename F>
Fiber* FiberManager::createTask(F&& func) {
Fiber* FiberManager::createTask(F&& func, TaskOptions taskOptions) {
typedef AddTaskHelper<F> Helper;
auto fiber = getFiber();
......@@ -367,11 +368,11 @@ Fiber* FiberManager::createTask(F&& func) {
auto funcLoc = static_cast<typename Helper::Func*>(fiber->getUserBuffer());
new (funcLoc) typename Helper::Func(std::forward<F>(func), *this);
fiber->setFunction(std::ref(*funcLoc));
fiber->setFunction(std::ref(*funcLoc), std::move(taskOptions));
} else {
auto funcLoc = new typename Helper::Func(std::forward<F>(func), *this);
fiber->setFunction(std::ref(*funcLoc));
fiber->setFunction(std::ref(*funcLoc), std::move(taskOptions));
}
if (observer_) {
......@@ -382,14 +383,15 @@ Fiber* FiberManager::createTask(F&& func) {
}
template <typename F>
void FiberManager::addTask(F&& func) {
readyFibers_.push_back(*createTask(std::forward<F>(func)));
void FiberManager::addTask(F&& func, TaskOptions taskOptions) {
readyFibers_.push_back(
*createTask(std::forward<F>(func), std::move(taskOptions)));
ensureLoopScheduled();
}
template <typename F>
void FiberManager::addTaskEager(F&& func) {
runEagerFiber(createTask(std::forward<F>(func)));
runEagerFiber(createTask(std::forward<F>(func), TaskOptions()));
}
template <typename F>
......@@ -569,6 +571,16 @@ inline bool FiberManager::hasActiveFiber() const {
return activeFiber_ != nullptr;
}
inline folly::Optional<std::chrono::nanoseconds>
FiberManager::getCurrentTaskRunningTime() const {
if (activeFiber_ && activeFiber_->taskOptions_.logRunningTime &&
activeFiber_->state_ == Fiber::RUNNING) {
return activeFiber_->prevDuration_ + std::chrono::steady_clock::now() -
activeFiber_->currStartTime_;
}
return folly::none;
}
inline void FiberManager::yield() {
assert(getCurrentFiberManager() == this);
assert(activeFiber_ != nullptr);
......
......@@ -53,6 +53,8 @@ namespace fibers {
class Baton;
class Fiber;
struct TaskOptions;
template <typename T>
class LocalType {};
......@@ -243,9 +245,10 @@ class FiberManager : public ::folly::Executor {
*
* @param func Task functor; must have a signature of `void func()`.
* The object will be destroyed once task execution is complete.
* @param taskOptions Task specific configs.
*/
template <typename F>
void addTask(F&& func);
void addTask(F&& func, TaskOptions taskOptions = TaskOptions());
/**
* Add a new task to be executed and return a future that will be set on
......@@ -366,10 +369,18 @@ class FiberManager : public ::folly::Executor {
size_t fibersPoolSize() const;
/**
* return true if running activeFiber_ is not nullptr.
* @return true if running activeFiber_ is not nullptr.
*/
bool hasActiveFiber() const;
/**
* @return How long has the currently running task on the fiber ran, in
* terms of wallclock time. This excludes the time spent in preempted or
* waiting stages. This only works if TaskOptions.logRunningTime is true
* during addTask().
*/
folly::Optional<std::chrono::nanoseconds> getCurrentTaskRunningTime() const;
/**
* @return The currently running fiber or null if no fiber is executing.
*/
......@@ -444,7 +455,7 @@ class FiberManager : public ::folly::Executor {
};
template <typename F>
Fiber* createTask(F&& func);
Fiber* createTask(F&& func, TaskOptions taskOptions);
template <typename F, typename G>
Fiber* createTaskFinally(F&& func, G&& finally);
......
......@@ -28,7 +28,7 @@ using namespace folly::fibers;
static size_t sNumAwaits;
void runBenchmark(size_t numAwaits, size_t toSend) {
void runBenchmark(size_t numAwaits, size_t toSend, bool logRunningTime) {
sNumAwaits = numAwaits;
FiberManager fiberManager(std::make_unique<SimpleLoopController>());
......@@ -38,7 +38,13 @@ void runBenchmark(size_t numAwaits, size_t toSend) {
std::queue<Promise<int>> pendingRequests;
static const size_t maxOutstanding = 5;
auto loop = [&fiberManager, &loopController, &pendingRequests, &toSend]() {
auto loop = [&fiberManager,
&loopController,
&pendingRequests,
&toSend,
logRunningTime]() {
TaskOptions tOpt;
tOpt.logRunningTime = logRunningTime;
if (pendingRequests.size() == maxOutstanding || toSend == 0) {
if (pendingRequests.empty()) {
return;
......@@ -46,14 +52,16 @@ void runBenchmark(size_t numAwaits, size_t toSend) {
pendingRequests.front().setValue(0);
pendingRequests.pop();
} else {
fiberManager.addTask([&pendingRequests]() {
fiberManager.addTask(
[&pendingRequests]() {
for (size_t i = 0; i < sNumAwaits; ++i) {
auto result = await([&pendingRequests](Promise<int> promise) {
pendingRequests.push(std::move(promise));
});
DCHECK_EQ(result, 0);
}
});
},
std::move(tOpt));
if (--toSend == 0) {
loopController.stop();
......@@ -65,11 +73,19 @@ void runBenchmark(size_t numAwaits, size_t toSend) {
}
BENCHMARK(FiberManagerBasicOneAwait, iters) {
runBenchmark(1, iters);
runBenchmark(1, iters, false);
}
BENCHMARK(FiberManagerBasicOneAwaitLogged, iters) {
runBenchmark(1, iters, true);
}
BENCHMARK(FiberManagerBasicFiveAwaits, iters) {
runBenchmark(5, iters);
runBenchmark(5, iters, false);
}
BENCHMARK(FiberManagerBasicFiveAwaitsLogged, iters) {
runBenchmark(5, iters, true);
}
BENCHMARK(FiberManagerCreateDestroy, iters) {
......
......@@ -190,6 +190,27 @@ TEST(FiberManager, batonTimedWaitPostEvb) {
EXPECT_EQ(1, tasksComplete);
}
TEST(FiberManager, fiberTimeLogged) {
FiberManager manager(std::make_unique<SimpleLoopController>());
TaskOptions tOpt;
tOpt.logRunningTime = true;
manager.addTask(
[&]() {
LOG(INFO) << "logging time.";
EXPECT_LT(-1, manager.getCurrentTaskRunningTime()->count());
},
tOpt /*logRunningTime = true*/);
EXPECT_FALSE(manager.getCurrentTaskRunningTime());
tOpt.logRunningTime = false;
manager.addTask(
[&]() {
LOG(INFO) << "Not logging time.";
EXPECT_FALSE(manager.getCurrentTaskRunningTime());
},
tOpt /*logRunningTime = false*/);
manager.loopUntilNoReady();
}
TEST(FiberManager, batonTryWait) {
FiberManager manager(std::make_unique<SimpleLoopController>());
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment