CASTOR-4743: tapeserverd logs fixes Naan + unclear message

The offending message has been changed in a previous case: CASTOR-4749

Reviewed all bandwidth calculations to homogenize the statistics printing.
Fixed a bug where the total time for a session was not properly retrieved before logging, leading to NaN printouts.

castor/tape/tapeserver/daemon/DiskReadTask.cpp

@@ -48,6 +48,7 @@ void DiskReadTask::execute(log::LogContext& lc, diskFile::DiskFileFactory & file
   using log::Param;
 
   castor::utils::Timer localTime;
+  castor::utils::Timer totalTime(localTime);
   size_t blockId=0;
   size_t migratingFileSize=m_migratedFile->fileSize();
   MemBlock* mb=NULL;
@@ -61,7 +62,8 @@ void DiskReadTask::execute(log::LogContext& lc, diskFile::DiskFileFactory & file
     std::auto_ptr<tape::diskFile::ReadFile> sourceFile(
       fileFactory.createReadFile(m_migratedFile->path()));
     log::ScopedParamContainer URLcontext(lc);
-    URLcontext.add("actualURL", sourceFile->URL());
+    URLcontext.add("path", m_migratedFile->path())
+               .add("actualURL", sourceFile->URL());
     if(migratingFileSize != sourceFile->size()){
       throw castor::exception::Exception("Mismtach between size given by the client "
               "and the real one");
@@ -102,8 +104,9 @@ void DiskReadTask::execute(log::LogContext& lc, diskFile::DiskFileFactory & file
       mb=NULL;
       
     } //end of while(migratingFileSize>0)
-    
     m_stats.filesCount++;
+    m_stats.totalTime = totalTime.secs();
+    logWithStat(LOG_INFO, "File successfully read from disk", lc);
   }
   catch(const castor::tape::tapeserver::daemon::ErrorFlag&){
    
@@ -166,8 +169,9 @@ void DiskReadTask::logWithStat(int level,const std::string& msg,log::LogContext&
            .addTiming("waitReportingTime",m_stats.waitReportingTime)
            .addTiming("checkingErrorTime",m_stats.checkingErrorTime)
            .addTiming("openingTime",m_stats.openingTime)
-           .add("payloadTransferSpeedMBps",
-                   1.0*m_stats.dataVolume/1000/1000/m_stats.transferTime)
+           .addTiming("totalTime", m_stats.totalTime)
+           .add("filePayloadTransferSpeedMBps",
+              m_stats.totalTime?1.0*m_stats.dataVolume/1000/1000/m_stats.totalTime:0)
            .add("FILEID",m_migratedFile->fileid())
            .add("path",m_migratedFile->path());
     lc.log(level,msg);

castor/tape/tapeserver/daemon/DiskReadTask.hpp

@@ -80,6 +80,11 @@ private:
    */
   void logWithStat(int level,const std::string& msg,log::LogContext& lc) ;
   
+  /**
+   * Circulate the remaining free blocks after an error
+   * @param fromBlockId the number of already processed
+   * @param mb pointer to a possible already popped free block (NULL otherwise)
+   */
   void circulateAllBlocks(size_t fromBlockId, MemBlock * mb);
   /**
    * The task (a TapeWriteTask) that will handle the read blocks

castor/tape/tapeserver/daemon/DiskReadThreadPool.cpp

@@ -129,16 +129,18 @@ void DiskReadThreadPool::addThreadStats(const DiskStats& other){
 //logWithStat
 //------------------------------------------------------------------------------
 void DiskReadThreadPool::logWithStat(int level, const std::string& message){
+  m_pooldStat.totalTime = m_totalTime.secs();
   log::ScopedParamContainer params(m_lc);
-     params.addTiming("poolTransferTime", m_pooldStat.transferTime)
-           .addTiming("poolWaitFreeMemoryTime",m_pooldStat.waitFreeMemoryTime)
-           .addTiming("poolCheckingErrorTime",m_pooldStat.checkingErrorTime)
-           .addTiming("poolOpeningTime",m_pooldStat.openingTime)
-           .add("poolFileCount",m_pooldStat.filesCount)
-           .add("poolDataVolumeInMB", 1.0*m_pooldStat.dataVolume/1000/1000)
-           .add("AveragePoolPayloadTransferSpeedMBps",
-                   1.0*m_pooldStat.dataVolume/1000/1000/m_pooldStat.transferTime);
-    m_lc.log(level,message);
+  params.addTiming("poolTransferTime", m_pooldStat.transferTime)
+        .addTiming("poolWaitFreeMemoryTime",m_pooldStat.waitFreeMemoryTime)
+        .addTiming("poolCheckingErrorTime",m_pooldStat.checkingErrorTime)
+        .addTiming("poolOpeningTime",m_pooldStat.openingTime)
+        .addTiming("poolRealTime",m_pooldStat.totalTime)
+        .add("poolFileCount",m_pooldStat.filesCount)
+        .add("poolDataVolumeInMB", 1.0*m_pooldStat.dataVolume/1000/1000)
+        .add("AveragePoolPayloadTransferSpeedMBps",
+           m_pooldStat.totalTime?1.0*m_pooldStat.dataVolume/1000/1000/m_pooldStat.totalTime:0);
+  m_lc.log(level,message);
 }
 //------------------------------------------------------------------------------
 // DiskReadWorkerThread::run
@@ -151,6 +153,7 @@ void DiskReadThreadPool::DiskReadWorkerThread::run() {
   
   std::auto_ptr<DiskReadTask> task;
   castor::utils::Timer localTime;
+  castor::utils::Timer totalTime;
   
   while(1) {
     task.reset( m_parent.popAndRequestMore(m_lc));
@@ -163,19 +166,21 @@ void DiskReadThreadPool::DiskReadWorkerThread::run() {
       break;
     }
   } //end of while(1)
+  m_threadStat.totalTime = totalTime.secs();
+  m_parent.addThreadStats(m_threadStat);
+  logWithStat(LOG_INFO, "Finishing of DiskReadWorkerThread");
   // We now acknowledge to the task injector that read reached the end. There
   // will hence be no more requests for more. (last thread turns off the light)
   int remainingThreads = --m_parent.m_nbActiveThread;
   if (!remainingThreads) {
     m_parent.m_injector->finish();
-    m_lc.log(LOG_INFO, "Signaled to task injector the end of disk read threads");
+    m_lc.log(LOG_INFO, "Signalled to task injector the end of disk read threads");
+    m_parent.logWithStat(LOG_INFO, "All the DiskReadWorkerThreads have completed");
   } else {
     castor::log::ScopedParamContainer params(m_lc);
     params.add("remainingThreads", remainingThreads);
     m_lc.log(LOG_DEBUG, "Will not signal the end to task injector yet");
   }
-  m_parent.addThreadStats(m_threadStat);
-  logWithStat(LOG_INFO, "Finishing of DiskReadWorkerThread");
 }
 
 //------------------------------------------------------------------------------
@@ -188,9 +193,11 @@ logWithStat(int level, const std::string& message){
            .addTiming("threadWaitFreeMemoryTime",m_threadStat.waitFreeMemoryTime)
            .addTiming("threadCheckingErrorTime",m_threadStat.checkingErrorTime)
            .addTiming("threadOpeningTime",m_threadStat.openingTime)
+           .addTiming("threadTotalTime",m_threadStat.totalTime)
            .add("threaDataVolumeInMB", 1.0*m_threadStat.dataVolume/1000/1000)
            .add("threadPayloadTransferSpeedMBps",
-                   1.0*m_threadStat.dataVolume/1000/1000/m_threadStat.transferTime);
+                   m_threadStat.totalTime?1.0*m_threadStat.dataVolume/1000/1000/m_threadStat.totalTime:0)
+           .addTiming("totalTime",m_threadStat.totalTime);
     m_lc.log(level,message);
 }
 }}}}

castor/tape/tapeserver/daemon/DiskReadThreadPool.hpp

@@ -29,6 +29,7 @@
 #include "castor/server/Threading.hpp"
 #include "castor/server/AtomicCounter.hpp"
 #include "castor/log/LogContext.hpp"
+#include "castor/utils/Timer.hpp"
 #include <vector>
 #include <stdint.h>
 
@@ -44,10 +45,10 @@ public:
    * start them.
    * @param nbThread Number of thread for reading files 
    * @param maxFilesReq maximal number of files we might require 
-   * within a single request to the task injectore
+   * within a single request to the task injector
    * @param maxBytesReq maximal number of bytes we might require
-   *  within a single request a single request to the task injectore
-   * @param lc log context fpr logging purpose
+   *  within a single request a single request to the task injector
+   * @param lc log context for logging purpose
    */
   DiskReadThreadPool(int nbThread, uint64_t maxFilesReq,uint64_t maxBytesReq, 
           castor::log::LogContext lc, const std::string & remoteFileProtocol,
@@ -131,6 +132,11 @@ private:
    */
   DiskStats m_pooldStat;
   
+  /**
+   * Measure the thread pool's lifetime
+   */
+  castor::utils::Timer m_totalTime;
+  
   /**
    * A disk file factory, that will create the proper type of file access class,
    * depending on the received path

castor/tape/tapeserver/daemon/DiskStats.hpp

@@ -35,7 +35,7 @@ namespace daemon {
     /** Mounting time, in seconds */
     double openingTime;
     
-    /** Mounting time, in seconds */
+    /** Closing time, in seconds */
     double closingTime;
     
     /** Cumulated time spent computing checksums */
@@ -44,9 +44,6 @@ namespace daemon {
     /** Cumulated time spent transfering data with the disk */
     double transferTime;
     
-    /** Closing time, in seconds */
-    //double closingTime;
-    
     /** Cumulated time spent waiting for data blocks. */
     double waitDataTime;
     
@@ -62,6 +59,9 @@ namespace daemon {
     /** Cumulated time spent reporting */
     double checkingErrorTime;
     
+    /** Total real time spent by the thread/pool. */
+    double totalTime;
+    
     /** Cumulated data volume (actual payload), in bytes. */
     uint64_t dataVolume;
     
@@ -70,15 +70,15 @@ namespace daemon {
     
     /** Constructor: all defaults are zero */
     DiskStats():  openingTime(0.0), 
-    closingTime(0.),
+    closingTime(0.0),
     checksumingTime(0.0),
     transferTime(0.0),
-    //closingTime(0.),
     waitDataTime(0.0), 
     waitFreeMemoryTime(0.0),
     waitInstructionsTime(0.0),
     waitReportingTime(0.0), 
-    checkingErrorTime(0),
+    checkingErrorTime(0.0),
+    totalTime(0.0),
     dataVolume(0),
     filesCount(0) {}
     
@@ -89,12 +89,12 @@ namespace daemon {
       closingTime += other.closingTime;
       checksumingTime += other.checksumingTime;
       transferTime += other.transferTime;
-      //closingTime += other.closingTime;
       waitDataTime += other.waitDataTime;
       waitFreeMemoryTime += other.waitFreeMemoryTime;
       waitInstructionsTime += other.waitInstructionsTime;
       waitReportingTime += other.waitReportingTime;
       checkingErrorTime += other.checkingErrorTime;
+      // total time is not a cumulative member. It is used to represent wallclock time.
       filesCount += other.filesCount;
       dataVolume += other.dataVolume;
     }

castor/tape/tapeserver/daemon/DiskWriteTask.cpp

@@ -48,6 +48,7 @@ bool DiskWriteTask::execute(RecallReportPacker& reporter,log::LogContext& lc,
   using log::LogContext;
   using log::Param;
   castor::utils::Timer localTime;
+  castor::utils::Timer totalTime(localTime);
   try{
     // Placeholder for the disk file. We will open it only
     // after getting a first correct memory block.
@@ -102,6 +103,7 @@ bool DiskWriteTask::execute(RecallReportPacker& reporter,log::LogContext& lc,
     } //end of while(1)
     reporter.reportCompletedJob(*m_recallingFile,checksum,m_stats.dataVolume);
     m_stats.waitReportingTime+=localTime.secs(castor::utils::Timer::resetCounter);
+    m_stats.totalTime = totalTime.secs();
     logWithStat(LOG_DEBUG, "File successfully transfered to disk",lc);
     
     //everything went well, return true
@@ -211,8 +213,9 @@ void DiskWriteTask::logWithStat(int level,const std::string& msg,log::LogContext
            .addTiming("checkingErrorTime",m_stats.checkingErrorTime)
            .addTiming("openingTime",m_stats.openingTime)
            .addTiming("closingTime",m_stats.closingTime)
-           .add("payloadTransferSpeedMBps",
-                   1.0*m_stats.dataVolume/1000/1000/m_stats.transferTime)
+           .addTiming("totalTime", m_stats.totalTime)
+           .add("filePayloadTransferSpeedMBps",
+              m_stats.totalTime?1.0*m_stats.dataVolume/1000/1000/m_stats.totalTime:0)
            .add("FILEID",m_recallingFile->fileid())
            .add("path",m_recallingFile->path());
     lc.log(level,msg);

castor/tape/tapeserver/daemon/DiskWriteThreadPool.cpp

@@ -121,19 +121,21 @@ void DiskWriteThreadPool::addThreadStats(const DiskStats& other){
 //logWithStat
 //------------------------------------------------------------------------------
 void DiskWriteThreadPool::logWithStat(int level, const std::string& message){
+  m_pooldStat.totalTime = m_totalTime.secs();
   log::ScopedParamContainer params(m_lc);
-     params.addTiming("poolTransferTime", m_pooldStat.transferTime)
-           .addTiming("poolChecksumingTime",m_pooldStat.checksumingTime)
-           .addTiming("poolWaitDataTime",m_pooldStat.waitDataTime)
-           .addTiming("poolWaitReportingTime",m_pooldStat.waitReportingTime)
-           .addTiming("poolCheckingErrorTime",m_pooldStat.checkingErrorTime)
-           .addTiming("poolOpeningTime",m_pooldStat.openingTime)
-           .add("poolFileCount",m_pooldStat.filesCount)
-           .addTiming("poolClosingTime", m_pooldStat.closingTime)
-           .add("poolDataVolumeInMB", 1.0*m_pooldStat.dataVolume/1024/1024)
-           .add("poolPayloadTransferSpeedMBps",
-                   1.0*m_pooldStat.dataVolume/1000/1000/m_pooldStat.transferTime);
-    m_lc.log(level,message);
+  params.addTiming("poolTransferTime", m_pooldStat.transferTime)
+        .addTiming("poolChecksumingTime",m_pooldStat.checksumingTime)
+        .addTiming("poolWaitDataTime",m_pooldStat.waitDataTime)
+        .addTiming("poolWaitReportingTime",m_pooldStat.waitReportingTime)
+        .addTiming("poolCheckingErrorTime",m_pooldStat.checkingErrorTime)
+        .addTiming("poolOpeningTime",m_pooldStat.openingTime)
+        .addTiming("poolClosingTime", m_pooldStat.closingTime)
+        .addTiming("poolRealTime",m_pooldStat.totalTime)
+        .add("poolFileCount",m_pooldStat.filesCount)
+        .add("poolDataVolumeInMB", 1.0*m_pooldStat.dataVolume/1024/1024)
+        .add("AveragePoolPayloadTransferSpeedMBps",
+           m_pooldStat.totalTime?1.0*m_pooldStat.dataVolume/1000/1000/m_pooldStat.transferTime:0);
+  m_lc.log(level,message);
 }
 //------------------------------------------------------------------------------
 // DiskWriteWorkerThread::run
@@ -147,6 +149,7 @@ void DiskWriteThreadPool::DiskWriteWorkerThread::run() {
   
   std::auto_ptr<DiskWriteTask>  task;
   castor::utils::Timer localTime;
+  castor::utils::Timer totalTime(localTime);
   
   while(1) {
     task.reset(m_parentThreadPool.m_tasks.pop());
@@ -165,6 +168,7 @@ void DiskWriteThreadPool::DiskWriteWorkerThread::run() {
       break;
     }
   } //enf of while(1)
+  m_threadStat.totalTime = totalTime.secs();
   logWithStat(LOG_INFO, "Finishing DiskWriteWorkerThread");
   m_parentThreadPool.addThreadStats(m_threadStat);
   if(0 == --m_parentThreadPool.m_nbActiveThread){
@@ -177,7 +181,7 @@ void DiskWriteThreadPool::DiskWriteWorkerThread::run() {
     else{
       m_parentThreadPool.m_reporter.reportEndOfSessionWithErrors("End of recall session with error(s)",SEINTERNAL);
       ScopedParam sp(m_lc, Param("errorCount", m_parentThreadPool.m_failedWriteCount));
-        m_parentThreadPool.logWithStat(LOG_ERR, "As last exiting DiskWriteWorkerThread, reported an end of session with errors");
+      m_parentThreadPool.logWithStat(LOG_INFO, "As last exiting DiskWriteWorkerThread, reported an end of session with errors");
     }
   }
 }
@@ -192,13 +196,14 @@ logWithStat(int level, const std::string& msg) {
            .addTiming("threadChecksumingTime",m_threadStat.checksumingTime)
            .addTiming("threadWaitDataTime",m_threadStat.waitDataTime)
            .addTiming("threadWaitReportingTime",m_threadStat.waitReportingTime)
-           .add("threadFileCount",m_threadStat.filesCount)
            .addTiming("threadCheckingErrorTime",m_threadStat.checkingErrorTime)
            .addTiming("threadOpeningTime",m_threadStat.openingTime)
            .addTiming("threadClosingTime", m_threadStat.closingTime)
-           .add("threaDataVolumeInMB", 1.0*m_threadStat.dataVolume/1024/1024)
+           .addTiming("threadTotalTime",m_threadStat.totalTime)
+           .add("threaDataVolumeInMB", 1.0*m_threadStat.dataVolume/1000/1000)
+           .add("threadFileCount",m_threadStat.filesCount)
            .add("threadPayloadTransferSpeedMBps",
-                   1.0*m_threadStat.dataVolume/1000/1000/m_threadStat.transferTime);
+                   m_threadStat.totalTime?1.0*m_threadStat.dataVolume/1000/1000/m_threadStat.totalTime:0);
     m_lc.log(level,msg);
 }
 }}}}

castor/tape/tapeserver/daemon/DiskWriteThreadPool.hpp

@@ -32,6 +32,7 @@
 #include "castor/tape/tapeserver/daemon/RecallReportPacker.hpp"
 #include "castor/tape/tapeserver/daemon/DiskWriteTask.hpp"
 #include "castor/tape/tapeserver/daemon/DiskStats.hpp"
+#include "castor/utils/Timer.hpp"
 #include <vector>
 #define __STDC_FORMAT_MACROS
 #include <inttypes.h>
@@ -129,7 +130,7 @@ private:
      * For measuring how long  are the the different steps 
      */
     DiskStats m_threadStat;
-    
+  
     /**
      * To identify the thread 
      */
@@ -182,6 +183,12 @@ private:
    * Aggregate all threads' stats 
    */
   DiskStats m_pooldStat;
+
+  /**
+   * Measure the thread pool's lifetime
+   */
+  castor::utils::Timer m_totalTime;
+    
   /** Reference to the report packer where tasks report the result of their 
    * individual files and the end of session (for the last thread) */
   RecallReportPacker& m_reporter;

castor/tape/tapeserver/daemon/RecallReportPacker.cpp

@@ -121,25 +121,28 @@ void RecallReportPacker::flush(){
     return;
   }
  
-    client::ClientInterface::RequestReport chrono;
-    try{
-         m_client.reportRecallResults(*m_listReports,chrono);
-         logRequestReport(chrono,"RecallReportList successfully transmitted to client (contents follow)");
-         
-         logReport(m_listReports->failedRecalls(),"Reported failed recall to client");
-         logReport(m_listReports->successfulRecalls(),"Reported successful recall to client");
-       }
-   catch(const castor::exception::Exception& e){
+  client::ClientInterface::RequestReport chrono;
+  try{
+    m_client.reportRecallResults(*m_listReports,chrono);
+    {
+      log::ScopedParamContainer params(m_lc);
+      params.add("successCount", m_listReports->successfulRecalls().size())
+            .add("failureCount", m_listReports->failedRecalls().size());
+      logRequestReport(chrono,"RecallReportList successfully transmitted to client (contents follow)");
+    }
+    logReport(m_listReports->failedRecalls(),"Reported failed recall to client");
+    logReport(m_listReports->successfulRecalls(),"Reported successful recall to client");
+  } catch(const castor::exception::Exception& e){
     LogContext::ScopedParam s(m_lc, Param("exceptionCode",e.code()));
     LogContext::ScopedParam ss(m_lc, Param("exceptionMessageValue", e.getMessageValue()));
     LogContext::ScopedParam sss(m_lc, Param("exceptionWhat",e.what()));
     const std::string msg_error="An exception was caught trying to call reportRecallResults";
     m_lc.log(LOG_ERR,msg_error);
     throw failedReportRecallResult(msg_error);
-    }
-    //delete the old pointer and replace it with the new one provided
-    //that way, all the reports that have been send are deleted (by FileReportList's destructor)
-    m_listReports.reset(new FileReportList);
+  }
+  //delete the old pointer and replace it with the new one provided
+  //that way, all the reports that have been send are deleted (by FileReportList's destructor)
+  m_listReports.reset(new FileReportList);
 }
 //------------------------------------------------------------------------------
 //ReportEndofSession::execute

castor/tape/tapeserver/daemon/ReportPackerInterface.hpp

@@ -138,17 +138,13 @@ template <class PlaceHolder> class ReportPackerInterface{
    * @param msg the message we want to have in the log 
    * @param level the log level wanted
    */
-  void logRequestReport(const client::ClientInterface::RequestReport& chono,const std::string& msg,int level=LOG_INFO){
-    using castor::log::LogContext;
-    using castor::log::Param;
-     
-        LogContext::ScopedParam sp[]={
-          LogContext::ScopedParam(m_lc, Param("connectDuration",chono.connectDuration)),
-          LogContext::ScopedParam(m_lc, Param("sendRecvDuration",chono.sendRecvDuration)),
-          LogContext::ScopedParam(m_lc, Param("transactionId", chono.transactionId)),
-        };
-        tape::utils::suppresUnusedVariable(sp);
-        m_lc.log(level,msg);
+  void logRequestReport(const client::ClientInterface::RequestReport& chono,
+    const std::string& msg, int level=LOG_INFO){
+    castor::log::ScopedParamContainer params(m_lc);
+    params.add("connectDuration",chono.connectDuration)
+          .add("sendRecvDuration",chono.sendRecvDuration)
+          .add("transactionId", chono.transactionId);
+    m_lc.log(level,msg);
         
   } 
   /**

castor/tape/tapeserver/daemon/TapeReadSingleThread.cpp

@@ -187,8 +187,9 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::run() {
     // at the end of the previous block. Log the results.
     log::ScopedParamContainer params(m_logContext);
     params.add("status", "success");
+    m_stats.totalTime = totalTimer.secs();
     logWithStat(LOG_INFO, "Tape thread complete",
-            params,totalTimer.secs());
+            params);
   } catch(const castor::exception::Exception& e){
     // We end up here because one step failed, be it at mount time, of after
     // failing to position by fseq (this is fatal to a read session as we need
@@ -198,8 +199,9 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::run() {
     log::ScopedParamContainer params(m_logContext);
     params.add("status", "error")
           .add("ErrorMesage", e.getMessageValue());
-    logWithStat(LOG_ERR, "Tape thread complete",
-            params,totalTimer.secs());
+    m_stats.totalTime = totalTimer.secs();
+    logWithStat(LOG_INFO, "Tape thread complete",
+            params);
     // Flush the remaining tasks to cleanly exit.
     while(1){
       TapeReadTask* task=m_tasks.pop();
@@ -216,8 +218,7 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::run() {
 //TapeReadSingleThread::logWithStat()
 //------------------------------------------------------------------------------
 void castor::tape::tapeserver::daemon::TapeReadSingleThread::logWithStat(
-  int level, const std::string& msg, log::ScopedParamContainer& params, 
-  double sessionTime) {
+  int level, const std::string& msg, log::ScopedParamContainer& params) {
     params.add("type", "read")
           .add("VID", m_volInfo.vid)
           .addTiming("mountTime", m_stats.mountTime)
@@ -229,13 +230,13 @@ void castor::tape::tapeserver::daemon::TapeReadSingleThread::logWithStat(
           .addTiming("waitReportingTime", m_stats.waitReportingTime)
           .addTiming("unloadTime", m_stats.unloadTime)
           .addTiming("unmountTime", m_stats.unmountTime)
+          .addTiming("totalTime", m_stats.totalTime)
           .add("dataVolume", m_stats.dataVolume)
           .add("headerVolume", m_stats.headerVolume)
           .add("files", m_stats.filesCount)
-          .add("dataBandwidthMBps", 1.0*m_stats.dataVolume
-                  /1000/1000/sessionTime)
-          .add("driveBandwidthMBps", 1.0*(m_stats.dataVolume+m_stats.headerVolume)
-                  /1000/1000/sessionTime)
-          .addTiming("sessionTime", sessionTime);
+          .add("payloadTransferSpeedMBps", m_stats.totalTime?1.0*m_stats.dataVolume
+                  /1000/1000/m_stats.totalTime:0.0)
+          .add("driveTransferSpeedMBps", m_stats.totalTime?1.0*(m_stats.dataVolume+m_stats.headerVolume)
+                  /1000/1000/m_stats.totalTime:0.0);
     m_logContext.log(level,msg);  
 }

castor/tape/tapeserver/daemon/TapeReadSingleThread.hpp

@@ -112,7 +112,7 @@ private:
    * @param sessionTime
    */
   void logWithStat(int level,const std::string& msg,
-    log::ScopedParamContainer& params,double sessionTime);
+    log::ScopedParamContainer& params);
   
   /**
    * Number of files a single request to the client might give us.

castor/tape/tapeserver/daemon/TapeReadTask.hpp

@@ -78,6 +78,7 @@ public:
     // stats to the session's.
     TapeSessionStats localStats;
     castor::utils::Timer localTime;
+    castor::utils::Timer totalTime(localTime);
 
     // Read the file and transmit it
     bool stillReading = true;
@@ -125,20 +126,22 @@ public:
       //  we have to signal the end of the tape read to the disk write task.
       m_fifo.pushDataBlock(NULL);
       // Log the successful transfer
-      double fileTime = localTime.secs();
+      localStats.totalTime = localTime.secs();
+      // Hardcoded header size for lack of a better mechanism
+      // Head + trailer, 3 * 80 bytes each
+      localStats.headerVolume = (2 * 3 * 80);
       log::ScopedParamContainer params(lc);
       params.addTiming("positionTime", localStats.positionTime)
             .addTiming("transferTime", localStats.transferTime)
             .addTiming("waitFreeMemoryTime",localStats.waitFreeMemoryTime)
             .addTiming("waitReportingTime",localStats.waitReportingTime)
+            .addTiming("totalTime", localStats.totalTime)
             .add("dataVolume",localStats.dataVolume)
-            .addTiming("totalTime", fileTime)
             .add("driveTransferSpeedMBps",
-                    (localStats.dataVolume+localStats.headerVolume)
-                     /1000/1000
-                     /localStats.transferTime)
+                    localStats.totalTime?(1.0*localStats.dataVolume+1.0*localStats.headerVolume)
+                     /1000/1000/localStats.totalTime:0)
             .add("payloadTransferSpeedMBps",
-                     1.0*localStats.dataVolume/1000/1000/fileTime)
+                     localStats.totalTime?1.0*localStats.dataVolume/1000/1000/localStats.totalTime:0)
             .add("fileid",m_fileToRecall->fileid())
             .add("fseq",m_fileToRecall->fseq())
             .add("fileTransactionId",m_fileToRecall->fileTransactionId());

castor/tape/tapeserver/daemon/TapeSessionStats.hpp

@@ -65,6 +65,9 @@ namespace daemon {
     /** Cumulated time spent reporting */
     double waitReportingTime;
     
+    /** Total time of the session, computed in parallel */
+    double totalTime;
+    
     /** Cumulated data volume (actual payload), in bytes. */
     uint64_t dataVolume;
     
@@ -80,7 +83,8 @@ namespace daemon {
     TapeSessionStats():  mountTime(0.0), positionTime(0.0), checksumingTime(0.0),
     transferTime(0.0), flushTime(0.0), unloadTime(0.0), unmountTime(0.0),
     waitDataTime(0.0), waitFreeMemoryTime(0.0), waitInstructionsTime(0.0),
-    waitReportingTime(0.0), dataVolume(0), headerVolume(0), filesCount(0) {}
+    waitReportingTime(0.0), totalTime(0.0), dataVolume(0), headerVolume(0),
+    filesCount(0) {}
     
     /** Accumulate contents of another stats block */
     void add(const TapeSessionStats& other) {
@@ -95,6 +99,7 @@ namespace daemon {
       waitFreeMemoryTime += other.waitFreeMemoryTime;
       waitInstructionsTime += other.waitInstructionsTime;
       waitReportingTime += other.waitReportingTime;
+      // totalTime is not cumulative between threads (it's real time)
       dataVolume += other.dataVolume;
       headerVolume += other.headerVolume;
       filesCount += other.filesCount;

castor/tape/tapeserver/daemon/TapeWriteSingleThread.cpp

@@ -201,7 +201,8 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
     // at the end of the previous block. Log the results.
     log::ScopedParamContainer params(m_logContext);
     params.add("status", "success");
-    logWithStats(LOG_INFO, "Tape thread complete",params,totalTimer.secs());
+    m_stats.totalTime = totalTimer.secs();
+    logWithStats(LOG_INFO, "Tape thread complete",params);
   } //end of try 
   catch(const castor::exception::Exception& e){
     //we end there because write session could not be opened 
@@ -240,8 +241,9 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
     log::ScopedParamContainer params(m_logContext);
     params.add("status", "error")
           .add("ErrorMesage", errorMessage);
-    logWithStats(LOG_ERR, "Tape thread complete",
-            params,totalTimer.secs());
+    m_stats.totalTime = totalTimer.secs();
+    logWithStats(LOG_INFO, "Tape thread complete",
+            params);
     m_reportPacker.reportEndOfSessionWithErrors(errorMessage,errorCode);
   }    
 }
@@ -250,8 +252,7 @@ void castor::tape::tapeserver::daemon::TapeWriteSingleThread::run() {
 //logWithStats
 //------------------------------------------------------------------------------
 void castor::tape::tapeserver::daemon::TapeWriteSingleThread::logWithStats(
-int level,const std::string& msg, log::ScopedParamContainer& params,
-double sessionTime){
+int level,const std::string& msg, log::ScopedParamContainer& params){
   params.add("type", "write")
         .add("VID", m_volInfo.vid)
         .addTiming("mountTime", m_stats.mountTime)
@@ -264,13 +265,13 @@ double sessionTime){
         .addTiming("flushTime", m_stats.flushTime)
         .addTiming("unloadTime", m_stats.unloadTime)
         .addTiming("unmountTime", m_stats.unmountTime)
+        .addTiming("totalTime", m_stats.totalTime)