Added job information to fileinfo.log: total duration, CPU time reported by ROOT...
authoragheata <agheata@f7af4fe6-9843-0410-8265-dc069ae4e863>
Tue, 11 Sep 2012 06:46:22 +0000 (06:46 +0000)
committeragheata <agheata@f7af4fe6-9843-0410-8265-dc069ae4e863>
Tue, 11 Sep 2012 06:46:22 +0000 (06:46 +0000)
ANALYSIS/AliAnalysisAlien.cxx
ANALYSIS/AliAnalysisAlien.h
ANALYSIS/AliAnalysisManager.cxx
ANALYSIS/AliAnalysisManager.h

index af97440..21eed7c 100644 (file)
@@ -1535,6 +1535,7 @@ Bool_t AliAnalysisAlien::CreateJDL()
 {
 // Generate a JDL file according to current settings. The name of the file is 
 // specified by fJDLName.
+   AliAnalysisManager *mgr = AliAnalysisManager::GetAnalysisManager();
    Bool_t error = kFALSE;
    TObjArray *arr = 0;
    Bool_t copy = kTRUE;
@@ -1719,7 +1720,11 @@ Bool_t AliAnalysisAlien::CreateJDL()
                delete arr;
             }
             files.ReplaceAll(".root", "*.root");
-            outputArchive += Form("root_archive.zip:%s,*.stat@disk=%d",files.Data(),fNreplicas);
+            
+            if (mgr->IsCollectThroughput())
+               outputArchive += Form("root_archive.zip:%s,*.stat,*%s@disk=%d",files.Data(),mgr->GetFileInfoLog(),fNreplicas);
+            else
+               outputArchive += Form("root_archive.zip:%s,*.stat@disk=%d",files.Data(),fNreplicas);
          } else {
             TString files = fOutputArchive;
             files.ReplaceAll(".root", "*.root"); // nreplicas etc should be already atttached by use
@@ -2631,6 +2636,44 @@ Int_t AliAnalysisAlien::SubmitSingleJob(const char *query)
 }  
 
 //______________________________________________________________________________
