Update timer, only print out those timers that consume more than 1% of total time (deepmodeling#5984)

* change namespace and timer of check_atomic_stru

* update stress timer and some formats

* update timer

* update timer

* update wrong timer

* update timer in symmetry

* update pot_local

* update timer

* only print out timer that is larger than 1 precent of total time

* update formats in rt-TDDFT

* fix unit tests

Author: mohanchen

source/driver_run.cpp

@@ -46,7 +46,7 @@ void Driver::driver_run()
                 PARAM.inp.fixed_axes);
 
     ucell.setup_cell(PARAM.globalv.global_in_stru, GlobalV::ofs_running);
-    Check_Atomic_Stru::check_atomic_stru(ucell, PARAM.inp.min_dist_coef);
+    unitcell::check_atomic_stru(ucell, PARAM.inp.min_dist_coef);
 
     //! 2: initialize the ESolver (depends on a set-up ucell after `setup_cell`)
     ModuleESolver::ESolver* p_esolver = ModuleESolver::init_esolver(PARAM.inp, ucell);

source/module_base/mathzone_add1.cpp

@@ -138,7 +138,7 @@ void Mathzone_Add1::Cubic_Spline_Interpolation
 	double * const dy
 )
 {	
-	ModuleBase::timer::tick("Mathzone_Add1","Cubic_Spline_Interpolation");
+	ModuleBase::timer::tick("Mathzone","cubic_spline");
 
 #ifdef _OPENMP
 	#pragma omp parallel for schedule(static)
@@ -175,7 +175,7 @@ void Mathzone_Add1::Cubic_Spline_Interpolation
 		//ddy[m] = ddy_tmp;
 	}
 
-	ModuleBase::timer::tick("Mathzone_Add1","Cubic_Spline_Interpolation");
+	ModuleBase::timer::tick("Mathzone","cubic_spline");
 }
 
 /// Interpolation for Numerical Orbitals

source/module_base/module_mixing/broyden_mixing.cpp

