add more timers

3rd_party/gslib/ogs/ogs.hpp

@@ -120,11 +120,6 @@ SOFTWARE.
 #include "mpi.h"
 #include "types.h"
 
-//#define OGS_ENABLE_TIMER
-#ifdef OGS_ENABLE_TIMER
-#include "timer.hpp"
-#endif
-
 #define ogsFloat "float"
 #define ogsDouble "double"
 #define ogsDfloat dfloatString

3rd_party/gslib/ogs/src/oogs.cpp

@@ -5,6 +5,13 @@
 #include "ogsInterface.h"
 #include <list>
 
+//#define DISABLE_OOGS
+//#define OGS_ENABLE_TIMER
+
+#ifdef OGS_ENABLE_TIMER
+#include "timer.hpp"
+#endif
+
 #ifdef __cplusplus
 extern "C" {
 #endif
@@ -100,11 +107,8 @@ static void pairwiseExchange(int unit_size, oogs_t *gs)
  }
  }
 
- if(gs->mode == OOGS_HOSTMPI)
- gs->o_bufSend.copyTo(gs->bufSend, pwd->comm[send].total*unit_size, 0, "async: true");
-
  { // pw exchange
- if(gs->mode != OOGS_DEVICEMPI) ogs->device.finish(); // waiting for buffers to be ready
+ if(gs->mode != OOGS_DEVICEMPI) ogs->device.finish(); // waiting for send buffers to be ready
 
  comm_req *req = &pwd->req[pwd->comm[recv].n]; 
  const struct pw_comm_data *c = &pwd->comm[send];
@@ -119,9 +123,6 @@ static void pairwiseExchange(int unit_size, oogs_t *gs)
  }
  MPI_Waitall(pwd->comm[send].n + pwd->comm[recv].n,pwd->req,MPI_STATUSES_IGNORE);
  }
-
- if(gs->mode == OOGS_HOSTMPI)
- gs->o_bufRecv.copyFrom(gs->bufRecv,pwd->comm[recv].total*unit_size, 0, "async: true");
 }
 
 oogs_t* oogs::setup(ogs_t *ogs, int nVec, dlong stride, const char *type, std::function<void()> callback, oogs_mode gsMode)
@@ -230,7 +231,9 @@ oogs_t* oogs::setup(ogs_t *ogs, int nVec, dlong stride, const char *type, std::f
  gs->mode = gsMode;
  }
 
- //gs->mode = OOGS_DEFAULT;
+#ifdef DISABLE_OOGS
+ gs->mode = OOGS_DEFAULT;
+#endif
  if(rank == 0) printf("used mode: %d\n", gs->mode);
 
  return gs; 
