From 1819747381d8e0fc475c73d4745416c813e297bc Mon Sep 17 00:00:00 2001
From: Eric Cano <Eric.Cano@cern.ch>
Date: Fri, 18 Aug 2017 15:58:00 +0200
Subject: [PATCH] Added timing logs to Scheduler::getNextMount().
---
scheduler/Scheduler.cpp | 68 +++++++++++++++++++++++++++++++++++++++--
1 file changed, 65 insertions(+), 3 deletions(-)
diff --git a/scheduler/Scheduler.cpp b/scheduler/Scheduler.cpp
index 5645a6e32f..fa5674774f 100644
--- a/scheduler/Scheduler.cpp
+++ b/scheduler/Scheduler.cpp
@@ -469,9 +469,24 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
// Many steps for this logic are not specific for the database and are hence
// implemented in the scheduler itself.
// First, get the mount-related info from the DB
+ utils::Timer timer;
+ double getMountInfoTime = 0;
+ double queueTrimingTime = 0;
+ double getTapeInfoTime = 0;
+ double candidateSortingTime = 0;
+ double getTapeForWriteTime = 0;
+ double decisionTime = 0;
+ double mountCreationTime = 0;
+ double driveStatusSetTime = 0;
+ double schedulerDbTime = 0;
+ double catalogueTime = 0;
std::unique_ptr<SchedulerDatabase::TapeMountDecisionInfo> mountInfo;
mountInfo = m_db.getMountInfo(lc);
- if (mountInfo->queueTrimRequired) m_db.trimEmptyQueues(lc);
+ getMountInfoTime = timer.secs(utils::Timer::resetCounter);
+ if (mountInfo->queueTrimRequired) {
+ m_db.trimEmptyQueues(lc);
+ queueTrimingTime = timer.secs(utils::Timer::resetCounter);
+ }
__attribute__((unused)) SchedulerDatabase::TapeMountDecisionInfo & debugMountInfo = *mountInfo;
// The library information is not know for the tapes involved in retrieves. We
@@ -483,6 +498,7 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
}
if (tapeSet.size()) {
auto tapesInfo=m_catalogue.getTapesByVid(tapeSet);
+ getTapeInfoTime = timer.secs(utils::Timer::resetCounter);
for (auto &m:mountInfo->potentialMounts) {
if (m.type==common::dataStructures::MountType::Retrieve) {
m.logicalLibrary=tapesInfo[m.vid].logicalLibraryName;
@@ -591,6 +607,8 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
std::sort(mountInfo->potentialMounts.begin(), mountInfo->potentialMounts.end());
std::reverse(mountInfo->potentialMounts.begin(), mountInfo->potentialMounts.end());
+ candidateSortingTime = timer.secs(utils::Timer::resetCounter);
+
// Find out if we have any potential archive mount in the list. If so, get the
// list of tapes from the catalogue.
std::list<catalogue::TapeForWriting> tapeList;
@@ -598,6 +616,7 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
mountInfo->potentialMounts.cbegin(), mountInfo->potentialMounts.cend(),
[](decltype(*mountInfo->potentialMounts.cbegin())& m){ return m.type == common::dataStructures::MountType::Archive; } )) {
tapeList = m_catalogue.getTapesForWriting(logicalLibraryName);
+ getTapeForWriteTime = timer.secs(utils::Timer::resetCounter);
}
// Remove from the tape list the ones already or soon to be mounted
@@ -626,18 +645,23 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
std::unique_ptr<ArchiveMount> internalRet(new ArchiveMount(m_catalogue));
// Get the db side of the session
try {
+ decisionTime += timer.secs(utils::Timer::resetCounter);
internalRet->m_dbMount.reset(mountInfo->createArchiveMount(t,
driveName,
logicalLibraryName,
utils::getShortHostname(),
time(NULL)).release());
+ mountCreationTime += timer.secs(utils::Timer::resetCounter);
internalRet->m_sessionRunning = true;
internalRet->setDriveStatus(common::dataStructures::DriveStatus::Starting);
+ driveStatusSetTime += timer.secs(utils::Timer::resetCounter);
log::ScopedParamContainer params(lc);
uint32_t existingMounts = 0;
try {
existingMounts=existingMountsSummary.at(tpType(m->tapePool, m->type));
} catch (...) {}
+ schedulerDbTime = getMountInfoTime + queueTrimingTime + mountCreationTime + driveStatusSetTime;
+ catalogueTime = getTapeInfoTime + getTapeForWriteTime;
params.add("tapepool", m->tapePool)
.add("vid", t.vid)
.add("mountType", common::dataStructures::toString(m->type))
@@ -647,7 +671,17 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
.add("filesQueued", m->filesQueued)
.add("minFilesToWarrantMount", m_minFilesToWarrantAMount)
.add("oldestJobAge", time(NULL) - m->oldestJobStartTime)
- .add("minArchiveRequestAge", m->minArchiveRequestAge);
+ .add("minArchiveRequestAge", m->minArchiveRequestAge)
+ .add("getMountInfoTime", getMountInfoTime)
+ .add("queueTrimingTime", queueTrimingTime)
+ .add("getTapeInfoTime", getTapeInfoTime)
+ .add("candidateSortingTime", candidateSortingTime)
+ .add("getTapeForWriteTime", getTapeForWriteTime)
+ .add("decisionTime", decisionTime)
+ .add("mountCreationTime", mountCreationTime)
+ .add("driveStatusSetTime", driveStatusSetTime)
+ .add("schedulerDbTime", schedulerDbTime)
+ .add("catalogueTime", catalogueTime);
lc.log(log::DEBUG, "In Scheduler::getNextMount(): Selected next mount (archive)");
return std::unique_ptr<TapeMount> (internalRet.release());
} catch (cta::exception::Exception & ex) {
@@ -665,6 +699,7 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
if (tapesInUse.count(m->vid)) continue;
try {
// create the mount, and populate its DB side.
+ decisionTime += timer.secs(utils::Timer::resetCounter);
std::unique_ptr<RetrieveMount> internalRet (
new RetrieveMount(mountInfo->createRetrieveMount(m->vid,
m->tapePool,
@@ -672,15 +707,19 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
logicalLibraryName,
utils::getShortHostname(),
time(NULL))));
+ mountCreationTime += timer.secs(utils::Timer::resetCounter);
internalRet->m_sessionRunning = true;
internalRet->m_diskRunning = true;
internalRet->m_tapeRunning = true;
internalRet->setDriveStatus(common::dataStructures::DriveStatus::Starting);
+ driveStatusSetTime += timer.secs(utils::Timer::resetCounter);
log::ScopedParamContainer params(lc);
uint32_t existingMounts = 0;
try {
existingMounts=existingMountsSummary.at(tpType(m->tapePool, m->type));
} catch (...) {}
+ schedulerDbTime = getMountInfoTime + queueTrimingTime + mountCreationTime + driveStatusSetTime;
+ catalogueTime = getTapeInfoTime + getTapeForWriteTime;
params.add("tapepool", m->tapePool)
.add("vid", m->vid)
.add("mountType", common::dataStructures::toString(m->type))
@@ -690,7 +729,17 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
.add("filesQueued", m->filesQueued)
.add("minFilesToWarrantMount", m_minFilesToWarrantAMount)
.add("oldestJobAge", time(NULL) - m->oldestJobStartTime)
- .add("minArchiveRequestAge", m->minArchiveRequestAge);
+ .add("minArchiveRequestAge", m->minArchiveRequestAge)
+ .add("getMountInfoTime", getMountInfoTime)
+ .add("queueTrimingTime", queueTrimingTime)
+ .add("getTapeInfoTime", getTapeInfoTime)
+ .add("candidateSortingTime", candidateSortingTime)
+ .add("getTapeForWriteTime", getTapeForWriteTime)
+ .add("decisionTime", decisionTime)
+ .add("mountCreationTime", mountCreationTime)
+ .add("driveStatusSetTime", driveStatusSetTime)
+ .add("schedulerDbTime", schedulerDbTime)
+ .add("catalogueTime", catalogueTime);
lc.log(log::DEBUG, "In Scheduler::getNextMount(): Selected next mount (retrieve)");
return std::unique_ptr<TapeMount> (internalRet.release());
} catch (exception::Exception & ex) {
@@ -703,6 +752,19 @@ std::unique_ptr<TapeMount> Scheduler::getNextMount(const std::string &logicalLib
throw std::runtime_error("In Scheduler::getNextMount unexpected mount type");
}
}
+ schedulerDbTime = getMountInfoTime + queueTrimingTime + mountCreationTime + driveStatusSetTime;
+ catalogueTime = getTapeInfoTime + getTapeForWriteTime;
+ log::ScopedParamContainer params(lc);
+ params.add("getMountInfoTime", getMountInfoTime)
+ .add("queueTrimingTime", queueTrimingTime)
+ .add("getTapeInfoTime", getTapeInfoTime)
+ .add("candidateSortingTime", candidateSortingTime)
+ .add("getTapeForWriteTime", getTapeForWriteTime)
+ .add("decisionTime", decisionTime)
+ .add("mountCreationTime", mountCreationTime)
+ .add("driveStatusSetTime", driveStatusSetTime)
+ .add("schedulerDbTime", schedulerDbTime)
+ .add("catalogueTime", catalogueTime);
lc.log(log::DEBUG, "In Scheduler::getNextMount(): No valid mount found.");
return std::unique_ptr<TapeMount>();
}
--
GitLab