/// pauses
void stop()
{
if (running)
EACH_TIMER_TYPE(i)
totals[i] = total_time((timer_type)i);
running = false;
}
void netlist_t::print_stats() const
{
if (nperftime_t::enabled)
{
std::vector<size_t> index;
for (size_t i=0; i<m_devices.size(); i++)
index.push_back(i);
std::sort(index.begin(), index.end(),
[&](size_t i1, size_t i2) { return m_devices[i1]->m_stat_total_time.total() < m_devices[i2]->m_stat_total_time.total(); });
nperftime_t::type total_time(0);
uint_least64_t total_count(0);
for (auto & j : index)
{
auto entry = m_devices[j].get();
log().verbose("Device {1:20} : {2:12} {3:12} {4:15} {5:12}", entry->name(),
entry->m_stat_call_count(), entry->m_stat_total_time.count(),
entry->m_stat_total_time.total(), entry->m_stat_inc_active());
total_time += entry->m_stat_total_time.total();
total_count += entry->m_stat_total_time.count();
}
nperftime_t overhead;
nperftime_t test;
overhead.start();
for (int j=0; j<100000;j++)
{
test.start();
test.stop();
}
overhead.stop();
nperftime_t::type total_overhead = overhead()
* static_cast<nperftime_t::type>(total_count)
/ static_cast<nperftime_t::type>(200000);
log().verbose("Queue Pushes {1:15}", queue().m_prof_call());
log().verbose("Queue Moves {1:15}", queue().m_prof_sortmove());
log().verbose("Total loop {1:15}", m_stat_mainloop());
/* Only one serialization should be counted in total time */
/* But two are contained in m_stat_mainloop */
log().verbose("Total devices {1:15}", total_time);
log().verbose("");
log().verbose("Take the next lines with a grain of salt. They depend on the measurement implementation.");
log().verbose("Total overhead {1:15}", total_overhead);
nperftime_t::type overhead_per_pop = (m_stat_mainloop()-2*total_overhead - (total_time - total_overhead))
/ static_cast<nperftime_t::type>(queue().m_prof_call());
log().verbose("Overhead per pop {1:11}", overhead_per_pop );
log().verbose("");
for (auto &entry : m_devices)
{
if (entry->m_stat_inc_active() > 3 * entry->m_stat_total_time.count())
log().verbose("HINT({}, NO_DEACTIVATE)", entry->name());
}
}
}
/// Starts the testing. All tests in this suite and embedded suites will
/// be executed.
///
/// \param output Progress report destination.
/// \param cont_after_fail Continue functions despite failures.
///
/// \return True if no test failed; false otherwise.
///
bool
Suite::run(Output& output, bool cont_after_fail)
{
int ntests = total_tests();
output.initialize(ntests);
do_run(&output, cont_after_fail);
output.finished(ntests, total_time(true));
return _success;
}
// Execute all tests in this and added suites.
//
void
Suite::do_run(Output* os, bool cont_after_fail)
{
_continue = cont_after_fail;
_output = os;
_output->suite_start(_tests.size(), _name);
for_each(_tests.begin(), _tests.end(), ExecTests(*this));
_output->suite_end(_tests.size(), _name, total_time(false));
for_each(_suites.begin(), _suites.end(), DoRun(_output, _continue));
}
static
chrono::duration
run_for(
command_type command,
chrono::duration command_time_limit,
chrono::duration total_time_limit
)
{
chrono::duration total_time(0, chrono::time_unit::TICK);
while (total_time < total_time_limit) {
total_time += run_command_for(command, command_time_limit);
}
return total_time;
}
// Execute all tests in this and added suites.
//
void
Suite::do_run(Output* os, bool cont_after_fail)
{
_continue = cont_after_fail;
_output = os;
_output->suite_start(_tests.size(), _name);
for_each(_tests.begin(), _tests.end(), ExecTests(*this));
_output->suite_end(_tests.size(), _name, total_time(false));
for_each(_suites.begin(), _suites.end(), DoRun(_output, _continue));
// FIXME Find a cleaner way
Suites::const_iterator iter = _suites.begin();
while (iter != _suites.end())
{
if (!(*iter)->_success)
{
_success = false;
break;
}
iter++;
}
}
void print(Ostream &os) const
{
os << '[' << total_time(WALL_TIME) << " wall sec, " << total_time(USER_TIME) << " user sec, " << total_time(SYSTEM_TIME) << " system sec, " << total_time(PAGEFAULTS) << " major page faults]";
}
void log_diagnostics() {
int i,j;
int level;
int icell;
int num_level_cells;
int *level_cells;
double kinetic_energy;
double gas_kinetic, gas_thermal, gas_potential, gas_mass;
double total_gas_kinetic, total_gas_thermal, total_gas_potential, total_gas_mass;
double particle_kinetic, particle_potential;
double total_particle_kinetic, total_particle_potential;
double error;
double da;
double dtyears, current_age, current_dt;
#ifdef STAR_FORMATION
double stellar_mass, stellar_initial_mass;
double old_stellar_mass, old_stellar_initial_mass;
double d_stellar_mass, d_stellar_initial_mass;
double resolved_volume[max_level-min_level+1];
double local_resolved_volume[max_level-min_level+1];
double total_resolved_volume;
double sfr;
#endif /* STAR_FORMATION */
dtyears = dtl[min_level]*units->time/constants->yr;
#ifdef COSMOLOGY
current_age = tphys_from_abox(abox[min_level]);
current_dt = dtyears;
#else
current_age = tl[min_level]*units->time;
current_dt = dtl[min_level]*units->time;
#endif
#ifdef PARTICLES
#ifdef COSMOLOGY
ap1 = abox_from_tcode( tl[min_level] - 0.5*dtl[min_level] );
da = abox[min_level] - abox_old[min_level];
#else
ap1 = 1.0;
ap0 = 0.0;
da = 0.0;
#endif
#endif
/* log profiling information */
#ifdef COSMOLOGY
fprintf( timing, "%u %e %e %e", step, tl[min_level], auni[min_level], current_time( TOTAL_TIME, min_level-1 ) );
#else
fprintf( timing, "%u %e %e", step, tl[min_level], current_time( TOTAL_TIME, min_level-1 ) );
#endif /* COSMOLOGY */
for ( level = min_level-1; level <= max_level; level++ ) {
for ( i = 1; i < NUM_TIMERS; i++ ) {
fprintf( timing, " %e", total_time(i, level) );
}
}
fprintf( timing, "\n" );
fflush(timing);
#ifdef PAPI_PROFILING
fprintf( papi_profile, "%u %e", step, current_time( TOTAL_TIME, min_level-1 ) );
for ( level = min_level-1; level <= max_level; level++ ) {
for ( i = 1; i < NUM_TIMERS; i++ ) {
for ( j = 0; j < num_papi_events; j++ ) {
fprintf( papi_profile, " %llu", papi_total_counter(i,level,j) );
}
}
}
fprintf( papi_profile, "\n" );
fflush(papi_profile);
#endif /* PAPI_PROFILING */
/* log workload information */
#ifdef PARTICLES
#ifdef COSMOLOGY
fprintf( workload, "%u %e %e %u %u", step, tl[min_level], auni[min_level], num_local_particles, max_level_now() );
#else
fprintf( workload, "%u %e %u %u", step, tl[min_level], num_local_particles, max_level_now() );
#endif /* COSMOLOGY */
#else
#ifdef COSMOLOGY
fprintf( workload, "%u %e %e 0 %u", step, tl[min_level], auni[min_level], max_level_now() );
#else
fprintf( workload, "%u %e 0 %u", step, tl[min_level], max_level_now() );
#endif /* COSMOLOGY */
#endif /* PARTICLES */
for ( i = min_level; i <= max_level; i++ ) {
fprintf(workload, " %u %u", num_cells_per_level[i], num_buffer_cells[i] );
}
#ifdef DEBUG_MEMORY_USE
fprintf( workload, " %lu",dmuReportAllocatedMemory());
#endif /* DEBUG_MEMORY_USE */
fprintf(workload, "\n");
fflush(workload);
/* log dependency information */
#ifdef COSMOLOGY
fprintf( dependency, "%u %e %e", step, tl[min_level], auni[min_level] );
#else
fprintf( dependency, "%u %e", step, tl[min_level] );
#endif /* COSMOLOGY */
for ( level = min_level; level <= max_level; level++ ) {
for ( i = 0; i < num_procs; i++ ) {
if ( level == min_level ) {
fprintf( dependency, " %u %u", num_remote_buffers[level][i],
num_local_buffers[level][i] );
} else {
fprintf( dependency, " %u %u", num_children*num_remote_buffers[level][i],
num_children*num_local_buffers[level][i] );
}
}
}
fprintf(dependency, "\n");
fflush(dependency);
/* compute energies */
gas_kinetic = gas_thermal = gas_potential = gas_mass = 0.0;
total_gas_kinetic = total_gas_thermal = total_gas_potential = total_gas_mass = 0.0;
#ifdef HYDRO
for ( level = min_level; level <= max_level; level++ ) {
select_level( level, CELL_TYPE_LOCAL, &num_level_cells, &level_cells );
for ( i = 0; i < num_level_cells; i++ ) {
icell = level_cells[i];
if ( cell_is_leaf( icell ) ) {
gas_thermal += cell_volume[level]*cell_gas_pressure(icell)/(constants->gamma-1);
kinetic_energy = 0.0;
for ( j = 0; j < nDim; j++ ) {
kinetic_energy += cell_momentum(icell,j)*cell_momentum(icell,j);
}
kinetic_energy *= 0.5*cell_volume[level]/cell_gas_density(icell);
gas_kinetic += kinetic_energy;
#ifdef GRAVITY
gas_potential += cell_gas_density(icell)*cell_volume[level]*cell_potential(icell);
#endif
gas_mass += cell_gas_density(icell)*cell_volume[level];
}
}
cart_free( level_cells );
}
/* add stellar mass to gas mass */
#ifdef STAR_FORMATION
stellar_mass = 0.0;
stellar_initial_mass = 0.0;
for ( i = 0; i < num_star_particles; i++ ) {
if ( particle_level[i] != FREE_PARTICLE_LEVEL && particle_is_star(i) ) {
gas_mass += particle_mass[i];
stellar_mass += particle_mass[i];
stellar_initial_mass += star_initial_mass[i];
}
}
#endif /* STAR_FORMATION */
MPI_Reduce( &gas_thermal, &total_gas_thermal, 1, MPI_DOUBLE, MPI_SUM, MASTER_NODE, mpi.comm.run );
MPI_Reduce( &gas_kinetic, &total_gas_kinetic, 1, MPI_DOUBLE, MPI_SUM, MASTER_NODE, mpi.comm.run );
#ifdef GRAVITY
MPI_Reduce( &gas_potential, &total_gas_potential, 1, MPI_DOUBLE, MPI_SUM, MASTER_NODE, mpi.comm.run );
#endif /* GRAVITY */
MPI_Reduce( &gas_mass, &total_gas_mass, 1, MPI_DOUBLE, MPI_SUM, MASTER_NODE, mpi.comm.run );
#endif /* HYDRO */
#ifdef STAR_FORMATION
old_stellar_mass = total_stellar_mass;
old_stellar_initial_mass = total_stellar_initial_mass;
MPI_Reduce( &stellar_mass, &total_stellar_mass, 1, MPI_DOUBLE, MPI_SUM, MASTER_NODE, mpi.comm.run );
MPI_Reduce( &stellar_initial_mass, &total_stellar_initial_mass, 1, MPI_DOUBLE, MPI_SUM, MASTER_NODE, mpi.comm.run );
d_stellar_mass = MAX( 0.0, total_stellar_mass - old_stellar_mass );
d_stellar_initial_mass = MAX( 0.0, total_stellar_initial_mass - old_stellar_initial_mass );
/* compute resolved volume */
local_resolved_volume[min_level] = 0.0;
for ( level = min_level+1; level <= max_level; level++ ) {
local_resolved_volume[level] = 0.0;
select_level( level, CELL_TYPE_LOCAL, &num_level_cells, &level_cells );
for ( i = 0; i < num_level_cells; i++ ) {
icell = level_cells[i];
if ( cell_is_leaf( icell ) ) {
local_resolved_volume[level] += cell_volume[level];
}
}
cart_free(level_cells);
}
MPI_Reduce( local_resolved_volume, resolved_volume, max_level-min_level+1, MPI_DOUBLE, MPI_SUM, MASTER_NODE, mpi.comm.run );
if ( local_proc_id == MASTER_NODE ) {
/* sum resolved volume over all levels except min_level (works for MMR simulations) */
total_resolved_volume = 0.0;
for ( level = min_level; level <= max_level; level++ ) {
total_resolved_volume += resolved_volume[level];
}
#ifdef COSMOLOGY
total_resolved_volume *= pow(units->length/constants->Mpc/abox[min_level],3.0);
#else
total_resolved_volume *= pow(units->length/constants->Mpc,3.0);
#endif /* COSMOLOGY */
if ( total_resolved_volume > 0.0 ) {
sfr = d_stellar_initial_mass * units->mass / constants->Msun / dtyears / total_resolved_volume;
} else {
sfr = 0.0;
}
#ifdef COSMOLOGY
fprintf( star_log, "%u %e %e %e %e %e %lu %e %e %e %e %e\n", step, tl[min_level],
dtl[min_level], auni[min_level], current_age, dtyears,
#else
fprintf( star_log, "%u %e %e %e %e %lu %e %e %e %e %e\n", step, tl[min_level],
dtl[min_level], current_age, dtyears,
#endif /* COSMOLOGY */
particle_species_num[num_particle_species-1],
total_stellar_mass*units->mass/constants->Msun,
d_stellar_mass*units->mass/constants->Msun,
total_stellar_initial_mass*units->mass/constants->Msun,
d_stellar_initial_mass*units->mass/constants->Msun, sfr );
fflush(star_log);
}
void netlist_t::print_stats() const
{
if (nperftime_t<NL_KEEP_STATISTICS>::enabled)
{
std::vector<size_t> index;
for (size_t i=0; i < m_state->m_devices.size(); i++)
index.push_back(i);
std::sort(index.begin(), index.end(),
[&](size_t i1, size_t i2) { return m_state->m_devices[i1].second->m_stat_total_time.total() < m_state->m_devices[i2].second->m_stat_total_time.total(); });
nperftime_t<NL_KEEP_STATISTICS>::type total_time(0);
nperftime_t<NL_KEEP_STATISTICS>::ctype total_count(0);
for (auto & j : index)
{
auto entry = m_state->m_devices[j].second.get();
log().verbose("Device {1:20} : {2:12} {3:12} {4:15} {5:12}", entry->name(),
entry->m_stat_call_count(), entry->m_stat_total_time.count(),
entry->m_stat_total_time.total(), entry->m_stat_inc_active());
total_time += entry->m_stat_total_time.total();
total_count += entry->m_stat_total_time.count();
}
log().verbose("Total calls : {1:12} {2:12} {3:12}", total_count,
total_time, total_time / static_cast<decltype(total_time)>(total_count));
nperftime_t<NL_KEEP_STATISTICS> overhead;
nperftime_t<NL_KEEP_STATISTICS> test;
{
auto overhead_guard(overhead.guard());
for (int j=0; j<100000;j++)
{
auto test_guard(test.guard());
}
}
nperftime_t<NL_KEEP_STATISTICS>::type total_overhead = overhead()
* static_cast<nperftime_t<NL_KEEP_STATISTICS>::type>(total_count)
/ static_cast<nperftime_t<NL_KEEP_STATISTICS>::type>(200000);
log().verbose("Queue Pushes {1:15}", m_queue.m_prof_call());
log().verbose("Queue Moves {1:15}", m_queue.m_prof_sortmove());
log().verbose("Queue Removes {1:15}", m_queue.m_prof_remove());
log().verbose("Queue Retimes {1:15}", m_queue.m_prof_retime());
log().verbose("Total loop {1:15}", m_stat_mainloop());
/* Only one serialization should be counted in total time */
/* But two are contained in m_stat_mainloop */
log().verbose("Total devices {1:15}", total_time);
log().verbose("");
log().verbose("Take the next lines with a grain of salt. They depend on the measurement implementation.");
log().verbose("Total overhead {1:15}", total_overhead);
nperftime_t<NL_KEEP_STATISTICS>::type overhead_per_pop = (m_stat_mainloop()-2*total_overhead - (total_time - total_overhead))
/ static_cast<nperftime_t<NL_KEEP_STATISTICS>::type>(m_queue.m_prof_call());
log().verbose("Overhead per pop {1:11}", overhead_per_pop );
log().verbose("");
auto trigger = total_count * 200 / 1000000; // 200 ppm
for (auto &entry : m_state->m_devices)
{
auto ep = entry.second.get();
// Factor of 3 offers best performace increase
if (ep->m_stat_inc_active() > 3 * ep->m_stat_total_time.count()
&& ep->m_stat_inc_active() > trigger)
log().verbose("HINT({}, NO_DEACTIVATE) // {} {} {}", ep->name(),
static_cast<double>(ep->m_stat_inc_active()) / static_cast<double>(ep->m_stat_total_time.count()),
ep->m_stat_inc_active(), ep->m_stat_total_time.count());
}
}
}