@@ -104,15 +104,20 @@ template void Broyden_Mixing::tem_cal_coef(
 template <class FPTYPE>
 void Broyden_Mixing::tem_cal_coef(const Mixing_Data& mdata, std::function<double(FPTYPE*, FPTYPE*)> inner_product)
 {
-    ModuleBase::TITLE("Charge_Mixing", "Simplified_Broyden_mixing");
-    ModuleBase::timer::tick("Charge", "Broyden_mixing");
-    if (address != &mdata && address != nullptr)
-        ModuleBase::WARNING_QUIT(
-            "Broyden_mixing",
-            "One Broyden_Mixing object can only bind one Mixing_Data object to calculate coefficients");
-    const int length = mdata.length;
+    ModuleBase::TITLE("Broyden_Mixing", "Simplified_Broyden_mixing");
+    ModuleBase::timer::tick("Broyden_Mixing", "tem_cal_coef");
+
+	if (address != &mdata && address != nullptr)
+	{
+		ModuleBase::WARNING_QUIT(
+				"Broyden_mixing",
+				"One Broyden_Mixing object can only bind one Mixing_Data object to calculate coefficients");
+	}
+
+	const int length = mdata.length;
     FPTYPE* FP_dF = static_cast<FPTYPE*>(dF);
     FPTYPE* FP_F = static_cast<FPTYPE*>(F);
+
     if (ndim_cal_dF > 0)
     {
         ModuleBase::matrix beta_tmp(ndim_cal_dF, ndim_cal_dF);
@@ -140,7 +145,7 @@ void Broyden_Mixing::tem_cal_coef(const Mixing_Data& mdata, std::function<double
         double* work = new double[ndim_cal_dF];   // workspace
         int* iwork = new int[ndim_cal_dF];   // ipiv
         char uu = 'U';
-        int info;
+        int info = 0;
         int m = 1;
         // gamma means the coeficients for mixing
         // but now gamma store <dFi|Fm>, namely c
@@ -150,10 +155,25 @@ void Broyden_Mixing::tem_cal_coef(const Mixing_Data& mdata, std::function<double
             FPTYPE* dFi = FP_dF + i * length;
             gamma[i] = inner_product(dFi, FP_F);
         }
-        // solve aG = c 
-        dsysv_(&uu, &ndim_cal_dF, &m, beta_tmp.c, &ndim_cal_dF, iwork, gamma.data(), &ndim_cal_dF, work, &ndim_cal_dF, &info);
-        if (info != 0)
-            ModuleBase::WARNING_QUIT("Charge_Mixing", "Error when DSYSV.");
+
+		// solve aG = c 
+		dsysv_(&uu, 
+				&ndim_cal_dF, 
+				&m, 
+				beta_tmp.c, 
+				&ndim_cal_dF, 
+				iwork, 
+				gamma.data(), 
+				&ndim_cal_dF, 
+				work, 
+				&ndim_cal_dF, 
+				&info);
+
+		if (info != 0)
+		{
+			ModuleBase::WARNING_QUIT("Charge_Mixing", "Error when DSYSV.");
+		}
+
         // after solving, gamma store the coeficients for mixing
         coef[mdata.start] = 1 + gamma[dFindex_move(0)];
         for (int i = 1; i < ndim_cal_dF; ++i)
@@ -178,6 +198,6 @@ void Broyden_Mixing::tem_cal_coef(const Mixing_Data& mdata, std::function<double
     {
         dFnext[i] = FP_F[i];
     }
-    ModuleBase::timer::tick("Charge", "Broyden_mixing");
+    ModuleBase::timer::tick("Broyden_Mixing", "tem_cal_coef");
 };
 } // namespace Base_Mixing

source/module_base/timer.cpp

@@ -1,8 +1,3 @@
-//==========================================================
-// AUTHOR : fangwei , mohan
-// DATE : 2008-11-06,
-// UPDATE : Peize Lin at 2019-11-21
-//==========================================================
 #include "timer.h"
 
 #include <cmath>
@@ -53,19 +48,10 @@ double timer::cpu_time()
 // only first call can let t0 = 0,clock begin
 // when enter this function second time , t0 > 0
 //----------------------------------------------------------
-	// static clock_t t0 = clock();
-	// const clock_t t1 = clock() - t0;
-	// return (t1<0) ? 0 : (double)t1/CLOCKS_PER_SEC;
-
-	// static time_t t0 = time(NULL);
-	// const time_t t1 = time(NULL);
-	// double res = difftime(t1, t0);
-	// return (res<0) ? 0 : res;
 	static auto t1 = std::chrono::system_clock::now();
 	const auto t2 = std::chrono::system_clock::now();
 	auto duration = std::chrono::duration_cast<std::chrono::microseconds>(t2 - t1);
 	return double(duration.count()) * std::chrono::microseconds::period::num / std::chrono::microseconds::period::den;
-		// mohan add, abandon the cross point time 2^32 ~ -2^32 .
 }
 
 void timer::tick(const std::string &class_name,const std::string &name)
@@ -118,13 +104,6 @@ void timer::tick(const std::string &class_name,const std::string &name)
 				timer_one.cpu_second += MPI_Wtime() - timer_one.cpu_start;
 			}
 #else
-			// if(class_name=="electrons"&&name=="c_bands")
-			// {
-			// 	cout<<"call times"<<timer_one.calls<<endl;
-			// 	cout<<"electrons c_bands cost time:"<<endl;
-			// 	cout<<cpu_time()<<"-"<<timer_one.cpu_start<<endl;
-			// }
-
 			timer_one.cpu_second += (cpu_time() - timer_one.cpu_start);
 #endif
 			timer_one.start_flag = true;
@@ -201,7 +180,9 @@ void timer::write_to_json(std::string file_name)
 		order_a ++;
 		// if calss_name == "", it means total time, so we skip it
 		if(timer_pool_A.first == "")
+		{
 			continue;
+		}
 		int order_b = 0;
 		const std::string class_name = timer_pool_A.first;
 		ofs << indent << indent << "{\n";
@@ -214,20 +195,32 @@ void timer::write_to_json(std::string file_name)
 			const Timer_One timer_one = timer_pool_B.second;
 			ofs << indent << indent << indent << indent << "{\n";
 			ofs << indent << indent << indent << indent << "\"name\": \"" << name << "\",\n";
-			ofs << indent << indent << indent << indent << "\"cpu_second\": " << std::setprecision(15) << timer_one.cpu_second << ",\n";
+			ofs << indent << indent << indent << indent << "\"cpu_second\": " 
+				<< std::setprecision(15) << timer_one.cpu_second << ",\n";
 			ofs << indent << indent << indent << indent << "\"calls\": " << timer_one.calls << ",\n";
-			ofs << indent << indent << indent << indent << "\"cpu_second_per_call\": " << double_to_string(timer_one.cpu_second/timer_one.calls) << ",\n";
-			ofs << indent << indent << indent << indent << "\"cpu_second_per_total\": " << double_to_string(timer_one.cpu_second/timer_pool[""]["total"].cpu_second) << "\n";
+			ofs << indent << indent << indent << indent << "\"cpu_second_per_call\": " 
+				<< double_to_string(timer_one.cpu_second/timer_one.calls) << ",\n";
+			ofs << indent << indent << indent << indent << "\"cpu_second_per_total\": " 
+				<< double_to_string(timer_one.cpu_second/timer_pool[""]["total"].cpu_second) << "\n";
+
 			if (order_b == timer_pool_A.second.size())
+			{
 				ofs << indent << indent << indent << indent << "}\n";
+			}
 			else
+			{
 				ofs << indent << indent << indent << indent << "},\n";
+			}
 		}
 		ofs << indent << indent << indent << "]\n";
 		if (order_a == timer_pool.size())
