Skip to content

Commit 627172c

Browse files
ktfktf
committed
DPL: support for Signposts in CCDB
1 parent 393608c commit 627172c

File tree

1 file changed

+26
-13
lines changed

1 file changed

+26
-13
lines changed

‎Framework/CCDBSupport/src/CCDBHelpers.cxx‎

Lines changed: 26 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -19,11 +19,14 @@
1919
#include "Framework/DataSpecUtils.h"
2020
#include "CCDB/CcdbApi.h"
2121
#include "CommonConstants/LHCConstants.h"
22+
#include "Framework/Signpost.h"
2223
#include <typeinfo>
2324
#include <TError.h>
2425
#include <TMemFile.h>
2526
#include <functional>
2627

28+
O2_DECLARE_DYNAMIC_LOG(ccdb);
29+
2730
namespace o2::framework
2831
{
2932

@@ -181,8 +184,12 @@ auto populateCacheWith(std::shared_ptr<CCDBFetcherHelper> const& helper,
181184
{
182185
std::string ccdbMetadataPrefix = "ccdb-metadata-";
183186
int objCnt = -1;
187+
// We use the timeslice, so that we hook into the same interval as the rest of the
188+
// callback.
189+
auto sid = _o2_signpost_id_t{(int64_t)timingInfo.timeslice};
190+
O2_SIGNPOST_START(ccdb, sid, "populateCacheWith", "Starting to populate cache with CCDB objects");
184191
for (auto& route : helper->routes) {
185-
LOGP(debug, "Fetching object for route {}", DataSpecUtils::describe(route.matcher));
192+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Fetching object for route %{public}s", DataSpecUtils::describe(route.matcher).data());
186193
objCnt++;
187194
auto concrete = DataSpecUtils::asConcreteDataMatcher(route.matcher);
188195
Output output{concrete.origin, concrete.description, concrete.subSpec};
@@ -201,7 +208,7 @@ auto populateCacheWith(std::shared_ptr<CCDBFetcherHelper> const& helper,
201208
} else if (isPrefix(ccdbMetadataPrefix, meta.name)) {
202209
std::string key = meta.name.substr(ccdbMetadataPrefix.size());
203210
auto value = meta.defaultValue.get<std::string>();
204-
LOGP(debug, "Adding metadata {}: {} to the request", key, value);
211+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Adding metadata %{public}s: %{public}s to the request", key.data(), value.data());
205212
metadata[key] = value;
206213
} else if (meta.name == "ccdb-query-rate") {
207214
chRate = meta.defaultValue.get<int>() * helper->queryPeriodFactor;
@@ -215,7 +222,7 @@ auto populateCacheWith(std::shared_ptr<CCDBFetcherHelper> const& helper,
215222
checkValidity = true; // never skip check if the cache is empty
216223
}
217224

218-
LOGP(debug, "checkValidity is {} for tfID {} of {}", checkValidity, timingInfo.tfCounter, path);
225+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "checkValidity is %{public}s for tfID %d of %{public}s", checkValidity ? "true" : "false", timingInfo.tfCounter, path.data());
219226

220227
const auto& api = helper->getAPI(path);
221228
if (checkValidity && (!api.isSnapshotMode() || etag.empty())) { // in the snapshot mode the object needs to be fetched only once
@@ -238,7 +245,7 @@ auto populateCacheWith(std::shared_ptr<CCDBFetcherHelper> const& helper,
238245
helper->mapURL2UUID[path].maxSize = std::max(v.size(), helper->mapURL2UUID[path].maxSize);
239246
auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodCCDB);
240247
helper->mapURL2DPLCache[path] = cacheId;
241-
LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value);
248+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value);
242249
continue;
243250
}
244251
if (v.size()) { // but should be overridden by fresh object
@@ -249,19 +256,20 @@ auto populateCacheWith(std::shared_ptr<CCDBFetcherHelper> const& helper,
249256
helper->mapURL2UUID[path].maxSize = std::max(v.size(), helper->mapURL2UUID[path].maxSize);
250257
auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodCCDB);
251258
helper->mapURL2DPLCache[path] = cacheId;
252-
LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value);
259+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value);
253260
// one could modify the adoptContainer to take optional old cacheID to clean:
254261
// mapURL2DPLCache[URL] = ctx.outputs().adoptContainer(output, std::move(outputBuffer), DataAllocator::CacheStrategy::Always, mapURL2DPLCache[URL]);
255262
continue;
256263
}
257264
}
258265
// cached object is fine
259266
auto cacheId = helper->mapURL2DPLCache[path];
260-
LOGP(debug, "Reusing {} for {}", cacheId.value, path);
267+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Reusing %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value);
261268
helper->mapURL2UUID[path].cacheHit++;
262269
allocator.adoptFromCache(output, cacheId, header::gSerializationMethodCCDB);
263270
// the outputBuffer was not used, can we destroy it?
264271
}
272+
O2_SIGNPOST_END(ccdb, sid, "populateCacheWith", "Finished populating cache with CCDB objects");
265273
};
266274

