// Copyright Vespa.ai. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. #include "deadlockdetector.h" #include "htmltable.h" #include #include #include #include #include #include LOG_SETUP(".deadlock.detector"); using document::BucketSpace; namespace storage { DeadLockDetector::DeadLockDetector(StorageComponentRegister& compReg, AppKiller::UP killer) : framework::HtmlStatusReporter("deadlockdetector", "Dead lock detector"), _killer(std::move(killer)), _states(), _lock(), _cond(), _enableWarning(true), _enableShutdown(false), _processSlack(30s), _waitSlack(5s) { auto* dComp(dynamic_cast(&compReg)); if (dComp) { _dComponent = std::make_unique(*dComp, "deadlockdetector"); _component = _dComponent.get(); } else { auto* slComp(dynamic_cast(&compReg)); assert(slComp != nullptr); _slComponent = std::make_unique(*slComp, "deadlockdetector"); _component = _slComponent.get(); } _component->registerStatusPage(*this); _thread = _component->startThread(*this); } DeadLockDetector::~DeadLockDetector() { if (_thread) { _thread->interruptAndJoin(_cond); } } void DeadLockDetector::enableWarning(bool enable) { if (enable == warning_enabled_relaxed()) { return; } LOG(debug, "%s dead lock detection warnings", enable ? "Enabling" : "Disabling"); _enableWarning.store(enable, std::memory_order_relaxed); } void DeadLockDetector::enableShutdown(bool enable) { if (enable == shutdown_enabled_relaxed()) { return; } LOG(debug, "%s dead lock detection", enable ? "Enabling" : "Disabling"); _enableShutdown.store(enable, std::memory_order_relaxed); } namespace { struct VisitorWrapper : public framework::ThreadVisitor { std::map& _states; DeadLockDetector::ThreadVisitor& _visitor; VisitorWrapper(std::map& s, DeadLockDetector::ThreadVisitor& visitor) : _states(s), _visitor(visitor) { } void visitThread(const framework::Thread& thread) override { if (_states.find(thread.getId()) == _states.end()) { _states[thread.getId()] = DeadLockDetector::OK; } _visitor.visitThread(thread, _states[thread.getId()]); } }; } void DeadLockDetector::visitThreads(ThreadVisitor& visitor) const { VisitorWrapper wrapper(_states, visitor); _component->getThreadPool().visitThreads(wrapper); } bool DeadLockDetector::isAboveFailThreshold(vespalib::steady_time time, const framework::ThreadProperties& tp, const framework::ThreadTickData& tick) const { if (tp.getMaxCycleTime() == vespalib::duration::zero()) { return false; } vespalib::duration slack(tick._lastTickType == framework::WAIT_CYCLE ? getWaitSlack() : getProcessSlack()); return (tick._lastTick + tp.getMaxCycleTime() + slack < time); } bool DeadLockDetector::isAboveWarnThreshold(vespalib::steady_time time, const framework::ThreadProperties& tp, const framework::ThreadTickData& tick) const { if (tp.getMaxCycleTime() == vespalib::duration::zero()) return false; vespalib::duration slack = tick._lastTickType == framework::WAIT_CYCLE ? getWaitSlack() : getProcessSlack(); return (tick._lastTick + tp.getMaxCycleTime() + slack / 4 < time); } vespalib::string DeadLockDetector::getBucketLockInfo() const { vespalib::asciistream ost; if (_dComponent.get() != nullptr) { ost << "No bucket lock information available for distributor\n"; } else { for (const auto &elem : _slComponent->getBucketSpaceRepo()) { const auto &bucketDatabase = elem.second->bucketDatabase(); if (bucketDatabase.size() > 0) { bucketDatabase.showLockClients(ost); } } } return ost.str(); } namespace { struct ThreadChecker : public DeadLockDetector::ThreadVisitor { DeadLockDetector& _detector; vespalib::steady_time _currentTime; ThreadChecker(DeadLockDetector& d, vespalib::steady_time time) : _detector(d), _currentTime(time) {} void visitThread(const framework::Thread& thread, DeadLockDetector::State& state) override { const auto& id = thread.getId(); const auto& tp = thread.getProperties(); const auto tick = thread.getTickData(); // In case we just got a new tick, ignore the thread if (tick._lastTick > _currentTime) return; // If thread is already in halted state, ignore it. if (state == DeadLockDetector::HALTED) return; if (_detector.isAboveFailThreshold(_currentTime, tp, tick)) { state = DeadLockDetector::HALTED; _detector.handleDeadlock(_currentTime, thread, id, tp, tick, false); } else if (_detector.isAboveWarnThreshold(_currentTime, tp, tick)) { state = DeadLockDetector::WARNED; _detector.handleDeadlock(_currentTime, thread, id, tp, tick, true); } else if (state != DeadLockDetector::OK) { vespalib::asciistream ost; ost << "Thread " << id << " has registered tick again."; LOGBP(info, "%s", ost.str().data()); state = DeadLockDetector::OK; } } }; } void DeadLockDetector::handleDeadlock(vespalib::steady_time currentTime, const framework::Thread& deadlocked_thread, const vespalib::string& id, const framework::ThreadProperties&, const framework::ThreadTickData& tick, bool warnOnly) { vespalib::asciistream error; error << "Thread " << id << " has gone " << vespalib::count_ms(currentTime - tick._lastTick) << " milliseconds without registering a tick."; const bool shutdown_enabled = shutdown_enabled_relaxed(); const bool warning_enabled = warning_enabled_relaxed(); if (!warnOnly) { if (shutdown_enabled) { error << " Restarting process due to presumed internal deadlock."; } else { error << " Would have restarted process due to deadlock if shutdown had been enabled."; } } else { // TODO would ideally print thread ID here, but it's not well-defined how to print a pthread_t... error << " Global slack not expended yet. Warning for now. Attempting to dump stack of thread...\n"; error << deadlocked_thread.get_live_thread_stack_trace(); } if (warnOnly) { if (warning_enabled) { LOGBT(warning, "deadlockw-" + id, "%s", vespalib::string(error.str()).c_str()); } return; } else { if (shutdown_enabled || warning_enabled) { LOGBT(error, "deadlock-" + id, "%s", vespalib::string(error.str()).c_str()); } } if (shutdown_enabled) { _killer->kill(); } } void DeadLockDetector::run(framework::ThreadHandle& thread) { std::unique_lock sync(_lock); while (!thread.interrupted()) { ThreadChecker checker(*this, _component->getClock().getMonotonicTime()); visitThreads(checker); _cond.wait_for(sync, 1s); thread.registerTick(framework::WAIT_CYCLE); } } namespace { struct ThreadTable { HtmlTable _table; LongColumn _msSinceLastTick; LongColumn _maxProcTickTime; LongColumn _maxWaitTickTime; LongColumn _maxProcTickTimeSeen; LongColumn _maxWaitTickTimeSeen; ThreadTable() : _table("Thread name"), _msSinceLastTick("Milliseconds since last tick", " ms", &_table), _maxProcTickTime("Max milliseconds before wait tick", " ms", &_table), _maxWaitTickTime("Max milliseconds before wait tick", " ms", &_table), _maxProcTickTimeSeen("Max processing tick time observed", " ms", &_table), _maxWaitTickTimeSeen("Max wait tick time observed", " ms", &_table) { _maxProcTickTime._alignment = Column::LEFT; _maxProcTickTimeSeen._alignment = Column::LEFT; _maxWaitTickTimeSeen._alignment = Column::LEFT; } ~ThreadTable(); }; ThreadTable::~ThreadTable() = default; struct ThreadStatusWriter : public DeadLockDetector::ThreadVisitor { ThreadTable& _table; vespalib::steady_time _time; ThreadStatusWriter(ThreadTable& table, vespalib::steady_time time) : _table(table), _time(time) {} template vespalib::string toS(const T& val) { vespalib::asciistream ost; ost << val; return ost.str(); } void visitThread(const framework::Thread& thread, DeadLockDetector::State& /*state*/) override { _table._table.addRow(thread.getId()); uint32_t i = _table._table.getRowCount() - 1; const auto& tp = thread.getProperties(); const auto tick = thread.getTickData(); _table._msSinceLastTick[i] = vespalib::count_ms(_time - tick._lastTick); _table._maxProcTickTime[i] = vespalib::count_ms(tp.getMaxProcessTime()); _table._maxWaitTickTime[i] = vespalib::count_ms(tp.getWaitTime()); _table._maxProcTickTimeSeen[i] = vespalib::count_ms(tick._maxProcessingTimeSeen); _table._maxWaitTickTimeSeen[i] = vespalib::count_ms(tick._maxWaitTimeSeen); } }; } void DeadLockDetector::reportHtmlStatus(std::ostream& os, const framework::HttpUrlPath&) const { vespalib::asciistream out; out << "

Overview of latest thread ticks

\n"; ThreadTable threads; std::lock_guard guard(_lock); ThreadStatusWriter writer(threads, _component->getClock().getMonotonicTime()); visitThreads(writer); std::ostringstream ost; threads._table.print(ost); out << ost.str(); out << "

\n" << "Note that there is a global slack period of " << vespalib::count_ms(getProcessSlack()) << " ms for processing ticks and " << vespalib::count_ms(getWaitSlack()) << " ms for wait ticks. Actual shutdown or warning logs will not" << " appear before this slack time is expendede on top of the per" << " thread value.\n" << "

\n"; if (shutdown_enabled_relaxed()) { out << "

The deadlock detector is enabled and will kill the process " << "if a deadlock is detected

\n"; } else { out << "

The deadlock detector is disabled and will only monitor " << "tick times.

\n"; } out << "

Current locks in the bucket database

\n" << "

In case of a software bug causing a deadlock in the code, bucket" << " database locks are a likely reason. Thus, we list current locks " << "here in hopes that it will simplify debugging.

\n" << "

Bucket database

\n" << "
\n"
        << getBucketLockInfo()
        << "
\n"; os << out.str(); } } // storage