Created TimingList class to help accumulation and logging of timings.

Created initial (incomplete) logging of timings for generic popping from container.

common/CMakeLists.txt

@@ -109,6 +109,7 @@ set (COMMON_LIB_SRC_FILES
   log/StringLogger.cpp
   log/SyslogLogger.cpp
   log/StdoutLogger.cpp
+  log/TimingList.cpp
   priorities/DriveQuota.cpp
   priorities/MountCriteria.cpp
   priorities/UserGroup.cpp

common/log/TimingList.cpp

+/*
+ * The CERN Tape Archive (CTA) project
+ * Copyright (C) 2015  CERN
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include "TimingList.hpp"
+#include "LogContext.hpp"
+#include "common/Timer.hpp"
+
+namespace cta { namespace log {
+
+void TimingList::addToLog(ScopedParamContainer& spc) {
+  for (auto & t: *this) {
+    std::string name;
+    double value;
+    std::tie(name, value) = t;
+    spc.add(name, value);
+  }
+}
+
+void TimingList::insert(const std::string& name, double value) {
+  push_back(std::make_tuple(name, value));
+}
+
+void TimingList::insertAndReset(const std::string& name, utils::Timer& t) {
+  push_back(std::make_tuple(name, t.secs(utils::Timer::resetCounter)));
+}
+
+TimingList& TimingList::operator+=(const TimingList& other) {
+  for (auto & ot: other) {
+    std::string oName;
+    double oVal;
+    std::tie(oName, oVal) = ot;
+    for (auto & t: *this) {
+      std::string name;
+      double val;
+      std::tie(name, val) = t;
+      if (name == oName) {
+        std::get<1>(t) = val+oVal;
+        goto done;
+      }
+    }
+    // We did not add this one to an existing entry: just insert a new one.
+    push_back(ot);
+    done:;
+  }
+  return *this;
+}
+
+}} // namespace cta::log

common/log/TimingList.hpp

+/*
+ * The CERN Tape Archive (CTA) project
+ * Copyright (C) 2015  CERN
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+#pragma once
+
+#include <list>
+#include <tuple>
+#include <string>
+
+namespace cta { namespace utils {
+class Timer;
+}}
+
+namespace cta { namespace log {
+
+class ScopedParamContainer;
+
+class TimingList: public std::list<std::tuple<std::string, double>> {
+public:
+  void insert(const std::string &, double);
+  void insertAndReset(const std::string&, utils::Timer &);
+  TimingList & operator+= (const TimingList &);
+  void addToLog(ScopedParamContainer &);
+};
+
+}} // namespace cta::log
\ No newline at end of file

objectstore/Algorithms.hpp

@@ -28,6 +28,7 @@
 #include "Helpers.hpp"
 #include "common/log/LogContext.hpp"
 #include "common/exception/Exception.hpp"
+#include "common/log/TimingList.hpp"
 
 namespace cta { namespace objectstore {
 
@@ -42,6 +43,8 @@ public:
   typedef std::string                         ContainerAddress;
   typedef std::string                         ElementAddress;
   typedef std::string                         ContainerIdentifyer;
+  static const std::string                    c_containerTypeName; //= "genericContainer";
+  static const std::string                    c_identifyerType; // = "genericId";
   struct InsertedElement {
     typedef std::list<InsertedElement> list;
   };
@@ -79,6 +82,7 @@ public:
     PoppedElementsBatch();
     PoppedElementsList elements;
     PoppedElementsSummary summary;
+    void addToLog(log::ScopedParamContainer &);
   };
   typedef std::set<ElementAddress> ElementsToSkipSet;
   
@@ -162,7 +166,10 @@ public:
     typename ContainerTraits<C>::PopCriteria unfulfilledCriteria = popCriteria;
     size_t iterationCount=0;
     typename ContainerTraits<C>::ElementsToSkipSet elementsToSkip;
+    log::TimingList timingList;
+    utils::Timer t;
     while (ret.summary < popCriteria) {
+      log::TimingList localTimingList;
       // Get a container if it exists
       C cont(m_backend);
       iterationCount++;
@@ -170,12 +177,16 @@ public:
       try {
         ContainerTraits<C>::getLockedAndFetchedNoCreate(cont, contLock, contId, lc);
       } catch (typename ContainerTraits<C>::NoSuchContainer &) {
+        localTimingList.insertAndReset("findQueueTime", t);
+        timingList+=localTimingList;
         // We could not find a container to pop from: return what we have.
-        return ret;
+        goto logAndReturn;
       }
+      localTimingList.insertAndReset("findQueueTime", t);
       // We have a container. Get candidate element list from it.
       typename ContainerTraits<C>::PoppedElementsBatch candidateElements = 
           ContainerTraits<C>::getPoppingElementsCandidates(cont, unfulfilledCriteria, elementsToSkip, lc);
+      
       // Reference the candidates to our agent
       std::list<typename ContainerTraits<C>::ElementAddress> candidateElementsAddresses;
       for (auto & e: candidateElements.elements) {
@@ -245,6 +256,15 @@ public:
         }
       }
     }
+  logAndReturn:;
+    {
+      log::ScopedParamContainer params(lc);
+      params.add("C", ContainerTraits<C>::c_containerTypeName);
+      params.add(ContainerTraits<C>::c_identifyerType, contId);
+      ret.addToLog(params);
+      timingList.addToLog(params);
+      lc.log(log::INFO, "In ContainerTraits<C>::PoppedElementsBatch(): elements retrieval complete.");
+    } 
     return ret;
   }
 private:

objectstore/AlgorithmsTest.cpp

@@ -27,6 +27,9 @@
 #include "common/make_unique.hpp"
 #include "ArchiveQueueAlgorithms.hpp"
 #include "RetrieveQueueAlgorithms.hpp"
+#ifdef STDOUT_LOGGING
+#include "common/log/StdoutLogger.hpp"
+#endif
 
 #include <gtest/gtest.h>
 

objectstore/ArchiveQueueAlgorithms.cpp

@@ -22,6 +22,10 @@
 
 namespace cta { namespace objectstore {
 
+const std::string ContainerTraits<ArchiveQueue>::c_containerTypeName = "ArchiveQueue";
+
+const std::string ContainerTraits<ArchiveQueue>::c_identifyerType = "tapepool";
+
 void ContainerTraits<ArchiveQueue>::getLockedAndFetched(Container& cont, ScopedExclusiveLock& aqL, AgentReference& agRef,
     const ContainerIdentifyer& contId, log::LogContext& lc) {
   Helpers::getLockedAndFetchedQueue<Container>(cont, aqL, agRef, contId, QueueType::LiveJobs, lc);
@@ -78,7 +82,6 @@ auto ContainerTraits<ArchiveQueue>::switchElementsOwnership(InsertedElement::lis
   return ret;
 }
 
-
 void ContainerTraits<ArchiveQueue>::getLockedAndFetchedNoCreate(Container& cont, ScopedExclusiveLock& contLock,
     const ContainerIdentifyer& cId, log::LogContext& lc) {
   // Try and get access to a queue.
@@ -132,6 +135,11 @@ void ContainerTraits<ArchiveQueue>::getLockedAndFetchedNoCreate(Container& cont,
   }
 }
 
+void ContainerTraits<ArchiveQueue>::PoppedElementsBatch::addToLog(log::ScopedParamContainer& params) {
+  params.add("bytes", summary.bytes)
+        .add("files", summary.files);
+}
+
 auto ContainerTraits<ArchiveQueue>::getPoppingElementsCandidates(Container& cont, PopCriteria& unfulfilledCriteria,
     ElementsToSkipSet& elemtsToSkip, log::LogContext& lc) -> PoppedElementsBatch {
   PoppedElementsBatch ret;

objectstore/ArchiveQueueAlgorithms.hpp

@@ -29,6 +29,8 @@ public:
   typedef std::string                                            ContainerAddress;
   typedef std::string                                            ElementAddress;
   typedef std::string                                            ContainerIdentifyer;
+  static const std::string                    c_containerTypeName; //= "ArchiveQueue";
+  static const std::string                    c_identifyerType; // = "tapepool";
   struct InsertedElement {
     std::unique_ptr<ArchiveRequest> archiveRequest;
     uint16_t copyNb;
@@ -108,6 +110,7 @@ public:
   public:
     PoppedElementsList elements;
     PoppedElementsSummary summary;
+    void addToLog(log::ScopedParamContainer &);
   };
   
   typedef std::set<ElementAddress> ElementsToSkipSet;

tests/TestsCompileTimeSwitches.hpp

@@ -20,4 +20,4 @@
 
 #undef LOOPING_TEST
 #undef LOW_LEVEL_TRACING
-#undef STDOUT_LOGGING
\ No newline at end of file
+#undef STDOUT_LOGGING