267275
AlgorithmSpec CCDBHelpers::fetchFromCCDB()
@@ -276,6 +284,7 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB()
276284
helper->queryPeriodGlo = checkRate > 0 ? checkRate : std::numeric_limits<int>::max();
277285
helper->queryPeriodFactor = checkMult > 0 ? checkMult : 1;
278286
LOGP(info, "CCDB Backend at: {}, validity check for every {} TF{}", defHost, helper->queryPeriodGlo, helper->queryPeriodFactor == 1 ? std::string{} : fmt::format(", (query for high-rate objects downscaled by {})", helper->queryPeriodFactor));
287+
LOGP(info, "Hook to enable signposts for CCDB messages at {}", (void*)&private_o2_log_ccdb->stacktrace);
279288
auto remapString = options.get<std::string>("condition-remap");
280289
ParserResult result = CCDBHelpers::parseRemappings(remapString.c_str());
281290
if (!result.error.empty()) {
@@ -322,6 +331,8 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB()
322331
});
323332

324333
return adaptStateless([helper](DataTakingContext& dtc, DataAllocator& allocator, TimingInfo& timingInfo) {
334+
auto sid = _o2_signpost_id_t{(int64_t)timingInfo.timeslice};
335+
O2_SIGNPOST_START(ccdb, sid, "fetchFromCCDB", "Fetching CCDB objects for timeslice %" PRIu64, (uint64_t)timingInfo.timeslice);
325336
static Long64_t orbitResetTime = -1;
326337
static size_t lastTimeUsed = -1;
327338
if (timingInfo.creation & DataProcessingHeader::DUMMY_CREATION_TIME_OFFSET) {
@@ -342,7 +353,8 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB()
342353
} else {
343354
checkValidity = true; // never skip check if the cache is empty
344355
}
345-
LOG(debug) << "checkValidity = " << checkValidity << " for TF " << timingInfo.timeslice;
356+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "checkValidity is %{public}s for tfID %d of %{public}s",
357+
checkValidity ? "true" : "false", timingInfo.tfCounter, path.data());
346358
Output output{"CTP", "OrbitReset", 0};
347359
Long64_t newOrbitResetTime = orbitResetTime;
348360
auto&& v = allocator.makeVector<char>(output);
@@ -363,7 +375,7 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB()
363375
newOrbitResetTime = getOrbitResetTime(v);
364376
auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodNone);
365377
helper->mapURL2DPLCache[path] = cacheId;
366-
LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value);
378+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value);
367379
} else if (v.size()) { // but should be overridden by fresh object
368380
// somewhere here pruneFromCache should be called
369381
helper->mapURL2UUID[path].etag = headers["ETag"]; // update uuid
@@ -373,19 +385,19 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB()
373385
newOrbitResetTime = getOrbitResetTime(v);
374386
auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodNone);
375387
helper->mapURL2DPLCache[path] = cacheId;
376-
LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value);
388+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value);
377389
// one could modify the adoptContainer to take optional old cacheID to clean:
378390
// mapURL2DPLCache[URL] = ctx.outputs().adoptContainer(output, std::move(outputBuffer), DataAllocator::CacheStrategy::Always, mapURL2DPLCache[URL]);
379391
}
380392
// cached object is fine
381393
}
382394
auto cacheId = helper->mapURL2DPLCache[path];
383-
LOGP(debug, "Reusing {} for {}", cacheId.value, path);
395+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Reusing %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value);
384396
helper->mapURL2UUID[path].cacheHit++;
385397
allocator.adoptFromCache(output, cacheId, header::gSerializationMethodNone);
386398

387399
if (newOrbitResetTime != orbitResetTime) {
388-
LOGP(debug, "Orbit reset time now at {} (was {})", newOrbitResetTime, orbitResetTime);
400+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Orbit reset time changed from %lld to %lld", orbitResetTime, newOrbitResetTime);
389401
orbitResetTime = newOrbitResetTime;
390402
dtc.orbitResetTimeMUS = orbitResetTime;
391403
}
@@ -403,10 +415,11 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB()
403415
timestamp = timingInfo.creation;
404416
}
405417
// Fetch the rest of the objects.
406-
LOGP(debug, "Fetching objects. Run: {}. OrbitResetTime: {}, Creation: {}, Timestamp: {}, firstTForbit: {}",
407-
dtc.runNumber, orbitResetTime, timingInfo.creation, timestamp, timingInfo.firstTForbit);
418+
O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Fetching objects. Run %{public}s. OrbitResetTime %lld. Creation %lld. Timestamp %lld. firstTForbit %" PRIu32,
419+
dtc.runNumber.data(), orbitResetTime, timingInfo.creation, timestamp, timingInfo.firstTForbit);
408420

409421
populateCacheWith(helper, timestamp, timingInfo, dtc, allocator);
422+
O2_SIGNPOST_END(ccdb, _o2_signpost_id_t{(int64_t)timingInfo.timeslice}, "fetchFromCCDB", "Fetching CCDB objects");
410423
}); });
411424
}
412425

0 commit comments

Comments
 (0)