Merge pull request #4960 from ye-luo/opt-output

Print more timing from various stages of optimization

src/QMCDrivers/WFOpt/QMCFixedSampleLinearOptimizeBatched.cpp

@@ -189,33 +189,24 @@ QMCFixedSampleLinearOptimizeBatched::RealType QMCFixedSampleLinearOptimizeBatche
 
 void QMCFixedSampleLinearOptimizeBatched::start()
 {
-  //close files automatically generated by QMCDriver
-  //     branchEngine->finalize();
-  //generate samples
-  generate_samples_timer_.start();
   generateSamples();
-  generate_samples_timer_.stop();
-  //store active number of walkers
-  app_log() << "<opt stage=\"setup\">" << std::endl;
-  app_log() << "  <log>" << std::endl;
-  //reset the rootname
-  optTarget->setRootName(get_root_name());
+
   optTarget->setWaveFunctionNode(wfNode);
-  app_log() << "   Reading configurations from h5FileRoot " << std::endl;
-  //get configuration from the previous run
-  Timer t1;
-  initialize_timer_.start();
-  optTarget->getConfigurations("");
-  optTarget->setRng(vmcEngine->getRngRefs());
-  NullEngineHandle handle;
-  optTarget->checkConfigurations(handle);
-  initialize_timer_.stop();
-  app_log() << "  Execution time = " << std::setprecision(4) << t1.elapsed() << std::endl;
-  app_log() << "  </log>" << std::endl;
-  app_log() << "</opt>" << std::endl;
-  app_log() << R"(<opt stage="main" walkers=")" << optTarget->getNumSamples() << "\">" << std::endl;
-  app_log() << "  <log>" << std::endl;
-  t1.restart();
+
+  {
+    app_log() << std::endl
+              << "*****************************" << std::endl
+              << "Compute parameter derivatives" << std::endl
+              << "*****************************" << std::endl
+              << std::endl;
+    ScopedTimer local(initialize_timer_);
+    Timer t_deriv;
+    optTarget->getConfigurations("");
+    optTarget->setRng(vmcEngine->getRngRefs());
+    NullEngineHandle handle;
+    optTarget->checkConfigurations(handle);
+    app_log() << "  Execution time (derivatives) = " << std::setprecision(4) << t_deriv.elapsed() << std::endl;
+  }
 }
 
 #ifdef HAVE_LMY_ENGINE
@@ -258,38 +249,35 @@ void QMCFixedSampleLinearOptimizeBatched::engine_start(cqmc::engine::LMYEngine<V
   initialize_timer_.stop();
   app_log() << "  Execution time = " << std::setprecision(4) << t1.elapsed() << std::endl;
   app_log() << "  </log>" << std::endl;
-  app_log() << "</opt>" << std::endl;
   app_log() << R"(<opt stage="main" walkers=")" << optTarget->getNumSamples() << "\">" << std::endl;
-  app_log() << "  <log>" << std::endl;
-  t1.restart();
 }
 #endif
 
 
 void QMCFixedSampleLinearOptimizeBatched::finish()
 {
-  app_log() << "  Execution time = " << std::setprecision(4) << t1.elapsed() << std::endl;
-  app_log() << "  </log>" << std::endl;
-
   if (optTarget->reportH5)
     optTarget->reportParametersH5();
   optTarget->reportParameters();
-
-  app_log() << "</opt>" << std::endl;
-  app_log() << "</optimization-report>" << std::endl;
 }
 
 void QMCFixedSampleLinearOptimizeBatched::generateSamples()
 {
-  app_log() << "<optimization-report>" << std::endl;
-  t1.restart();
-  //     W.reset();
+  ScopedTimer local(generate_samples_timer_);
+  app_log() << std::endl
+            << "******************" << std::endl
+            << "Generating samples" << std::endl
+            << "******************" << std::endl
+            << std::endl;
   samples_.resetSampleCount();
 
+  Timer t_gen;
   vmcEngine->run();
-  app_log() << "  Execution time = " << std::setprecision(4) << t1.elapsed() << std::endl;
-  app_log() << "</vmc>" << std::endl;
+  app_log() << "  Execution time (sampling) = " << std::setprecision(4) << t_gen.elapsed() << std::endl;
+
+  //reset the rootname
   h5_file_root_ = get_root_name();
+  optTarget->setRootName(get_root_name());
 }
 
 bool QMCFixedSampleLinearOptimizeBatched::run()
@@ -1605,6 +1593,7 @@ bool QMCFixedSampleLinearOptimizeBatched::one_shift_run()
             << "Building overlap and Hamiltonian matrices" << std::endl
             << "*****************************************" << std::endl;
 
+  Timer t_build_matrices;
   // allocate the matrices we will need
   Matrix<RealType> ovlMat(N, N);
   ovlMat = 0.0;
@@ -1617,7 +1606,6 @@ bool QMCFixedSampleLinearOptimizeBatched::one_shift_run()
 
   // build the overlap and hamiltonian matrices
   optTarget->fillOverlapHamiltonianMatrices(hamMat, ovlMat);
-  invMat.copy(ovlMat);
 
   if (do_output_matrices_csv_)
   {
@@ -1635,7 +1623,15 @@ bool QMCFixedSampleLinearOptimizeBatched::one_shift_run()
     hout.write(bestShift_i, "bestShift_i");
     hout.write(bestShift_s, "bestShift_s");
   }
+  app_log() << "  Execution time (building matrices) = " << std::setprecision(4) << t_build_matrices.elapsed() << std::endl;
+
+  app_log() << std::endl
+            << "**************************" << std::endl
+            << "Solving eigenvalue problem" << std::endl
+            << "**************************" << std::endl;
 
+  Timer t_eigen;
+  invMat.copy(ovlMat);
   // apply the identity shift
   for (int i = 1; i < N; i++)
   {
@@ -1680,6 +1676,7 @@ bool QMCFixedSampleLinearOptimizeBatched::one_shift_run()
     hout.write(objFuncWrapper_.Lambda, "non_linear_rescale");
     hout.close();
   }
+  app_log() << "  Execution time (eigenvalue) = " << std::setprecision(4) << t_eigen.elapsed() << std::endl;
 
   // scale the update by the scaling constant
   for (int i = 0; i < numParams; i++)

src/QMCDrivers/WFOpt/QMCFixedSampleLinearOptimizeBatched.h

@@ -280,7 +280,6 @@ class QMCFixedSampleLinearOptimizeBatched : public QMCDriverNew, LinearMethod
   NewTimer& involvmat_timer_;
   NewTimer& line_min_timer_;
   NewTimer& cost_function_timer_;
-  Timer t1;
 
   ///xml node to be dumped
   xmlNodePtr wfNode;

tests/test_automation/github-actions/ci/run_step_ornl-nitrogen-1.sh

@@ -73,6 +73,7 @@ case "$1" in
 
   test)
     echo "Running deterministic tests"
+    rocm-smi --showdriverversion
     cd ${GITHUB_WORKSPACE}/../qmcpack-build
     ctest --output-on-failure -L deterministic -j 32 --timeout 120 --repeat after-timeout:4
     ;;