Merge pull request #47171 from cms-AlCaDB/hlt-crash-diag

Print diagnostics on ProductResolver's loadTag setIntervalFor and IOVProxy's fetchSequence

Author: cmsbuild

CondCore/CondDB/interface/IOVProxy.h

@@ -98,18 +98,11 @@ namespace cond {
     // value semantics. to be used WITHIN the parent session transaction ( therefore the session should be kept alive ).
     class IOVProxy {
     public:
-      //
-      IOVProxy();
+      IOVProxy() = default;
 
       // the only way to construct it from scratch...
       explicit IOVProxy(const std::shared_ptr<SessionImpl>& session);
 
-      //
-      IOVProxy(const IOVProxy& rhs);
-
-      //
-      IOVProxy& operator=(const IOVProxy& rhs);
-
       IOVArray selectAll();
       IOVArray selectAll(const boost::posix_time::ptime& snapshottime);
 
@@ -160,6 +153,8 @@ namespace cond {
       // maybe will be removed with a re-design of the top level interface (ESSources )
       const std::shared_ptr<SessionImpl>& session() const;
 
+      void setPrintDebug(bool printDebug) { m_printDebug = printDebug; }
+
     private:
       void checkTransaction(const std::string& ctx) const;
       void resetIOVCache();
@@ -169,6 +164,9 @@ namespace cond {
     private:
       std::shared_ptr<IOVProxyData> m_data;
       std::shared_ptr<SessionImpl> m_session;
+
+      // whether additional debug info should be printed in fetchSequence
+      bool m_printDebug = false;
     };
 
   }  // namespace persistency

CondCore/CondDB/interface/Time.h

@@ -54,7 +54,14 @@ namespace cond {
 
     Time_t tillTimeForIOV(Time_t since, unsigned int iovSize, TimeType timeType);
 
-    Time_t lumiTime(unsigned int run, unsigned int lumiId);
+    // LumiNr is the number of the luminosity block (LumiSection) in a run.
+    // LumiTime also called LumiId is an unique identifier for a luminosity block,
+    // being a combination of run number and LumiNr
+    Time_t lumiTime(unsigned int run, unsigned int lumiNr);
+
+    Time_t lumiIdToRun(Time_t lumiId);
+
+    Time_t lumiIdToLumiNr(Time_t lumiId);
 
     // conversion from framework types
     edm::IOVSyncValue toIOVSyncValue(cond::Time_t time, TimeType timetype, bool startOrStop);

CondCore/CondDB/src/IOVProxy.cc

@@ -1,9 +1,12 @@
 #include <memory>
 
 #include "CondCore/CondDB/interface/IOVProxy.h"
+#include "CondCore/CondDB/interface/Time.h"
 #include "FWCore/MessageLogger/interface/MessageLogger.h"
 #include "SessionImpl.h"
 
+using cond::time::lumiIdToLumiNr;
+using cond::time::lumiIdToRun;
 namespace cond {
 
   namespace persistency {
@@ -125,18 +128,8 @@ namespace cond {
       size_t numberOfQueries = 0;
     };
 
-    IOVProxy::IOVProxy() : m_data(), m_session() {}
-
     IOVProxy::IOVProxy(const std::shared_ptr<SessionImpl>& session) : m_data(new IOVProxyData), m_session(session) {}
 
-    IOVProxy::IOVProxy(const IOVProxy& rhs) : m_data(rhs.m_data), m_session(rhs.m_session) {}
-
-    IOVProxy& IOVProxy::operator=(const IOVProxy& rhs) {
-      m_data = rhs.m_data;
-      m_session = rhs.m_session;
-      return *this;
-    }
-
     void IOVProxy::load(const std::string& tagName) {
       boost::posix_time::ptime notime;
       load(tagName, notime);
@@ -293,8 +286,47 @@ namespace cond {
         throwException("The transaction is not active.", ctx);
     }
 
+    void printTagInfoAndRanges(edm::LogSystem& log,
+                               const IOVProxyData& iovProxyData,
+                               cond::Time_t lowerGroup,
+                               cond::Time_t higherGroup) {
+      log << "Fetched new IOV for '" << iovProxyData.tagInfo.name << "'\n"
+          << "payload type: " << iovProxyData.tagInfo.payloadType << "\n"
+          << "request interval [ " << lowerGroup << " , " << higherGroup << " ]\n"
+          << "new range [ " << iovProxyData.groupLowerIov << " , " << iovProxyData.groupHigherIov << " ]\n";
+      if (iovProxyData.tagInfo.timeType == cond::TimeType::lumiid) {
+        log << "request interval (run, LS): [ ("  // comments to override code-format
+            << lumiIdToRun(lowerGroup) << ", " << lumiIdToLumiNr(lowerGroup) << ") , ("  //
+            << lumiIdToRun(higherGroup) << ", " << lumiIdToLumiNr(higherGroup) << ") ]\n"
+            << "new range (run, LS): [ ("  //
+            << lumiIdToRun(iovProxyData.groupLowerIov) << ", " << lumiIdToLumiNr(iovProxyData.groupLowerIov) << ") , ("
+            << lumiIdToRun(iovProxyData.groupHigherIov) << ", " << lumiIdToLumiNr(iovProxyData.groupHigherIov)
+            << ") ]\n";
+      }
+    }
+
+    void printIovsAndHashesOfSequence(edm::LogSystem& log, const IOVProxyData& iovProxyData) {
+      const bool isLumiid = iovProxyData.tagInfo.timeType == cond::TimeType::lumiid;
+      log << "#entries " << iovProxyData.iovSequence.size() << "\n"
+          << "sequence [iov " << (isLumiid ? "(run, LS)" : "") << ", hash]:\n";
+      for (const auto& [iov, hash] : iovProxyData.iovSequence) {
+        log << iov << " ";
+        if (isLumiid) {
+          log << "(" << lumiIdToRun(iov) << ", " << lumiIdToLumiNr(iov) << ")";
+        }
+        log << ", " << hash << ",\n";
+      }
+    }
+
+    void printIOVSequenceDiagnostics(const IOVProxyData& iovProxyData,
+                                     cond::Time_t lowerGroup,
+                                     cond::Time_t higherGroup) {
+      edm::LogSystem log("NewIOV");  // creating here so everything is in one message
+      printTagInfoAndRanges(log, iovProxyData, lowerGroup, higherGroup);
+      printIovsAndHashesOfSequence(log, iovProxyData);
+    }
+
     void IOVProxy::fetchSequence(cond::Time_t lowerGroup, cond::Time_t higherGroup) {
-      bool firstTime = m_data->iovSequence.empty();
       m_data->iovSequence.clear();
       m_session->iovSchema().iovTable().select(
           m_data->tagInfo.name, lowerGroup, higherGroup, m_data->snapshotTime, m_data->iovSequence);
@@ -315,13 +347,11 @@ namespace cond {
           m_data->groupHigherIov = cond::time::MAX_VAL;
         }
       }
-      if (not firstTime) {
-        edm::LogSystem("NewIOV") << "Fetched new IOV for '" << m_data->tagInfo.name << "' request interval [ "
-                                 << lowerGroup << " , " << higherGroup << " ] new range [ " << m_data->groupLowerIov
-                                 << " , " << m_data->groupHigherIov << " ] #entries " << m_data->iovSequence.size();
-      }
-
       m_data->numberOfQueries++;
+
+      if (m_printDebug) {
+        printIOVSequenceDiagnostics(*m_data, lowerGroup, higherGroup);
+      }
     }
 
     cond::Iov_t IOVProxy::getInterval(cond::Time_t time) {

CondCore/CondDB/src/Time.cc

@@ -63,7 +63,11 @@ namespace cond {
       }
     }
 
-    Time_t lumiTime(unsigned int run, unsigned int lumiId) { return cond::time::pack(std::make_pair(run, lumiId)); }
+    Time_t lumiTime(unsigned int run, unsigned int lumiNr) { return cond::time::pack(std::make_pair(run, lumiNr)); }
+
+    Time_t lumiIdToRun(Time_t lumiId) { return cond::time::unpack(lumiId).first; }
+
+    Time_t lumiIdToLumiNr(Time_t lumiId) { return cond::time::unpack(lumiId).second; }
 
     Time_t sinceGroupSize(TimeType tp) {
       if (tp == TIMESTAMP)

CondCore/ESSources/interface/ProductResolver.h

@@ -107,6 +107,8 @@ namespace cond {
     ValidityInterval setIntervalFor(Time_t target);
     TimeType timeType() const { return m_iovProxy.tagInfo().timeType; }
 
+    void setPrintDebug(bool printDebug) { m_printDebug = printDebug; }
+
   private:
     std::string m_label;
     std::string m_connString;
@@ -115,6 +117,9 @@ namespace cond {
     Iov_t m_currentIov;
     persistency::Session m_session;
     std::shared_ptr<std::vector<Iov_t>> m_requests;
+
+    // whether additional debug info should be printed in loadTag and setIntervalFor
+    bool m_printDebug = false;
   };
 }  // namespace cond
 

CondCore/ESSources/plugins/CondDBESSource.cc

@@ -127,6 +127,8 @@ CondDBESSource::CondDBESSource(const edm::ParameterSet& iConfig)
       m_connectionString(iConfig.getParameter<std::string>("connect")),
       m_globalTag(iConfig.getParameter<std::string>("globaltag")),
       m_frontierKey(iConfig.getUntrackedParameter<std::string>("frontierKey", "")),
+      m_recordsToDebug(
+          iConfig.getUntrackedParameter<std::vector<std::string>>("recordsToDebug", std::vector<std::string>())),
       m_lastRun(0),   // for the stat
       m_lastLumi(0),  // for the stat
       m_policy(NOREFRESH),
@@ -254,11 +256,20 @@ CondDBESSource::CondDBESSource(const edm::ParameterSet& iConfig)
    */
   std::vector<std::unique_ptr<cond::ProductResolverWrapperBase>> resolverWrappers(m_tagCollection.size());
   size_t ipb = 0;
+
   for (it = itBeg; it != itEnd; ++it) {
     size_t ind = ipb++;
     resolverWrappers[ind] = std::unique_ptr<cond::ProductResolverWrapperBase>{
         cond::ProductResolverFactory::get()->tryToCreate(buildName(it->second.recordName()))};
-    if (!resolverWrappers[ind].get()) {
+
+    if (resolverWrappers[ind].get()) {
+      // Enable debug if the record name is in m_recordsToDebug or if "*" is present, meaning debug for all records.
+      bool printDebug = std::find(m_recordsToDebug.begin(), m_recordsToDebug.end(), "*") != m_recordsToDebug.end() ||
+                        std::find(m_recordsToDebug.begin(), m_recordsToDebug.end(), it->second.recordName()) !=
+                            m_recordsToDebug.end();
+
+      resolverWrappers[ind]->setPrintDebug(printDebug);
+    } else {
       edm::LogWarning("CondDBESSource") << "Plugin for Record " << it->second.recordName() << " has not been found.";
     }
   }
@@ -774,6 +785,7 @@ void CondDBESSource::fillDescriptions(edm::ConfigurationDescriptions& descriptio
   desc.addUntracked<bool>("RefreshOpenIOVs", false);
   desc.addUntracked<std::string>("pfnPostfix", "");
   desc.addUntracked<std::string>("pfnPrefix", "");
+  desc.addUntracked<std::vector<std::string>>("recordsToDebug", {});
 
   descriptions.add("default_CondDBESource", desc);
 }

CondCore/ESSources/plugins/CondDBESSource.h

@@ -124,6 +124,8 @@ class CondDBESSource : public edm::eventsetup::ESProductResolverProvider, public
   typedef std::map<std::string, cond::GTEntry_t> TagCollection;
   // the collections of tag, record/label used in this ESSource
   TagCollection m_tagCollection;
+  std::vector<std::string> m_recordsToDebug;
+
   std::map<std::string, std::pair<cond::Time_t, bool> > m_refreshTimeForRecord;
   std::map<std::string, std::pair<cond::persistency::Session, std::string> > m_sessionPool;
   std::map<std::string, std::pair<cond::persistency::Session, std::string> > m_sessionPoolForLumiConditions;

CondCore/ESSources/python/CondDBESSource_cfi.py

@@ -20,5 +20,6 @@
     RefreshEachRun   = False,
     RefreshOpenIOVs  = False,
     pfnPostfix       = '',
-    pfnPrefix        = '' ,
+    pfnPrefix        = '',
+    recordsToDebug   = [],
 )

CondCore/ESSources/src/ProductResolverFactory.cc

@@ -15,6 +15,7 @@
 // user include files
 #include "CondCore/ESSources/interface/ProductResolverFactory.h"
 #include "CondCore/ESSources/interface/ProductResolver.h"
+#include "FWCore/MessageLogger/interface/MessageLogger.h"
 
 cond::ProductResolverWrapperBase::ProductResolverWrapperBase() {}
 
@@ -29,17 +30,26 @@ void cond::ProductResolverWrapperBase::addInfo(std::string const& il, std::strin
 void cond::ProductResolverWrapperBase::loadTag(std::string const& tag) {
   m_session.transaction().start(true);
   m_iovProxy = m_session.readIov(tag);
+  m_iovProxy.setPrintDebug(m_printDebug);
   m_session.transaction().commit();
   m_currentIov.clear();
   m_requests = std::make_shared<std::vector<cond::Iov_t>>();
+  if (m_printDebug) {
+    edm::LogSystem("ProductResolverWrapperBase") << "loadTag executed with tag: " << tag;
+  }
 }
 
 void cond::ProductResolverWrapperBase::loadTag(std::string const& tag, boost::posix_time::ptime const& snapshotTime) {
   m_session.transaction().start(true);
   m_iovProxy = m_session.readIov(tag, snapshotTime);
+  m_iovProxy.setPrintDebug(m_printDebug);
   m_session.transaction().commit();
   m_currentIov.clear();
   m_requests = std::make_shared<std::vector<cond::Iov_t>>();
+  if (m_printDebug) {
+    edm::LogSystem("ProductResolverWrapperBase")
+        << "loadTag executed with tag: " << tag << " and snapshotTime: " << snapshotTime;
+  }
 }
 
 void cond::ProductResolverWrapperBase::reload() {
@@ -55,6 +65,11 @@ cond::ValidityInterval cond::ProductResolverWrapperBase::setIntervalFor(Time_t t
     m_currentIov = m_iovProxy.getInterval(time);
     m_session.transaction().commit();
   }
+  if (m_printDebug) {
+    edm::LogSystem("ProductResolverWrapperBase")
+        << "setIntervalFor for tag:" << m_iovProxy.tagInfo().name << " executed with time: " << time << "\n"
+        << " set ValidityInterval: since: " << m_currentIov.since << " till: " << m_currentIov.till;
+  }
   return cond::ValidityInterval(m_currentIov.since, m_currentIov.till);
 }