@@ -333,29 +336,23 @@ void oogs::start(occa::memory o_v, const int k, const dlong stride, const char *
 
  ogs_t *ogs = gs->ogs; 
 
-#if 1
- if(gs->mode == OOGS_DEFAULT) {
+ if(gs->mode == OOGS_DEFAULT) { 
  if(k>1)
  ogsGatherScatterManyStart(o_v, k, stride, type, op, ogs);
  else
  ogsGatherScatterStart(o_v, type, op, ogs);
 
  return;
  }
-#endif
 
  if (ogs->NhaloGather) {
  reallocBuffers(Nbytes*k, gs);
 
- occaGatherMany(ogs->NhaloGather, k, stride, ogs->NhaloGather, ogs->o_haloGatherOffsets, ogs->o_haloGatherIds, type, op, o_v, ogs::o_haloBuf);
- if(gs->mode != OOGS_DEFAULT) packBuf(gs, ogs->NhaloGather, k, gs->o_scatterOffsets, gs->o_scatterIds, type, ogs::o_haloBuf, gs->o_bufSend);
- ogs->device.finish();
+ occaGatherMany(ogs->NhaloGather, k, stride, ogs->NhaloGather, ogs->o_haloGatherOffsets, 
+ ogs->o_haloGatherIds, type, op, o_v, ogs::o_haloBuf);
 
- if(gs->mode == OOGS_DEFAULT) {
- ogs->device.setStream(ogs::dataStream);
- ogs::o_haloBuf.copyTo(ogs::haloBuf, ogs->NhaloGather*Nbytes*k, 0, "async: true");
- ogs->device.setStream(ogs::defaultStream);
- }
+ packBuf(gs, ogs->NhaloGather, k, gs->o_scatterOffsets, gs->o_scatterIds, type, ogs::o_haloBuf, gs->o_bufSend);
+ ogs->device.finish();
  }
 }
 
@@ -369,45 +366,42 @@ void oogs::finish(occa::memory o_v, const int k, const dlong stride, const char
 
  ogs_t *ogs = gs->ogs; 
 
-#if 1
- if(gs->mode == OOGS_DEFAULT) {
+ if(gs->mode == OOGS_DEFAULT) { 
  if(k>1)
  ogsGatherScatterManyFinish(o_v, k, stride, type, op, ogs);
  else
  ogsGatherScatterFinish(o_v, type, op, ogs);
 
  return;
  }
-#endif
 
- if(ogs->NlocalGather) {
- occaGatherScatterMany(ogs->NlocalGather, k, stride, ogs->o_localGatherOffsets, ogs->o_localGatherIds, type, op, o_v);
- }
+ if(ogs->NlocalGather) 
+ occaGatherScatterMany(ogs->NlocalGather, k, stride, ogs->o_localGatherOffsets, 
+ ogs->o_localGatherIds, type, op, o_v);
 
  if (ogs->NhaloGather) {
  ogs->device.setStream(ogs::dataStream);
 
- if(gs->mode == OOGS_DEFAULT) {
- ogs->device.finish(); // waiting for gs::haloBuf copy to finish 
+ struct gs_data *hgs = (gs_data*) ogs->haloGshSym;
+ const void* execdata = hgs->r.data;
+ const struct pw_data *pwd = (pw_data*) execdata;
+ const unsigned transpose = 0; // hardwired for now
+ const unsigned recv = 0^transpose, send = 1^transpose;
+ if(gs->mode == OOGS_HOSTMPI)
+ gs->o_bufSend.copyTo(gs->bufSend, pwd->comm[send].total*Nbytes*k, 0, "async: true");
 
- void* H[10];
- for (int i=0;i<k;i++) H[i] = (char*)ogs::haloBuf + i*ogs->NhaloGather*Nbytes;
- ogsHostGatherScatterMany(H, k, type, op, ogs->haloGshSym);
- } else {
 #ifdef OGS_ENABLE_TIMER
- timer::tic("oogsMPI",1);
+ timer::hostTic("oogsMPI",1);
 #endif
-  pairwiseExchange(Nbytes*k, gs);
+ pairwiseExchange(Nbytes*k, gs);
 #ifdef OGS_ENABLE_TIMER
- timer::toc("oogsMPI");
+ timer::hostToc("oogsMPI");
 #endif
- } 
+
+ if(gs->mode == OOGS_HOSTMPI)
+ gs->o_bufRecv.copyFrom(gs->bufRecv,pwd->comm[recv].total*Nbytes*k, 0, "async: true");
 
- if(gs->mode == OOGS_DEFAULT) { 
- ogs::o_haloBuf.copyFrom(ogs::haloBuf, ogs->NhaloGather*Nbytes*k, 0, "async: true");
- } else {
- unpackBuf(gs, ogs->NhaloGather, k, gs->o_gatherOffsets, gs->o_gatherIds, type, op, gs->o_bufRecv, ogs::o_haloBuf);
- }
+ unpackBuf(gs, ogs->NhaloGather, k, gs->o_gatherOffsets, gs->o_gatherIds, type, op, gs->o_bufRecv, ogs::o_haloBuf);
  occaScatterMany(ogs->NhaloGather, k, ogs->NhaloGather, stride, ogs->o_haloGatherOffsets, 
  ogs->o_haloGatherIds, type, op, ogs::o_haloBuf, o_v);
 
@@ -422,17 +416,6 @@ void oogs::startFinish(void *v, const int k, const dlong stride, const char *typ
 }
 void oogs::startFinish(occa::memory o_v, const int k, const dlong stride, const char *type, const char *op, oogs_t *h)
 {
-#if 1
- if(h->mode == OOGS_DEFAULT) {
- if(k>1)
- ogsGatherScatterMany(o_v, k, stride, type, op, h->ogs);
- else
- ogsGatherScatter(o_v, type, op, h->ogs);
-
- return;
- }
-#endif
-
  start(o_v, k, stride, type, op, h);
  finish(o_v, k, stride, type, op, h);
 }

src/core/runTime.cpp

@@ -53,10 +53,11 @@ void runStep(ins_t* ins, dfloat time, dfloat dt, int tstep)
  if(ins->Nscalar)
  scalarSolve(ins, time, dt, cds->o_S);
 
- timer::tic("udfProperties", 1);
- if(udf.properties)
+ if(udf.properties) {
+  timer::tic("udfProperties", 1);
  udf.properties(ins, time + dt, ins->o_U, cds->o_S, ins->o_prop, cds->o_prop);
- timer::toc("udfProperties");
+ timer::toc("udfProperties");
+ }
 
  if(ins->lowMach) {
  if(udf.div)
@@ -72,6 +73,8 @@ void runStep(ins_t* ins, dfloat time, dfloat dt, int tstep)
  mesh->device.finish();
  MPI_Barrier(mesh->comm);
  const double tElapsedStep = MPI_Wtime() - tStart;
+ tElapsed += tElapsedStep;
+ timer::set("solve", tElapsed);
  if(mesh->rank == 0) {
  printf("step= %d t= %.8e dt=%.1e C= %.2f",
  tstep, time + dt, dt, cfl);
@@ -86,7 +89,6 @@ void runStep(ins_t* ins, dfloat time, dfloat dt, int tstep)
  for(int is = 0; is < ins->Nscalar; is++)
  if(cds->compute[is]) printf(" S: %d", cds->Niter[is]);
 
- tElapsed += tElapsedStep;
  printf(" eTime= %.2e, %.5e s\n", tElapsedStep, tElapsed);
  }
 
@@ -140,7 +142,11 @@ void makeq(ins_t* ins, dfloat time, occa::memory o_FS, occa::memory o_BF)
  cds_t* cds = ins->cds;
  mesh_t* mesh = cds->mesh;
 
- if(udf.sEqnSource) udf.sEqnSource(ins, time, cds->o_S, o_FS);
+ if(udf.sEqnSource) {
+ timer::tic("udfSEqnSource", 1);
+ udf.sEqnSource(ins, time, cds->o_S, o_FS);
+ timer::toc("udfSEqnSource");
+ }
 
  for(int is = 0; is < cds->NSfields; is++) {
  if(!cds->compute[is]) continue;
@@ -266,7 +272,11 @@ void makef(ins_t* ins, dfloat time, occa::memory o_FU, occa::memory o_BF)
 {
  mesh_t* mesh = ins->mesh;
 
- if(udf.uEqnSource) udf.uEqnSource(ins, time, ins->o_U, o_FU);
+ if(udf.uEqnSource) {
+ timer::tic("udfUEqnSource", 1);
+ udf.uEqnSource(ins, time, ins->o_U, o_FU);
+ timer::toc("udfUEqnSource");
+ }
 
  if(ins->options.compareArgs("FILTER STABILIZATION", "RELAXATION"))
  ins->filterRTKernel(
@@ -669,10 +679,13 @@ void qthermal(ins_t* ins, dfloat time, occa::memory o_div)
  ins->o_InvM,
  cds->o_wrk0);
 
- if(udf.sEqnSource)
+ if(udf.sEqnSource) {
+ timer::tic("udfSEqnSource", 1);
  udf.sEqnSource(ins, time, cds->o_S, cds->o_wrk3);
- else
+ timer::toc("udfSEqnSource");
+ } else {
  ins->fillKernel(mesh->Nelements * mesh->Np, 0.0, cds->o_wrk3);
+ }
 
  ins->qtlKernel(
  mesh->Nelements,

src/core/timer.cpp

@@ -38,6 +38,20 @@ void init(MPI_Comm comm,occa::device device,int ifSync)
  comm_ = comm;
 }
 
+void set(const std::string tag, double time)
+{
+ m_[tag].startTime = time; 
+ auto it = m_.find(tag);
+ if(it == m_.end()) {
+ printf("Error in set: Invalid tag name. %s:%u\n",__FILE__,__LINE__);
+ MPI_Abort(comm_,1);
+ }
+
+ it->second.hostElapsed = time; 
+ it->second.deviceElapsed = it->second.hostElapsed;
+ it->second.count++;
+}
+
 void reset()
 {
  m_.clear();
@@ -213,7 +227,7 @@ void printRunStat()
  int rank;
  MPI_Comm_rank(comm_, &rank);
 
- double dEtime[10];
+ double dEtime[20];
  dEtime[0] = timer::query("makef", "DEVICE:MAX");
  dEtime[1] = timer::query("velocitySolve", "DEVICE:MAX");
  dEtime[2] = timer::query("pressureSolve", "DEVICE:MAX");
@@ -222,17 +236,33 @@ void printRunStat()
  dEtime[5] = timer::query("preconditioner", "DEVICE:MAX");
  dEtime[6] = timer::query("preSolveProjection", "DEVICE:MAX");
  dEtime[6]+= timer::query("postSolveProjection", "DEVICE:MAX");
- dEtime[7] = timer::query("oogsMPI", "DEVICE:MAX");
+
  dEtime[8] = timer::query("dotp", "DEVICE:MAX");
 
+ dEtime[9] = timer::query("solve", "DEVICE:MAX");
+ dEtime[10] = timer::query("setup", "DEVICE:MAX");
+ dEtime[11] = timer::query("checkpointing", "DEVICE:MAX");
+
+ dEtime[12] = timer::query("udfExecuteStep", "DEVICE:MAX");
+ dEtime[13] = timer::query("udfUEqnSource", "DEVICE:MAX");
+ dEtime[14] = timer::query("udfSEqnSource", "DEVICE:MAX");
+ dEtime[15] = timer::query("udfProperties", "DEVICE:MAX");
+
  double hEtime[10];
  hEtime[0] = timer::query("BoomerAMGSolve", "HOST:MAX");
+ hEtime[1] = timer::query("oogsMPI", "HOST:MAX");
 
  if (rank == 0) {
  std::cout.setf ( std::ios::scientific );
 
  std::cout << "runtime statistics\n\n"
- << " makef " << dEtime[0] << " s\n"
+ << " setup " << dEtime[10]<< " s\n";
+
+ if(dEtime[11] > 0)
+ std::cout << " checkpointing " << dEtime[11]<< " s\n";
+
+ std::cout << " total solve " << dEtime[9] << " s\n"
+ << " makef " << dEtime[0] << " s\n"
  << " velocitySolve " << dEtime[1] << " s\n"
  << " pressureSolve " << dEtime[2] << " s\n";
 
@@ -247,9 +277,18 @@ void printRunStat()
  << " scalarSolve " << dEtime[4] << " s\n"
  << std::endl;
 
+ if(dEtime[12] > 0)
+ std::cout << " udfExecuteStep " << dEtime[12] << " s\n";
+ if(dEtime[13] > 0)
+ std::cout << " udfUEqnSource " << dEtime[13] << " s\n";
+ if(dEtime[14] > 0)
+ std::cout << " udfSEqnSource " << dEtime[14] << " s\n";
+ if(dEtime[15] > 0)
+ std::cout << " udfProperties " << dEtime[15] << " s\n"
+ << std::endl;
 
- if(dEtime[7] > 0)
- std::cout << " gsMPI " << dEtime[7] << " s\n";
+ if(hEtime[1] > 0)
+ std::cout << " gsMPI " << hEtime[1] << " s (without overlap)\n";
  if(dEtime[8] > 0)
  std::cout << " dotp " << dEtime[8] << " s\n";
 

src/core/timer.hpp

@@ -23,6 +23,8 @@ void deviceTic(const std::string tag);
 void deviceTic(const std::string tag,int ifSync);
 void deviceToc(const std::string tag);
 
+void set(const std::string tag, double time);
+
 double hostElapsed(const std::string tag);
 double deviceElapsed(const std::string tag);
 int count(const std::string tag);

src/libP/parAlmond/src/parAlmond.cpp

@@ -56,6 +56,8 @@ void AMGSetup(solver_t *MM,
  hlong TotalRows = globalRowStarts[M->size];
  dlong numLocalRows = (dlong) (globalRowStarts[M->rank+1]-globalRowStarts[M->rank]);
 
+ MPI_Barrier(M->comm);
+ double startTime = MPI_Wtime();
  if(rank==0) printf("Setting up AMG...");fflush(stdout);
 
  //populate null space vector
@@ -70,7 +72,7 @@ void AMGSetup(solver_t *MM,
 
  M->AMGSetup(A);
 
- if(rank==0) printf("done.\n");
+ if(rank==0) printf("done (%gs)\n", MPI_Wtime()-startTime);
 }
 
 void Precon(solver_t *M, occa::memory o_x, occa::memory o_rhs) {

src/nekInterface/nekInterfaceAdapter.cpp

@@ -63,19 +63,25 @@ void* nek_scPtr(int id)
 
 void nek_outfld()
 {
+ timer::tic("checkpointing", 1);
  const char suffix[] = " ";
  (*nek_outfld_ptr)((char*)suffix);
+ timer::toc("checkpointing");
 }
 
 void nek_outfld(const char* suffix)
 {
+ timer::tic("checkpointing", 1);
  (*nek_outfld_ptr)((char*)suffix);
+ timer::toc("checkpointing");
 }
 
 void nek_outfld(const char* suffix, dfloat t, int coords,
  occa::memory o_u, occa::memory o_p, occa::memory o_s,
  int NSfields, int FP64)
 {
+
+ timer::tic("checkpointing", 1);
  mesh_t* mesh = (*ins)->mesh;
  cds_t* cds = (*ins)->cds;
  dlong Nlocal = mesh->Nelements * mesh->Np;
@@ -118,6 +124,7 @@ void nek_outfld(const char* suffix, dfloat t, int coords,
  (*nek_setio_ptr)(&t, &xo, &vo, &po, &so, &NSfields, &FP64);
  (*nek_outfld_ptr)((char*)suffix);
  (*nek_resetio_ptr)();
+ timer::toc("checkpointing");
 }
 
 void nek_uic(int ifield)