+		{
 			ofs << indent << indent << "}\n";
+		}
 		else
+		{
 			ofs << indent << indent << "},\n";
+		}
 	}
 	ofs << indent << "]\n";
 	ofs << "}\n";
@@ -248,9 +241,12 @@ void timer::print_all(std::ofstream &ofs)
 			const std::string name = timer_pool_B.first;
 			const Timer_One timer_one = timer_pool_B.second;
 			if(timer_pool_order.size() < timer_one.order+1)
+			{
 				timer_pool_order.resize(timer_one.order+1);
+			}
 			//timer_pool_order[timer_one.order] = {{class_name, name}, timer_one}; //qianrui change it to make it compatible with old compiler version
-			timer_pool_order[timer_one.order] = std::pair<std::pair<std::string,std::string>, Timer_One> {std::pair<std::string,std::string >{class_name,name}, timer_one};
+			timer_pool_order[timer_one.order] = std::pair<std::pair<std::string,std::string>, Timer_One> {
+            std::pair<std::string,std::string >{class_name,name}, timer_one};
 		}
 	}
 	std::vector<std::string> class_names;
@@ -266,25 +262,42 @@ void timer::print_all(std::ofstream &ofs)
 		const Timer_One &timer_one = timer_pool_order_A.second;
 
 		if(timer_one.cpu_second < 0)
+		{
 			continue;
+		}
+
+		// only print out timers that are larger than 1%
+		// mohan add 2025-03-09
+		const double percentage_thr = 1.0;
+        const double percentage = timer_one.cpu_second / timer_pool_order[0].second.cpu_second * 100;
+		if(percentage<percentage_thr)
+		{
+			continue;
+		}
+
 		class_names.push_back(class_name);
 		names.push_back(name);
 		times.push_back(timer_one.cpu_second);
 		calls.push_back(timer_one.calls);
 		avgs.push_back(timer_one.cpu_second/timer_one.calls);
 
+
 		// if the total time is too small, we do not calculate the percentage
-		if (timer_pool_order[0].second.cpu_second < 1e-9) {
-    		pers.push_back(0);
-		} else {
-    		pers.push_back(timer_one.cpu_second / timer_pool_order[0].second.cpu_second * 100);
+		if (timer_pool_order[0].second.cpu_second < 1e-9) 
+		{
+			pers.push_back(0);
+		} 
+		else 
+		{
+			pers.push_back(percentage);
 		}
 	}
 	assert(class_names.size() == names.size());
 	assert(class_names.size() == times.size());
 	assert(class_names.size() == calls.size());
 	assert(class_names.size() == avgs.size());
 	assert(class_names.size() == pers.size());
+
 	std::vector<std::string> titles = {"CLASS_NAME", "NAME", "TIME/s", "CALLS", "AVG/s", "PER/%"};
 	std::vector<std::string> formats = {"%-10s", "%-10s", "%6.2f", "%8d", "%6.2f", "%6.2f"};
 	FmtTable time_statistics(titles, pers.size(), formats, {FmtTable::Align::LEFT, FmtTable::Align::CENTER});
@@ -293,107 +306,6 @@ void timer::print_all(std::ofstream &ofs)
 	std::cout<<table<<std::endl;
 	ofs<<table<<std::endl;
 	write_to_json("time.json");
-}
-}
 
