diff --git a/Framework/CCDBSupport/src/CCDBHelpers.cxx b/Framework/CCDBSupport/src/CCDBHelpers.cxx index f2d329db39b6d..837b20cf4262b 100644 --- a/Framework/CCDBSupport/src/CCDBHelpers.cxx +++ b/Framework/CCDBSupport/src/CCDBHelpers.cxx @@ -19,11 +19,14 @@ #include "Framework/DataSpecUtils.h" #include "CCDB/CcdbApi.h" #include "CommonConstants/LHCConstants.h" +#include "Framework/Signpost.h" #include #include #include #include +O2_DECLARE_DYNAMIC_LOG(ccdb); + namespace o2::framework { @@ -181,8 +184,12 @@ auto populateCacheWith(std::shared_ptr const& helper, { std::string ccdbMetadataPrefix = "ccdb-metadata-"; int objCnt = -1; + // We use the timeslice, so that we hook into the same interval as the rest of the + // callback. + auto sid = _o2_signpost_id_t{(int64_t)timingInfo.timeslice}; + O2_SIGNPOST_START(ccdb, sid, "populateCacheWith", "Starting to populate cache with CCDB objects"); for (auto& route : helper->routes) { - LOGP(debug, "Fetching object for route {}", DataSpecUtils::describe(route.matcher)); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Fetching object for route %{public}s", DataSpecUtils::describe(route.matcher).data()); objCnt++; auto concrete = DataSpecUtils::asConcreteDataMatcher(route.matcher); Output output{concrete.origin, concrete.description, concrete.subSpec}; @@ -201,7 +208,7 @@ auto populateCacheWith(std::shared_ptr const& helper, } else if (isPrefix(ccdbMetadataPrefix, meta.name)) { std::string key = meta.name.substr(ccdbMetadataPrefix.size()); auto value = meta.defaultValue.get(); - LOGP(debug, "Adding metadata {}: {} to the request", key, value); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Adding metadata %{public}s: %{public}s to the request", key.data(), value.data()); metadata[key] = value; } else if (meta.name == "ccdb-query-rate") { chRate = meta.defaultValue.get() * helper->queryPeriodFactor; @@ -215,7 +222,7 @@ auto populateCacheWith(std::shared_ptr const& helper, checkValidity = true; // never skip check if the cache is empty } - LOGP(debug, "checkValidity is {} for tfID {} of {}", checkValidity, timingInfo.tfCounter, path); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "checkValidity is %{public}s for tfID %d of %{public}s", checkValidity ? "true" : "false", timingInfo.tfCounter, path.data()); const auto& api = helper->getAPI(path); 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 const& helper, helper->mapURL2UUID[path].maxSize = std::max(v.size(), helper->mapURL2UUID[path].maxSize); auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodCCDB); helper->mapURL2DPLCache[path] = cacheId; - LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value); continue; } if (v.size()) { // but should be overridden by fresh object @@ -249,7 +256,7 @@ auto populateCacheWith(std::shared_ptr const& helper, helper->mapURL2UUID[path].maxSize = std::max(v.size(), helper->mapURL2UUID[path].maxSize); auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodCCDB); helper->mapURL2DPLCache[path] = cacheId; - LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value); // one could modify the adoptContainer to take optional old cacheID to clean: // mapURL2DPLCache[URL] = ctx.outputs().adoptContainer(output, std::move(outputBuffer), DataAllocator::CacheStrategy::Always, mapURL2DPLCache[URL]); continue; @@ -257,11 +264,12 @@ auto populateCacheWith(std::shared_ptr const& helper, } // cached object is fine auto cacheId = helper->mapURL2DPLCache[path]; - LOGP(debug, "Reusing {} for {}", cacheId.value, path); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "populateCacheWith", "Reusing %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value); helper->mapURL2UUID[path].cacheHit++; allocator.adoptFromCache(output, cacheId, header::gSerializationMethodCCDB); // the outputBuffer was not used, can we destroy it? } + O2_SIGNPOST_END(ccdb, sid, "populateCacheWith", "Finished populating cache with CCDB objects"); }; AlgorithmSpec CCDBHelpers::fetchFromCCDB() @@ -276,6 +284,7 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB() helper->queryPeriodGlo = checkRate > 0 ? checkRate : std::numeric_limits::max(); helper->queryPeriodFactor = checkMult > 0 ? checkMult : 1; 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)); + LOGP(info, "Hook to enable signposts for CCDB messages at {}", (void*)&private_o2_log_ccdb->stacktrace); auto remapString = options.get("condition-remap"); ParserResult result = CCDBHelpers::parseRemappings(remapString.c_str()); if (!result.error.empty()) { @@ -322,6 +331,8 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB() }); return adaptStateless([helper](DataTakingContext& dtc, DataAllocator& allocator, TimingInfo& timingInfo) { + auto sid = _o2_signpost_id_t{(int64_t)timingInfo.timeslice}; + O2_SIGNPOST_START(ccdb, sid, "fetchFromCCDB", "Fetching CCDB objects for timeslice %" PRIu64, (uint64_t)timingInfo.timeslice); static Long64_t orbitResetTime = -1; static size_t lastTimeUsed = -1; if (timingInfo.creation & DataProcessingHeader::DUMMY_CREATION_TIME_OFFSET) { @@ -342,7 +353,8 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB() } else { checkValidity = true; // never skip check if the cache is empty } - LOG(debug) << "checkValidity = " << checkValidity << " for TF " << timingInfo.timeslice; + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "checkValidity is %{public}s for tfID %d of %{public}s", + checkValidity ? "true" : "false", timingInfo.tfCounter, path.data()); Output output{"CTP", "OrbitReset", 0}; Long64_t newOrbitResetTime = orbitResetTime; auto&& v = allocator.makeVector(output); @@ -363,7 +375,7 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB() newOrbitResetTime = getOrbitResetTime(v); auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodNone); helper->mapURL2DPLCache[path] = cacheId; - LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value); } else if (v.size()) { // but should be overridden by fresh object // somewhere here pruneFromCache should be called helper->mapURL2UUID[path].etag = headers["ETag"]; // update uuid @@ -373,19 +385,19 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB() newOrbitResetTime = getOrbitResetTime(v); auto cacheId = allocator.adoptContainer(output, std::move(v), DataAllocator::CacheStrategy::Always, header::gSerializationMethodNone); helper->mapURL2DPLCache[path] = cacheId; - LOGP(debug, "Caching {} for {} (DPL id {})", path, headers["ETag"], cacheId.value); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Caching %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value); // one could modify the adoptContainer to take optional old cacheID to clean: // mapURL2DPLCache[URL] = ctx.outputs().adoptContainer(output, std::move(outputBuffer), DataAllocator::CacheStrategy::Always, mapURL2DPLCache[URL]); } // cached object is fine } auto cacheId = helper->mapURL2DPLCache[path]; - LOGP(debug, "Reusing {} for {}", cacheId.value, path); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Reusing %{public}s for %{public}s (DPL id %" PRIu64 ")", path.data(), headers["ETag"].data(), cacheId.value); helper->mapURL2UUID[path].cacheHit++; allocator.adoptFromCache(output, cacheId, header::gSerializationMethodNone); if (newOrbitResetTime != orbitResetTime) { - LOGP(debug, "Orbit reset time now at {} (was {})", newOrbitResetTime, orbitResetTime); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Orbit reset time changed from %lld to %lld", orbitResetTime, newOrbitResetTime); orbitResetTime = newOrbitResetTime; dtc.orbitResetTimeMUS = orbitResetTime; } @@ -403,10 +415,11 @@ AlgorithmSpec CCDBHelpers::fetchFromCCDB() timestamp = timingInfo.creation; } // Fetch the rest of the objects. - LOGP(debug, "Fetching objects. Run: {}. OrbitResetTime: {}, Creation: {}, Timestamp: {}, firstTForbit: {}", - dtc.runNumber, orbitResetTime, timingInfo.creation, timestamp, timingInfo.firstTForbit); + O2_SIGNPOST_EVENT_EMIT(ccdb, sid, "fetchFromCCDB", "Fetching objects. Run %{public}s. OrbitResetTime %lld. Creation %lld. Timestamp %lld. firstTForbit %" PRIu32, + dtc.runNumber.data(), orbitResetTime, timingInfo.creation, timestamp, timingInfo.firstTForbit); populateCacheWith(helper, timestamp, timingInfo, dtc, allocator); + O2_SIGNPOST_END(ccdb, _o2_signpost_id_t{(int64_t)timingInfo.timeslice}, "fetchFromCCDB", "Fetching CCDB objects"); }); }); }