Skip to content

Commit 77763ba

Browse files
committed
DPL: reduce verbosity of the missing resources warning
In order to avoid too many messages about missing resources, keep a watermark so that if some resource exhaustion is normal (e.g. the task can read faster than it can process) we do not complain unless the behavior exceeds the watermark.
1 parent 27f5bda commit 77763ba

1 file changed

Lines changed: 53 additions & 22 deletions

File tree

‎Framework/Core/src/DataProcessingDevice.cxx‎

Lines changed: 53 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -1377,11 +1377,47 @@ void DataProcessingDevice::Run()
13771377
bool enough = ref.get<ComputingQuotaEvaluator>().selectOffer(streamRef.index, spec.resourcePolicy.request, uv_now(state.loop), &accumulated);
13781378

13791379
struct SchedulingStats {
1380+
// minWarnDelay: stalls shorter than this are never worth warning about.
1381+
// healthToForget: uninterrupted health needed to halve the threshold, as a
1382+
// multiple of the threshold itself.
1383+
// minHealthToForget: no decay at all below this much health, so a storm of
1384+
// short hiccups separated by short recoveries never re-arms the warning.
1385+
enum : size_t { minWarnDelay = 50,
1386+
healthToForget = 3,
1387+
minHealthToForget = 60000 };
13801388
std::atomic<size_t> lastScheduled = 0;
13811389
std::atomic<size_t> numberOfUnscheduledSinceLastScheduled = 0;
13821390
std::atomic<size_t> numberOfUnscheduled = 0;
13831391
std::atomic<size_t> numberOfScheduled = 0;
1384-
std::atomic<size_t> nextWarnAt = 1;
1392+
// Longest stall already warned about, doubled, so a stall no worse than an
1393+
// earlier one stays silent.
1394+
std::atomic<size_t> warnAboveDelay = minWarnDelay;
1395+
// Start of the current uninterrupted healthy stretch, 0 until we first
1396+
// recover from a stall.
1397+
std::atomic<size_t> healthySince = 0;
1398+
1399+
// Halve the threshold for every healthToForget x threshold of health, down
1400+
// to minWarnDelay, so a later and smaller stall is reported again instead
1401+
// of being hidden by an older and worse one. The healthy stretch is spent
1402+
// in one go at the start of a stall: letting it apply again mid-stall would
1403+
// undo each backoff step and warn on every poll.
1404+
void decayWarnThreshold(size_t now)
1405+
{
1406+
size_t const since = healthySince.exchange(0);
1407+
if (since == 0) {
1408+
return;
1409+
}
1410+
size_t healthy = now - since;
1411+
if (healthy < minHealthToForget) {
1412+
return;
1413+
}
1414+
size_t threshold = warnAboveDelay;
1415+
while (threshold > minWarnDelay && healthy >= healthToForget * threshold) {
1416+
healthy -= healthToForget * threshold;
1417+
threshold = std::max<size_t>(threshold / 2, minWarnDelay);
1418+
}
1419+
warnAboveDelay = threshold;
1420+
}
13851421
};
13861422
static SchedulingStats schedulingStats;
13871423
O2_SIGNPOST_ID_GENERATE(sid, scheduling);
@@ -1391,8 +1427,10 @@ void DataProcessingDevice::Run()
13911427
stream.registry = &mServiceRegistry;
13921428
schedulingStats.lastScheduled = uv_now(state.loop);
13931429
schedulingStats.numberOfScheduled++;
1430+
if (schedulingStats.numberOfUnscheduledSinceLastScheduled != 0) {
1431+
schedulingStats.healthySince = schedulingStats.lastScheduled.load();
1432+
}
13941433
schedulingStats.numberOfUnscheduledSinceLastScheduled = 0;
1395-
schedulingStats.nextWarnAt = 1;
13961434
O2_SIGNPOST_EVENT_EMIT(scheduling, sid, "Run", "Enough resources to schedule computation on stream %d", streamRef.index);
13971435
if (dplEnableMultithreding) [[unlikely]] {
13981436
stream.task = &handle;
@@ -1421,27 +1459,20 @@ void DataProcessingDevice::Run()
14211459
}
14221460
return missingInfo.empty() ? std::string(" (policy: ") + spec.resourcePolicy.name + ")" : " -" + missingInfo;
14231461
};
1424-
auto const timeSinceLastScheduled = lastSched ? uv_now(state.loop) - lastSched : 0;
1425-
if (schedulingStats.numberOfUnscheduledSinceLastScheduled >= schedulingStats.nextWarnAt) {
1426-
auto const missingStr = buildMissingInfo();
1427-
if (timeSinceLastScheduled >= 50) {
1428-
O2_SIGNPOST_EVENT_EMIT_WARN(scheduling, sid, "Run",
1429-
"Not enough resources to schedule computation on stream %d. %zu consecutive skips%s. Missing:%s. Data is not lost and it will be scheduled again.",
1430-
streamRef.index,
1431-
schedulingStats.numberOfUnscheduledSinceLastScheduled.load(),
1432-
schedInfo.c_str(),
1433-
missingStr.c_str());
1434-
} else {
1435-
O2_SIGNPOST_EVENT_EMIT(scheduling, sid, "Run",
1436-
"Not enough resources to schedule computation on stream %d. %zu consecutive skips%s. Missing:%s. Data is not lost and it will be scheduled again.",
1437-
streamRef.index,
1438-
schedulingStats.numberOfUnscheduledSinceLastScheduled.load(),
1439-
schedInfo.c_str(),
1440-
missingStr.c_str());
1441-
}
1442-
schedulingStats.nextWarnAt = schedulingStats.nextWarnAt * 2;
1462+
size_t const now = uv_now(state.loop);
1463+
schedulingStats.decayWarnThreshold(now);
1464+
size_t const timeSinceLastScheduled = lastSched ? now - lastSched : 0;
1465+
bool const warn = timeSinceLastScheduled >= schedulingStats.warnAboveDelay;
1466+
auto const missingStr = buildMissingInfo();
1467+
if (warn) {
1468+
schedulingStats.warnAboveDelay = timeSinceLastScheduled * 2;
1469+
O2_SIGNPOST_EVENT_EMIT_WARN(scheduling, sid, "Run",
1470+
"Not enough resources to schedule computation on stream %d. %zu consecutive skips%s. Missing:%s. Data is not lost and it will be scheduled again.",
1471+
streamRef.index,
1472+
schedulingStats.numberOfUnscheduledSinceLastScheduled.load(),
1473+
schedInfo.c_str(),
1474+
missingStr.c_str());
14431475
} else {
1444-
auto const missingStr = buildMissingInfo();
14451476
O2_SIGNPOST_EVENT_EMIT(scheduling, sid, "Run",
14461477
"Not enough resources to schedule computation on stream %d. %zu consecutive skips%s. Missing:%s. Data is not lost and it will be scheduled again.",
14471478
streamRef.index,

0 commit comments

Comments
 (0)