-/*
-void timer::print_all(std::ofstream &ofs)
-{
-//	std::cout<<"\n timer::print_all()"<<std::endl;
-	const double small = 0.1; // cpu = 10^6
-	// if want to print > 1s , set small = 10^6
-
-	std::cout << std::setprecision(2);
-
-	// prepare
-	bool *print_flag = new bool[n_clock];
-	for(int i=0; i<n_clock; i++)
-	{
-		print_flag[i] = false;
-	}
-
-	int type = 1; // 2:calls 1:total_time
-	bool non_reorder = 1;
-
-	std::cout<<"\n  |CLASS_NAME---------|NAME---------------|TIME(Sec)-----|CALLS----|AVG------|PER%-------" << std::endl;
-	ofs <<"\n\n\n\n  |CLASS_NAME---------|NAME---------------|TIME(Sec)-----|CALLS----|AVG------|PER%-------" << std::endl;
-	ofs << std::setprecision(3);
-	for (int i=0; i<n_clock; i++)
-	{
-		int k = 0;
-		double tmp = -1.0;
-
-		if(non_reorder)
-		{
-			k = i;
-		}
-		else
-		{
-			// search in all clocks
-			for(int j=0; j<n_clock; j++)
-			{
-				if(print_flag[j])
-				{
-					continue;
-				}
-				if(type==1)
-				{
-					if(tmp < cpu_second[j])
-					{
-						k = j;
-						tmp = cpu_second[j];
-					}
-				}
-				else if(type==2)
-				{
-					if(tmp < calls[j])
-					{
-						k = j;
-						tmp = calls[j];
-					}
-				}
-			}
-		}
-		print_flag[k]=true;
-
-		if ((cpu_second[k] >= 0 && cpu_second[k] < small) ||
-		        (cpu_second[k] <= 0 && cpu_second[k] > -small))
-		{
-			continue;
-		}
-
-		if( level[k] > 'X' ) continue;
-
-
-		const long double spend_time = cpu_second[k];
-		const double average_spend_time = spend_time/calls[k];
-
-
-		ofs  << " "
-			 << std::setw(2) << level[k]
-			 << std::setw(20) << class_name[k]
-			 << std::setw(20) << name[k]
-			 << std::setw(15) << spend_time
-			 << std::setw(10) << calls[k]
-			 << std::setw(10) << std::setprecision(2) << average_spend_time
-			 << std::setw(10) << spend_time / cpu_second[0] * 100 << "%" << std::endl;
-
-
-		std::cout << std::resetiosflags(ios::scientific);
-
-		std::cout  << " "
-		     << std::setw(2) << level[k]
-			 << std::setw(20) << class_name[k]
-			 << std::setw(20) << name[k]
-			 << std::setw(15) << spend_time
-			 << std::setw(10) << calls[k]
-			 << std::setw(10) << std::setprecision(2) << average_spend_time
-			 << std::setw(10) << spend_time / cpu_second[0] * 100 << "%" << std::endl;
-
-	}
-	std::cout<<" ----------------------------------------------------------------------------------------"<<std::endl;
-	ofs <<" ----------------------------------------------------------------------------------------"<<std::endl;
-	delete[] print_flag;
-	return;
 }
-*/
+}

source/module_cell/check_atomic_stru.cpp

@@ -3,8 +3,12 @@
 #include "module_base/element_covalent_radius.h"
 #include "module_base/timer.h"
 
-void Check_Atomic_Stru::check_atomic_stru(UnitCell& ucell, const double& factor)
+namespace unitcell
 {
+
+void check_atomic_stru(UnitCell& ucell, const double& factor)
+{
+    ModuleBase::timer::tick("unitcell", "check_atomic_stru");
     // First we calculate all bond length in the structure,
     // and compare with the covalent_bond_length,
     // if there has bond length is shorter than covalent_bond_length * factor,
@@ -17,7 +21,6 @@ void Check_Atomic_Stru::check_atomic_stru(UnitCell& ucell, const double& factor)
 
     if (GlobalV::MY_RANK == 0)
     {
-        ModuleBase::timer::tick("Check_Atomic_Stru", "Check_Atomic_Stru");
 
         const int ntype = ucell.ntype;
         const double lat0 = ucell.lat0;
@@ -138,7 +141,6 @@ void Check_Atomic_Stru::check_atomic_stru(UnitCell& ucell, const double& factor)
                 } // it2
             } // iat
         }
-        ModuleBase::timer::tick("Check_Atomic_Stru", "Check_Atomic_Stru");
     }
     if (!all_pass || !no_warning)
     {
@@ -165,4 +167,8 @@ void Check_Atomic_Stru::check_atomic_stru(UnitCell& ucell, const double& factor)
             ModuleBase::WARNING_QUIT("Input", "The structure is unreasonable!");
         }
     }
+
+    ModuleBase::timer::tick("unitcell", "check_atomic_stru");
+}
+
 }