Commit 8fb87585 authored by Cedric Caffy's avatar Cedric Caffy
Browse files

[cta-taped] Added logging for the time the drive takes to load a tape

parent 847aa9bd
...@@ -4,7 +4,9 @@ ...@@ -4,7 +4,9 @@
### Features ### Features
- Upgraded EOS to 4.8.35-1
- cta/CTA#954 The drive is put down if the CleanerSession fails to eject the tape from it after a shutdown - cta/CTA#954 The drive is put down if the CleanerSession fails to eject the tape from it after a shutdown
- cta/CTA#945 The timeout for tape load action is now configurable
### Bug fixes ### Bug fixes
......
...@@ -492,7 +492,9 @@ Currently contains a helper for the client-ar script, which should be installed ...@@ -492,7 +492,9 @@ Currently contains a helper for the client-ar script, which should be installed
%changelog %changelog
* Thu Jan 07 2021 julien.leduc (at) cern.ch - 3.1-14 * Thu Jan 07 2021 julien.leduc (at) cern.ch - 3.1-14
- Upgraded EOS to 4.8.35-1
- cta/CTA#954 The drive is put down if the CleanerSession fails to eject the tape from it after a shutdown - cta/CTA#954 The drive is put down if the CleanerSession fails to eject the tape from it after a shutdown
- cta/CTA#945 The timeout for tape load action is now configurable
- cta/CTA#957 The state of the successful Archive for repack jobs is now changed before being queued for reporting - cta/CTA#957 The state of the successful Archive for repack jobs is now changed before being queued for reporting
- cta/CTA#958 The RepackRequest garbage collection now changes the owner of the garbage collected RepackRequest. - cta/CTA#958 The RepackRequest garbage collection now changes the owner of the garbage collected RepackRequest.
* Thu Jan 07 2021 julien.leduc (at) cern.ch - 3.1-13 * Thu Jan 07 2021 julien.leduc (at) cern.ch - 3.1-13
......
...@@ -253,13 +253,16 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::run() { ...@@ -253,13 +253,16 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::run() {
m_logContext.log(cta::log::INFO, "Tape session started"); m_logContext.log(cta::log::INFO, "Tape session started");
mountTapeReadOnly(); mountTapeReadOnly();
currentErrorToCount = "Error_tapeLoad"; currentErrorToCount = "Error_tapeLoad";
cta::utils::Timer tapeLoadTimer;
waitForDrive(); waitForDrive();
double tapeLoadTime = tapeLoadTimer.secs();
currentErrorToCount = "Error_checkingTapeAlert"; currentErrorToCount = "Error_checkingTapeAlert";
logTapeAlerts(); logTapeAlerts();
m_stats.mountTime += timer.secs(cta::utils::Timer::resetCounter); m_stats.mountTime += timer.secs(cta::utils::Timer::resetCounter);
{ {
cta::log::ScopedParamContainer scoped(m_logContext); cta::log::ScopedParamContainer scoped(m_logContext);
scoped.add("mountTime", m_stats.mountTime); scoped.add("mountTime", m_stats.mountTime);
scoped.add("tapeLoadTime",tapeLoadTime);
m_logContext.log(cta::log::INFO, "Tape mounted and drive ready"); m_logContext.log(cta::log::INFO, "Tape mounted and drive ready");
} }
m_retrieveMount.setTapeMounted(m_logContext); m_retrieveMount.setTapeMounted(m_logContext);
......
...@@ -151,14 +151,16 @@ protected: ...@@ -151,14 +151,16 @@ protected:
* case of timeout) * case of timeout)
*/ */
void waitForDrive(){ void waitForDrive(){
cta::utils::Timer tapeLoadTime;
try{ try{
cta::utils::Timer timer;
// wait tapeLoadTimeout seconds for drive to be ready (the mount call is synchronous, so this just the load operation. // wait tapeLoadTimeout seconds for drive to be ready (the mount call is synchronous, so this just the load operation.
m_drive.waitUntilReady(m_tapeLoadTimeout); m_drive.waitUntilReady(m_tapeLoadTimeout);
cta::log::LogContext::ScopedParam sp0(m_logContext, cta::log::Param("loadTime", timer.secs()));
}catch(const cta::exception::Exception& e){ }catch(const cta::exception::Exception& e){
cta::log::LogContext::ScopedParam sp01(m_logContext, cta::log::Param("exceptionMessage", e.getMessageValue())); cta::log::ScopedParamContainer spc(m_logContext);
m_logContext.log(cta::log::INFO, "Got timeout or error while waiting for drive to be ready."); spc.add("exceptionMessage",e.getMessageValue())
.add("configuredTapeLoadTimeout",m_tapeLoadTimeout)
.add("tapeLoadTime",tapeLoadTime.secs());
m_logContext.log(cta::log::ERR, "Got timeout or error while waiting for drive to be ready.");
throw; throw;
} }
} }
......
...@@ -327,7 +327,9 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() { ...@@ -327,7 +327,9 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
m_logContext.log(cta::log::INFO, "Tape session started"); m_logContext.log(cta::log::INFO, "Tape session started");
mountTapeReadWrite(); mountTapeReadWrite();
currentErrorToCount = "Error_tapeLoad"; currentErrorToCount = "Error_tapeLoad";
cta::utils::Timer tapeLoadTimer;
waitForDrive(); waitForDrive();
double tapeLoadTime = tapeLoadTimer.secs();
currentErrorToCount = "Error_checkingTapeAlert"; currentErrorToCount = "Error_checkingTapeAlert";
if(logAndCheckTapeAlertsForWrite()) { if(logAndCheckTapeAlertsForWrite()) {
throw cta::exception::Exception("Aborting migration session in" throw cta::exception::Exception("Aborting migration session in"
...@@ -341,6 +343,7 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() { ...@@ -341,6 +343,7 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
{ {
cta::log::ScopedParamContainer scoped(m_logContext); cta::log::ScopedParamContainer scoped(m_logContext);
scoped.add("mountTime", m_stats.mountTime); scoped.add("mountTime", m_stats.mountTime);
scoped.add("tapeLoadTime",tapeLoadTime);
m_logContext.log(cta::log::INFO, "Tape mounted and drive ready"); m_logContext.log(cta::log::INFO, "Tape mounted and drive ready");
} }
m_archiveMount.setTapeMounted(m_logContext); m_archiveMount.setTapeMounted(m_logContext);
......
Supports Markdown
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment