TIming info. Will need to revert in future.

Grid/algorithms/iterative/ConjugateGradientMixedPrecBatched.h

@@ -98,6 +98,8 @@ public:
 
     GridStopWatch InnerCGtimer;
     GridStopWatch PrecChangeTimer;
+    GridStopWatch OuterResidualTimer;
+    GridStopWatch PatchupTimer;
     
     int cb = src_d_in[0].Checkerboard();
     
@@ -138,14 +140,15 @@ public:
     CG_f.ErrorOnNoConverge = false;
     
     //Optionally clone the single precision operator onto split-communicator partitions
-    GridStopWatch SplitTimer;
+    GridStopWatch SplitCloneTimer;
+    SplitTimers   splitTimers;
     SplitOperator<FieldF> *split = nullptr;
     int partitions;
     Coordinate layout = BatchedSolverSplitLayout(SinglePrecGrid,BatchedSplit,BatchedSplitNode,NBatch,partitions);
     if ( partitions > 1 ) {
-      SplitTimer.Start();
+      SplitCloneTimer.Start();
       split = Linop_f.SplitClone(layout);
-      SplitTimer.Stop();
+      SplitCloneTimer.Stop();
       if ( split == nullptr ) {
         std::cout << GridLogMessage << "MixedPrecisionConjugateGradientBatched: operator cannot be split; serial inner solves" << std::endl;
       }
@@ -161,8 +164,10 @@ public:
       
       for (int i=0; i<NBatch; i++) {
         //Compute double precision rsd and also new RHS vector.
+        OuterResidualTimer.Start();
         Linop_d.HermOp(sol_d[i], tmp_d);
         norm[i] = axpy_norm(src_d[i], -1., tmp_d, src_d_in[i]); //src_d is residual vector
+        OuterResidualTimer.Stop();
         
         std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: Outer iteration " << outer_iter <<" solve " << i << " residual "<< norm[i] << " target "<< stop[i] <<std::endl;
 
@@ -191,7 +196,7 @@ public:
       }
 
       if ( split != nullptr ) {
-        InnerSplitSolves(*split, CG_f, src_f, sol_f, TotalInnerIterations, InnerCGtimer, SplitTimer);
+        InnerSplitSolves(*split, CG_f, src_f, sol_f, TotalInnerIterations, InnerCGtimer, splitTimers);
       }
 
       for (int i=0; i<NBatch; i++) {
@@ -213,17 +218,21 @@ public:
 
     }
 
+    SplitCloneTimer.Start();
     delete split;
+    SplitCloneTimer.Stop();
     
     //Final trial CG
     std::cout << GridLogMessage << std::endl;
     std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: Starting final patch-up double-precision solve"<<std::endl;
     
+    PatchupTimer.Start();
     for (int i=0; i<NBatch; i++) {
       ConjugateGradient<FieldD> CG_d(Tolerance, MaxPatchupIterations);
       CG_d(Linop_d, src_d_in[i], sol_d[i]);
       TotalFinalStepIterations[i] += CG_d.IterationsToComplete;
     }
+    PatchupTimer.Stop();
 
     TotalTimer.Stop();
 
@@ -232,12 +241,37 @@ public:
       std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: solve " << i << " Inner CG iterations " << TotalInnerIterations[i] << " Restarts " << TotalOuterIterations << " Final CG iterations " << TotalFinalStepIterations[i] << std::endl;
     }
     std::cout << GridLogMessage << std::endl;
-    std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: Total time " << TotalTimer.Elapsed() << " Precision change " << PrecChangeTimer.Elapsed() << " Inner CG total " << InnerCGtimer.Elapsed() << " Split setup and transfer " << SplitTimer.Elapsed() << std::endl;
+    std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: Total time " << TotalTimer.Elapsed() << " Precision change " << PrecChangeTimer.Elapsed() << " Inner CG total " << InnerCGtimer.Elapsed() << std::endl;
+    std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: Outer residual " << OuterResidualTimer.Elapsed() << " Patch-up " << PatchupTimer.Elapsed() << std::endl;
+    if ( partitions > 1 ) {
+      std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: Split clone and delete " << SplitCloneTimer.Elapsed()
+               << " Grid_split " << splitTimers.Split.Elapsed() << " (" << splitTimers.SplitCalls << " calls)"
+               << " Grid_unsplit " << splitTimers.Unsplit.Elapsed() << " (" << splitTimers.UnsplitCalls << " calls)"
+               << " Staging copies " << splitTimers.Staging.Elapsed()
+               << " Host to device " << splitTimers.H2D.Elapsed()
+               << " Iteration count sum " << splitTimers.Reduce.Elapsed() << std::endl;
+    }
+    double accounted = PrecChangeTimer.useconds() + InnerCGtimer.useconds() + OuterResidualTimer.useconds()
+                     + PatchupTimer.useconds() + SplitCloneTimer.useconds() + splitTimers.Split.useconds()
+                     + splitTimers.Unsplit.useconds() + splitTimers.Staging.useconds() + splitTimers.H2D.useconds()
+                     + splitTimers.Reduce.useconds();
+    std::cout<<GridLogMessage<<"MixedPrecisionConjugateGradientBatched: Unaccounted " << (TotalTimer.useconds()-accounted)/1.0e6 << " s" << std::endl;
     
   }
 
 private:
 
+  // Coarse breakdown of the split path outside the inner CG
+  struct SplitTimers {
+    GridStopWatch Split;
+    GridStopWatch Unsplit;
+    GridStopWatch Staging;
+    GridStopWatch H2D;
+    GridStopWatch Reduce;
+    int SplitCalls   = 0;
+    int UnsplitCalls = 0;
+  };
+
   ////////////////////////////////////////////////////////////////////////////////////////
   // One inner solve per partition, in groups of Partitions right-hand sides. The last
   // group is zero-padded; a zero source returns at once from CG. Collective.
@@ -248,7 +282,7 @@ private:
                         std::vector<FieldF> &sol_f,
                         std::vector<Integer> &TotalInnerIterations,
                         GridStopWatch &InnerCGtimer,
-                        GridStopWatch &SplitTimer)
+                        SplitTimers &timers)
   {
     int NBatch = src_f.size();
     int P      = split.Partitions;
@@ -263,6 +297,7 @@ private:
     for(int g=0;g<NBatch;g+=P){
 
       // Gather the group; zero-pad past the end of the batch
+      timers.Staging.Start();
       for(int p=0;p<P;p++){
         group_src[p].Checkerboard() = cb;
         group_sol[p].Checkerboard() = cb;
@@ -274,22 +309,34 @@ private:
           group_sol[p] = Zero();
         }
       }
+      timers.Staging.Stop();
 
       // The initial guess (e.g. from the guesser) travels with the source
-      SplitTimer.Start();
+      timers.Split.Start();
       Grid_split(group_src,s_src);
       Grid_split(group_sol,s_sol);
-      SplitTimer.Stop();
+      timers.Split.Stop();
+      timers.SplitCalls += 2;
+
+      // Grid_split leaves its output on the host; move it now so the copy is not in the CG time
+      timers.H2D.Start();
+      {
+        autoView(s_src_v, s_src, AcceleratorRead);
+        autoView(s_sol_v, s_sol, AcceleratorRead);
+      }
+      timers.H2D.Stop();
 
       InnerCGtimer.Start();
       CG_f(*split.Linop,s_src,s_sol);
       InnerCGtimer.Stop();
 
-      SplitTimer.Start();
+      timers.Unsplit.Start();
       Grid_unsplit(group_sol,s_sol);
-      SplitTimer.Stop();
+      timers.Unsplit.Stop();
+      timers.UnsplitCalls += 1;
 
       // One iteration count per partition, contributed by the partition's rank 0 only
+      timers.Reduce.Start();
       for(int p=0;p<P;p++){
         iters[p] = 0;
       }
@@ -297,11 +344,15 @@ private:
         iters[split.Partition] = CG_f.IterationsToComplete;
       }
       SinglePrecGrid->GlobalSumVector(&iters[0],P);
+      timers.Reduce.Stop();
 
+      // Includes the host to device copy of group_sol left by Grid_unsplit
+      timers.Staging.Start();
       for(int p=0;p<P && g+p<NBatch;p++){
         sol_f[g+p] = group_sol[p];
         TotalInnerIterations[g+p] += iters[p];
       }
+      timers.Staging.Stop();
     }
   }
 };

Grid/lattice/Lattice_transfer.h

@@ -1637,17 +1637,35 @@ void Grid_split(std::vector<Lattice<Vobj> > & full,Lattice<Vobj>   & split)
     ratio[d] = full_grid->_processors[d]/ split_grid->_processors[d];
   }
 
+  // Coarse phase timers, reported on GridLogPerformance
+  double t_start   = usecond();
+  double t_d2h     = 0;
+  double t_unvec   = 0;
+  double t_a2a     = 0;
+  double t_reorder = 0;
+  double t_vec     = 0;
+  double t0;
+
   uint64_t lsites = full_grid->lSites();
   uint64_t     sz = lsites * nvector;
   std::vector<Sobj> tmpdata(sz);
   std::vector<Sobj> alldata(sz);
   std::vector<Sobj> scalardata(lsites); 
+  double t_alloc = usecond() - t_start;
 
   for(int v=0;v<nvector;v++){
+    // Open and close a host view first so any device to host copy is timed on its own
+    t0 = usecond();
+    {
+      autoView(full_v, full[v], CpuRead);
+    }
+    t_d2h += usecond() - t0;
+    t0 = usecond();
     unvectorizeToLexOrdArray(scalardata,full[v]);    
     thread_for(site,lsites,{
       alldata[v*lsites+site] = scalardata[site];
     });
+    t_unvec += usecond() - t0;
   }
 
   int nvec = nvector; // Counts down to 1 as we collapse dims
@@ -1657,11 +1675,14 @@ void Grid_split(std::vector<Lattice<Vobj> > & full,Lattice<Vobj>   & split)
 
     if ( ratio[d] != 1 ) {
 
+      t0 = usecond();
       full_grid ->AllToAll(d,alldata,tmpdata);
       if ( split_grid->_processors[d] > 1 ) {
 	alldata=tmpdata;
 	split_grid->AllToAll(d,alldata,tmpdata);
       }
+      t_a2a += usecond() - t0;
+      t0 = usecond();
 
       auto rdims = ldims; 
       auto     M = ratio[d];
@@ -1701,12 +1722,25 @@ void Grid_split(std::vector<Lattice<Vobj> > & full,Lattice<Vobj>   & split)
 	  }
 	}
       });
+      t_reorder += usecond() - t0;
       ldims[d]*= ratio[d];
       lsites  *= ratio[d];
 
     }
   }
+  t0 = usecond();
   vectorizeFromLexOrdArray(alldata,split);    
+  t_vec = usecond() - t0;
+  double t_total = usecond() - t_start;
+
+  // Host to device copy of split happens lazily at its first accelerator use; not counted here
+  std::cout << GridLogPerformance << "Grid_split: " << nvector << " x " << sz/nvector*sizeof(Sobj)/1.0e6
+            << " MB/rank total " << t_total/1.0e6 << " s : alloc " << t_alloc/1.0e6
+            << " d2h " << t_d2h/1.0e6
+            << " unvectorise " << t_unvec/1.0e6
+            << " alltoall " << t_a2a/1.0e6
+            << " reorder " << t_reorder/1.0e6
+            << " vectorise " << t_vec/1.0e6 << std::endl;
 }
 
 template<class Vobj>
@@ -1763,13 +1797,29 @@ void Grid_unsplit(std::vector<Lattice<Vobj> > & full,Lattice<Vobj>   & split)
     ratio[d] = full_grid->_processors[d]/ split_grid->_processors[d];
   }
 
+  // Coarse phase timers, reported on GridLogPerformance
+  double t_start   = usecond();
+  double t_a2a     = 0;
+  double t_reorder = 0;
+  double t_vec     = 0;
+  double t0;
+
   uint64_t lsites = full_grid->lSites();
   uint64_t     sz = lsites * nvector;
   std::vector<Sobj> tmpdata(sz);
   std::vector<Sobj> alldata(sz);
   std::vector<Sobj> scalardata(lsites); 
+  double t_alloc = usecond() - t_start;
 
