diff --git a/cmake/link_vt.cmake b/cmake/link_vt.cmake index cf1051d0a3..951654d1b9 100644 --- a/cmake/link_vt.cmake +++ b/cmake/link_vt.cmake @@ -24,6 +24,7 @@ function(link_target_with_vt) LINK_ATOMIC LINK_MPI LINK_FMT + LINK_ENG_FORMAT LINK_ZLIB LINK_FCONTEXT LINK_CHECKPOINT @@ -163,6 +164,15 @@ function(link_target_with_vt) ) endif() + if (NOT DEFINED ARG_LINK_ENG_FORMAT AND ${ARG_DEFAULT_LINK_SET} OR ARG_LINK_ENG_FORMAT) + if (${ARG_DEBUG_LINK}) + message(STATUS "link_target_with_vt: EngFormat-Cpp=${ARG_LINK_ENG_FORMAT}") + endif() + target_link_libraries( + ${ARG_TARGET} PUBLIC ${ARG_BUILD_TYPE} ${ENG_FORMAT_LIBRARY} + ) + endif() + if (NOT DEFINED ARG_LINK_CHECKPOINT AND ${ARG_DEFAULT_LINK_SET} OR ARG_LINK_CHECKPOINT) if (${ARG_DEBUG_LINK}) message(STATUS "link_target_with_vt: checkpoint=${ARG_LINK_CHECKPOINT}") diff --git a/cmake/load_bundled_libraries.cmake b/cmake/load_bundled_libraries.cmake index 9dc1224d6a..7fc4b68e24 100644 --- a/cmake/load_bundled_libraries.cmake +++ b/cmake/load_bundled_libraries.cmake @@ -23,6 +23,10 @@ add_subdirectory(${PROJECT_LIB_DIR}/CLI) set(FMT_LIBRARY fmt) add_subdirectory(${PROJECT_LIB_DIR}/fmt) +# EngFormat-Cpp always included in the build +set(ENG_FORMAT_LIBRARY EngFormat-Cpp) +add_subdirectory(${PROJECT_LIB_DIR}/EngFormat-Cpp) + # json library always included in the build set(JSON_BuildTests OFF) set(JSON_MultipleHeaders ON) diff --git a/cmake/trace_only_functions.cmake b/cmake/trace_only_functions.cmake index 6c00465e0e..0987892c80 100644 --- a/cmake/trace_only_functions.cmake +++ b/cmake/trace_only_functions.cmake @@ -98,6 +98,11 @@ function(create_trace_only_target) DESTINATION "include/vt-trace/fmt" ) + install( + FILES "${CMAKE_CURRENT_SOURCE_DIR}/../lib/EngFormat-Cpp/include/EngFormat-Cpp/eng_format.hpp" + DESTINATION "include/vt-trace/EngFormat-Cpp" + ) + set(VT_TRACE_LIB vt-trace CACHE INTERNAL "" FORCE) add_library( ${VT_TRACE_LIB} @@ -114,6 +119,7 @@ function(create_trace_only_target) TARGET ${VT_TRACE_LIB} LINK_VT_LIB LINK_FMT 1 + LINK_ENG_FORMAT 1 LINK_ZLIB 1 LINK_MPI 1 ) diff --git a/examples/collection/lb_iter.cc b/examples/collection/lb_iter.cc index d55ada725f..dd7eeed7c6 100644 --- a/examples/collection/lb_iter.cc +++ b/examples/collection/lb_iter.cc @@ -124,13 +124,13 @@ int main(int argc, char** argv) { .wait(); for (int i = 0; i < num_iter; i++) { - auto cur_time = vt::timing::Timing::getCurrentTime(); + auto cur_time = vt::timing::getCurrentTime(); vt::runInEpochCollective([=]{ proxy.broadcastCollective(10, i); }); - auto total_time = vt::timing::Timing::getCurrentTime() - cur_time; + auto total_time = vt::timing::getCurrentTime() - cur_time; if (this_node == 0) { fmt::print("iteration: iter={},time={}\n", i, total_time); } diff --git a/lib/EngFormat-Cpp/CMakeLists.txt b/lib/EngFormat-Cpp/CMakeLists.txt new file mode 100644 index 0000000000..745a024340 --- /dev/null +++ b/lib/EngFormat-Cpp/CMakeLists.txt @@ -0,0 +1,23 @@ +project(EngFormat-Cpp CXX) +cmake_minimum_required(VERSION 3.0) + +add_library(${PROJECT_NAME} include/EngFormat-Cpp/eng_format.hpp src/eng_format.cpp) + +target_include_directories(${PROJECT_NAME} SYSTEM PUBLIC + $ + $) + +if(CMAKE_PROJECT_NAME STREQUAL PROJECT_NAME) + include(CTest) + if(BUILD_TESTING) + target_compile_definitions(${PROJECT_NAME} PRIVATE ENG_FORMAT_MICRO_GLYPH="u") + add_subdirectory(test) + endif() +endif() + +install( + DIRECTORY include/EngFormat-Cpp + DESTINATION include + CONFIGURATIONS ${build_type_list} + FILES_MATCHING PATTERN "*" +) diff --git a/lib/EngFormat-Cpp/include/EngFormat-Cpp/eng_format.hpp b/lib/EngFormat-Cpp/include/EngFormat-Cpp/eng_format.hpp new file mode 100644 index 0000000000..5cf4a5b121 --- /dev/null +++ b/lib/EngFormat-Cpp/include/EngFormat-Cpp/eng_format.hpp @@ -0,0 +1,115 @@ +// Copyright (C) 2005-2009 by Jukka Korpela +// Copyright (C) 2009-2013 by David Hoerl +// Copyright (C) 2013 by Martin Moene +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +#ifndef ENG_FORMAT_H_INCLUDED +#define ENG_FORMAT_H_INCLUDED + +#include + +/** + * convert a double to the specified number of digits in SI (prefix) or + * exponential notation, optionally followed by a unit. + */ +std::string +to_engineering_string( double value, int digits, bool exponential, std::string unit = "", std::string separator = " " ); + +/** + * convert the output of to_engineering_string() into a double. + */ +double +from_engineering_string( std::string text ); + +/** + * step a value by the smallest possible increment. + */ +std::string +step_engineering_string( std::string text, int digits, bool exponential, bool increment ); + +// +// Extended interface: +// + +/** + * \var eng_prefixed + * \brief select SI (prefix) presentation: to_engineering_string(), step_engineering_string(). + */ + +/** + * \var eng_exponential + * \brief select exponential presentation: to_engineering_string(), step_engineering_string(). + */ + +extern struct eng_prefixed_t {} eng_prefixed; +extern struct eng_exponential_t {} eng_exponential; + +/** + * \var eng_increment + * \brief let step_engineering_string() make a postive step. + */ + +/** + * \var eng_decrement + * \brief let step_engineering_string() make a negative step. + */ + +constexpr bool eng_increment = true; +constexpr bool eng_decrement = false; + +/** + * convert a double to the specified number of digits in SI (prefix) notation, + * optionally followed by a unit. + */ +inline std::string +to_engineering_string( double value, int digits, eng_prefixed_t, std::string unit = "", std::string separator = " " ) +{ + return to_engineering_string( value, digits, false, unit, separator ); +} + +/** + * convert a double to the specified number of digits in exponential notation, + * optionally followed by a unit. + */ +inline std::string +to_engineering_string( double value, int digits, eng_exponential_t, std::string unit = "", std::string separator = " " ) +{ + return to_engineering_string( value, digits, true, unit, separator ); +} + +/** + * step a value by the smallest possible increment, using SI notation. + */ +inline std::string +step_engineering_string( std::string text, int digits, eng_prefixed_t, bool increment ) +{ + return step_engineering_string( text, digits, false, increment ); +} + +/** + * step a value by the smallest possible increment, using exponential notation. + */ +inline std::string +step_engineering_string( std::string text, int digits, eng_exponential_t, bool increment ) +{ + return step_engineering_string( text, digits, true, increment ); +} + +#endif // ENG_FORMAT_H_INCLUDED diff --git a/lib/EngFormat-Cpp/src/eng_format.cpp b/lib/EngFormat-Cpp/src/eng_format.cpp new file mode 100644 index 0000000000..c28faac223 --- /dev/null +++ b/lib/EngFormat-Cpp/src/eng_format.cpp @@ -0,0 +1,214 @@ +// Copyright (C) 2005-2009 by Jukka Korpela +// Copyright (C) 2009-2013 by David Hoerl +// Copyright (C) 2013 by Martin Moene +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +#include "EngFormat-Cpp/eng_format.hpp" + +#include +#include +#include +#include +#include +#include + +/* + * Note: micro, µ, may not work everywhere, so you can define a glyph yourself: + */ +#ifndef ENG_FORMAT_MICRO_GLYPH +# define ENG_FORMAT_MICRO_GLYPH "µ" +#endif + +/* + * Note: if not using signed at the computation of prefix_end below, + * VC2010 -Wall issues a warning about unsigned and addition overflow. + * Hence the cast to signed int here. + */ +#define ENG_FORMAT_DIMENSION_OF(a) ( static_cast( sizeof(a) / sizeof(0[a]) ) ) + +eng_prefixed_t eng_prefixed; +eng_exponential_t eng_exponential; + +namespace +{ + +char const * const prefixes[/*exp*/][2][9] = +{ + { + { "", "m", ENG_FORMAT_MICRO_GLYPH + , "n", "p", "f", "a", "z", "y", }, + { "", "k", "M", "G", "T", "P", "E", "Z", "Y", }, + }, + { + { "e0", "e-3", "e-6", "e-9", "e-12", "e-15", "e-18", "e-21", "e-24", }, + { "e0", "e3", "e6", "e9", "e12", "e15", "e18", "e21", "e24", }, + }, +}; + +const int prefix_count = ENG_FORMAT_DIMENSION_OF( prefixes[false][false] ); + +int sign( int const value ) +{ + return value == 0 ? +1 : value / std::abs( value ); +} + +bool is_zero( double const value ) +{ + return FP_ZERO == std::fpclassify( value ); +} + +long degree_of( double const value ) +{ + return is_zero( value ) ? + 0 : std::lrint( std::floor( std::log10( std::fabs( value ) ) / 3) ); +} + +int precision( double const scaled, int const digits ) +{ + // MSVC6 requires -2 * DBL_EPSILON; + // g++ 4.8.1: ok with -1 * DBL_EPSILON + + return is_zero( scaled ) ? + digits - 1 : digits - std::log10( std::fabs( scaled ) ) - 2 * DBL_EPSILON; +} + +std::string prefix_or_exponent( bool const exponential, int const degree, std::string separator ) +{ + return std::string( exponential || 0 == degree ? "" : separator ) + prefixes[ exponential ][ sign(degree) > 0 ][ std::abs( degree ) ]; +} + +std::string exponent( int const degree ) +{ + std::ostringstream os; + os << "e" << 3 * degree; + return os.str(); +} + +char const * first_non_space( char const * text ) +{ + while ( *text && std::isspace( *text ) ) + { + ++text; + } + return text; +} + +bool starts_with( std::string const text, std::string const start ) +{ + return 0 == text.find( start ); +} + +/* + * "k" => 3 + */ +int prefix_to_exponent( std::string const pfx ) +{ + for ( int i = 0; i < 2; ++i ) + { + // skip prefixes[0][i][0], it matches everything + for( int k = 1; k < prefix_count; ++k ) + { + if ( starts_with( pfx, prefixes[0][i][k] ) ) + { + return ( i ? 1 : -1 ) * k * 3; + } + } + } + return 0; +} + +} // anonymous namespace + +/** + * convert real number to prefixed or exponential notation, optionally followed by a unit. + */ +std::string +to_engineering_string( double const value, int const digits, bool exponential, std::string const unit /*= ""*/, std::string separator /*= " "*/ ) +{ + if ( std::isnan( value ) ) return "NaN"; + else if ( std::isinf( value ) ) return "INFINITE"; + + const int degree = degree_of( value ); + + std::string factor; + + if ( std::abs( degree ) < prefix_count ) + { + factor = prefix_or_exponent( exponential, degree, separator ); + } + else + { + exponential = true; + factor = exponent( degree ); + } + + std::ostringstream os; + + const double scaled = value * std::pow( 1000.0, -degree ); + + const std::string space = ( 0 == degree || exponential ) && unit.length() ? separator : ""; + + os << std::fixed << std::setprecision( precision( scaled, digits ) ) << scaled << factor << space << unit; + + return os.str(); +} + +/** + * convert the output of to_engineering_string() into a double. + * + * The engineering presentation should not contain a unit, as the first letter + * is interpreted as an SI prefix, e.g. "1 T" is 1e12, not 1 (Tesla). + * + * "1.23 M" => 1.23e+6 + * "1.23 kPa" => 1.23e+3 (ok, but not recommended) + * "1.23 Pa" => 1.23e+12 (not what's intended!) + */ +double from_engineering_string( std::string const text ) +{ + char * tail; + const double magnitude = strtod( text.c_str(), &tail ); + + return magnitude * std::pow( 10.0, prefix_to_exponent( first_non_space( tail ) ) ); +} + +/** + * step a value by the smallest possible increment. + */ +std::string step_engineering_string( std::string const text, int digits, bool const exponential, bool const positive ) +{ + const double value = from_engineering_string( text ); + + if ( digits < 3 ) + { + digits = 3; + } + + // correctly round to desired precision + const int expof10 = is_zero(value) ? + 0 : std::lrint( std::floor( std::log10( value ) ) ); + const int power = expof10 + 1 - digits; + + const double inc = std::pow( 10.0, power ) * ( positive ? +1 : -1 ); + const double ret = value + inc; + + return to_engineering_string( ret, digits, exponential ); +} + +// end of file diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index e88d9440da..b3f1969656 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -318,6 +318,7 @@ install( set(FMT_LIBRARY_EXPORT ${FMT_LIBRARY}) install(TARGETS ${FMT_LIBRARY} EXPORT ${VIRTUAL_TRANSPORT_LIBRARY}) +install(TARGETS ${ENG_FORMAT_LIBRARY} EXPORT ${VIRTUAL_TRANSPORT_LIBRARY}) install(TARGETS ${JSON_LIBRARY} EXPORT ${VIRTUAL_TRANSPORT_LIBRARY}) install(TARGETS ${BROTLI_LIBRARY} EXPORT ${VIRTUAL_TRANSPORT_LIBRARY}) @@ -342,6 +343,7 @@ export( ${MIMALLOC_LIBRARY_EXPORT} ${FORT_LIBRARY_EXPORT} ${FMT_LIBRARY_EXPORT} + ${ENG_FORMAT_LIBRARY} ${JSON_LIBRARY} ${BROTLI_LIBRARY} FILE "vtTargets.cmake" diff --git a/src/vt/configs/debug/debug_fmt.h b/src/vt/configs/debug/debug_fmt.h index 986ad4aac0..d561271cd6 100644 --- a/src/vt/configs/debug/debug_fmt.h +++ b/src/vt/configs/debug/debug_fmt.h @@ -46,7 +46,7 @@ #include "vt/config.h" -#include "fmt/core.h" +#include #include diff --git a/src/vt/configs/error/assert_out.impl.h b/src/vt/configs/error/assert_out.impl.h index ac8c62fdae..655ed88693 100644 --- a/src/vt/configs/error/assert_out.impl.h +++ b/src/vt/configs/error/assert_out.impl.h @@ -56,7 +56,7 @@ #include #include -#include "fmt/core.h" +#include namespace vt { namespace debug { namespace assert { diff --git a/src/vt/configs/error/assert_out_info.impl.h b/src/vt/configs/error/assert_out_info.impl.h index 2693e72908..a5305bcb00 100644 --- a/src/vt/configs/error/assert_out_info.impl.h +++ b/src/vt/configs/error/assert_out_info.impl.h @@ -57,7 +57,7 @@ #include #include -#include "fmt/core.h" +#include namespace vt { namespace debug { namespace assert { diff --git a/src/vt/configs/error/error.impl.h b/src/vt/configs/error/error.impl.h index df08635d69..7f3317cf57 100644 --- a/src/vt/configs/error/error.impl.h +++ b/src/vt/configs/error/error.impl.h @@ -54,7 +54,7 @@ #include #include -#include "fmt/core.h" +#include namespace vt { namespace error { diff --git a/src/vt/configs/error/keyval_printer.impl.h b/src/vt/configs/error/keyval_printer.impl.h index f2c2c0a75d..d68105ac9e 100644 --- a/src/vt/configs/error/keyval_printer.impl.h +++ b/src/vt/configs/error/keyval_printer.impl.h @@ -53,7 +53,7 @@ #include #include -#include "fmt/core.h" +#include namespace vt { namespace util { namespace error { diff --git a/src/vt/configs/error/pretty_print_message.cc b/src/vt/configs/error/pretty_print_message.cc index ae22eddf82..5bb10c22d7 100644 --- a/src/vt/configs/error/pretty_print_message.cc +++ b/src/vt/configs/error/pretty_print_message.cc @@ -50,7 +50,7 @@ #include #include // gethostname -#include "fmt/core.h" +#include namespace vt { namespace debug { diff --git a/src/vt/configs/error/soft_error.h b/src/vt/configs/error/soft_error.h index 0327ada443..7b939081fe 100644 --- a/src/vt/configs/error/soft_error.h +++ b/src/vt/configs/error/soft_error.h @@ -57,7 +57,7 @@ #include -#include "fmt/core.h" +#include namespace vt { diff --git a/src/vt/configs/error/stack_out.cc b/src/vt/configs/error/stack_out.cc index a142ca1841..040d49fe82 100644 --- a/src/vt/configs/error/stack_out.cc +++ b/src/vt/configs/error/stack_out.cc @@ -41,7 +41,7 @@ //@HEADER */ -#include "fmt/core.h" +#include #include "vt/configs/error/stack_out.h" diff --git a/src/vt/elm/elm_stats.cc b/src/vt/elm/elm_stats.cc index 4a11b15176..732903d312 100644 --- a/src/vt/elm/elm_stats.cc +++ b/src/vt/elm/elm_stats.cc @@ -46,11 +46,13 @@ #include "vt/elm/elm_stats.h" +#include "vt/config.h" + namespace vt { namespace elm { void ElementStats::startTime() { - auto const start_time = timing::Timing::getCurrentTime(); - cur_time_ = start_time; + TimeTypeWrapper const start_time = timing::getCurrentTime(); + cur_time_ = start_time.seconds(); cur_time_started_ = true; vt_debug_print( @@ -61,8 +63,8 @@ void ElementStats::startTime() { } void ElementStats::stopTime() { - auto const stop_time = timing::Timing::getCurrentTime(); - auto const total_time = stop_time - cur_time_; + TimeTypeWrapper const stop_time = timing::getCurrentTime(); + TimeTypeWrapper const total_time = stop_time.seconds() - cur_time_; //vtAssert(cur_time_started_, "Must have started time"); auto const started = cur_time_started_; if (started) { @@ -122,16 +124,17 @@ void ElementStats::recvToNode( recvComm(key, bytes); } -void ElementStats::addTime(TimeType const& time) { - phase_timings_[cur_phase_] += time; +void ElementStats::addTime(TimeTypeWrapper const& time) { + phase_timings_[cur_phase_] += time.seconds(); subphase_timings_[cur_phase_].resize(cur_subphase_ + 1); - subphase_timings_[cur_phase_].at(cur_subphase_) += time; + subphase_timings_[cur_phase_].at(cur_subphase_) += time.seconds(); vt_debug_print( verbose,lb, "ElementStats: addTime: time={}, cur_load={}\n", - time, phase_timings_[cur_phase_] + time, + TimeTypeWrapper(phase_timings_[cur_phase_]) ); } @@ -163,7 +166,7 @@ PhaseType ElementStats::getPhase() const { TimeType ElementStats::getLoad(PhaseType const& phase) const { auto iter = phase_timings_.find(phase); if (iter != phase_timings_.end()) { - auto const& total_load = phase_timings_.at(phase); + TimeTypeWrapper const total_load = phase_timings_.at(phase); vt_debug_print( verbose, lb, @@ -171,7 +174,7 @@ TimeType ElementStats::getLoad(PhaseType const& phase) const { total_load, phase, phase_timings_.size() ); - return total_load; + return total_load.seconds(); } else { return 0.0; } @@ -184,7 +187,7 @@ TimeType ElementStats::getLoad(PhaseType phase, SubphaseType subphase) const { auto const& subphase_loads = subphase_timings_.at(phase); vtAssert(subphase_loads.size() > subphase, "Must have subphase"); - auto total_load = subphase_loads.at(subphase); + TimeTypeWrapper const total_load = subphase_loads.at(subphase); vt_debug_print( verbose, lb, @@ -192,7 +195,7 @@ TimeType ElementStats::getLoad(PhaseType phase, SubphaseType subphase) const { total_load, phase, subphase ); - return total_load; + return total_load.seconds(); } std::vector const& ElementStats::getSubphaseTimes(PhaseType phase) { diff --git a/src/vt/elm/elm_stats.h b/src/vt/elm/elm_stats.h index 31bd5989da..58049b7c42 100644 --- a/src/vt/elm/elm_stats.h +++ b/src/vt/elm/elm_stats.h @@ -63,7 +63,7 @@ struct ElementStats { void startTime(); void stopTime(); - void addTime(TimeType const& time); + void addTime(TimeTypeWrapper const& time); void sendToEntity(ElementIDStruct to, ElementIDStruct from, double bytes); void sendComm(elm::CommKey key, double bytes); diff --git a/src/vt/event/event.cc b/src/vt/event/event.cc index 26cab672be..f6b8476a57 100644 --- a/src/vt/event/event.cc +++ b/src/vt/event/event.cc @@ -307,7 +307,7 @@ void AsyncEvent::testEventsTrigger(int const& num_events) { TimeType tr_begin = 0.0; if (theConfig()->vt_trace_event_polling) { - tr_begin = timing::Timing::getCurrentTime(); + tr_begin = timing::getCurrentTime(); } # endif @@ -329,7 +329,7 @@ void AsyncEvent::testEventsTrigger(int const& num_events) { # if vt_check_enabled(diagnostics) mpiEventWaitTime.update( - event->getCreateTime(), timing::Timing::getCurrentTime() + event->getCreateTime(), timing::getCurrentTime() ); # endif @@ -356,7 +356,7 @@ void AsyncEvent::testEventsTrigger(int const& num_events) { # if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_event_polling) { if (num_completed > 0) { - TimeType tr_end = timing::Timing::getCurrentTime(); + TimeType tr_end = timing::getCurrentTime(); auto tr_note = fmt::format("completed {} of {}", num_completed, cur); trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_event_polling); } diff --git a/src/vt/event/event_record.cc b/src/vt/event/event_record.cc index ae7d16e19b..d6d3951f68 100644 --- a/src/vt/event/event_record.cc +++ b/src/vt/event/event_record.cc @@ -57,7 +57,7 @@ EventRecord::EventRecord(EventRecordType const& type, EventType const& id) { # if vt_check_enabled(diagnostics) - creation_time_stamp_ = timing::Timing::getCurrentTime(); + creation_time_stamp_ = timing::getCurrentTime(); # endif switch (type) { diff --git a/src/vt/messaging/active.cc b/src/vt/messaging/active.cc index e32d56051d..323339c308 100644 --- a/src/vt/messaging/active.cc +++ b/src/vt/messaging/active.cc @@ -367,7 +367,7 @@ EventType ActiveMessenger::sendMsgMPI( #if vt_check_enabled(trace_enabled) double tr_begin = 0; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::Timing::getCurrentTime(); + tr_begin = vt::timing::getCurrentTime(); } #endif int const ret = MPI_Isend( @@ -378,7 +378,7 @@ EventType ActiveMessenger::sendMsgMPI( #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::Timing::getCurrentTime(); + auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format("Isend(AM): dest={}, bytes={}", dest, msg_size); trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_isend); } @@ -599,7 +599,7 @@ std::tuple ActiveMessenger::sendDataMPI( #if vt_check_enabled(trace_enabled) double tr_begin = 0; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::Timing::getCurrentTime(); + tr_begin = vt::timing::getCurrentTime(); } #endif @@ -619,7 +619,7 @@ std::tuple ActiveMessenger::sendDataMPI( #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::Timing::getCurrentTime(); + auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format("Isend(Data): dest={}, bytes={}", dest, subsize); trace::addUserBracketedNote(tr_begin, tr_end, tr_note, trace_isend); } @@ -797,7 +797,7 @@ void ActiveMessenger::recvDataDirect( #if vt_check_enabled(trace_enabled) double tr_begin = 0; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::Timing::getCurrentTime(); + tr_begin = vt::timing::getCurrentTime(); } #endif @@ -814,7 +814,7 @@ void ActiveMessenger::recvDataDirect( #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::Timing::getCurrentTime(); + auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format( "Irecv(Data): from={}, bytes={}", from, sublen @@ -1046,7 +1046,7 @@ bool ActiveMessenger::tryProcessIncomingActiveMsg() { #if vt_check_enabled(trace_enabled) double tr_begin = 0; if (theConfig()->vt_trace_mpi) { - tr_begin = vt::timing::Timing::getCurrentTime(); + tr_begin = vt::timing::getCurrentTime(); } #endif @@ -1060,7 +1060,7 @@ bool ActiveMessenger::tryProcessIncomingActiveMsg() { #if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_mpi) { - auto tr_end = vt::timing::Timing::getCurrentTime(); + auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format( "Irecv(AM): from={}, bytes={}", stat.MPI_SOURCE, num_probe_bytes diff --git a/src/vt/messaging/request_holder.h b/src/vt/messaging/request_holder.h index 15f9eae666..5f5bb7dd2c 100644 --- a/src/vt/messaging/request_holder.h +++ b/src/vt/messaging/request_holder.h @@ -100,7 +100,7 @@ struct RequestHolder { std::size_t const holder_size_start = holder_.size(); TimeType tr_begin = 0.0; if (theConfig()->vt_trace_irecv_polling) { - tr_begin = vt::timing::Timing::getCurrentTime(); + tr_begin = vt::timing::getCurrentTime(); } # endif @@ -131,7 +131,7 @@ struct RequestHolder { # if vt_check_enabled(trace_enabled) if (theConfig()->vt_trace_irecv_polling) { if (holder_size_start > 0) { - auto tr_end = vt::timing::Timing::getCurrentTime(); + auto tr_end = vt::timing::getCurrentTime(); auto tr_note = fmt::format( "completed {} of {}", holder_size_start - holder_.size(), diff --git a/src/vt/phase/phase_manager.cc b/src/vt/phase/phase_manager.cc index 843b97b2ae..8c875dab18 100644 --- a/src/vt/phase/phase_manager.cc +++ b/src/vt/phase/phase_manager.cc @@ -44,6 +44,7 @@ #include "vt/phase/phase_manager.h" #include "vt/objgroup/headers.h" #include "vt/pipe/pipe_manager.h" +#include "vt/timing/timing.h" namespace vt { namespace phase { @@ -216,4 +217,18 @@ void PhaseManager::runHooksManual(PhaseHook type) { runHooks(type); } +void PhaseManager::setStartTime() { + start_time_ = timing::getCurrentTime(); +} + +void PhaseManager::printSummary() { + if (theContext()->getNode() == 0 and cur_phase_ != 0) { + TimeTypeWrapper const time = timing::getCurrentTime() - start_time_; + vt_print( + phase, "PhaseManager::printSummary, phase={}, time={}\n", + cur_phase_, time + ); + } +} + }} /* end namespace vt::phase */ diff --git a/src/vt/phase/phase_manager.h b/src/vt/phase/phase_manager.h index 7908a0fac5..1a8b2a019e 100644 --- a/src/vt/phase/phase_manager.h +++ b/src/vt/phase/phase_manager.h @@ -153,6 +153,16 @@ struct PhaseManager : runtime::component::Component { */ void nextPhaseCollective(); + /** + * \brief Store start time for the current phase. + */ + void setStartTime(); + + /** + * \brief Print summary for the current phase. + */ + void printSummary(); + private: /** * \internal @@ -197,7 +207,8 @@ struct PhaseManager : runtime::component::Component { | next_rooted_hook_id_ | in_next_phase_collective_ | reduce_next_phase_done_ - | reduce_finished_; + | reduce_finished_ + | start_time_; } private: @@ -210,6 +221,7 @@ struct PhaseManager : runtime::component::Component { bool in_next_phase_collective_ = false; /**< Whether blocked in next phase */ bool reduce_next_phase_done_ = false; /**< Whether reduce is complete */ bool reduce_finished_ = false; /**< Whether next phase is done */ + TimeType start_time_; /**< Current phase start time */ }; }} /* end namespace vt::phase */ diff --git a/src/vt/runtime/component/diagnostic_value_format.h b/src/vt/runtime/component/diagnostic_value_format.h index 976f952732..8c9f608083 100644 --- a/src/vt/runtime/component/diagnostic_value_format.h +++ b/src/vt/runtime/component/diagnostic_value_format.h @@ -229,7 +229,7 @@ struct DiagnosticFormatter { // and if not, upgrade it until we find one that works auto multiplier = static_cast(TimeMultiplier::Nanoseconds); for ( ; multiplier < 0; multiplier++) { - auto value_tmp = static_cast(val); + auto value_tmp = std::abs(static_cast(val)); for (int8_t i = static_cast(multiplier); i < 0; i++) { value_tmp *= 1000.0; } @@ -260,9 +260,7 @@ struct DiagnosticFormatter { } else { // Compute the new value with multiplier as a double auto new_value = static_cast(val); - for (int8_t i = static_cast(multiplier); i < 0; i++) { - new_value *= 1000.0; - } + new_value *= std::pow(1000.0, static_cast(-multiplier)); auto decimal = std::string{decimal_format}; return fmt::format( diff --git a/src/vt/runtime/component/meter/timer.h b/src/vt/runtime/component/meter/timer.h index c00963f924..65cc0d4e40 100644 --- a/src/vt/runtime/component/meter/timer.h +++ b/src/vt/runtime/component/meter/timer.h @@ -95,7 +95,7 @@ struct Timer : DiagnosticStatsPack { * \brief Start the timer for an event being tracked */ void start() { - start_time_ = timing::Timing::getCurrentTime(); + start_time_ = timing::getCurrentTime(); } /** @@ -103,7 +103,7 @@ struct Timer : DiagnosticStatsPack { */ void stop() { if (start_time_ != 0) { - update(start_time_, timing::Timing::getCurrentTime()); + update(start_time_, timing::getCurrentTime()); start_time_ = 0; } } diff --git a/src/vt/scheduler/scheduler.cc b/src/vt/scheduler/scheduler.cc index a73ab4075b..e0455d3fff 100644 --- a/src/vt/scheduler/scheduler.cc +++ b/src/vt/scheduler/scheduler.cc @@ -95,8 +95,6 @@ Scheduler::Scheduler() // Explicitly define these out when diagnostics are disabled---they might be // expensive # if vt_check_enabled(diagnostics) - using timing::Timing; - // Triggers to get the in-scheduler-loop time added to diagnostics registerTrigger(BeginSchedulerLoop, [this]{ schedLoopTime.start(); }); registerTrigger(EndSchedulerLoop, [this]{ schedLoopTime.stop(); }); @@ -236,13 +234,11 @@ void Scheduler::runProgress(bool msg_only) { // Reset count of processed handlers since the last time progress was invoked processed_after_last_progress_ = 0; - last_progress_time_ = timing::Timing::getCurrentTime(); + last_progress_time_ = timing::getCurrentTime(); } void Scheduler::runSchedulerOnceImpl(bool msg_only) { - using TimerType = timing::Timing; - - auto time_since_last_progress = TimerType::getCurrentTime() - last_progress_time_; + auto time_since_last_progress = timing::getCurrentTime() - last_progress_time_; if ( work_queue_.empty() or shouldCallProgress(processed_after_last_progress_, time_since_last_progress) diff --git a/src/vt/timetrigger/time_trigger_manager.cc b/src/vt/timetrigger/time_trigger_manager.cc index b399392b01..cee53a750a 100644 --- a/src/vt/timetrigger/time_trigger_manager.cc +++ b/src/vt/timetrigger/time_trigger_manager.cc @@ -88,7 +88,7 @@ void TimeTriggerManager::triggerReady(TimeType cur_time) { } int TimeTriggerManager::progress() { - auto const cur_time = timing::Timing::getCurrentTime(); + auto const cur_time = timing::getCurrentTime(); triggerReady(cur_time); return 0; } diff --git a/src/vt/timing/timing.cc b/src/vt/timing/timing.cc index 6610919140..059449d502 100644 --- a/src/vt/timing/timing.cc +++ b/src/vt/timing/timing.cc @@ -41,15 +41,14 @@ //@HEADER */ -#include "vt/config.h" #include "vt/timing/timing.h" -#include "vt/timing/timing_type.h" + #include namespace vt { namespace timing { -/*static*/ TimeType Timing::getCurrentTime() { +TimeType getCurrentTime() { return MPI_Wtime(); } diff --git a/src/vt/timing/timing.h b/src/vt/timing/timing.h index cbc1260d0b..ffc5991b8a 100644 --- a/src/vt/timing/timing.h +++ b/src/vt/timing/timing.h @@ -44,15 +44,42 @@ #if !defined INCLUDED_VT_TIMING_TIMING_H #define INCLUDED_VT_TIMING_TIMING_H -#include "vt/config.h" +#include + +#include +#include + #include "vt/timing/timing_type.h" namespace vt { namespace timing { -struct Timing { - static TimeType getCurrentTime(); -}; +/** + * \brief Get current time on the calling processor + * + * \return current time in seconds + */ +TimeType getCurrentTime(); }} /* end namespace vt::timing */ +namespace fmt { + +template<> +struct formatter<::vt::TimeTypeWrapper> { + template + constexpr auto parse(ParseContext& ctx) { + return ctx.begin(); + } + + template + auto format(::vt::TimeTypeWrapper const& t, FormatContext& ctx) { + return fmt::format_to( + ctx.out(), "{}", + to_engineering_string(t.seconds(), 3, eng_exponential, "s") + ); + } +}; + +} /* end namespace fmt */ + #endif /*INCLUDED_VT_TIMING_TIMING_H*/ diff --git a/src/vt/timing/timing_type.h b/src/vt/timing/timing_type.h index a8356d11cd..222b2085c3 100644 --- a/src/vt/timing/timing_type.h +++ b/src/vt/timing/timing_type.h @@ -44,12 +44,24 @@ #if !defined INCLUDED_VT_TIMING_TIMING_TYPE_H #define INCLUDED_VT_TIMING_TIMING_TYPE_H -#include "vt/config.h" - namespace vt { using TimeType = double; +struct TimeTypeWrapper { + TimeTypeWrapper(const TimeType time) : time_(time) {} + + TimeType seconds() const {return time_; } + + template + void serialize(Serializer& s) { + s | time_; + } + +private: + TimeType time_; +}; + } /* end namespace vt */ #endif /*INCLUDED_VT_TIMING_TIMING_TYPE_H*/ diff --git a/src/vt/trace/trace_lite.h b/src/vt/trace/trace_lite.h index 9572722ef8..b7f3e9dbfc 100644 --- a/src/vt/trace/trace_lite.h +++ b/src/vt/trace/trace_lite.h @@ -238,7 +238,7 @@ struct TraceLite { * \return query the current clock time */ static inline double getCurrentTime() { - return ::vt::timing::Timing::getCurrentTime(); + return ::vt::timing::getCurrentTime(); } /** diff --git a/src/vt/utils/json/json_appender.h b/src/vt/utils/json/json_appender.h index cfd4d48466..da44c40281 100644 --- a/src/vt/utils/json/json_appender.h +++ b/src/vt/utils/json/json_appender.h @@ -49,7 +49,7 @@ #include -#include +#include namespace vt { namespace util { namespace json { diff --git a/src/vt/vrt/collection/balance/baselb/baselb.cc b/src/vt/vrt/collection/balance/baselb/baselb.cc index 615b89944a..2035b69608 100644 --- a/src/vt/vrt/collection/balance/baselb/baselb.cc +++ b/src/vt/vrt/collection/balance/baselb/baselb.cc @@ -67,7 +67,7 @@ std::shared_ptr BaseLB::startLB( ElementCommType const& in_comm_stats, TimeType total_load ) { - start_time_ = timing::Timing::getCurrentTime(); + start_time_ = timing::getCurrentTime(); phase_ = phase; proxy_ = proxy; load_model_ = model; @@ -240,7 +240,7 @@ void BaseLB::finalize(CountMsg* msg) { pending_reassignment_->global_migration_count = global_count; auto const& this_node = theContext()->getNode(); if (this_node == 0) { - auto const total_time = timing::Timing::getCurrentTime() - start_time_; + TimeTypeWrapper const total_time = timing::getCurrentTime() - start_time_; vt_print( lb, "BaseLB::finalize: LB total time={}, total migration count={}\n", diff --git a/src/vt/vrt/collection/balance/baselb/load_sampler.cc b/src/vt/vrt/collection/balance/baselb/load_sampler.cc index 7b4d592443..0a7425ce58 100644 --- a/src/vt/vrt/collection/balance/baselb/load_sampler.cc +++ b/src/vt/vrt/collection/balance/baselb/load_sampler.cc @@ -43,15 +43,16 @@ #include "vt/vrt/collection/balance/baselb/load_sampler.h" #include "vt/vrt/collection/balance/model/load_model.h" +#include "vt/timing/timing.h" namespace vt { namespace vrt { namespace collection { namespace lb { void LoadSamplerBaseLB::buildHistogram() { for (auto obj : *load_model_) { - auto load = load_model_->getWork( + TimeTypeWrapper load = load_model_->getWork( obj, {balance::PhaseOffset::NEXT_PHASE, balance::PhaseOffset::WHOLE_PHASE} ); - auto const& load_milli = loadMilli(load); + auto const& load_milli = loadMilli(load.seconds()); auto const& bin = histogramSample(load_milli); if (obj.isMigratable()) { obj_sample[bin].push_back(obj); diff --git a/src/vt/vrt/collection/balance/greedylb/greedylb.cc b/src/vt/vrt/collection/balance/greedylb/greedylb.cc index cf66b5ca24..1e66db3a82 100644 --- a/src/vt/vrt/collection/balance/greedylb/greedylb.cc +++ b/src/vt/vrt/collection/balance/greedylb/greedylb.cc @@ -56,6 +56,7 @@ #include "vt/vrt/collection/manager.h" #include "vt/collective/reduce/reduce.h" #include "vt/vrt/collection/balance/lb_args_enum_converter.h" +#include "vt/timing/timing.h" #include #include @@ -168,10 +169,11 @@ void GreedyLB::loadStats() { if (this_node == 0) { vt_print( lb, - "loadStats: load={:.2f}, total={:.2f}, avg={:.2f}, I={:.2f}," + "loadStats: load={}, total={}, avg={}, I={:.2f}," "should_lb={}, auto={}, threshold={}\n", - this_load, total_load, avg_load, I, should_lb, auto_threshold, - this_threshold + TimeTypeWrapper(this_load / 1000), TimeTypeWrapper(total_load / 1000), + TimeTypeWrapper(avg_load / 1000), I, should_lb, auto_threshold, + TimeTypeWrapper(this_threshold / 1000) ); fflush(stdout); } @@ -206,7 +208,8 @@ void GreedyLB::reduceCollect() { vt_debug_print( verbose, lb, "GreedyLB::reduceCollect: load={}, load_begin={} load_over.size()={}\n", - this_load, this_load_begin, load_over.size() + TimeTypeWrapper(this_load / 1000), + TimeTypeWrapper(this_load_begin / 1000), load_over.size() ); using MsgType = GreedyCollectMsg; auto cb = vt::theCB()->makeSend(proxy[0]); @@ -260,8 +263,9 @@ void GreedyLB::runBalancer( verbose, lb, "\t GreedyLB::runBalancer: min_node={}, load_={}, " "recs_={}, max_rec: obj={}, time={}\n", - min_node.node_, min_node.load_, min_node.recs_.size(), - max_rec.getObj(), max_rec.getLoad() + min_node.node_, TimeTypeWrapper(min_node.load_ / 1000), + min_node.recs_.size(), max_rec.getObj(), + TimeTypeWrapper(max_rec.getLoad() / 1000) ); min_node.recs_.push_back(max_rec.getObj()); min_node.load_ += max_rec.getLoad(); @@ -403,7 +407,9 @@ void GreedyLB::loadOverBin(ObjBinType bin, ObjBinListType& bin_list) { normal, lb, "loadOverBin: this_load_begin={}, this_load={}, threshold={}: " "adding unit: bin={}, milli={}\n", - this_load_begin, this_load, threshold, bin, obj_time_milli + TimeTypeWrapper(this_load_begin / 1000), + TimeTypeWrapper(this_load / 1000), TimeTypeWrapper(threshold / 1000), + bin, obj_time_milli ); } @@ -414,7 +420,9 @@ void GreedyLB::calcLoadOver() { vt_debug_print( normal, lb, "calcLoadOver: this_load={}, avg_load={}, threshold={}\n", - this_load, avg_load, threshold + TimeTypeWrapper(this_load / 1000), + TimeTypeWrapper(avg_load / 1000), + TimeTypeWrapper(threshold / 1000) ); auto cur_item = obj_sample.begin(); diff --git a/src/vt/vrt/collection/balance/hierarchicallb/hierlb.cc b/src/vt/vrt/collection/balance/hierarchicallb/hierlb.cc index 2ad0376b50..90e16342ae 100644 --- a/src/vt/vrt/collection/balance/hierarchicallb/hierlb.cc +++ b/src/vt/vrt/collection/balance/hierarchicallb/hierlb.cc @@ -153,7 +153,7 @@ void HierarchicalLB::inputParams(balance::SpecEntry* spec) { } } -void HierarchicalLB::setupTree(double const threshold) { +void HierarchicalLB::setupTree(TimeTypeWrapper const threshold) { vtAssert( tree_setup == false, "Tree must not already be set up when is this called" @@ -162,7 +162,7 @@ void HierarchicalLB::setupTree(double const threshold) { auto const& this_node = theContext()->getNode(); auto const& num_nodes = theContext()->getNumNodes(); - this_threshold = threshold; + this_threshold = threshold.seconds(); vt_debug_print( terse, hierlb, @@ -265,10 +265,11 @@ void HierarchicalLB::loadStats() { if (this_node == 0) { vt_print( hierlb, - "loadStats: load={:.2f}, total={:.2f}, avg={:.2f}, I={:.2f}," + "loadStats: load={}, total={}, avg={}, I={:.2f}," "should_lb={}, auto={}, threshold={}\n", - this_load, total_load, avg_load, I, should_lb, auto_threshold, - this_threshold + TimeTypeWrapper(this_load / 1000), TimeTypeWrapper(total_load / 1000), + TimeTypeWrapper(avg_load / 1000), I, should_lb, auto_threshold, + TimeTypeWrapper(this_threshold / 1000) ); fflush(stdout); } @@ -304,7 +305,9 @@ void HierarchicalLB::loadOverBin(ObjBinType bin, ObjBinListType& bin_list) { normal, hierlb, "loadOverBin: this_load_begin={}, this_load={}, threshold={}: " "adding unit: bin={}, milli={}\n", - this_load_begin, this_load, threshold, bin, obj_time_milli + TimeTypeWrapper(this_load_begin / 1000), + TimeTypeWrapper(this_load / 1000), TimeTypeWrapper(threshold / 1000), + bin, obj_time_milli ); } @@ -315,7 +318,8 @@ void HierarchicalLB::calcLoadOver(HeapExtractEnum const extract) { normal, hierlb, "calcLoadOver: this_load={}, avg_load={}, threshold={}, " "strategy={}\n", - this_load, getAvgLoad(), threshold, + TimeTypeWrapper(this_load / 1000), TimeTypeWrapper(getAvgLoad() / 1000), + TimeTypeWrapper(threshold / 1000), extract == HeapExtractEnum::LoadOverLessThan ? "LoadOverLessThan" : extract == HeapExtractEnum::LoadOverGreaterThan ? "LoadOverGreaterThan" : extract == HeapExtractEnum::LoadOverRandom ? "LoadOverRandom" : @@ -411,7 +415,8 @@ void HierarchicalLB::downTree( verbose, hierlb, "downTree: from={}, taken_bin={}, taken_bin_count={}, " "total_taken_load={}\n", - from, item.first, item.second.size(), total_taken_load + from, item.first, item.second.size(), + TimeTypeWrapper(total_taken_load / 1000) ); this_load += total_taken_load; @@ -420,7 +425,8 @@ void HierarchicalLB::downTree( vt_debug_print( normal, hierlb, "downTree: this_load_begin={}, new load profile={}, avg_load={}\n", - this_load_begin, this_load, getAvgLoad() + TimeTypeWrapper(this_load_begin / 1000), + TimeTypeWrapper(this_load / 1000), TimeTypeWrapper(getAvgLoad() / 1000) ); startMigrations(); @@ -460,8 +466,10 @@ void HierarchicalLB::lbTreeUp( "lbTreeUp: child={}, child_load={}, child_size={}, " "child_msgs={}, children.size()={}, agg_node_size={}, " "avg_load={}, child_avg={}, incoming load.size={}\n", - child, child_load, child_size, child_msgs+1, children.size(), - agg_node_size + child_size, getAvgLoad(), child_load/child_size, + child, TimeTypeWrapper(child_load / 1000), child_size, child_msgs+1, + children.size(), agg_node_size + child_size, + TimeTypeWrapper(getAvgLoad() / 1000), + TimeTypeWrapper(child_load/child_size/1000), load.size() ); @@ -535,7 +543,8 @@ void HierarchicalLB::lbTreeUp( vt_debug_print( normal, hierlb, "lbTreeUp: reached root!: total_load={}, avg={}\n", - total_child_load, total_child_load/agg_node_size + TimeTypeWrapper(total_child_load / 1000), + TimeTypeWrapper(total_child_load/agg_node_size/1000) ); sendDownTree(); } else { @@ -558,7 +567,7 @@ HierLBChild* HierarchicalLB::findMinChild() { vt_debug_print( normal, hierlb, "findMinChild, cur->node={}, load={}\n", - cur->node, cur->cur_load + cur->node, TimeTypeWrapper(cur->cur_load / 1000) ); for (auto&& c : children) { @@ -567,12 +576,15 @@ HierLBChild* HierarchicalLB::findMinChild() { vt_debug_print( verbose, hierlb, "\t findMinChild: CUR node={}, node_size={}, load={}, rel-load={}\n", - cur->node, cur->node_size, cur->cur_load, cur_load + cur->node, cur->node_size, TimeTypeWrapper(cur->cur_load / 1000), + TimeTypeWrapper(cur_load / 1000) ); vt_debug_print( verbose, hierlb, "\t findMinChild: C node={}, node_size={}, load={}, rel-load={}\n", - c.second->node, c.second->node_size, c.second->cur_load, load + c.second->node, c.second->node_size, + TimeTypeWrapper(c.second->cur_load / 1000), + TimeTypeWrapper(load / 1000) ); if (load < cur_load && cur->is_live) { cur = c.second.get(); @@ -612,7 +624,8 @@ void HierarchicalLB::sendDownTree() { vt_debug_print( verbose, hierlb, "\t sendDownTree: distribute: child={}, cur_load={}, time={}\n", - c->node, c->cur_load, cIter->first + c->node, TimeTypeWrapper(c->cur_load / 1000), + TimeTypeWrapper(cIter->first) ); // @todo agglomerate units into this bin together to increase efficiency @@ -683,7 +696,8 @@ void HierarchicalLB::distributeAmoungChildren() { print_ptr(c), c ? c->node : -1, c ? c->cur_load : -1.0, - weight, getAvgLoad(), threshold + weight, TimeTypeWrapper(getAvgLoad() / 1000), + TimeTypeWrapper(threshold / 1000) ); if (c == nullptr || c->cur_load > threshold || weight == 0) { @@ -693,7 +707,8 @@ void HierarchicalLB::distributeAmoungChildren() { vt_debug_print( verbose, hierlb, "\t Up: distribute: child={}, cur_load={}, time={}\n", - c->node, c->cur_load, cIter->first + c->node, TimeTypeWrapper(c->cur_load / 1000), + TimeTypeWrapper(cIter->first) ); // @todo agglomerate units into this bin together to increase efficiency @@ -726,7 +741,7 @@ void HierarchicalLB::distributeAmoungChildren() { verbose, hierlb, "distributeAmoungChildren: parent={}, child={}. is_live={}, size={}, " "load={}\n", - parent, node, is_live, node_size, load + parent, node, is_live, node_size, TimeTypeWrapper(load / 1000) ); if (is_live) { total_child_load += load; diff --git a/src/vt/vrt/collection/balance/hierarchicallb/hierlb.h b/src/vt/vrt/collection/balance/hierarchicallb/hierlb.h index f478ddb04b..7c4b9880e6 100644 --- a/src/vt/vrt/collection/balance/hierarchicallb/hierlb.h +++ b/src/vt/vrt/collection/balance/hierarchicallb/hierlb.h @@ -78,7 +78,7 @@ struct HierarchicalLB : LoadSamplerBaseLB { static std::unordered_map getInputKeysWithHelp(); - void setupTree(double const threshold); + void setupTree(TimeTypeWrapper const threshold); void calcLoadOver(HeapExtractEnum const extract); void loadOverBin(ObjBinType bin, ObjBinListType& bin_list); void procDataIn(ElementLoadType const& data_in); diff --git a/src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc b/src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc index 7250fccc06..f6af650ced 100644 --- a/src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc +++ b/src/vt/vrt/collection/balance/lb_invoke/lb_manager.cc @@ -44,6 +44,7 @@ #include "vt/config.h" #include "vt/configs/arguments/app_config.h" #include "vt/context/context.h" +#include "vt/phase/phase_hook_enum.h" #include "vt/vrt/collection/balance/lb_invoke/lb_manager.h" #include "vt/vrt/collection/balance/stats_msg.h" #include "vt/vrt/collection/balance/read_lb.h" @@ -338,8 +339,13 @@ void LBManager::printLBArgsHelp(std::string lb_name) { } void LBManager::startup() { + thePhase()->registerHookRooted(phase::PhaseHook::Start, []{ + thePhase()->setStartTime(); + }); + thePhase()->registerHookCollective(phase::PhaseHook::EndPostMigration, []{ auto const phase = thePhase()->getCurrentPhase(); + thePhase()->printSummary(); theLBManager()->finishedLB(phase); }); } @@ -350,15 +356,6 @@ void LBManager::finishedLB(PhaseType phase) { "finishedLB\n" ); - auto this_node = theContext()->getNode(); - - if (this_node == 0) { - vt_print( - lb, - "LBManager::finishedLB, phase={}\n", phase - ); - } - theNodeStats()->startIterCleanup(phase, model_->getNumPastPhasesNeeded()); theNodeStats()->outputStatsForPhase(phase); diff --git a/src/vt/vrt/collection/balance/rotatelb/rotatelb.cc b/src/vt/vrt/collection/balance/rotatelb/rotatelb.cc index deaebb72a6..d091a2705a 100644 --- a/src/vt/vrt/collection/balance/rotatelb/rotatelb.cc +++ b/src/vt/vrt/collection/balance/rotatelb/rotatelb.cc @@ -42,6 +42,7 @@ */ #include "vt/config.h" +#include "vt/timing/timing.h" #include "vt/vrt/collection/balance/rotatelb/rotatelb.h" #include "vt/vrt/collection/manager.h" @@ -75,7 +76,7 @@ void RotateLB::runLB(TimeType) { } for (auto obj : *load_model_) { - auto load = load_model_->getWork(obj, {balance::PhaseOffset::NEXT_PHASE, balance::PhaseOffset::WHOLE_PHASE}); + TimeTypeWrapper const load = load_model_->getWork(obj, {balance::PhaseOffset::NEXT_PHASE, balance::PhaseOffset::WHOLE_PHASE}); vt_debug_print( terse, lb, "\t RotateLB::migrating object to: obj={}, load={}, to_node={}\n", diff --git a/src/vt/vrt/collection/balance/temperedlb/temperedlb.cc b/src/vt/vrt/collection/balance/temperedlb/temperedlb.cc index 8431188a35..21909fab1b 100644 --- a/src/vt/vrt/collection/balance/temperedlb/temperedlb.cc +++ b/src/vt/vrt/collection/balance/temperedlb/temperedlb.cc @@ -42,6 +42,7 @@ */ #include "vt/config.h" +#include "vt/timing/timing.h" #include "vt/vrt/collection/balance/baselb/baselb.h" #include "vt/vrt/collection/balance/model/load_model.h" #include "vt/vrt/collection/balance/temperedlb/temperedlb.h" @@ -448,7 +449,8 @@ void TemperedLB::runLB(TimeType total_load) { vt_debug_print( terse, temperedlb, "TemperedLB::runLB: avg={}, max={}, pole={}, imb={}, load={}, should_lb={}\n", - avg, max, pole, imb, load, should_lb + TimeTypeWrapper(avg), TimeTypeWrapper(max), TimeTypeWrapper(pole), imb, + TimeTypeWrapper(load), should_lb ); } @@ -500,7 +502,8 @@ void TemperedLB::doLBStages(TimeType start_imb) { normal, temperedlb, "TemperedLB::doLBStages: (before) running trial={}, iter={}, " "num_iters={}, load={}, new_load={}\n", - trial_, iter_, num_iters_, this_load, this_new_load_ + trial_, iter_, num_iters_, TimeTypeWrapper(this_load), + TimeTypeWrapper(this_new_load_) ); if (isOverloaded(this_new_load_)) { @@ -526,7 +529,8 @@ void TemperedLB::doLBStages(TimeType start_imb) { verbose, temperedlb, "TemperedLB::doLBStages: (after) running trial={}, iter={}, " "num_iters={}, load={}, new_load={}\n", - trial_, iter_, num_iters_, this_load, this_new_load_ + trial_, iter_, num_iters_, TimeTypeWrapper(this_load), + TimeTypeWrapper(this_new_load_) ); if (rollback_ || theConfig()->vt_debug_temperedlb || (iter_ == num_iters_ - 1)) { @@ -605,10 +609,12 @@ void TemperedLB::loadStatsHandler(StatsMsgType* msg) { if (this_node == 0) { vt_debug_print( terse, temperedlb, - "TemperedLB::loadStatsHandler: trial={} iter={} max={:0.2f} min={:0.2f} " - "avg={:0.2f} pole={:0.2f} imb={:0.4f}\n", - trial_, iter_, in.max(), in.min(), in.avg(), - stats.at(lb::Statistic::O_l).at(lb::StatisticQuantity::max), + "TemperedLB::loadStatsHandler: trial={} iter={} max={} min={} " + "avg={} pole={} imb={:0.4f}\n", + trial_, iter_, TimeTypeWrapper(in.max()), + TimeTypeWrapper(in.min()), TimeTypeWrapper(in.avg()), + TimeTypeWrapper( + stats.at(lb::Statistic::O_l).at(lb::StatisticQuantity::max)), in.I() ); } @@ -640,7 +646,8 @@ void TemperedLB::informAsync() { normal, temperedlb, "TemperedLB::informAsync: starting inform phase: trial={}, iter={}, " "k_max={}, is_underloaded={}, is_overloaded={}, load={}\n", - trial_, iter_, k_max_, is_underloaded_, is_overloaded_, this_new_load_ + trial_, iter_, k_max_, is_underloaded_, is_overloaded_, + TimeTypeWrapper(this_new_load_) ); vtAssert(k_max_ > 0, "Number of rounds (k) must be greater than zero"); @@ -1086,7 +1093,8 @@ std::vector TemperedLB::orderObjects( vt_debug_print( normal, temperedlb, "TemperedLB::decide: over_avg={}, single_obj_load={}\n", - over_avg, cur_objs[ordered_obj_ids[0]] + TimeTypeWrapper(over_avg), + TimeTypeWrapper(cur_objs[ordered_obj_ids[0]]) ); } } @@ -1146,7 +1154,8 @@ std::vector TemperedLB::orderObjects( vt_debug_print( normal, temperedlb, "TemperedLB::decide: over_avg={}, marginal_obj_load={}\n", - over_avg, cur_objs[ordered_obj_ids[0]] + TimeTypeWrapper(over_avg), + TimeTypeWrapper(cur_objs[ordered_obj_ids[0]]) ); } } @@ -1235,7 +1244,7 @@ void TemperedLB::decide() { verbose, temperedlb, "TemperedLB::decide: trial={}, iter={}, under.size()={}, " "selected_node={}, selected_load={:e}, obj_id={:x}, home={}, " - "obj_load={:e}, target_max_load={:e}, this_new_load_={:e}, " + "obj_load={}, target_max_load={}, this_new_load_={}, " "criterion={}\n", trial_, iter_, @@ -1244,9 +1253,9 @@ void TemperedLB::decide() { selected_load, obj_id.id, obj_id.getHomeNode(), - obj_load, - target_max_load_, - this_new_load_, + TimeTypeWrapper(obj_load), + TimeTypeWrapper(target_max_load_), + TimeTypeWrapper(this_new_load_), eval ); diff --git a/tests/perf/comm_cost_curve.cc b/tests/perf/comm_cost_curve.cc index b99e6e05f3..d7cca1e673 100644 --- a/tests/perf/comm_cost_curve.cc +++ b/tests/perf/comm_cost_curve.cc @@ -85,7 +85,7 @@ static void handler(PingMsg*) { template void sender() { - auto start = vt::timing::Timing::getCurrentTime(); + auto start = vt::timing::getCurrentTime(); for (int i = 0; i < pings; i++) { auto msg = vt::makeMessage(bytes); vt::theMsg()->sendMsg(1, msg); @@ -94,7 +94,7 @@ void sender() { vt::theSched()->runSchedulerWhile([]{return !is_done; }); is_done = false; - auto time = (vt::timing::Timing::getCurrentTime() - start) / pings; + auto time = (vt::timing::getCurrentTime() - start) / pings; auto Mb = static_cast(bytes) / 1024.0 / 1024.0; fmt::print("{:<8} {:<16} 0x{:<10x} {:<22} {:<22}\n", pings, bytes, bytes, Mb, time); } diff --git a/tests/unit/collection/test_lb_lite.extended.cc b/tests/unit/collection/test_lb_lite.extended.cc index cf32ba4de4..7b47f8c853 100644 --- a/tests/unit/collection/test_lb_lite.extended.cc +++ b/tests/unit/collection/test_lb_lite.extended.cc @@ -133,13 +133,13 @@ TEST_F(TestLB, test_lb_1) { auto proxy = theCollection()->constructCollective(range); for (int i = 0; i < num_iter; i++) { - auto cur_time = vt::timing::Timing::getCurrentTime(); + auto cur_time = vt::timing::getCurrentTime(); vt::runInEpochCollective([=]{ proxy.broadcastCollective(i); }); - auto total_time = vt::timing::Timing::getCurrentTime() - cur_time; + auto total_time = vt::timing::getCurrentTime() - cur_time; if (this_node == 0) { fmt::print("iteration: iter={},time={}\n", i, total_time); } @@ -154,7 +154,7 @@ TEST_F(TestLB, test_lb_1) { // auto const& range = Index1D(64); // auto proxy_1 = theCollection()->construct(range); // auto proxy_2 = theCollection()->construct(range); -// cur_time = ::vt::timing::Timing::getCurrentTime(); +// cur_time = ::vt::timing::getCurrentTime(); // startIter(0,proxy_1); // startIter(0,proxy_2); // } @@ -167,7 +167,7 @@ TEST_F(TestLB, test_lb_1) { // auto proxy_1 = theCollection()->construct(range); // auto proxy_2 = theCollection()->construct(range); // auto proxy_3 = theCollection()->construct(range); -// cur_time = ::vt::timing::Timing::getCurrentTime(); +// cur_time = ::vt::timing::getCurrentTime(); // startIter(0,proxy_1); // startIter(0,proxy_2); // startIter(0,proxy_3); diff --git a/tests/unit/scheduler/test_scheduler_progress.extended.cc b/tests/unit/scheduler/test_scheduler_progress.extended.cc index 2b13377024..9715e27ec7 100644 --- a/tests/unit/scheduler/test_scheduler_progress.extended.cc +++ b/tests/unit/scheduler/test_scheduler_progress.extended.cc @@ -65,7 +65,7 @@ TEST_F(TestSchedProgress, test_scheduler_progress_1) { bool done = false; - auto cur_time = vt::timing::Timing::getCurrentTime(); + auto cur_time = vt::timing::getCurrentTime(); auto testSched = std::make_unique(); testSched->runProgress(); @@ -86,7 +86,7 @@ TEST_F(TestSchedProgress, test_scheduler_progress_1) { // This ought to take close to a second EXPECT_GT( - vt::timing::Timing::getCurrentTime() - cur_time, + vt::timing::getCurrentTime() - cur_time, vt::theConfig()->vt_sched_progress_sec * fudge ); @@ -106,7 +106,7 @@ TEST_F(TestSchedProgress, test_scheduler_progress_2) { bool done = false; - auto cur_time = vt::timing::Timing::getCurrentTime(); + auto cur_time = vt::timing::getCurrentTime(); auto testSched = std::make_unique(); testSched->runProgress(); @@ -125,7 +125,7 @@ TEST_F(TestSchedProgress, test_scheduler_progress_2) { // This ought to take close to a second EXPECT_GT( - vt::timing::Timing::getCurrentTime() - cur_time, + vt::timing::getCurrentTime() - cur_time, vt::theConfig()->vt_sched_progress_sec * fudge ); diff --git a/tests/unit/timing/test_timing.nompi.cc b/tests/unit/timing/test_timing.nompi.cc new file mode 100644 index 0000000000..fd6310ea80 --- /dev/null +++ b/tests/unit/timing/test_timing.nompi.cc @@ -0,0 +1,91 @@ +/* +//@HEADER +// ***************************************************************************** +// +// test_timing.nompi.cc +// DARMA/vt => Virtual Transport +// +// Copyright 2019-2021 National Technology & Engineering Solutions of Sandia, LLC +// (NTESS). Under the terms of Contract DE-NA0003525 with NTESS, the U.S. +// Government retains certain rights in this software. +// +// Redistribution and use in source and binary forms, with or without +// modification, are permitted provided that the following conditions are met: +// +// * Redistributions of source code must retain the above copyright notice, +// this list of conditions and the following disclaimer. +// +// * Redistributions in binary form must reproduce the above copyright notice, +// this list of conditions and the following disclaimer in the documentation +// and/or other materials provided with the distribution. +// +// * Neither the name of the copyright holder nor the names of its +// contributors may be used to endorse or promote products derived from this +// software without specific prior written permission. +// +// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" +// AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE +// IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE +// ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE +// LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR +// CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF +// SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS +// INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN +// CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) +// ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE +// POSSIBILITY OF SUCH DAMAGE. +// +// Questions? Contact darma@sandia.gov +// +// ***************************************************************************** +//@HEADER +*/ + +#include + +#include "test_harness.h" + +#include "vt/timing/timing.h" + +namespace vt { namespace tests { namespace unit { + +using TestTiming = TestHarness; + +TEST_F(TestTiming, test_time_formatting) { + { + TimeTypeWrapper const t = 15664645.400691890716; + EXPECT_EQ(fmt::format("{}", t), "15.7e6 s"); + } + + { + TimeTypeWrapper const t = 4.0006918907165527344; + EXPECT_EQ(fmt::format("{}", t), "4.00e0 s"); + } + + { + TimeTypeWrapper const t = 0.0691890716552734423; + EXPECT_EQ(fmt::format("{}", t), "69.2e-3 s"); + } + + { + TimeTypeWrapper const t = -0.0691890716552734423; + EXPECT_EQ(fmt::format("{}", t), "-69.2e-3 s"); + } + + { + TimeTypeWrapper const t = 0.0006918907165527344; + EXPECT_EQ(fmt::format("{}", t), "692e-6 s"); + } + + { + TimeTypeWrapper const t = 0.0000006918907165527; + EXPECT_EQ(fmt::format("{}", t), "692e-9 s"); + } + + { + TimeTypeWrapper const t = 3.14; + EXPECT_EQ(fmt::format("{}", t), "3.14e0 s"); + } +} + +}}} /* end namespace vt::tests::unit */