+Bool_t AliAnalysisAlien::MergeInfo(const char *output, const char *collection)
+{
+// Merges a collection of output files using concatenation.
+   TGridCollection *coll = (TGridCollection*)gROOT->ProcessLine(Form("TAlienCollection::Open(\"%s\");", collection));
+   if (!coll) {
+      ::Error("MergeInfo", "Input XML %s collection empty.", collection);
+      return kFALSE;
+   }
+   // Iterate grid collection
+   TString outtmp;
+   Bool_t merged = kFALSE;
+   Int_t ifile = 0;
+   while (coll->Next()) {
+      TString fname = gSystem->DirName(coll->GetTURL());
+      fname += "/";
+      fname += output;
+      outtmp = Form("%d_%s", ifile, output);
+      if (!TFile::Cp(fname, outtmp)) {
+         ::Error("MergeInfo", "Could not copy %s", fname.Data());
+         continue;
+      }
+      ifile++;
+      if (ifile<2) {
+         gSystem->Exec(Form("cp %s lastmerged", outtmp.Data()));
+         continue;
+      }
+      gSystem->Exec(Form("cat lastmerged %s > tempmerged", outtmp.Data()));
+      gSystem->Exec("cp tempmerged lastmerged");
+   }
+   if (ifile) {
+      gSystem->Exec(Form("cp lastmerged %s", output));
+      gSystem->Exec(Form("rm tempmerged lastmerged *_%s", output));
+      merged = kTRUE;
+   }
+   return merged;
+}   
+
+//______________________________________________________________________________
 Bool_t AliAnalysisAlien::MergeOutput(const char *output, const char *basedir, Int_t nmaxmerge, Int_t stage)
 {
 // Merge given output files from basedir. Basedir can be an alien output directory
@@ -3272,7 +3315,10 @@ Bool_t AliAnalysisAlien::StartAnalysis(Long64_t /*nentries*/, Long64_t /*firstEn
       }
       // Compose the output archive.
       fOutputArchive = "log_archive.zip:std*@disk=1 ";
-      fOutputArchive += Form("root_archive.zip:%s,*.stat@disk=%d",fOutputFiles.Data(),fNreplicas);
+      if (mgr->IsCollectThroughput())
+         fOutputArchive += Form("root_archive.zip:%s,*.stat,*%s@disk=%d",fOutputFiles.Data(),mgr->GetFileInfoLog(),fNreplicas);
+      else
+         fOutputArchive += Form("root_archive.zip:%s,*.stat@disk=%d",fOutputFiles.Data(),fNreplicas);
    }
 //   if (!fCloseSE.Length()) fCloseSE = gSystem->Getenv("alien_CLOSE_SE");
    if (TestBit(AliAnalysisGrid::kOffline)) {
@@ -4075,6 +4121,7 @@ void AliAnalysisAlien::WriteMergingMacro()
       Error("WriteMergingMacro", "No output file names defined. Are you running the right AliAnalysisAlien configuration ?");
       return;
    }   
+   AliAnalysisManager *mgr = AliAnalysisManager::GetAnalysisManager();
    TString mergingMacro = fExecutable;
    mergingMacro.ReplaceAll(".sh","_merge.C");
    if (gGrid && !fGridOutputDir.Contains("/")) fGridOutputDir = Form("%s/%s/%s", gGrid->GetHomeDirectory(), fGridWorkingDir.Data(), fGridOutputDir.Data());
@@ -4257,6 +4304,14 @@ void AliAnalysisAlien::WriteMergingMacro()
       out << "   TObjString *str;" << endl;
       out << "   TString outputFile;" << endl;
       out << "   Bool_t merged = kTRUE;" << endl;
+      TString analysisFile = fExecutable;
+      analysisFile.ReplaceAll(".sh", ".root");
+      out << "   AliAnalysisManager *mgr = AliAnalysisAlien::LoadAnalysisManager(\""
+          << analysisFile << "\");" << endl;
+      out << "   if (!mgr) {" << endl;
+      out << "      printf(\"ERROR: Analysis manager could not be extracted from file \");" << endl;
+      out << "      return;" << endl;
+      out << "   }" << endl;
       out << "   while((str=(TObjString*)iter->Next())) {" << endl;
       out << "      outputFile = str->GetString();" << endl;
       out << "      if (outputFile.Contains(\"*\")) continue;" << endl;
@@ -4274,22 +4329,21 @@ void AliAnalysisAlien::WriteMergingMacro()
       out << "         return;" << endl;
       out << "      }" << endl;
       out << "   }" << endl;
+      if (mgr && mgr->IsCollectThroughput()) {
+         out << "   TString infolog = \"" << mgr->GetFileInfoLog() << "\";" << endl;
+         out << "   AliAnalysisAlien::MergeInfo(infolog, outputDir);" << endl;
+      }
       out << "   // all outputs merged, validate" << endl;
       out << "   ofstream out;" << endl;
       out << "   out.open(\"outputs_valid\", ios::out);" << endl;
       out << "   out.close();" << endl;
       out << "   // read the analysis manager from file" << endl;
-      TString analysisFile = fExecutable;
-      analysisFile.ReplaceAll(".sh", ".root");
       out << "   if (!outputDir.Contains(\"Stage\")) return;" << endl;
-      out << "   AliAnalysisManager *mgr = AliAnalysisAlien::LoadAnalysisManager(\"" 
-          << analysisFile << "\");" << endl;
-      out << "   if (!mgr) return;" << endl;
       out << "   mgr->SetRunFromPath(mgr->GetRunFromAlienPath(dir));" << endl;
       out << "   mgr->SetSkipTerminate(kFALSE);" << endl;
       out << "   mgr->PrintStatus();" << endl;
-      if (AliAnalysisManager::GetAnalysisManager()) {
-         if (AliAnalysisManager::GetAnalysisManager()->GetDebugLevel()>3) {
+      if (mgr) {
+         if (mgr->GetDebugLevel()>3) {
             out << "   gEnv->SetValue(\"XNet.Debug\", \"1\");" << endl;
          } else {
             if (TestBit(AliAnalysisGrid::kTest))            
index 541eb32..dabba50 100644 (file)
@@ -118,6 +118,7 @@ public:
    const char         *GetListOfFiles(const char *type);
    Bool_t              CheckMergedFiles(const char *filename, const char *aliendir, Int_t nperchunk, const char *jdl="");
    static AliAnalysisManager *LoadAnalysisManager(const char *fname);
+   static Bool_t       MergeInfo(const char *output, const char *collection);
    static Bool_t       MergeOutput(const char *output, const char *basedir, Int_t nmaxmerge, Int_t stage=0);
    virtual Bool_t      MergeOutputs();
    virtual void        Print(Option_t *option="") const;
index 88c7232..9455399 100644 (file)
@@ -104,7 +104,13 @@ AliAnalysisManager::AliAnalysisManager(const char *name, const char *title)
                     fStatisticsMsg(),
                     fRequestedBranches(),
                     fStatistics(0),
-                    fGlobals(0)
+                    fGlobals(0),
+                    fIOTimer(0),
+                    fCPUTimer(0),
+                    fInitTimer(0),
+                    fIOTime(0),
+                    fCPUTime(0),
+                    fInitTime(0)
 {
 // Default constructor.
    fgAnalysisManager = this;
@@ -118,7 +124,10 @@ AliAnalysisManager::AliAnalysisManager(const char *name, const char *title)
      fOutputs    = new TObjArray();
      fParamCont  = new TObjArray();
      fGlobals    = new TMap();
-   }  
+   }
+   fIOTimer = new TStopwatch();
+   fCPUTimer = new TStopwatch();
+   fInitTimer = new TStopwatch();
    SetEventLoop(kTRUE);
 }
 
@@ -163,7 +172,13 @@ AliAnalysisManager::AliAnalysisManager(const AliAnalysisManager& other)
                     fStatisticsMsg(other.fStatisticsMsg),
                     fRequestedBranches(other.fRequestedBranches),
                     fStatistics(other.fStatistics),
-                    fGlobals(other.fGlobals)
+                    fGlobals(other.fGlobals),
+                    fIOTimer(new TStopwatch()),
+                    fCPUTimer(new TStopwatch()),
+                    fInitTimer(new TStopwatch()),
+                    fIOTime(0),
+                    fCPUTime(0),
+                    fInitTime(0)
 {
 // Copy constructor.
    fTasks      = new TObjArray(*other.fTasks);
@@ -222,6 +237,12 @@ AliAnalysisManager& AliAnalysisManager::operator=(const AliAnalysisManager& othe
       fRequestedBranches = other.fRequestedBranches;
       fStatistics = other.fStatistics;
       fGlobals = new TMap();
+      fIOTimer = new TStopwatch();
+      fCPUTimer = new TStopwatch();
+      fInitTimer = new TStopwatch();
+      fIOTime = 0.;
+      fCPUTime = 0.;
+      fInitTime = 0.;
    }
    return *this;
 }
@@ -246,6 +267,9 @@ AliAnalysisManager::~AliAnalysisManager()
    if (fgAnalysisManager==this) fgAnalysisManager = NULL;
    if (fGlobals) {fGlobals->DeleteAll(); delete fGlobals;}
    if (fFileDescriptors) {fFileDescriptors->Delete(); delete fFileDescriptors;}
+   delete fIOTimer;
+   delete fCPUTimer;
+   delete fInitTimer;
 }
 
 //______________________________________________________________________________
@@ -255,8 +279,11 @@ Int_t AliAnalysisManager::GetEntry(Long64_t entry, Int_t getall)
    fCurrentEntry = entry;
    if (!fAutoBranchHandling)
      return 123456789;
-   if (!fTree) return -1;  
+   if (!fTree) return -1; 
+   fIOTimer->Start(kTRUE); 
    Long64_t readbytes = fTree->GetTree()->GetEntry(entry, getall);
+   fIOTimer->Stop();
+   fIOTime += fIOTimer->RealTime();
    return (Int_t)readbytes;
 }
 
@@ -378,7 +405,7 @@ void AliAnalysisManager::SlaveBegin(TTree *tree)
   // When running with PROOF SlaveBegin() is called on each slave server.
   // The tree argument is deprecated (on PROOF 0 is passed).
    if (fDebug > 1) printf("->AliAnalysisManager::SlaveBegin()\n");
-
+   // Init timer should be already started
    // Apply debug options
    ApplyDebugOptions();
    
@@ -457,6 +484,10 @@ void AliAnalysisManager::SlaveBegin(TTree *tree)
    }
    TH1::AddDirectory(dirStatus);
    if (curdir) curdir->cd();
+   fInitTimer->Stop();
+   fInitTime += fInitTimer->RealTime();
+   fInitTimer->Continue();
+   printf("Initialization time: %g [sec]\n", fInitTime);
    if (fDebug > 1) printf("<-AliAnalysisManager::SlaveBegin()\n");
 }
 
@@ -468,6 +499,7 @@ Bool_t AliAnalysisManager::Notify()
    // is started when using PROOF. It is normaly not necessary to make changes
    // to the generated code, but the routine can be extended by the
    // user if needed. The return value is currently not used.
+   fIOTimer->Start(kTRUE); 
    if (!fTree) return kFALSE;
    if (!TObject::TestBit(AliAnalysisManager::kTrueNotify)) return kFALSE;
 
@@ -478,7 +510,7 @@ Bool_t AliAnalysisManager::Notify()
    if (!curfile) {
       Error("Notify","No current file");
       return kFALSE;
-   }   
+   }  
    if (IsCollectThroughput()) {
       if (fCurrentDescriptor) fCurrentDescriptor->Done();
       fCurrentDescriptor = new AliAnalysisFileDescriptor(curfile);
@@ -512,6 +544,8 @@ Bool_t AliAnalysisManager::Notify()
       task->Notify();
 
    if (fDebug > 1) printf("<-AliAnalysisManager::Notify()\n");
+   fIOTimer->Stop();
+   fIOTime += fIOTimer->RealTime();
    return kTRUE;
 }    
 
@@ -546,12 +580,13 @@ void AliAnalysisManager::PackOutput(TList *target)
   // Pack all output data containers in the output list. Called at SlaveTerminate
   // stage in PROOF case for each slave.
    if (fDebug > 1) printf("->AliAnalysisManager::PackOutput()\n");
+   fIOTimer->Start(kTRUE);
+   std::ofstream out;
    if (IsCollectThroughput()) {
       if (fCurrentDescriptor) fCurrentDescriptor->Done();
       fFileDescriptors->Print();
       if (fFileInfoLog.IsNull()) fFileInfoLog = "fileinfo.log";
-      std::ofstream out;
-      out.open(fFileInfoLog, std::ios::out);
+      out.open(fFileInfoLog, std::ios::app);
       if (out.bad()) Error("SavePrimitive", "Bad file name: %s", fFileInfoLog.Data());
       else {
          TIter nextflog(fFileDescriptors);
@@ -765,6 +800,26 @@ void AliAnalysisManager::PackOutput(TList *target)
          }      
       }
    } 
+   fIOTime += fIOTimer->RealTime();
+   if ((fDebug || IsCollectThroughput())) {
+      fInitTimer->Stop();
+      fInitTime = fInitTimer->RealTime()-fIOTime-fCPUTime;
+      printf("=Analysis %s= init time:       %g[sec]\
+            \n              I/O & data mng.: %g [sec]\
+            \n              task execution: %g [sec]\
+            \n              total time:     CPU=%g [sec]  REAL=%g[sec]\n",
+            GetName(), fInitTime, fIOTime, fCPUTime, fInitTimer->CpuTime(), fInitTimer->RealTime());
+      if (IsCollectThroughput()) {
+         out << "#summary#########################################################" << endl;
+         out << "train_name   " << GetName() << endl;
+         out << "root_time    " << fInitTimer->RealTime() << endl;
+         out << "root_cpu     " << fInitTimer->CpuTime() << endl;
+         out << "init_time    " << fInitTime << endl;
+         out << "io_mng_time  " << fIOTime << endl;
+         out << "exec_time    " << fCPUTime << endl;
+      }
+   }
+              
    if (cdir) cdir->cd();
    if (fDebug > 1) printf("<-AliAnalysisManager::PackOutput: output list contains %d containers\n", target->GetSize());
 }
@@ -774,6 +829,7 @@ void AliAnalysisManager::ImportWrappers(TList *source)
 {
 // Import data in output containers from wrappers coming in source.
    if (fDebug > 1) printf("->AliAnalysisManager::ImportWrappers()\n");
+   fIOTimer->Start(kTRUE);
    TIter next(fOutputs);
    AliAnalysisDataContainer *cont;
    AliAnalysisDataWrapper   *wrap;
@@ -843,6 +899,8 @@ void AliAnalysisManager::ImportWrappers(TList *source)
       cont->ImportData(wrap);
    }
    if (cdir) cdir->cd();
+   fIOTimer->Stop();
+   fIOTime += fIOTimer->RealTime();
    if (fDebug > 1) printf("<-AliAnalysisManager::ImportWrappers(): %d containers imported\n", icont);
 }
 
@@ -850,6 +908,7 @@ void AliAnalysisManager::ImportWrappers(TList *source)
 void AliAnalysisManager::UnpackOutput(TList *source)
 {
   // Called by AliAnalysisSelector::Terminate only on the client.
+   fIOTimer->Start(kTRUE);
    if (fDebug > 1) printf("->AliAnalysisManager::UnpackOutput()\n");
    if (!source) {
       Error("UnpackOutput", "No target. Exiting.");
@@ -880,6 +939,8 @@ void AliAnalysisManager::UnpackOutput(TList *source)
          }
       }   
    }
+   fIOTimer->Stop();
+   fIOTime += fIOTimer->RealTime();
    if (fDebug > 1) printf("<-AliAnalysisManager::UnpackOutput()\n");
 }
 
@@ -890,6 +951,7 @@ void AliAnalysisManager::Terminate()
   // a query. It always runs on the client, it can be used to present
   // the results graphically.
    if (fDebug > 1) printf("->AliAnalysisManager::Terminate()\n");
+   fInitTimer->Start(kTRUE);
    TDirectory *cdir = gDirectory;
    gROOT->cd();
    AliAnalysisTask *task;
@@ -910,8 +972,8 @@ void AliAnalysisManager::Terminate()
       if (TObject::TestBit(kSaveCanvases)) {
          if (!gROOT->IsBatch()) {
             if (fDebug>1) printf("Waiting 5 sec for %s::Terminate() to finish drawing ...\n", task->ClassName());
-            timer.Start();
-            while (timer.CpuTime()<5) {
+            timer.Start(kTRUE);
+            while (timer.RealTime()<5) {
                timer.Continue();
                gSystem->ProcessEvents();
             }
@@ -1137,7 +1199,11 @@ void AliAnalysisManager::Terminate()
       out.open("outputs_valid", ios::out);
       out.close();
    }
-   if (cdir) cdir->cd();      
+   if (cdir) cdir->cd();  
+   fInitTimer->Stop();
+   if (fDebug || IsCollectThroughput()) {
+      printf("=Analysis %s= Terminate time:  %g[sec]\n", GetName(), fInitTimer->RealTime());
+   }
    if (fDebug > 1) printf("<-AliAnalysisManager::Terminate()\n");
 }
 //______________________________________________________________________________
@@ -2047,6 +2113,7 @@ void AliAnalysisManager::ExecAnalysis(Option_t *option)
       if (!fNcalls) timer->Start();
       if (!fIsRemote && TObject::TestBit(kUseProgressBar)) ProgressBar("Processing event", fNcalls, TMath::Min(fMaxEntries,nentries), timer, kFALSE);
    }
+   fIOTimer->Start(kTRUE);
    gROOT->cd();
    TDirectory *cdir = gDirectory;
    Bool_t getsysInfo = ((fNSysInfo>0) && (fMode==kLocalAnalysis))?kTRUE:kFALSE;
@@ -2085,6 +2152,9 @@ void AliAnalysisManager::ExecAnalysis(Option_t *option)
 //
 //    Execute the tasks
 //      TIter next1(cont->GetConsumers());
+      fIOTimer->Stop();
+      fIOTime += fIOTimer->RealTime();
+      fCPUTimer->Start(kTRUE);
       TIter next1(fTopTasks);
       Int_t itask = 0;
       while ((task=(AliAnalysisTask*)next1())) {
@@ -2097,6 +2167,9 @@ void AliAnalysisManager::ExecAnalysis(Option_t *option)
             AliSysInfo::AddStamp(task->ClassName(), fNcalls, itask, 1);
          itask++;   
       }
+      fCPUTimer->Stop();
+      fCPUTime += fCPUTimer->RealTime();
+      fIOTimer->Start(kTRUE);
 //
 //    Call FinishEvent() for optional output and MC services 
       if (fInputEventHandler)   fInputEventHandler  ->FinishEvent();
@@ -2106,17 +2179,23 @@ void AliAnalysisManager::ExecAnalysis(Option_t *option)
       if (getsysInfo && ((fNcalls%fNSysInfo)==0)) 
          AliSysInfo::AddStamp("Handlers_FinishEvent",fNcalls, 1001, 1);
       if (cdir) cdir->cd();   
+      fIOTimer->Stop();
+      fIOTime += fIOTimer->RealTime();
       return;
    }   
    // The event loop is not controlled by TSelector   
 //
 //  Call BeginEvent() for optional input/output and MC services 
+   fIOTimer->Start(kTRUE);
    if (fInputEventHandler)   fInputEventHandler  ->BeginEvent(-1);
    if (fOutputEventHandler)  fOutputEventHandler ->BeginEvent(-1);
    if (fMCtruthEventHandler) fMCtruthEventHandler->BeginEvent(-1);
+   fIOTimer->Stop();
+   fIOTime += fIOTimer->RealTime();
    gROOT->cd();
    if (getsysInfo && ((fNcalls%fNSysInfo)==0)) 
       AliSysInfo::AddStamp("Handlers_BeginEvent",fNcalls, 1000, 0);
+   fCPUTimer->Start(kTRUE);
    TIter next2(fTopTasks);
    while ((task=(AliAnalysisTask*)next2())) {
       task->SetActive(kTRUE);
@@ -2126,14 +2205,19 @@ void AliAnalysisManager::ExecAnalysis(Option_t *option)
       task->ExecuteTask(option);
       gROOT->cd();
    }   
+   fCPUTimer->Stop();
+   fCPUTime += fCPUTimer->RealTime();
 //
 // Call FinishEvent() for optional output and MC services 
+   fIOTimer->Start(kTRUE);
    if (fInputEventHandler)   fInputEventHandler  ->FinishEvent();
    if (fOutputEventHandler)  fOutputEventHandler ->FinishEvent();
    if (fMCtruthEventHandler) fMCtruthEventHandler->FinishEvent();
    if (getsysInfo && ((fNcalls%fNSysInfo)==0)) 
       AliSysInfo::AddStamp("Handlers_FinishEvent",fNcalls, 1000, 1);
    if (cdir) cdir->cd();   
+   fIOTimer->Stop();
+   fIOTime += fIOTimer->RealTime();
 }
 
 //______________________________________________________________________________
index 1b00ab4..6dfe3fd 100644 (file)
@@ -264,6 +264,12 @@ private:
    TString                 fRequestedBranches;   // Requested branch names
    AliAnalysisStatistics  *fStatistics;          // Statistics info about input events
    TMap                   *fGlobals;             // Map with global variables
+   TStopwatch             *fIOTimer;             //! Timer for I/O + deserialization
+   TStopwatch             *fCPUTimer;            //! Timer for useful processing
+   TStopwatch             *fInitTimer;           //! Timer for initialization
+   Double_t                fIOTime;              //! Cumulated time in IO
+   Double_t                fCPUTime;             //! Cumulated time in Exec
+   Double_t                fInitTime;            //! Cumulated time in initialization
    static TString          fgCommonFileName;     //! Common output file name (not streamed)
    static AliAnalysisManager *fgAnalysisManager; //! static pointer to object instance
    ClassDef(AliAnalysisManager,17)  // Analysis manager class