+  // Open and close a host view first so any device to host copy is timed on its own
+  t0 = usecond();
+  {
+    autoView(split_v, split, CpuRead);
+  }
+  double t_d2h = usecond() - t0;
+  t0 = usecond();
   unvectorizeToLexOrdArray(alldata,split);    
+  double t_unvec = usecond() - t0;
 
   /////////////////////////////////////////////////////////////////
   // Start from split grid and work towards full grid
@@ -1794,6 +1844,7 @@ void Grid_unsplit(std::vector<Lattice<Vobj> > & full,Lattice<Vobj>   & split)
       int fvol   = lsites;
       int chunk  = (nvec*fvol)/sP;          GRID_ASSERT(chunk*sP == nvec*fvol);
 	
+      t0 = usecond();
       {
 	// Loop over reordered data post A2A
 	thread_for(c, chunk,{
@@ -1821,17 +1872,22 @@ void Grid_unsplit(std::vector<Lattice<Vobj> > & full,Lattice<Vobj>   & split)
         });
       }
 
+      t_reorder += usecond() - t0;
+
+      t0 = usecond();
       if ( split_grid->_processors[d] > 1 ) {
 	split_grid->AllToAll(d,tmpdata,alldata);
 	tmpdata=alldata;
       }
       full_grid ->AllToAll(d,tmpdata,alldata);
+      t_a2a += usecond() - t0;
       rdims[d]/= M;
       rsites  /= M;
       nvec    *= M;       // Increase nvec by subdivision factor
     }
   }
 
+  t0 = usecond();
   lsites = full_grid->lSites();
   for(int v=0;v<nvector;v++){
     thread_for(site, lsites,{
@@ -1839,6 +1895,17 @@ void Grid_unsplit(std::vector<Lattice<Vobj> > & full,Lattice<Vobj>   & split)
     });
     vectorizeFromLexOrdArray(scalardata,full[v]);    
   }
+  t_vec = usecond() - t0;
+  double t_total = usecond() - t_start;
+
+  // Host to device copies of full happen lazily at their first accelerator use; not counted here
+  std::cout << GridLogPerformance << "Grid_unsplit: " << nvector << " x " << sz/nvector*sizeof(Sobj)/1.0e6
+            << " MB/rank total " << t_total/1.0e6 << " s : alloc " << t_alloc/1.0e6
+            << " d2h " << t_d2h/1.0e6
+            << " unvectorise " << t_unvec/1.0e6
+            << " alltoall " << t_a2a/1.0e6
+            << " reorder " << t_reorder/1.0e6
+            << " vectorise " << t_vec/1.0e6 << std::endl;
 }
 
 //////////////////////////////////////////////////////

Grid/qcd/action/fermion/FermionOperator.h

@@ -70,6 +70,8 @@ public:
     GRID_ASSERT(U != nullptr);
     GRID_ASSERT(mpi_split.size() == Nd);
 
+    double t0 = usecond();
+
     SplitOperator<FermionField> *split = new SplitOperator<FermionField>();
 
     split->GaugeGrid   = new GridCartesian(U->FullDimensions(),U->_simd_layout,mpi_split,*U);
@@ -85,6 +87,7 @@ public:
       split->FermionGrid   = split->GaugeGrid;
       split->FermionRBGrid = split->GaugeRBGrid;
     }
+    std::cout << GridLogPerformance << "MakeSplitGrids: " << (usecond()-t0)/1.0e6 << " s" << std::endl;
     return split;
   }
 

Grid/qcd/action/fermion/WilsonFermion5D.h

@@ -192,9 +192,14 @@ public:
   // Redistribute this operator's doubled gauge field onto clone's split grid. Collective.
   void SplitDoubledGaugeInto(WilsonFermion5D<Impl> &clone)
   {
+    double t0 = usecond();
     DoubledGaugeField sUmu(clone.GaugeGrid());
     Grid_split(Umu,sUmu);
+    double t1 = usecond();
     clone.ImportDoubledGauge(sUmu);
+    double t2 = usecond();
+    std::cout << GridLogPerformance << "SplitDoubledGaugeInto: Grid_split " << (t1-t0)/1.0e6
+              << " s import " << (t2-t1)/1.0e6 << " s" << std::endl;
   }
 
   ///////////////////////////////////////////////////////////////