From 0d5c557552e33d5fe14349bd80582b4e29be6928 Mon Sep 17 00:00:00 2001 From: "Jonathan R. Madsen" Date: Fri, 25 Feb 2022 03:56:41 -0600 Subject: [PATCH] Stability improvements (#26) * omnitrace verbprintf and errprintf * avail categories fix * omnitrace-dl namespace * OMNITRACE_CI macro / OMNITRACE_BUILD_CI option - always enables asserts * Roctracer improvements - Reworked roctracer significantly - Added categories to settings - create_cpu_cid_entry - handle clock_skew in roctracer - fixed roctracer activity names - hip_api_callback is "host" - perfetto::Flow for GPU * timemory submodule update * Tweak to redirect * Improved recursive guards - functors component - created "_hidden" variants of instrumentation funcs - omnitrace_* calls omnitrace_*_hidden - omnitrace-dl calls non-hidden - omnitrace-dl now strongly protects against recursion - omnitrace-dl now is standalone w.r.t. headers * Stability fixes - OMNITRACE_DEBUG_PUSH env variable - fix to HSA_TOOLS_LIB in dl.cpp - Fixed SFINAE warning in mpi_gotcha - Handle 64, _l, _r extensions in whole function names * cmake formatting * Fix for last commit + push/pop count info - don't instrument rocr::core::Signal::WaitAny - don't instrument rocr::core::Runtime::AsyncEventsLoop - fixed main not being popped in runtime instrument - updated interval data reserve - copy hash-ids and aliases onto main thread - warn about unclosed regions - removed guards in libomnitrace - added error checks for incorrect push_count vs. pop_count - fixed missing pop_timemory in last commit * Finalization methodology updates - added some more rocr:: functions to whole function names * Add event_base_loop to whole functions * Update VERSION to 0.1.0 --- .github/workflows/linux-ci.yml | 1 + CMakeLists.txt | 12 + VERSION | 2 +- cmake/BuildSettings.cmake | 5 + cmake/Packages.cmake | 2 +- external/timemory | 2 +- source/bin/omnitrace-avail/avail.cpp | 17 +- source/bin/omnitrace/details.cpp | 66 +-- source/bin/omnitrace/omnitrace.cpp | 187 ++++---- source/bin/omnitrace/omnitrace.hpp | 34 +- source/lib/CMakeLists.txt | 27 +- source/lib/include/library/api.hpp | 27 +- .../include/library/components/functors.hpp | 168 ++++++++ source/lib/include/library/components/fwd.hpp | 28 ++ .../include/library/components/mpi_gotcha.hpp | 4 + .../components/roctracer_callbacks.hpp | 6 +- source/lib/include/library/config.hpp | 14 + source/lib/include/library/defines.hpp.in | 10 + source/lib/include/library/redirect.hpp | 21 +- source/lib/src/dl.cpp | 224 +++++++--- source/lib/src/library.cpp | 404 +++++++++++------- source/lib/src/library/api.cpp | 65 +++ .../lib/src/library/components/mpi_gotcha.cpp | 8 +- .../lib/src/library/components/omnitrace.cpp | 4 +- .../lib/src/library/components/roctracer.cpp | 71 ++- .../components/roctracer_callbacks.cpp | 298 +++++++------ source/lib/src/library/config.cpp | 104 +++-- 27 files changed, 1214 insertions(+), 597 deletions(-) create mode 100644 source/lib/include/library/components/functors.hpp create mode 100644 source/lib/src/library/api.cpp diff --git a/.github/workflows/linux-ci.yml b/.github/workflows/linux-ci.yml index 7156141b0b..6a16872260 100644 --- a/.github/workflows/linux-ci.yml +++ b/.github/workflows/linux-ci.yml @@ -11,6 +11,7 @@ env: ELFUTILS_DOWNLOAD_VERSION: 0.183 OMNITRACE_DEBUG_FINALIZE: ON OMNITRACE_VERBOSE: 1 + OMNITRACE_CI: ON jobs: ubuntu-focal: diff --git a/CMakeLists.txt b/CMakeLists.txt index bef032d652..083aa11222 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -79,6 +79,18 @@ omnitrace_add_option(OMNITRACE_BUILD_TESTING "Enable building the testing suite" omnitrace_add_option(OMNITRACE_CUSTOM_DATA_SOURCE "Enable custom data source" OFF) omnitrace_add_option(OMNITRACE_BUILD_HIDDEN_VISIBILITY "Build with hidden visibility (disable for Debug builds)" ON) +omnitrace_add_option(OMNITRACE_BUILD_CI "Enable internal asserts, etc." OFF ADVANCED + NO_FEATURE) + +if(NOT "$ENV{OMNITRACE_CI}" STREQUAL "") + message( + AUTHOR_WARNING + "OMNITRACE_CI environment variable ($ENV{OMNITRACE_CI}) is overridding the OMNITRACE_BUILD_CI cache value" + ) + set(OMNITRACE_BUILD_CI + "$ENV{OMNITRACE_CI}" + CACHE BOOL "Enable internal asserts, etc" FORCE) +endif() if(NOT OMNITRACE_USE_HIP) set(OMNITRACE_USE_ROCTRACER diff --git a/VERSION b/VERSION index 1750564f27..6e8bf73aa5 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -0.0.6 +0.1.0 diff --git a/cmake/BuildSettings.cmake b/cmake/BuildSettings.cmake index 80fd6498c3..4b6ef852f8 100644 --- a/cmake/BuildSettings.cmake +++ b/cmake/BuildSettings.cmake @@ -32,6 +32,11 @@ if(OMNITRACE_USE_SANITIZER) "Sanitizer type, e.g. leak, thread, address, memory, etc.") endif() +if(OMNITRACE_BUILD_CI) + omnitrace_target_compile_definitions(${LIBNAME}-compile-options + INTERFACE OMNITRACE_CI) +endif() + # ----------------------------------------------------------------------------------------# # dynamic linking and runtime libraries # diff --git a/cmake/Packages.cmake b/cmake/Packages.cmake index 1a78985f3d..5c140fc17d 100644 --- a/cmake/Packages.cmake +++ b/cmake/Packages.cmake @@ -109,7 +109,7 @@ if(OMNITRACE_USE_MPI) elseif(OMNITRACE_USE_MPI_HEADERS) find_package(MPI-Headers ${omnitrace_FIND_QUIETLY} REQUIRED) omnitrace_target_compile_definitions( - omnitrace-mpi INTERFACE TIMEMORY_USE_MPI_HEADERS OMNITRACE_USE_MPI_HEADERS) + omnitrace-mpi INTERFACE TIMEMORY_USE_MPI_HEADERS=1 OMNITRACE_USE_MPI_HEADERS) target_link_libraries(omnitrace-mpi INTERFACE MPI::MPI_HEADERS) endif() diff --git a/external/timemory b/external/timemory index ba478a0188..b8d3b3e1fd 160000 --- a/external/timemory +++ b/external/timemory @@ -1 +1 @@ -Subproject commit ba478a0188bdc26f85368045fe91bf75e7004d4f +Subproject commit b8d3b3e1fd74384c927119c7bf1a9790dd25ca90 diff --git a/source/bin/omnitrace-avail/avail.cpp b/source/bin/omnitrace-avail/avail.cpp index 09062e7a66..ad53065f33 100644 --- a/source/bin/omnitrace-avail/avail.cpp +++ b/source/bin/omnitrace-avail/avail.cpp @@ -354,12 +354,16 @@ main(int argc, char** argv) for(const auto& itr : *_settings) { if(exclude_setting(itr.second->get_env_name())) continue; + auto _categories = itr.second->get_categories(); + if(_categories.find("native") != _categories.end()) + { + _categories.erase("native"); + _categories.emplace("timemory"); + itr.second->set_categories(_categories); + } for(const auto& eitr : itr.second->get_categories()) { - if(eitr == "native") - _category_options.emplace("settings::timemory"); - else - _category_options.emplace(TIMEMORY_JOIN("::", "settings", eitr)); + _category_options.emplace(TIMEMORY_JOIN("::", "settings", eitr)); } } } @@ -898,10 +902,7 @@ write_settings_info(std::ostream& os, const array_t& opts, str_set_t _categories{}; for(const auto& citr : sitr->second->get_categories()) { - if(citr == "native") - _categories.emplace("settings::timemory"); - else - _categories.emplace(TIMEMORY_JOIN("::", "settings", citr)); + _categories.emplace(TIMEMORY_JOIN("::", "settings", citr)); } bool _found = false; for(const auto& citr : _categories) diff --git a/source/bin/omnitrace/details.cpp b/source/bin/omnitrace/details.cpp index e6db65df73..effb457d3a 100644 --- a/source/bin/omnitrace/details.cpp +++ b/source/bin/omnitrace/details.cpp @@ -30,55 +30,23 @@ strset_t get_whole_function_names() { #if 1 - return strset_t{ "sem_init", - "sem_destroy", - "sem_open", - "sem_close", - "sem_post", - "sem_wait", - "sem_getvalue", - "sem_clockwait", - "sem_timedwait", - "sem_trywait", - "do_futex_wait", - "sem_unlink", - "fork", - "dl_iterate_phdr", - "dlinfo", - "dlopen", - "dlmopen", - "dlvsym", - "dlsym", - "getenv", - "setenv", - "unsetenv", - "fflush", - "malloc", - "malloc_stats", - "malloc_trim", - "mallopt", - "calloc", - "free", - "pvalloc", - "valloc", - "mmap", - "munmap", - "fmemopen", - "fmemclose", - "backtrace", - "backtrace_symbols", - "backtrace_symbols_fd", - "sigaddset", - "sigandset", - "sigdelset", - "sigemptyset", - "sigfillset", - "sighold", - "sigisemptyset", - "sigismember", - "sigorset", - "sigrelse", - "sigvec" }; + return strset_t{ + "sem_init", "sem_destroy", "sem_open", "sem_close", "sem_post", "sem_wait", + "sem_getvalue", "sem_clockwait", "sem_timedwait", "sem_trywait", "sem_unlink", + "fork", "do_futex_wait", "dl_iterate_phdr", "dlinfo", "dlopen", "dlmopen", + "dlvsym", "dlsym", "getenv", "setenv", "unsetenv", "printf", "fprintf", "fflush", + "malloc", "malloc_stats", "malloc_trim", "mallopt", "calloc", "free", "pvalloc", + "valloc", "mmap", "munmap", "fopen", "fclose", "fmemopen", "fmemclose", + "backtrace", "backtrace_symbols", "backtrace_symbols_fd", "sigaddset", + "sigandset", "sigdelset", "sigemptyset", "sigfillset", "sighold", "sigisemptyset", + "sigismember", "sigorset", "sigrelse", "sigvec", "strtok", "strstr", "sbrk", + "strxfrm", + // below are functions which never terminate + "rocr::core::Signal::WaitAny", "rocr::core::Runtime::AsyncEventsLoop", + "rocr::core::BusyWaitSignal::WaitAcquire", + "rocr::core::BusyWaitSignal::WaitRelaxed", "rocr::HSA::hsa_signal_wait_scacquire", + "rocr::os::ThreadTrampoline", "event_base_loop" + }; #else // should hopefully be removed soon return strset_t{ "a64l", diff --git a/source/bin/omnitrace/omnitrace.cpp b/source/bin/omnitrace/omnitrace.cpp index 7c0e59c694..4bc4d5b951 100644 --- a/source/bin/omnitrace/omnitrace.cpp +++ b/source/bin/omnitrace/omnitrace.cpp @@ -833,9 +833,7 @@ main(int argc, char** argv) if(!addr_space) { - fprintf(stderr, "[omnitrace][exe] Error! address space for dynamic " - "instrumentation was not created\n"); - exit(EXIT_FAILURE); + errprintf(-1, "address space for dynamic instrumentation was not created\n"); } process_t* app_thread = nullptr; @@ -977,8 +975,8 @@ main(int argc, char** argv) if(!app_binary && !app_thread) { - fprintf(stderr, "No application thread or binary!...\n"); - throw std::runtime_error("Nullptr to BPatch_binaryEdit* and BPatch_process*"); + errprintf(-1, "No application thread or binary! nullptr to BPatch_binaryEdit* " + "and BPatch_process*\n") } //----------------------------------------------------------------------------------// @@ -997,7 +995,7 @@ main(int argc, char** argv) _tried_libs += string_t("|") + _libname; verbprintf(0, "loading library: '%s'...\n", _libname.c_str()); result = (addr_space->loadLibrary(_libname.c_str()) != nullptr); - verbprintf(1, "loadLibrary(%s) result = %s\n", _libname.c_str(), + verbprintf(2, "loadLibrary(%s) result = %s\n", _libname.c_str(), (result) ? "success" : "failure"); if(result) break; } @@ -1191,17 +1189,15 @@ main(int argc, char** argv) if(!main_func && is_driver) { - fprintf(stderr, "[omnitrace][exe] Couldn't find '%s'\n", main_fname.c_str()); + errprintf(0, "could not find '%s'\n", main_fname.c_str()); if(!_mutatee_init || !_mutatee_fini) { - fprintf(stderr, "[omnitrace][exe] Couldn't find '%s' or '%s', aborting\n", - "_init", "_fini"); - throw std::runtime_error("Could not find main function"); + errprintf(-1, "could not find '%s' or '%s', aborting\n", "_init", "_fini"); } else { - fprintf(stderr, "[omnitrace][exe] using '%s' and '%s' in lieu of '%s'...", - "_init", "_fini", main_fname.c_str()); + errprintf(0, "using '%s' and '%s' in lieu of '%s'...", "_init", "_fini", + main_fname.c_str()); } } else if(!main_func && !is_driver) @@ -1220,17 +1216,15 @@ main(int argc, char** argv) if(itr.first == main_func && !is_driver) continue; if(!itr.first) { - stringstream_t ss; - ss << "Error! Couldn't find '" << itr.second.c_str() << "' function"; - fprintf(stderr, "[omnitrace][exe] %s\n", ss.str().c_str()); - throw std::runtime_error(ss.str()); + errprintf(-1, "could not find required function :: '%s;\n", + itr.second.c_str()); } } if(use_mpi && !(mpi_func || (mpi_init_func && mpi_fini_func))) { - throw std::runtime_error("MPI support was requested but omnitrace was not built " - "with MPI and GOTCHA support"); + errprintf(-1, "MPI support was requested but omnitrace was not built with MPI " + "and GOTCHA support"); } auto check_for_debug_info = [](bool& _has_debug_info, auto* _func) { @@ -1308,8 +1302,11 @@ main(int argc, char** argv) verbprintf(2, "Getting call expressions... "); + auto _init_arg0 = main_fname; + if(main_func) main_sign.get(); + auto main_call_args = omnitrace_call_expr(main_sign.get()); - auto init_call_args = omnitrace_call_expr(instr_mode, binary_rewrite, cmdv0); + auto init_call_args = omnitrace_call_expr(instr_mode, binary_rewrite, _init_arg0); auto fini_call_args = omnitrace_call_expr(); auto umpi_call_args = omnitrace_call_expr(use_mpi, is_attached); auto none_call_args = omnitrace_call_expr(); @@ -1322,7 +1319,6 @@ main(int argc, char** argv) auto umpi_call = umpi_call_args.get(mpi_func); auto main_beg_call = main_call_args.get(entr_trace); - auto main_end_call = main_call_args.get(exit_trace); verbprintf(2, "Done\n"); @@ -1367,9 +1363,8 @@ main(int argc, char** argv) auto p = tim::delimit(itr, "="); if(p.size() != 2) { - std::cerr << "Error! environment variable: " << itr - << " not in form VARIABLE=VALUE\n"; - throw std::runtime_error("Bad format"); + errprintf(0, "environment variable %s not in form VARIABLE=VALUE\n", + itr.c_str()); } tim::set_env(p.at(0), p.at(1)); auto _expr = omnitrace_call_expr(p.at(0), p.at(1)); @@ -1402,34 +1397,11 @@ main(int argc, char** argv) if(umpi_call) init_names.emplace_back(umpi_call.get()); if(init_call) init_names.emplace_back(init_call.get()); - - if(binary_rewrite) - { - verbprintf(2, "Adding main begin and end snippets...\n"); - if(main_beg_call) init_names.emplace_back(main_beg_call.get()); - if(main_end_call) fini_names.emplace_back(main_end_call.get()); - } - else if(app_thread) - { - verbprintf(2, "Patching main function\n"); - if(main_beg_call) - insert_instr(addr_space, main_func, main_beg_call, BPatch_entry, nullptr, - nullptr); - if(main_end_call) - insert_instr(addr_space, main_func, main_end_call, BPatch_exit, nullptr, - nullptr); - } - else - { - verbprintf(0, "No binary_rewrite and no app_thread!...\n"); - } - - if(fini_call) fini_names.emplace_back(fini_call.get()); + if(main_beg_call) init_names.emplace_back(main_beg_call.get()); for(const auto& itr : end_expr) - { if(itr.second) fini_names.emplace_back(itr.second.get()); - } + if(fini_call) fini_names.emplace_back(fini_call.get()); //----------------------------------------------------------------------------------// // @@ -1442,19 +1414,19 @@ main(int argc, char** argv) auto instr_procedures = [&](const procedure_vec_t& procedures) { // auto _report = [](int _lvl, const string_t& _action, const string_t& _type, - const string_t& _reason, const string_t& _name) { + const string_t& _reason, const string_t& _name, + const std::string& _extra = {}) { static std::map already_reported{}; if(already_reported[_type].count(_name) == 0) { - verbprintf(_lvl, "[%s][%s] %s :: '%s'...\n", _type.c_str(), - _action.c_str(), _reason.c_str(), _name.c_str()); + verbprintf(_lvl, "[%s][%s] %s :: '%s'", _type.c_str(), _action.c_str(), + _reason.c_str(), _name.c_str()); + if(!_extra.empty()) verbprintf_bare(_lvl, " (%s)", _extra.c_str()); + verbprintf_bare(_lvl, "...\n"); already_reported[_type].insert(_name); } }; - verbprintf(2, "Instrumenting %lu procedures...\n", - (unsigned long) procedures.size()); - auto check_regex_restrictions = [](const std::string& _name, const regexvec_t& _regexes) { // NOLINTNEXTLINE @@ -1463,6 +1435,7 @@ main(int argc, char** argv) return false; }; + std::pair _count = { 0, 0 }; for(auto* itr : procedures) { if(!itr) continue; @@ -1479,11 +1452,13 @@ main(int argc, char** argv) if(!itr->isInstrumentable()) { - _report(2, "Skipping", "function", "uninstrumentable", fname); + _report(3, "Skipping", "function", "uninstrumentable", fname); continue; } - if(itr == main_func) + auto name = get_func_file_line_info(mod, itr); + + if(itr == main_func || name.m_name == "main" || name.get() == main_sign.get()) { hash_ids.emplace_back(std::hash()(main_sign.get()), main_sign.get()); @@ -1496,8 +1471,6 @@ main(int argc, char** argv) continue; } - auto name = get_func_file_line_info(mod, itr); - if(strlen(modname) == 0) { _report(3, "Skipping", "module", "empty name", modname); @@ -1522,12 +1495,12 @@ main(int argc, char** argv) { if(check_regex_restrictions(modname, file_restrict)) { - _report(1, "Forcing", "module", "module-restrict-regex", modname); + _report(2, "Forcing", "module", "module-restrict-regex", modname); _force_inc = true; } else { - _report(2, "Skipping", "module", "module-restrict-regex", modname); + _report(3, "Skipping", "module", "module-restrict-regex", modname); continue; } } @@ -1536,19 +1509,19 @@ main(int argc, char** argv) { if(check_regex_restrictions(name.m_name, func_restrict)) { - _report(1, "Forcing", "function", "function-restrict-regex", + _report(2, "Forcing", "function", "function-restrict-regex", name.m_name); _force_inc = true; } else if(check_regex_restrictions(name.get(), func_restrict)) { - _report(1, "Forcing", "function", "function-restrict-regex", + _report(2, "Forcing", "function", "function-restrict-regex", name.get()); _force_inc = true; } else { - _report(2, "Skipping", "function", "function-restrict-regex", + _report(3, "Skipping", "function", "function-restrict-regex", name.get()); continue; } @@ -1563,7 +1536,7 @@ main(int argc, char** argv) { if(check_regex_restrictions(modname, file_include)) { - _report(1, "Forcing", "module", "module-include-regex", modname); + _report(2, "Forcing", "module", "module-include-regex", modname); _force_inc = true; } } @@ -1572,13 +1545,13 @@ main(int argc, char** argv) { if(check_regex_restrictions(name.m_name, func_include)) { - _report(1, "Forcing", "function", "function-include-regex", + _report(2, "Forcing", "function", "function-include-regex", name.m_name); _force_inc = true; } else if(check_regex_restrictions(name.get(), func_include)) { - _report(1, "Forcing", "function", "function-include-regex", + _report(2, "Forcing", "function", "function-include-regex", name.get()); _force_inc = true; } @@ -1593,7 +1566,7 @@ main(int argc, char** argv) { if(check_regex_restrictions(modname, file_exclude)) { - _report(1, "Skipping", "module", "module-exclude-regex", modname); + _report(2, "Skipping", "module", "module-exclude-regex", modname); continue; } } @@ -1602,13 +1575,13 @@ main(int argc, char** argv) { if(check_regex_restrictions(name.m_name, func_exclude)) { - _report(1, "Skipping", "function", "function-exclude-regex", + _report(2, "Skipping", "function", "function-exclude-regex", name.m_name); continue; } else if(check_regex_restrictions(name.get(), func_exclude)) { - _report(1, "Skipping", "function", "function-exclude-regex", + _report(2, "Skipping", "function", "function-exclude-regex", name.get()); continue; } @@ -1630,7 +1603,7 @@ main(int argc, char** argv) if(is_static_exe && has_debug_info && string_t{ fname } == "_fini" && string_t{ modname } == "DEFAULT_MODULE") { - _report(2, "Skipping", "function", "DEFAULT_MODULE", fname); + _report(3, "Skipping", "function", "DEFAULT_MODULE", fname); continue; } @@ -1640,7 +1613,7 @@ main(int argc, char** argv) overlapping_module_functions.find(module_function{ mod, itr }) != overlapping_module_functions.end()) { - _report(2, "Skipping", "function", "overlapping", fname); + _report(3, "Skipping", "function", "overlapping", fname); continue; } @@ -1668,16 +1641,18 @@ main(int argc, char** argv) if(_force_instr && (_skip_range || _skip_loop_range)) { - _report(1, "Forcing", "function", "dynamic-callsite", fname); + _report(2, "Forcing", "function", "dynamic-callsite", fname); } else if(_skip_range) { - _report(1, "Skipping", "function", "min-address-range", fname); + _report(2, "Skipping", "function", "min-address-range", fname, + TIMEMORY_JOIN('=', "range", _address_range)); continue; } else if(_skip_loop_range) { - _report(1, "Skipping", "function", "min-address-range-loop", fname); + _report(2, "Skipping", "function", "min-address-range-loop", fname, + TIMEMORY_JOIN('=', "range", _address_range)); continue; } } @@ -1688,7 +1663,7 @@ main(int argc, char** argv) query_instr(itr, BPatch_exit, nullptr, nullptr, instr_traps); if(!_entr_success && !_exit_success) { - _report(2, "Skipping", "function", + _report(3, "Skipping", "function", "Either no entry " "instrumentation points were found or instrumentation " "required traps and instrumenting via traps were disabled.", @@ -1701,7 +1676,7 @@ main(int argc, char** argv) _ss << "Function can be only partially instrument (entry = " << std::boolalpha << _entr_success << ", exit = " << _exit_success << ")"; - _report(2, "Skipping", "function", _ss.str(), fname); + _report(3, "Skipping", "function", _ss.str(), fname); continue; } @@ -1737,6 +1712,7 @@ main(int argc, char** argv) }; instr_procedure_functions.emplace_back(_f); + ++_count.first; if(loop_level_instr) { @@ -1752,7 +1728,7 @@ main(int argc, char** argv) if(!_lentr_success && !_lexit_success) { _report( - 2, "Skipping", "function-loop", + 3, "Skipping", "function-loop", "Either no entry instrumentation points were found or " "instrumentation " "required traps and instrumenting via traps were disabled.", @@ -1765,7 +1741,7 @@ main(int argc, char** argv) _ss << "Function can be only partially instrument (entry = " << std::boolalpha << _lentr_success << ", exit = " << _lexit_success << ")"; - _report(2, "Skipping", "function-loop", _ss.str(), fname); + _report(3, "Skipping", "function-loop", _ss.str(), fname); continue; } @@ -1799,9 +1775,11 @@ main(int argc, char** argv) instr_loop_traps); }; instr_procedure_functions.emplace_back(_lf); + ++_count.second; } } } + return _count; }; //----------------------------------------------------------------------------------// @@ -1812,7 +1790,9 @@ main(int argc, char** argv) if(instr_mode == "trace") { + const int _verbose_lvl = 2; verbprintf(2, "Beginning loop over modules [hash id generation pass]\n"); + std::vector>> _pass_info{}; for(auto& m : modules) { char modname[1024]; @@ -1821,15 +1801,39 @@ main(int argc, char** argv) if(!m->getProcedures()) { - verbprintf(1, "Skipping module w/ no procedures: '%s'\n", modname); + verbprintf(_verbose_lvl, "Skipping module w/ no procedures: '%s'\n", + modname); continue; } - verbprintf(3, "Parsing module: %s\n", modname); + verbprintf(_verbose_lvl + 1, "Parsing module: %s\n", modname); bpvector_t* p = m->getProcedures(); if(!p) continue; - instr_procedures(*p); + verbprintf(_verbose_lvl, "%4zu procedures are begin processed in %s\n", + p->size(), modname); + + auto _count = instr_procedures(*p); + + _pass_info.emplace_back(modname, _count); + } + // report the instrumented + for(auto& itr : _pass_info) + { + auto _valid = (verbose_level > _verbose_lvl || + (itr.second.first + itr.second.second) > 0); + if(_valid) + { + verbprintf(_verbose_lvl, "%4zu instrumented procedures in %s\n", + itr.second.first, itr.first.c_str()); + _valid = (loop_level_instr && + (verbose_level > _verbose_lvl || itr.second.second > 0)); + if(_valid) + { + verbprintf(_verbose_lvl, "%4zu instrumented loop procedures in %s\n", + itr.second.second, itr.first.c_str()); + } + } } } @@ -1889,8 +1893,10 @@ main(int argc, char** argv) } verbprintf(2, "Beginning loop over modules [instrumentation pass]\n"); + verbprintf(1, "\n"); for(auto& instr_procedure : instr_procedure_functions) instr_procedure(); + verbprintf(1, "\n"); if(app_thread) { @@ -2026,7 +2032,7 @@ main(int argc, char** argv) } else { - throw std::runtime_error("Unknown mode " + _mode); + errprintf(0, "Unknown mode :: %s\n", _mode.c_str()); } for(auto& mitr : _data) { @@ -2282,7 +2288,14 @@ instrument_entity(const string_t& function_name) regex_opts); static std::regex trailing("(\\.part\\.[0-9]+|\\.constprop\\.[0-9]+|\\.|\\.[0-9]+)$", regex_opts); - static strset_t whole = get_whole_function_names(); + static strset_t whole = []() { + auto _v = get_whole_function_names(); + auto _ret = _v; + for(std::string _ext : { "64", "_l", "_r" }) + for(const auto& itr : _v) + _ret.emplace(itr + _ext); + return _ret; + }(); // don't instrument the functions when key is found anywhere in function name if(std::regex_search(function_name, exclude) || @@ -2500,8 +2513,8 @@ get_absolute_exe_filepath(std::string exe_name, const std::string& env_path) if(file_exists(TIMEMORY_JOIN('/', pitr, exe_name))) { exe_name = get_realpath(TIMEMORY_JOIN('/', pitr, exe_name)); - verbprintf(0, "[omnitrace][exe] Resolved '%s' to '%s'...\n", - _exe_orig.c_str(), exe_name.c_str()); + verbprintf(0, "Resolved '%s' to '%s'...\n", _exe_orig.c_str(), + exe_name.c_str()); break; } } @@ -2536,8 +2549,8 @@ get_absolute_lib_filepath(std::string lib_name, const std::string& env_path) if(file_exists(TIMEMORY_JOIN('/', pitr, lib_name))) { lib_name = get_realpath(TIMEMORY_JOIN('/', pitr, lib_name)); - verbprintf(0, "[omnitrace][exe] Resolved '%s' to '%s'...\n", - _lib_orig.c_str(), lib_name.c_str()); + verbprintf(0, "Resolved '%s' to '%s'...\n", _lib_orig.c_str(), + lib_name.c_str()); break; } } diff --git a/source/bin/omnitrace/omnitrace.hpp b/source/bin/omnitrace/omnitrace.hpp index 528d3551a8..e799ee0ad9 100644 --- a/source/bin/omnitrace/omnitrace.hpp +++ b/source/bin/omnitrace/omnitrace.hpp @@ -163,19 +163,37 @@ static regexvec_t func_restrict = {}; //======================================================================================// // control debug printf statements -#define dprintf(...) \ - if(debug_print || verbose_level > 0) \ - fprintf(stderr, "[omnitrace][exe] " __VA_ARGS__); \ - fflush(stderr); +#define errprintf(LEVEL, ...) \ + { \ + if(werror || LEVEL < 0) \ + { \ + if(debug_print || verbose_level >= LEVEL) \ + fprintf(stderr, "[omnitrace][exe] Error! " __VA_ARGS__); \ + char _buff[FUNCNAMELEN]; \ + sprintf(_buff, "[omnitrace][exe] Error! " __VA_ARGS__); \ + throw std::runtime_error(std::string{ _buff }); \ + } \ + else \ + { \ + if(debug_print || verbose_level >= LEVEL) \ + fprintf(stderr, "[omnitrace][exe] Warning! " __VA_ARGS__); \ + } \ + fflush(stderr); \ + } // control verbose printf statements #define verbprintf(LEVEL, ...) \ - if(verbose_level >= LEVEL) fprintf(stdout, "[omnitrace][exe] " __VA_ARGS__); \ - fflush(stdout); + { \ + if(debug_print || verbose_level >= LEVEL) \ + fprintf(stdout, "[omnitrace][exe] " __VA_ARGS__); \ + fflush(stdout); \ + } #define verbprintf_bare(LEVEL, ...) \ - if(verbose_level >= LEVEL) fprintf(stdout, __VA_ARGS__); \ - fflush(stdout); + { \ + if(debug_print || verbose_level >= LEVEL) fprintf(stdout, __VA_ARGS__); \ + fflush(stdout); \ + } //======================================================================================// diff --git a/source/lib/CMakeLists.txt b/source/lib/CMakeLists.txt index bc1bec9911..cc4010dcc3 100644 --- a/source/lib/CMakeLists.txt +++ b/source/lib/CMakeLists.txt @@ -47,6 +47,7 @@ configure_file(${CMAKE_CURRENT_SOURCE_DIR}/include/library/defines.hpp.in set(library_sources ${CMAKE_CURRENT_LIST_DIR}/src/library.cpp + ${CMAKE_CURRENT_LIST_DIR}/src/library/api.cpp ${CMAKE_CURRENT_LIST_DIR}/src/library/config.cpp ${CMAKE_CURRENT_LIST_DIR}/src/library/cpu_freq.cpp ${CMAKE_CURRENT_LIST_DIR}/src/library/critical_trace.cpp @@ -85,6 +86,7 @@ set(library_headers ${CMAKE_CURRENT_LIST_DIR}/include/library/components/fwd.hpp ${CMAKE_CURRENT_LIST_DIR}/include/library/components/backtrace.hpp ${CMAKE_CURRENT_LIST_DIR}/include/library/components/fork_gotcha.hpp + ${CMAKE_CURRENT_LIST_DIR}/include/library/components/functors.hpp ${CMAKE_CURRENT_LIST_DIR}/include/library/components/mpi_gotcha.hpp ${CMAKE_CURRENT_LIST_DIR}/include/library/components/omnitrace.hpp ${CMAKE_CURRENT_LIST_DIR}/include/library/components/rocm_smi.hpp @@ -144,21 +146,38 @@ install( # # ------------------------------------------------------------------------------# +set(CMAKE_BUILD_TYPE "Release") +set(CMAKE_SKIP_RPATH OFF) +set(BUILD_RPATH_USE_ORIGIN ON) + add_library(omnitrace-dl-library SHARED) add_library(omnitrace::omnitrace-dl-library ALIAS omnitrace-dl-library) -target_compile_definitions(omnitrace-dl-library PRIVATE TIMEMORY_USE_VISIBILITY=0) target_sources(omnitrace-dl-library PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/src/dl.cpp) -target_link_libraries(omnitrace-dl-library - PRIVATE $) +target_link_libraries(omnitrace-dl-library PRIVATE ${dl_LIBRARY}) + +check_cxx_compiler_flag("-fno-exceptions" omnitrace_dl_library_fno_exceptions) +check_cxx_compiler_flag("-ftls-model=local-dynamic" + omnitrace_dl_library_ftls_module_local_dynamic) + +if(OMNITRACE_BUILD_DEVELOPER) + if(omnitrace_dl_library_fno_exceptions) + target_compile_options(omnitrace-dl-library PRIVATE -fno-exceptions) + endif() + + if(omnitrace_dl_library_ftls_module_local_dynamic) + target_compile_options(omnitrace-dl-library PRIVATE -ftls-model=local-dynamic) + endif() +endif() set_target_properties( omnitrace-dl-library PROPERTIES OUTPUT_NAME omnitrace-dl - CXX_VISIBILITY_PRESET "hidden" + CXX_VISIBILITY_PRESET "protected" VERSION ${PROJECT_VERSION} SOVERSION ${PROJECT_VERSION_MAJOR} POSITION_INDEPENDENT_CODE ON + BUILD_RPATH "\$ORIGIN" INSTALL_RPATH "\$ORIGIN") install( diff --git a/source/lib/include/library/api.hpp b/source/lib/include/library/api.hpp index 1419e88dc0..56e7bd35c4 100644 --- a/source/lib/include/library/api.hpp +++ b/source/lib/include/library/api.hpp @@ -30,27 +30,34 @@ extern "C" { /// handles configuration logic - void omnitrace_init_library(void) OMNITRACE_VISIBILITY("default"); + void omnitrace_init_library(void) OMNITRACE_PUBLIC_API; /// starts gotcha wrappers - void omnitrace_init(const char*, bool, const char*) OMNITRACE_VISIBILITY("default"); + void omnitrace_init(const char*, bool, const char*) OMNITRACE_PUBLIC_API; /// shuts down all tooling and generates output - void omnitrace_finalize(void) OMNITRACE_VISIBILITY("default"); + void omnitrace_finalize(void) OMNITRACE_PUBLIC_API; /// sets an environment variable - void omnitrace_set_env(const char* env_name, const char* env_val) - OMNITRACE_VISIBILITY("default"); + void omnitrace_set_env(const char* env_name, + const char* env_val) OMNITRACE_PUBLIC_API; /// sets whether MPI should be used - void omnitrace_set_mpi(bool use, bool attached) OMNITRACE_VISIBILITY("default"); + void omnitrace_set_mpi(bool use, bool attached) OMNITRACE_PUBLIC_API; /// starts an instrumentation region - void omnitrace_push_trace(const char* name) OMNITRACE_VISIBILITY("default"); + void omnitrace_push_trace(const char* name) OMNITRACE_PUBLIC_API; /// stops an instrumentation region - void omnitrace_pop_trace(const char* name) OMNITRACE_VISIBILITY("default"); + void omnitrace_pop_trace(const char* name) OMNITRACE_PUBLIC_API; - /// used by omnitrace-critical-trace - bool omnitrace_init_tooling() OMNITRACE_VISIBILITY("hidden"); + // these are the real implementations for internal calling convention + void omnitrace_init_library_hidden(void) OMNITRACE_HIDDEN_API; + void omnitrace_init_hidden(const char*, bool, const char*) OMNITRACE_HIDDEN_API; + void omnitrace_finalize_hidden(void) OMNITRACE_HIDDEN_API; + void omnitrace_set_env_hidden(const char* env_name, + const char* env_val) OMNITRACE_HIDDEN_API; + void omnitrace_set_mpi_hidden(bool use, bool attached) OMNITRACE_HIDDEN_API; + void omnitrace_push_trace_hidden(const char* name) OMNITRACE_HIDDEN_API; + void omnitrace_pop_trace_hidden(const char* name) OMNITRACE_HIDDEN_API; } diff --git a/source/lib/include/library/components/functors.hpp b/source/lib/include/library/components/functors.hpp new file mode 100644 index 0000000000..ff15643dab --- /dev/null +++ b/source/lib/include/library/components/functors.hpp @@ -0,0 +1,168 @@ +// MIT License +// +// Copyright (c) 2022 Advanced Micro Devices, Inc. All Rights Reserved. +// +// 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. + +#pragma once + +#include "library/components/fwd.hpp" +#include "library/defines.hpp" +#include "library/timemory.hpp" +#include "timemory/mpl/concepts.hpp" +#include "timemory/mpl/function_traits.hpp" +#include "timemory/utility/macros.hpp" + +#include +#include + +namespace omnitrace +{ +namespace component +{ +template +using enable_if_t = typename std::enable_if::type; + +template +static auto get_default_functor(tim::type_list) +{ + return [](Tp...) {}; +}; + +// timemory component which calls omnitrace functions +// (used in gotcha wrappers) +template +struct functors : comp::base, void> +{ + using this_type = functors; + using base_type = comp::base, void>; + using pair_type = std::pair; + + static constexpr bool begin_supports_cstr = + std::is_invocable::value; + static constexpr bool end_supports_cstr = + std::is_invocable::value; + + static constexpr bool begin_supports_void = std::is_invocable::value; + static constexpr bool end_supports_void = std::is_invocable::value; + + static void preinit(); + static void configure(StartFuncT&& _beg, StopFuncT&& _end); + static std::string label(); + + template 0) && + std::is_invocable_v), + int> = 0> + static auto start(Args&&... _args) + { + get_functors().first(std::forward(_args)...); + } + + template 0) && + std::is_invocable_v), + int> = 0> + static auto stop(Args&&... _args) + { + get_functors().second(std::forward(_args)...); + } + + TIMEMORY_DEFAULT_OBJECT(functors) + + template = 0> + void start() + { + get_functors().first(m_prefix); + } + + template = 0> + void stop() + { + get_functors().second(m_prefix); + } + + template = 0> + void start() + { + get_functors().first(); + } + + template = 0> + void stop() + { + get_functors().second(); + } + + template = 0> + void set_prefix(const char* _v) + { + m_prefix = _v; + } + +private: + static bool& is_configured(); + static pair_type& get_functors(); + +private: + const char* m_prefix = nullptr; +}; + +template +void +functors::preinit() +{ + using start_args_t = typename tim::mpl::function_traits::args_type; + using stop_args_t = typename tim::mpl::function_traits::args_type; + get_functors().first = get_default_functor(start_args_t{}); + get_functors().second = get_default_functor(stop_args_t{}); +} + +template +void +functors::configure(StartFuncT&& _beg, StopFuncT&& _end) +{ + is_configured() = true; + get_functors().first = std::forward(_beg); + get_functors().second = std::forward(_end); +} + +template +std::string +functors::label() +{ + return trait::name::value; +} + +template +bool& +functors::is_configured() +{ + static bool _v = false; + return _v; +} + +template +typename functors::pair_type& +functors::get_functors() +{ + static auto _v = pair_type{}; + return _v; +} +} // namespace component +} // namespace omnitrace diff --git a/source/lib/include/library/components/fwd.hpp b/source/lib/include/library/components/fwd.hpp index 6cd03b5e4a..82fa9879bc 100644 --- a/source/lib/include/library/components/fwd.hpp +++ b/source/lib/include/library/components/fwd.hpp @@ -32,10 +32,29 @@ #include #include +#include + TIMEMORY_DEFINE_NS_API(project, omnitrace) TIMEMORY_DECLARE_COMPONENT(roctracer) +/// \struct tim::trait::name +/// \brief provides a constexpr string in ::value +TIMEMORY_DECLARE_TYPE_TRAIT(name, typename Tp) + +#define TIMEMORY_DEFINE_NAME_TRAIT(NAME, ...) \ + namespace tim \ + { \ + namespace trait \ + { \ + template <> \ + struct name<__VA_ARGS__> \ + { \ + static constexpr auto value = NAME; \ + }; \ + } \ + } + namespace omnitrace { namespace component @@ -43,6 +62,11 @@ namespace component template using data_tracker = tim::component::data_tracker; +template +using functor_t = std::function; + +using default_functor_t = functor_t; + struct omnitrace; struct backtrace; struct backtrace_wall_clock @@ -67,6 +91,10 @@ using sampling_gpu_temp = data_tracker; using sampling_gpu_power = data_tracker; using sampling_gpu_memory = data_tracker; using roctracer = tim::component::roctracer; + +template +struct functors; } // namespace component } // namespace omnitrace diff --git a/source/lib/include/library/components/mpi_gotcha.hpp b/source/lib/include/library/components/mpi_gotcha.hpp index 8041b98293..0def35f764 100644 --- a/source/lib/include/library/components/mpi_gotcha.hpp +++ b/source/lib/include/library/components/mpi_gotcha.hpp @@ -58,6 +58,10 @@ struct mpi_gotcha : comp::base // called right after MPI_{Init,Init_thread,Comm_rank,Comm_size} with the return value void audit(const gotcha_data_t& _data, audit::outgoing, int _retval); + // without these you will get a verbosity level 1 warning + static void start() {} + static void stop() {} + private: int* m_rank_ptr = nullptr; int* m_size_ptr = nullptr; diff --git a/source/lib/include/library/components/roctracer_callbacks.hpp b/source/lib/include/library/components/roctracer_callbacks.hpp index cb81cc7e3c..b6091169ea 100644 --- a/source/lib/include/library/components/roctracer_callbacks.hpp +++ b/source/lib/include/library/components/roctracer_callbacks.hpp @@ -43,14 +43,14 @@ // Macro to check ROC-tracer calls status #define ROCTRACER_CALL(call) \ - do \ { \ + OMNITRACE_DEBUG_F(#call); \ int err = call; \ if(err != 0) \ { \ - std::cerr << roctracer_error_string() << " in: " << #call << std::flush; \ + OMNITRACE_PRINT_F("%s in: %s\n", roctracer_error_string(), #call); \ } \ - } while(0) + } namespace omnitrace { diff --git a/source/lib/include/library/config.hpp b/source/lib/include/library/config.hpp index da94c9f87a..e764301d3b 100644 --- a/source/lib/include/library/config.hpp +++ b/source/lib/include/library/config.hpp @@ -256,4 +256,18 @@ get_cpu_cid(); std::unique_ptr>& get_cpu_cid_stack(int64_t _tid = threading::get_id(), int64_t _parent = 0); + +using cpu_cid_data_t = std::tuple; +using cpu_cid_pair_t = std::tuple; +using cpu_cid_parent_map_t = std::unordered_map; + +std::unique_ptr& +get_cpu_cid_parents(int64_t _tid = threading::get_id()); + +cpu_cid_data_t +create_cpu_cid_entry(int64_t _tid = threading::get_id()); + +cpu_cid_pair_t +get_cpu_cid_entry(uint64_t _cid, int64_t _tid = threading::get_id()); + } // namespace omnitrace diff --git a/source/lib/include/library/defines.hpp.in b/source/lib/include/library/defines.hpp.in index 14e0aa7b67..603c13061c 100644 --- a/source/lib/include/library/defines.hpp.in +++ b/source/lib/include/library/defines.hpp.in @@ -55,3 +55,13 @@ #define OMNITRACE_VISIBILITY(MODE) OMNITRACE_ATTRIBUTE(visibility(MODE)) #define OMNITRACE_PUBLIC_API OMNITRACE_VISIBILITY("default") #define OMNITRACE_HIDDEN_API OMNITRACE_VISIBILITY("hidden") + +#if defined(OMNITRACE_CI) && OMNITRACE_CI > 0 +# if defined(NDEBUG) +# undef NDEBUG +# endif +# if !defined(DEBUG) +# define DEBUG 1 +# endif +# include +#endif diff --git a/source/lib/include/library/redirect.hpp b/source/lib/include/library/redirect.hpp index 6c26cb6d2e..9e26acf666 100644 --- a/source/lib/include/library/redirect.hpp +++ b/source/lib/include/library/redirect.hpp @@ -22,6 +22,7 @@ #pragma once +#include #include #include #include @@ -60,8 +61,8 @@ struct redirect // restore stream buffer m_os.rdbuf(m_strm_buffer); auto _v = m_buffer.str(); - _v = replace(m_buffer.str(), '\n'); - auto _expect = replace(m_expected, '\n'); + _v = replace<3>(m_buffer.str(), { '\n', '\t', ' ' }); + auto _expect = replace<3>(m_expected, { '\n', '\t', ' ' }); if(_v != _expect) { if(get_verbose() > 0) @@ -75,14 +76,18 @@ struct redirect } private: - template - static std::string replace(std::string _v, Tp _c, const std::string& _s = " ") + template + static std::string replace(std::string _v, const std::array& _c, + const std::string& _s = "") { - while(true) + for(const auto& itr : _c) { - auto _pos = _v.find(_c); - if(_pos == std::string::npos) break; - _v = _v.replace(_pos, 1, _s); + while(true) + { + auto _pos = _v.find(itr); + if(_pos == std::string::npos) break; + _v = _v.replace(_pos, 1, _s); + } } return _v; } diff --git a/source/lib/src/dl.cpp b/source/lib/src/dl.cpp index 5b2cbdee50..5f07558558 100644 --- a/source/lib/src/dl.cpp +++ b/source/lib/src/dl.cpp @@ -22,40 +22,37 @@ // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE // SOFTWARE. -#include -#include -#include -#include -#include -#include - #include #include +#include #include #include +#include #include +#include #include #include +#include #include #include #include +#include -#define OMNITRACE_VISIBLE __attribute__((visibility("default"))) -#define OMNITRACE_HIDDEN __attribute__((visibility("internal"))) -#define OMNITRACE_INLINE __attribute__((__always_inline__)) +#define OMNITRACE_FOLD_EXPRESSION(...) ((__VA_ARGS__), ...) +#define OMNITRACE_VISIBLE __attribute__((visibility("default"))) +#define OMNITRACE_HIDDEN __attribute__((visibility("internal"))) +#define OMNITRACE_INLINE __attribute__((__always_inline__)) #define OMNITRACE_DLSYM(VARNAME, HANDLE, FUNCNAME) \ if(HANDLE) \ { \ *(void**) (&VARNAME) = dlsym(HANDLE, FUNCNAME); \ if(VARNAME == nullptr && _omnitrace_dl_verbose >= 0) \ { \ - fprintf(stderr, "[omnitrace][dl][pid=%i]> %s :: %s\n", process::get_id(), \ - FUNCNAME, dlerror()); \ + fprintf(stderr, "[omnitrace][dl][pid=%i]> %s :: %s\n", getpid(), FUNCNAME, \ + dlerror()); \ } \ } -namespace process = tim::process; - //--------------------------------------------------------------------------------------// // // omnitrace symbols @@ -75,20 +72,51 @@ extern "C" //--------------------------------------------------------------------------------------// +inline namespace omnitrace +{ +inline namespace dl +{ namespace { inline int get_omnitrace_env(); +bool +get_env(const char* env_id, bool _default); + +std::string +get_env(const char* env_id, const char* _default); + +int +get_env(const char* env_id, int _default); + +template +auto +join(DelimT&& _delim, Args&&... _args) +{ + std::stringstream _ss{}; + OMNITRACE_FOLD_EXPRESSION(_ss << _delim << _args); + if constexpr(std::is_same::value) + { + return _ss.str().substr(1); + } + else + { + return _ss.str().substr(std::string{ _delim }.length()); + } +} // environment priority: // - OMNITRACE_DL_DEBUG // - OMNITRACE_DL_VERBOSE // - OMNITRACE_DEBUG // - OMNITRACE_VERBOSE -int _omnitrace_dl_verbose = - tim::get_env("OMNITRACE_DL_DEBUG", false, false) - ? 100 - : tim::get_env("OMNITRACE_DL_VERBOSE", get_omnitrace_env(), false); +int _omnitrace_dl_verbose = get_env("OMNITRACE_DL_DEBUG", false) + ? 100 + : get_env("OMNITRACE_DL_VERBOSE", get_omnitrace_env()); + +template > +inline ContainerT +delimit(const std::string& line, const char* delimiters = "\"',;: "); // The docs for dlopen suggest that the combination of RTLD_LOCAL + RTLD_DEEPBIND // (when available) helps ensure that the symbols in the instrumentation library @@ -142,9 +170,12 @@ struct OMNITRACE_HIDDEN indirect if(_omnitrace_dl_verbose > 0) { fprintf(stderr, "[omnitrace][dl][pid=%i] libomnitrace.so resolved to '%s'\n", - process::get_id(), m_libpath.c_str()); + getpid(), m_libpath.c_str()); } - tim::set_env("HSA_TOOLS_LIB", m_libpath, 0); + auto _omni_hsa_lib = m_libpath; + const char* _hsa_lib = getenv("HSA_TOOLS_LIB"); + if(_hsa_lib) _omni_hsa_lib.append(":").append(_hsa_lib); + setenv("HSA_TOOLS_LIB", _omni_hsa_lib.c_str(), 1); open(); init(); } @@ -163,7 +194,7 @@ struct OMNITRACE_HIDDEN indirect if(_omnitrace_dl_verbose > 0) { fprintf(stderr, "[omnitrace][dl][pid=%i] dlopen(%s, %s) :: success\n", - process::get_id(), m_libpath.c_str(), _omnitrace_dl_dlopen_descr); + getpid(), m_libpath.c_str(), _omnitrace_dl_dlopen_descr); } } else @@ -172,7 +203,7 @@ struct OMNITRACE_HIDDEN indirect { perror("dlopen"); fprintf(stderr, "[omnitrace][dl][pid=%i] dlopen(%s, %s) :: %s\n", - process::get_id(), m_libpath.c_str(), _omnitrace_dl_dlopen_descr, + getpid(), m_libpath.c_str(), _omnitrace_dl_dlopen_descr, dlerror()); } } @@ -196,11 +227,10 @@ struct OMNITRACE_HIDDEN indirect static OMNITRACE_INLINE std::string find_path(std::string&& _path) { - auto _paths = tim::delimit( - TIMEMORY_JOIN(":", tim::get_env("OMNITRACE_PATH", ""), - tim::get_env("LD_LIBRARY_PATH", ""), - tim::get_env("LIBRARY_PATH", "")), - ":"); + auto _paths = + delimit(join(":", get_env("OMNITRACE_PATH", ""), + get_env("LD_LIBRARY_PATH", ""), get_env("LIBRARY_PATH", "")), + ":"); auto file_exists = [](const std::string& name) { struct stat buffer; @@ -209,7 +239,7 @@ struct OMNITRACE_HIDDEN indirect for(auto&& itr : _paths) { - auto _f = TIMEMORY_JOIN('/', itr, _path); + auto _f = join('/', itr, _path); if(file_exists(_f)) return _f; } return _path; @@ -229,13 +259,15 @@ private: std::string m_libpath = {}; }; -inline std::unique_ptr& +inline indirect& get_indirect() OMNITRACE_HIDDEN; template inline void invoke(const char* _name, FuncT&& _func, Args... _args) OMNITRACE_HIDDEN; } // namespace +} // namespace dl +} // namespace omnitrace //--------------------------------------------------------------------------------------// @@ -243,57 +275,132 @@ extern "C" { void omnitrace_init_library(void) { - invoke(__FUNCTION__, get_indirect()->omnitrace_init_library_f); + invoke(__FUNCTION__, get_indirect().omnitrace_init_library_f); } void omnitrace_init(const char* a, bool b, const char* c) { - invoke(__FUNCTION__, get_indirect()->omnitrace_init_f, a, b, c); + invoke(__FUNCTION__, get_indirect().omnitrace_init_f, a, b, c); } void omnitrace_finalize(void) { - invoke(__FUNCTION__, get_indirect()->omnitrace_finalize_f); + invoke(__FUNCTION__, get_indirect().omnitrace_finalize_f); } void omnitrace_push_trace(const char* name) { - invoke(__FUNCTION__, get_indirect()->omnitrace_push_trace_f, name); + invoke(__FUNCTION__, get_indirect().omnitrace_push_trace_f, name); } void omnitrace_pop_trace(const char* name) { - invoke(__FUNCTION__, get_indirect()->omnitrace_pop_trace_f, name); + invoke(__FUNCTION__, get_indirect().omnitrace_pop_trace_f, name); } void omnitrace_set_env(const char* a, const char* b) { - tim::set_env(a, b, 0); - invoke(__FUNCTION__, get_indirect()->omnitrace_set_env_f, a, b); + setenv(a, b, 0); + invoke(__FUNCTION__, get_indirect().omnitrace_set_env_f, a, b); } void omnitrace_set_mpi(bool a, bool b) { - invoke(__FUNCTION__, get_indirect()->omnitrace_set_mpi_f, a, b); + invoke(__FUNCTION__, get_indirect().omnitrace_set_mpi_f, a, b); } } //--------------------------------------------------------------------------------------// +inline namespace omnitrace +{ +inline namespace dl +{ namespace { +template +inline ContainerT +delimit(const std::string& line, const char* delimiters) +{ + ContainerT _result{}; + size_t _beginp = 0; // position that is the beginning of the new string + size_t _delimp = 0; // position of the delimiter in the string + while(_beginp < line.length() && _delimp < line.length()) + { + // find the first character (starting at _delimp) that is not a delimiter + _beginp = line.find_first_not_of(delimiters, _delimp); + // if no a character after or at _end that is not a delimiter is not found + // then we are done + if(_beginp == std::string::npos) break; + // starting at the position of the new string, find the next delimiter + _delimp = line.find_first_of(delimiters, _beginp); + std::string _tmp{}; + // starting at the position of the new string, get the characters + // between this position and the next delimiter + _tmp = line.substr(_beginp, _delimp - _beginp); + // don't add empty strings + if(!_tmp.empty()) _result.emplace(_result.end(), _tmp); + } + return _result; +} + +std::string +get_env(const char* env_id, const char* _default) +{ + if(strlen(env_id) == 0) return _default; + char* env_var = ::std::getenv(env_id); + if(env_var) return std::string{ env_var }; + return _default; +} + +int +get_env(const char* env_id, int _default) +{ + if(strlen(env_id) == 0) return _default; + char* env_var = ::std::getenv(env_id); + if(env_var) return std::stoi(env_var); + return _default; +} + +bool +get_env(const char* env_id, bool _default) +{ + if(strlen(env_id) == 0) return _default; + char* env_var = ::std::getenv(env_id); + if(env_var) + { + if(std::string{ env_var }.find_first_not_of("0123456789") == std::string::npos) + return static_cast(std::stoi(env_var)); + else + { + for(size_t i = 0; i < strlen(env_var); ++i) + env_var[i] = tolower(env_var[i]); + for(const auto& itr : { "off", "false", "no", "n", "f", "0" }) + if(strcmp(env_var, itr) == 0) return false; + } + return true; + } + return _default; +} + int get_omnitrace_env() { - auto&& _debug = tim::get_env("OMNITRACE_DEBUG", false, false); - return tim::get_env("OMNITRACE_VERBOSE", (_debug) ? 100 : 0, false); + auto&& _debug = get_env("OMNITRACE_DEBUG", false); + return get_env("OMNITRACE_VERBOSE", (_debug) ? 100 : 0); } -std::unique_ptr& +indirect& get_indirect() { - static std::unique_ptr _v = std::make_unique( - tim::get_env("OMNITRACE_LIBRARY", "libomnitrace.so")); + static auto _v = indirect{ get_env("OMNITRACE_LIBRARY", "libomnitrace.so") }; + return _v; +} + +int32_t& +get_guard() +{ + static thread_local int32_t _v = 0; return _v; } @@ -301,25 +408,34 @@ template void invoke(const char* _name, FuncT&& _func, Args... _args) { - if(!get_indirect()) - { - // allow -2 verbosity to avoid throwing exception - if(_omnitrace_dl_verbose >= -1) - throw std::runtime_error( - "[omnitrace][dl] nullptr to struct holding dlsym function"); - return; - } - if(_func) { - std::invoke(std::forward(_func), _args...); + // if _lk is ever greater than zero on the same thread, this + // means a function within the current function is calling + // our instrumentation so we ignore the call + int32_t _lk = get_guard()++; + if(_lk == 0) + { + std::invoke(std::forward(_func), _args...); + } + else if(_omnitrace_dl_verbose > 2) + { + fflush(stderr); + fprintf(stderr, "[omnitrace][dl] call to %s was guarded :: value = %i\n", + _name, _lk); + fflush(stderr); + } + // decrement the guard as it exits the scope + --get_guard(); } else if(_omnitrace_dl_verbose >= 0) { fprintf(stderr, "[omnitrace][dl] %s\n", - TIMEMORY_JOIN("", "null function pointer to ", _name, ". Ignoring ", - _name, "(", _args..., ")") + join("", "null function pointer to ", _name, ". Ignoring ", _name, "(", + _args..., ")") .c_str()); } } } // namespace +} // namespace dl +} // namespace omnitrace diff --git a/source/lib/src/library.cpp b/source/lib/src/library.cpp index 88ee4589d2..b67ce203f3 100644 --- a/source/lib/src/library.cpp +++ b/source/lib/src/library.cpp @@ -21,7 +21,10 @@ // SOFTWARE. #include "library.hpp" +#include "library/api.hpp" #include "library/components/fork_gotcha.hpp" +#include "library/components/functors.hpp" +#include "library/components/fwd.hpp" #include "library/components/mpi_gotcha.hpp" #include "library/config.hpp" #include "library/critical_trace.hpp" @@ -34,22 +37,49 @@ #include "library/thread_sampler.hpp" #include "library/timemory.hpp" +#include #include #include using namespace omnitrace; +//======================================================================================// + +using library_functors = omnitrace::component::functors; + +TIMEMORY_DEFINE_NAME_TRAIT("cpu_instrumentation", library_functors); +TIMEMORY_INVOKE_PREINIT(library_functors) + +//======================================================================================// + +extern "C" bool +omnitrace_init_tooling_hidden() OMNITRACE_HIDDEN_API; + namespace { -std::vector& -get_interval_data() +using interval_data_instances = thread_data>; + +auto& +get_interval_data(int64_t _tid = threading::get_id()) { - static thread_local auto _v = []() { - auto _tmp = std::vector{}; - _tmp.reserve(max_supported_threads); - return _tmp; - }(); - return _v; + static auto& _v = + interval_data_instances::instances(interval_data_instances::construct_on_init{}); + return _v.at(_tid); +} + +auto& +get_timemory_hash_ids(int64_t _tid = threading::get_id()) +{ + static auto _v = std::array{}; + return _v.at(_tid); +} + +auto& +get_timemory_hash_aliases(int64_t _tid = threading::get_id()) +{ + static auto _v = + std::array{}; + return _v.at(_tid); } auto @@ -72,7 +102,7 @@ ensure_finalization(bool _static_init = false) // https://github.com/ROCm-Developer-Tools/roctracer/issues/22#issuecomment-572814465 tim::set_env("HSA_ENABLE_INTERRUPT", "0", 0); } - return scope::destructor{ []() { omnitrace_finalize(); } }; + return scope::destructor{ []() { omnitrace_finalize_hidden(); } }; } auto& @@ -97,19 +127,9 @@ get_instrumentation_bundles(int64_t _tid = threading::get_id()) } auto& -get_functors() +get_finalization_functions() { - using functor_t = std::function; - static auto _v = - std::pair{ [](const char*) {}, [](const char*) {} }; - return _v; -} - -auto& -get_cpu_cid_parents() -{ - static thread_local auto _v = - std::unordered_map>{}; + static auto _v = std::vector>{}; return _v; } @@ -119,8 +139,7 @@ using Phase = critical_trace::Phase; //======================================================================================// /// -/// \fn void omnitrace_push_trace(const char* name) -/// \brief the "start" function for an instrumentation region +/// /// //======================================================================================// namespace @@ -128,42 +147,42 @@ namespace auto& push_count() { - static thread_local uint16_t _v = 0; + static std::atomic _v{ 0 }; return _v; } auto& pop_count() { - static thread_local uint16_t _v = 0; + static std::atomic _v{ 0 }; return _v; } -struct reentry_guard -{ - reentry_guard(uint16_t& _v) - : m_v{ _v } - { - ++m_v; - } - ~reentry_guard() { --m_v; } - uint16_t& m_v; - - operator bool() const { return (m_v <= 1); } -}; +auto _debug_push = tim::get_env("OMNITRACE_DEBUG_PUSH", false) && !get_debug_env(); } // namespace +//======================================================================================// + extern "C" void -omnitrace_push_trace(const char* name) +omnitrace_push_trace_hidden(const char* name) { - reentry_guard _lk{ push_count() }; - if(!_lk) return; + ++push_count(); - // return if not active - if(get_state() == State::Finalized) return; - - if(get_state() != State::Active && !omnitrace_init_tooling()) + // unconditionally return if finalized + if(get_state() == State::Finalized) { - static auto _debug = get_debug_env(); + OMNITRACE_CONDITIONAL_BASIC_PRINT( + _debug_push, "%s(%s) called during finalization\n", __FUNCTION__, name); + return; + } + + OMNITRACE_CONDITIONAL_BASIC_PRINT(_debug_push, "%s(%s)\n", __FUNCTION__, name); + + // the expectation here is that if the state is not active then the call + // to omnitrace_init_tooling_hidden will activate all the appropriate + // tooling one time and as it exits set it to active and return true. + if(get_state() != State::Active && !omnitrace_init_tooling_hidden()) + { + static auto _debug = get_debug_env() || get_debug_init(); OMNITRACE_CONDITIONAL_BASIC_PRINT_F(_debug, "%s :: not active. state = %s\n", name, std::to_string(get_state()).c_str()); return; @@ -176,18 +195,15 @@ omnitrace_push_trace(const char* name) auto& _interval = get_interval_data(); auto _enabled = (_sample_idx++ % _sample_rate == 0); - _interval.emplace_back(_enabled); - if(_enabled) get_functors().first(name); + _interval->emplace_back(_enabled); + if(_enabled) library_functors::start(name); if(get_use_critical_trace()) { - auto _ts = comp::wall_clock::record(); - auto _cid = get_cpu_cid()++; - uint16_t _depth = (get_cpu_cid_stack()->empty()) - ? get_cpu_cid_stack(0)->size() - : get_cpu_cid_stack()->size() - 1; - auto _parent_cid = (get_cpu_cid_stack()->empty()) ? get_cpu_cid_stack(0)->back() - : get_cpu_cid_stack()->back(); - get_cpu_cid_parents().emplace(_cid, std::make_tuple(_parent_cid, _depth)); + uint64_t _cid = 0; + uint64_t _parent_cid = 0; + uint16_t _depth = 0; + std::tie(_cid, _parent_cid, _depth) = create_cpu_cid_entry(); + auto _ts = comp::wall_clock::record(); add_critical_trace( threading::get_id(), _cid, 0, _parent_cid, _ts, 0, critical_trace::add_hash_id(name), _depth); @@ -196,42 +212,38 @@ omnitrace_push_trace(const char* name) //======================================================================================// /// -/// \fn void omnitrace_pop_trace(const char* name) -/// \brief the "stop" function for an instrumentation region +/// /// //======================================================================================// extern "C" void -omnitrace_pop_trace(const char* name) +omnitrace_pop_trace_hidden(const char* name) { - // the same thread should not be pushing AND popping - if(push_count() > 0) return; - - reentry_guard _lk{ pop_count() }; - // return if reentry - if(!_lk) return; + ++pop_count(); // only execute when active if(get_state() == State::Active) { OMNITRACE_DEBUG_F("%s\n", name); + auto& _interval_data = get_interval_data(); - if(!_interval_data.empty()) + if(!_interval_data->empty()) { - if(_interval_data.back()) get_functors().second(name); - _interval_data.pop_back(); + if(_interval_data->back()) library_functors::stop(name); + _interval_data->pop_back(); } + if(get_use_critical_trace()) { if(get_cpu_cid_stack() && !get_cpu_cid_stack()->empty()) { auto _cid = get_cpu_cid_stack()->back(); - if(get_cpu_cid_parents().find(_cid) != get_cpu_cid_parents().end()) + if(get_cpu_cid_parents()->find(_cid) != get_cpu_cid_parents()->end()) { uint64_t _parent_cid = 0; uint16_t _depth = 0; auto _ts = comp::wall_clock::record(); - std::tie(_parent_cid, _depth) = get_cpu_cid_parents().at(_cid); + std::tie(_parent_cid, _depth) = get_cpu_cid_parents()->at(_cid); add_critical_trace( threading::get_id(), _cid, 0, _parent_cid, _ts, _ts, critical_trace::add_hash_id(name), _depth); @@ -242,20 +254,20 @@ omnitrace_pop_trace(const char* name) else { static auto _debug = get_debug_env(); - OMNITRACE_CONDITIONAL_BASIC_PRINT(_debug, "[%s] %s ignored :: not active\n", - __FUNCTION__, name); + OMNITRACE_CONDITIONAL_BASIC_PRINT(_debug, "[%s] %s ignored :: state = %s\n", + __FUNCTION__, name, + std::to_string(get_state()).c_str()); } } //======================================================================================// /// -/// \fn void omnitrace_set_env(const char* name, const char* env_val) -/// \brief Sets an initial environment variable +/// /// //======================================================================================// extern "C" void -omnitrace_set_env(const char* env_name, const char* env_val) +omnitrace_set_env_hidden(const char* env_name, const char* env_val) { // just search env to avoid initializing the settings OMNITRACE_CONDITIONAL_PRINT(get_debug_env() || get_verbose_env() > 2, @@ -273,8 +285,7 @@ omnitrace_set_env(const char* env_name, const char* env_val) //======================================================================================// /// -/// \fn void omnitrace_set_mpi(bool use, bool attached) -/// \brief Configures whether MPI support should be activated +/// /// //======================================================================================// @@ -285,7 +296,7 @@ std::function _start_gotcha_callback = []() {}; } // namespace extern "C" void -omnitrace_set_mpi(bool use, bool attached) +omnitrace_set_mpi_hidden(bool use, bool attached) { // just search env to avoid initializing the settings OMNITRACE_CONDITIONAL_PRINT(get_debug_env() || get_verbose_env() > 2, @@ -318,26 +329,41 @@ omnitrace_set_mpi(bool use, bool attached) //======================================================================================// extern "C" void -omnitrace_init_library() +omnitrace_init_library_hidden() { auto _tid = threading::get_id(); (void) _tid; - auto _mode = get_mode(); + auto _mode = get_mode(); + auto _debug_init = get_debug_init(); + + OMNITRACE_CONDITIONAL_BASIC_PRINT_F(_debug_init, "State is %s. Setting to %s...\n", + std::to_string(get_state()).c_str(), + std::to_string(State::Init).c_str()); + + { + OMNITRACE_CONDITIONAL_BASIC_PRINT_F( + _debug_init, "Calling backtrace once so that the one-time call of malloc in " + "glibc's backtrace() occurs...\n"); + std::stringstream _ss{}; + tim::print_backtrace<64>(_ss); + (void) _ss; + } get_state() = State::Init; + OMNITRACE_CONDITIONAL_BASIC_PRINT_F(_debug_init, "Configuring settings...\n"); + // configure the settings configure_settings(); - auto _debug_init = get_debug_init(); auto _debug_value = get_debug(); if(_debug_init) config::set_setting_value("OMNITRACE_DEBUG", true); scope::destructor _debug_dtor{ [_debug_value, _debug_init]() { if(_debug_init) config::set_setting_value("OMNITRACE_DEBUG", _debug_value); } }; - OMNITRACE_DEBUG("[%s]\n", __FUNCTION__); + OMNITRACE_DEBUG_F("\n"); // below will effectively do: // get_cpu_cid_stack(0)->emplace_back(-1); @@ -346,7 +372,7 @@ omnitrace_init_library() if(gpu::device_count() == 0 && get_state() != State::Active) { - OMNITRACE_DEBUG( + OMNITRACE_DEBUG_F( "No HIP devices were found: disabling roctracer and rocm_smi...\n"); get_use_roctracer() = false; get_use_rocm_smi() = false; @@ -354,9 +380,9 @@ omnitrace_init_library() if(_mode == Mode::Sampling) { - OMNITRACE_CONDITIONAL_PRINT(get_verbose() >= 0, - "Disabling critical trace in %s mode...\n", - std::to_string(_mode).c_str()); + OMNITRACE_CONDITIONAL_PRINT_F(get_verbose() >= 0, + "Disabling critical trace in %s mode...\n", + std::to_string(_mode).c_str()); get_use_sampling() = true; get_use_critical_trace() = false; } @@ -365,7 +391,6 @@ omnitrace_init_library() tim::trait::runtime_enabled::set(get_use_roctracer()); if(get_instrumentation_interval() < 1) get_instrumentation_interval() = 1; - get_interval_data().reserve(512); if(get_use_kokkosp()) { @@ -383,9 +408,14 @@ omnitrace_init_library() //======================================================================================// extern "C" bool -omnitrace_init_tooling() +omnitrace_init_tooling_hidden() { - static bool _once = false; + static bool _once = false; + static auto _debug_init = get_debug_init(); + + OMNITRACE_CONDITIONAL_BASIC_PRINT_F(_debug_init, "State is %s...\n", + std::to_string(get_state()).c_str()); + if(get_state() != State::PreInit || get_state() == State::Init || _once) return false; _once = true; @@ -393,15 +423,20 @@ omnitrace_init_tooling() get_state() == State::Init, "%s called after omnitrace_init_library() was explicitly called", __FUNCTION__); - OMNITRACE_CONDITIONAL_BASIC_PRINT(get_verbose_env() >= 0, - "Instrumentation mode: %s\n", - std::to_string(config::get_mode()).c_str()); + OMNITRACE_CONDITIONAL_BASIC_PRINT_F(get_verbose_env() >= 0, + "Instrumentation mode: %s\n", + std::to_string(config::get_mode()).c_str()); + + OMNITRACE_CONDITIONAL_BASIC_PRINT_F(_debug_init, "Printing banner...\n"); if(get_verbose_env() >= 0) print_banner(); - omnitrace_init_library(); + OMNITRACE_CONDITIONAL_BASIC_PRINT_F(_debug_init, + "Calling omnitrace_init_library()...\n"); - OMNITRACE_DEBUG("[%s]\n", __FUNCTION__); + omnitrace_init_library_hidden(); + + OMNITRACE_DEBUG_F("\n"); auto _dtor = scope::destructor{ []() { if(get_use_sampling()) @@ -422,15 +457,6 @@ omnitrace_init_tooling() sampling::block_signals(); } - if(!get_use_timemory() && !get_use_perfetto() && !get_use_sampling() && - !get_use_rocm_smi()) - { - get_state() = State::Finalized; - OMNITRACE_DEBUG_F("Both perfetto and timemory are disabled. Setting the state " - "to finalized\n"); - return false; - } - if(get_use_timemory()) { comp::user_global_bundle::global_init(); @@ -491,8 +517,10 @@ omnitrace_init_tooling() (void) get_perfetto_output_filename(); } - auto _exe = get_exe_name(); - static auto _thread_init = [_exe]() { + auto _exe = get_exe_name(); + auto _hash_ids = tim::get_hash_ids(); + auto _hash_aliases = tim::get_hash_aliases(); + auto _thread_init = [_exe, _hash_ids, _hash_aliases]() { static thread_local auto _thread_setup = [_exe]() { if(threading::get_id() > 0) threading::set_thread_name( @@ -500,20 +528,33 @@ omnitrace_init_tooling() thread_data::construct( TIMEMORY_JOIN("", _exe, "/thread-", threading::get_id()), quirk::config{}); - if(get_use_sampling()) sampling::setup(); - }; - static thread_local auto _once = std::once_flag{}; - std::call_once(_once, _thread_setup); + get_interval_data()->reserve(512); + // save the hash maps + get_timemory_hash_ids() = tim::get_hash_ids(); + get_timemory_hash_aliases() = tim::get_hash_aliases(); + return true; + }(); static thread_local auto _dtor = scope::destructor{ []() { if(get_use_sampling()) sampling::shutdown(); thread_data::instance()->stop(); } }; + (void) _thread_setup; (void) _dtor; }; + // separate from _thread_init so that it can be called after the first + // instrumentation on the thread + auto _setup_thread_sampling = []() { + static thread_local auto _v = []() { + auto _use_sampling = get_use_sampling(); + if(_use_sampling) sampling::setup(); + return _use_sampling; + }(); + (void) _v; + }; + // functors for starting and stopping timemory - static auto _push_timemory = [](const char* name) { - _thread_init(); + auto _push_timemory = [](const char* name) { auto& _data = get_instrumentation_bundles(); // this generates a hash for the raw string array auto _hash = tim::add_hash_id(tim::string_view_t{ name }); @@ -523,13 +564,12 @@ omnitrace_init_tooling() _bundle->start(); }; - static auto _push_perfetto = [](const char* name) { - _thread_init(); + auto _push_perfetto = [](const char* name) { uint64_t _ts = comp::wall_clock::record(); TRACE_EVENT_BEGIN("host", perfetto::StaticString(name), _ts); }; - static auto _pop_timemory = [](const char* name) { + auto _pop_timemory = [](const char* name) { auto _hash = tim::hash::get_hash_id(tim::string_view_t{ name }); auto& _data = get_instrumentation_bundles(); if(_data.bundles.empty()) @@ -551,31 +591,44 @@ omnitrace_init_tooling() } }; - static auto _pop_perfetto = [](const char*) { + auto _pop_perfetto = [](const char*) { uint64_t _ts = comp::wall_clock::record(); TRACE_EVENT_END("host", _ts); }; if(get_use_perfetto() && get_use_timemory()) { - get_functors().first = [](const char* name) { - _push_perfetto(name); - _push_timemory(name); - }; - get_functors().second = [](const char* name) { - _pop_timemory(name); - _pop_perfetto(name); - }; + library_functors::configure( + [=](const char* name) { + _thread_init(); + _push_perfetto(name); + _push_timemory(name); + _setup_thread_sampling(); + }, + [=](const char* name) { + _pop_timemory(name); + _pop_perfetto(name); + }); } else if(get_use_perfetto()) { - get_functors().first = _push_perfetto; - get_functors().second = _pop_perfetto; + library_functors::configure( + [=](const char* name) { + _thread_init(); + _push_perfetto(name); + _setup_thread_sampling(); + }, + [=](const char* name) { _pop_perfetto(name); }); } else if(get_use_timemory()) { - get_functors().first = _push_timemory; - get_functors().second = _pop_timemory; + library_functors::configure( + [=](const char* name) { + _thread_init(); + _push_timemory(name); + _setup_thread_sampling(); + }, + [=](const char* name) { _pop_timemory(name); }); } if(get_use_perfetto() && !is_system_backend()) @@ -613,10 +666,23 @@ omnitrace_init_tooling() //======================================================================================// extern "C" void -omnitrace_init(const char* _mode, bool _is_binary_rewrite, const char* _argv0) +omnitrace_init_hidden(const char* _mode, bool _is_binary_rewrite, const char* _argv0) { // always the first - std::atexit(&omnitrace_finalize); + (void) get_state(); + (void) push_count(); + (void) pop_count(); + + get_finalization_functions().emplace_back([_argv0]() { + // if main hasn't been popped yet, pop it + OMNITRACE_BASIC_PRINT("Running omnitrace_pop_trace(%s)...\n", _argv0); + omnitrace_pop_trace_hidden(_argv0); + }); + + std::atexit([]() { + // if not already finalized then we should finalize + if(get_state() != State::Finalized) omnitrace_finalize_hidden(); + }); OMNITRACE_CONDITIONAL_BASIC_PRINT( get_debug_env() || get_verbose_env() > 2, @@ -643,7 +709,7 @@ omnitrace_init(const char* _mode, bool _is_binary_rewrite, const char* _argv0) //======================================================================================// extern "C" void -omnitrace_finalize(void) +omnitrace_finalize_hidden(void) { // return if not active if(get_state() != State::Active) @@ -653,27 +719,25 @@ omnitrace_finalize(void) return; } - get_state() = State::Finalized; + // some functions called during finalization may alter the push/pop count so we need + // to save them here + auto _push_count = push_count().load(); + auto _pop_count = pop_count().load(); - get_functors().first = [](const char*) {}; - get_functors().second = [](const char*) {}; - - if(get_use_timemory()) + // e.g. omnitrace_pop_trace("main"); + if(_push_count > _pop_count) { - auto& _data = get_instrumentation_bundles(); - if(!_data.bundles.empty()) + for(auto& itr : get_finalization_functions()) { - for(size_t i = _data.bundles.size(); i > 0; --i) - { - auto*& _v = _data.bundles.at(i - 1); - _v->stop(); - _data.allocator.destroy(_v); - _data.allocator.deallocate(_v, 1); - } - _data.bundles.clear(); + itr(); + ++_pop_count; } } + get_state() = State::Finalized; + + library_functors::configure([](const char*) {}, [](const char*) {}); + pthread_gotcha::enable_sampling_on_child_threads() = false; auto _debug_init = get_debug_finalize(); @@ -691,6 +755,47 @@ omnitrace_finalize(void) if(dmp::rank() == 0 && get_verbose() >= 0) fprintf(stderr, "\n"); if(get_verbose() > 0 || get_debug()) config::print_settings(); + OMNITRACE_VERBOSE_F(1, "omnitrace_push_trace :: called %zux\n", _push_count); + OMNITRACE_VERBOSE_F(1, "omnitrace_pop_trace :: called %zux\n", _pop_count); + + OMNITRACE_DEBUG_F("Copying over all timemory hash information to main thread...\n"); + // copy these over so that all hashes are known + auto& _hzero = get_timemory_hash_ids(0); + auto& _azero = get_timemory_hash_aliases(0); + for(size_t i = 1; i < max_supported_threads; ++i) + { + auto& _hitr = get_timemory_hash_ids(i); + auto& _aitr = get_timemory_hash_aliases(i); + if(_hzero && _hitr) + { + for(auto itr : *_hitr) + _hzero->emplace(itr.first, itr.second); + } + if(_azero && _aitr) + { + for(auto itr : *_aitr) + _azero->emplace(itr.first, itr.second); + } + } + + OMNITRACE_DEBUG_F("Stopping and destroying instrumentation bundles...\n"); + for(auto& itr : instrumentation_bundles::instances()) + { + while(!itr.bundles.empty()) + { + OMNITRACE_VERBOSE_F(1, + "Warning! instrumentation bundle on thread %li with " + "label '%s' was not stopped.\n", + itr.bundles.back()->tid(), + itr.bundles.back()->key().c_str()); + itr.bundles.back()->stop(); + itr.bundles.back()->pop(); + itr.allocator.destroy(itr.bundles.back()); + itr.allocator.deallocate(itr.bundles.back(), 1); + itr.bundles.pop_back(); + } + } + if(get_use_sampling()) { OMNITRACE_DEBUG_F("Shutting down sampling...\n"); @@ -900,6 +1005,15 @@ omnitrace_finalize(void) OMNITRACE_THROW("Error opening perfetto output file: %s", get_perfetto_output_filename().c_str()); } + + OMNITRACE_CONDITIONAL_THROW( + get_is_continuous_integration() && _push_count > _pop_count, "%s", + TIMEMORY_JOIN(" ", + "omnitrace_push_trace was called more times than " + "omnitrace_pop_trace. The inverse is fine but the current state " + "means not every measurement was ended :: pushed:", + _push_count, "vs. popped:", _pop_count) + .c_str()); } //======================================================================================// @@ -908,6 +1022,6 @@ namespace { // if static objects are destroyed randomly (relatively uncommon behavior) // this might call finalization before perfetto ends the tracing session -// but static variable in omnitrace_init_tooling is more likely +// but static variable in omnitrace_init_tooling_hidden is more likely auto _ensure_finalization = ensure_finalization(true); } // namespace diff --git a/source/lib/src/library/api.cpp b/source/lib/src/library/api.cpp new file mode 100644 index 0000000000..cc369caf88 --- /dev/null +++ b/source/lib/src/library/api.cpp @@ -0,0 +1,65 @@ +// MIT License +// +// Copyright (c) 2022 Advanced Micro Devices, Inc. All Rights Reserved. +// +// 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 "library/api.hpp" + +extern "C" void +omnitrace_push_trace(const char* _name) +{ + omnitrace_push_trace_hidden(_name); +} + +extern "C" void +omnitrace_pop_trace(const char* _name) +{ + omnitrace_pop_trace_hidden(_name); +} + +extern "C" void +omnitrace_init_library(void) +{ + omnitrace_init_library_hidden(); +} + +extern "C" void +omnitrace_init(const char* _mode, bool _rewrite, const char* _arg0) +{ + omnitrace_init_hidden(_mode, _rewrite, _arg0); +} + +extern "C" void +omnitrace_finalize(void) +{ + omnitrace_finalize_hidden(); +} + +extern "C" void +omnitrace_set_env(const char* env_name, const char* env_val) +{ + omnitrace_set_env_hidden(env_name, env_val); +} + +extern "C" void +omnitrace_set_mpi(bool use, bool attached) +{ + omnitrace_set_mpi_hidden(use, attached); +} diff --git a/source/lib/src/library/components/mpi_gotcha.cpp b/source/lib/src/library/components/mpi_gotcha.cpp index e2dbe68264..7a1cc82176 100644 --- a/source/lib/src/library/components/mpi_gotcha.cpp +++ b/source/lib/src/library/components/mpi_gotcha.cpp @@ -89,7 +89,7 @@ mpi_gotcha::audit(const gotcha_data_t& _data, audit::incoming, int*, char***) if(get_state() == ::omnitrace::State::DelayedInit) get_state() = ::omnitrace::State::PreInit; - omnitrace_push_trace(_data.tool_id.c_str()); + omnitrace_push_trace_hidden(_data.tool_id.c_str()); #if !defined(TIMEMORY_USE_MPI) && defined(TIMEMORY_USE_MPI_HEADERS) tim::mpi::is_initialized_callback() = []() { return true; }; tim::mpi::is_finalized() = false; @@ -105,7 +105,7 @@ mpi_gotcha::audit(const gotcha_data_t& _data, audit::incoming, int*, char***, in if(get_state() == ::omnitrace::State::DelayedInit) get_state() = ::omnitrace::State::PreInit; - omnitrace_push_trace(_data.tool_id.c_str()); + omnitrace_push_trace_hidden(_data.tool_id.c_str()); #if !defined(TIMEMORY_USE_MPI) && defined(TIMEMORY_USE_MPI_HEADERS) tim::mpi::is_initialized_callback() = []() { return true; }; tim::mpi::is_finalized() = false; @@ -136,7 +136,7 @@ mpi_gotcha::audit(const gotcha_data_t& _data, audit::incoming, comm_t, int* _val OMNITRACE_CONDITIONAL_BASIC_PRINT(get_debug_env(), "[%s] %s()\n", __FUNCTION__, _data.tool_id.c_str()); - omnitrace_push_trace(_data.tool_id.c_str()); + omnitrace_push_trace_hidden(_data.tool_id.c_str()); if(_data.tool_id == "MPI_Comm_rank") { m_rank_ptr = _val; @@ -224,7 +224,7 @@ mpi_gotcha::audit(const gotcha_data_t& _data, audit::outgoing, int _retval) _data.tool_id.c_str(), (int) _retval); } } - omnitrace_pop_trace(_data.tool_id.c_str()); + omnitrace_pop_trace_hidden(_data.tool_id.c_str()); } } // namespace omnitrace diff --git a/source/lib/src/library/components/omnitrace.cpp b/source/lib/src/library/components/omnitrace.cpp index 8d2342af32..3b7b24dc5c 100644 --- a/source/lib/src/library/components/omnitrace.cpp +++ b/source/lib/src/library/components/omnitrace.cpp @@ -30,13 +30,13 @@ namespace component void omnitrace::start() { - if(m_prefix) omnitrace_push_trace(m_prefix); + if(m_prefix) omnitrace_push_trace_hidden(m_prefix); } void omnitrace::stop() { - if(m_prefix) omnitrace_pop_trace(m_prefix); + if(m_prefix) omnitrace_pop_trace_hidden(m_prefix); } void diff --git a/source/lib/src/library/components/roctracer.cpp b/source/lib/src/library/components/roctracer.cpp index 4340e8b5a6..396a8cdfe0 100644 --- a/source/lib/src/library/components/roctracer.cpp +++ b/source/lib/src/library/components/roctracer.cpp @@ -113,29 +113,24 @@ roctracer::setup() if(roctracer_is_setup()) return; roctracer_is_setup() = true; - OMNITRACE_DEBUG("[%s]\n", __FUNCTION__); + OMNITRACE_VERBOSE_F(1, "setting up roctracer...\n"); #if OMNITRACE_HIP_VERSION_MAJOR == 4 && OMNITRACE_HIP_VERSION_MINOR < 4 auto _kfdwrapper = dynamic_library{ "OMNITRACE_ROCTRACER_LIBKFDWRAPPER", OMNITRACE_ROCTRACER_LIBKFDWRAPPER }; #endif - ROCTRACER_CALL( - roctracer_set_properties(ACTIVITY_DOMAIN_HIP_API, (void*) hip_api_callback)); + ROCTRACER_CALL(roctracer_set_properties(ACTIVITY_DOMAIN_HIP_API, nullptr)); - if(roctracer_default_pool() == nullptr) - { - // Allocating tracing pool - roctracer_properties_t properties{}; - memset(&properties, 0, sizeof(roctracer_properties_t)); - // properties.mode = 0x1000; - properties.buffer_size = 0x1000; - properties.buffer_callback_fun = hip_activity_callback; - ROCTRACER_CALL(roctracer_open_pool(&properties)); - } + // Allocating tracing pool + roctracer_properties_t properties{}; + memset(&properties, 0, sizeof(roctracer_properties_t)); + // properties.mode = 0x1000; + properties.buffer_size = 0x100; + properties.buffer_callback_fun = hip_activity_callback; + ROCTRACER_CALL(roctracer_open_pool(&properties)); -#if OMNITRACE_HIP_VERSION_MAJOR == 4 && OMNITRACE_HIP_VERSION_MINOR >= 4 && \ - OMNITRACE_HIP_VERSION_MINOR <= 5 +#if OMNITRACE_HIP_VERSION_MAJOR == 4 && OMNITRACE_HIP_VERSION_MINOR >= 4 // HIP 4.5.0 has an invalid warning redirect _rd{ std::cerr, "roctracer_enable_callback(), get_op_end(), invalid domain " "ID(4) in: roctracer_enable_callback(hip_api_callback, " @@ -143,14 +138,18 @@ roctracer::setup() "invalid domain ID(4) in: roctracer_enable_activity()" }; #endif - // Enable API callbacks, all domains - ROCTRACER_CALL(roctracer_enable_callback(hip_api_callback, nullptr)); - // Enable activity tracing, all domains - ROCTRACER_CALL(roctracer_enable_activity()); + ROCTRACER_CALL(roctracer_enable_domain_callback(ACTIVITY_DOMAIN_HIP_API, + hip_api_callback, nullptr)); + // ROCTRACER_CALL(roctracer_enable_domain_callback(ACTIVITY_DOMAIN_ROCTX, + // hip_api_callback, nullptr)); + // Enable HIP activity tracing + ROCTRACER_CALL(roctracer_enable_domain_activity(ACTIVITY_DOMAIN_HIP_OPS)); // callback for HSA for(auto& itr : roctracer_setup_routines()) itr.second(); + + OMNITRACE_VERBOSE_F(1, "roctracer is setup\n"); } void @@ -159,31 +158,20 @@ roctracer::shutdown() auto_lock_t _lk{ type_mutex() }; if(!roctracer_is_setup()) return; roctracer_is_setup() = false; - OMNITRACE_DEBUG("[%s]\n", __FUNCTION__); - // flush all the activity - if(roctracer_default_pool() != nullptr) - { - OMNITRACE_DEBUG("[%s] roctracer_flush_activity\n", __FUNCTION__); - ROCTRACER_CALL(roctracer_flush_activity()); + OMNITRACE_VERBOSE_F(1, "shutting down roctracer...\n"); - // flush all buffers - OMNITRACE_DEBUG("[%s] roctracer_flush_buf\n", __FUNCTION__); - roctracer_flush_buf(); - } - - OMNITRACE_DEBUG("[%s] executing hip_exec_activity_callbacks\n", __FUNCTION__); + OMNITRACE_DEBUG_F("executing hip_exec_activity_callbacks\n"); // make sure all async operations are executed for(size_t i = 0; i < max_supported_threads; ++i) hip_exec_activity_callbacks(i); // callback for hsa - OMNITRACE_DEBUG("[%s] executing roctracer_shutdown_routines...\n", __FUNCTION__); + OMNITRACE_DEBUG_F("executing roctracer_shutdown_routines...\n"); for(auto& itr : roctracer_shutdown_routines()) itr.second(); -#if OMNITRACE_HIP_VERSION_MAJOR == 4 && OMNITRACE_HIP_VERSION_MINOR >= 4 && \ - OMNITRACE_HIP_VERSION_MINOR <= 5 +#if OMNITRACE_HIP_VERSION_MAJOR == 4 && OMNITRACE_HIP_VERSION_MINOR >= 4 OMNITRACE_DEBUG("[%s] redirecting roctracer warnings\n", __FUNCTION__); // HIP 4.5.0 has an invalid warning redirect _rd{ @@ -193,17 +181,12 @@ roctracer::shutdown() }; #endif - // Disable tracing and closing the pool - OMNITRACE_DEBUG("[%s] roctracer_disable_callback\n", __FUNCTION__); - ROCTRACER_CALL(roctracer_disable_callback()); + // ROCTRACER_CALL(roctracer_disable_domain_callback(ACTIVITY_DOMAIN_ROCTX)); + ROCTRACER_CALL(roctracer_disable_domain_callback(ACTIVITY_DOMAIN_HIP_API)); + ROCTRACER_CALL(roctracer_disable_domain_activity(ACTIVITY_DOMAIN_HIP_OPS)); + ROCTRACER_CALL(roctracer_flush_activity()); - OMNITRACE_DEBUG("[%s] roctracer_disable_activity\n", __FUNCTION__); - ROCTRACER_CALL(roctracer_disable_activity()); - - OMNITRACE_DEBUG("[%s] roctracer_close_pool\n", __FUNCTION__); - ROCTRACER_CALL(roctracer_close_pool()); - - OMNITRACE_DEBUG("[%s] roctracer is shutdown\n", __FUNCTION__); + OMNITRACE_VERBOSE_F(1, "roctracer is shutdown\n"); } } // namespace component } // namespace tim diff --git a/source/lib/src/library/components/roctracer_callbacks.cpp b/source/lib/src/library/components/roctracer_callbacks.cpp index e04ae22925..e6e7ec7d7b 100644 --- a/source/lib/src/library/components/roctracer_callbacks.cpp +++ b/source/lib/src/library/components/roctracer_callbacks.cpp @@ -24,9 +24,11 @@ #include "library.hpp" #include "library/config.hpp" #include "library/critical_trace.hpp" +#include "library/debug.hpp" #include "library/sampling.hpp" #include "library/thread_data.hpp" +#include #include #include @@ -36,6 +38,35 @@ namespace omnitrace { namespace api = tim::api; +int64_t +get_clock_skew() +{ + static auto _v = []() { + // synchronize timestamps + // We'll take a CPU timestamp before and after taking a GPU timestmp, then + // take the average of those two, hoping that it's roughly at the same time + // as the GPU timestamp. + auto _now = []() { + return std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count(); + }; + uint64_t _cpu_ts = _now(); + uint64_t _gpu_ts; + roctracer_get_timestamp(&_gpu_ts); + _cpu_ts += _now(); + _cpu_ts /= 2; + + // assume CPU timestamp is greater than GPU + OMNITRACE_BASIC_VERBOSE_F(2, "CPU timestamp: %lu\n", _cpu_ts); + OMNITRACE_BASIC_VERBOSE_F(2, "HIP timestamp: %lu\n", _gpu_ts); + auto _diff = static_cast(_cpu_ts) - static_cast(_gpu_ts); + OMNITRACE_BASIC_VERBOSE_F(2, "CPU/HIP timestamp skew: %li\n", _diff); + return _diff; + }(); + return _v; +} + std::unordered_set& get_roctracer_kernels() { @@ -183,15 +214,15 @@ hsa_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* if(get_use_timemory()) { std::unique_lock _lk{ tasking::get_roctracer_mutex() }; - auto _begin_ns = begin_timestamp; - auto _end_ns = end_timestamp; + auto _beg_ns = begin_timestamp; + auto _end_ns = end_timestamp; if(tasking::get_roctracer_task_group().pool()) tasking::get_roctracer_task_group().exec( - [_name, _begin_ns, _end_ns]() { + [_name, _beg_ns, _end_ns]() { roctracer_hsa_bundle_t _bundle{ _name, _scope }; _bundle.start() .store(std::plus{}, - static_cast(_end_ns - _begin_ns)) + static_cast(_end_ns - _beg_ns)) .stop(); }); } @@ -226,27 +257,27 @@ hsa_activity_callback(uint32_t op, activity_record_t* record, void* arg) if(!_name) return; - auto _begin_ns = record->begin_ns; - auto _end_ns = record->end_ns; - static auto _scope = []() { + auto _beg_ns = record->begin_ns + get_clock_skew(); + auto _end_ns = record->end_ns + get_clock_skew(); + static auto _scope = []() { auto _v = scope::config{}; if(get_roctracer_timeline_profile()) _v += scope::timeline{}; if(get_roctracer_flat_profile()) _v += scope::flat{}; return _v; }(); - auto _func = [_begin_ns, _end_ns, _name]() { + auto _func = [_beg_ns, _end_ns, _name]() { if(get_use_perfetto()) { TRACE_EVENT_BEGIN("device", perfetto::StaticString{ *_name }, - static_cast(_begin_ns)); + static_cast(_beg_ns)); TRACE_EVENT_END("device", static_cast(_end_ns)); } if(get_use_timemory()) { roctracer_hsa_bundle_t _bundle{ *_name, _scope }; _bundle.start() - .store(std::plus{}, static_cast(_end_ns - _begin_ns)) + .store(std::plus{}, static_cast(_end_ns - _beg_ns)) .stop(); } }; @@ -283,17 +314,16 @@ hip_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* if(get_state() != State::Active || !trait::runtime_enabled::get()) return; + (void) get_clock_skew(); + using Device = critical_trace::Device; using Phase = critical_trace::Phase; + assert(domain == ACTIVITY_DOMAIN_HIP_API); const char* op_name = roctracer_op_string(domain, cid, 0); if(op_name == nullptr) op_name = hip_api_name(cid); if(op_name == nullptr) return; - - const hip_api_data_t* data = reinterpret_cast(callback_data); - OMNITRACE_DEBUG("<%-30s id(%u)\tcorrelation_id(%lu) %s>\n", op_name, cid, - data->correlation_id, - (data->phase == ACTIVITY_API_PHASE_ENTER) ? "on-enter" : "on-exit"); + assert(std::string{ op_name } == std::string{ hip_api_name(cid) }); switch(cid) { @@ -305,56 +335,77 @@ hip_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* default: break; } - int64_t _ts = comp::wall_clock::record(); + const hip_api_data_t* data = reinterpret_cast(callback_data); + OMNITRACE_DEBUG("<%-30s id(%u)\tcorrelation_id(%lu) %s>\n", op_name, cid, + data->correlation_id, + (data->phase == ACTIVITY_API_PHASE_ENTER) ? "on-enter" : "on-exit"); + + int64_t _ts = comp::wall_clock::record(); + auto _tid = threading::get_id(); + uint64_t _cid = 0; + uint64_t _parent_cid = 0; + uint16_t _depth = 0; + auto _corr_id = data->correlation_id; if(data->phase == ACTIVITY_API_PHASE_ENTER) { + const char* _name = nullptr; switch(cid) { case HIP_API_ID_hipLaunchKernel: case HIP_API_ID_hipLaunchCooperativeKernel: { - const char* _name = - hipKernelNameRefByPtr(data->args.hipLaunchKernel.function_address, - data->args.hipLaunchKernel.stream); - if(_name != nullptr) - { - if(get_use_perfetto() || get_use_timemory() || get_use_rocm_smi()) - { - tim::auto_lock_t _lk{ tim::type_mutex() }; - get_roctracer_key_data().emplace(data->correlation_id, _name); - get_roctracer_tid_data().emplace(data->correlation_id, - threading::get_id()); - } - } + _name = hipKernelNameRefByPtr(data->args.hipLaunchKernel.function_address, + data->args.hipLaunchKernel.stream); + break; + } + case HIP_API_ID_hipHccModuleLaunchKernel: + { + _name = hipKernelNameRef(data->args.hipHccModuleLaunchKernel.f); break; } case HIP_API_ID_hipModuleLaunchKernel: { - const char* _name = hipKernelNameRef(data->args.hipModuleLaunchKernel.f); - if(_name != nullptr) - { - if(get_use_perfetto() || get_use_timemory() || get_use_rocm_smi()) - { - tim::auto_lock_t _lk{ tim::type_mutex() }; - get_roctracer_key_data().emplace(data->correlation_id, _name); - get_roctracer_tid_data().emplace(data->correlation_id, - threading::get_id()); - } - } + _name = hipKernelNameRef(data->args.hipModuleLaunchKernel.f); + break; + } + case HIP_API_ID_hipExtModuleLaunchKernel: + { + _name = hipKernelNameRef(data->args.hipExtModuleLaunchKernel.f); + break; + } + case HIP_API_ID_hipExtLaunchKernel: + { + _name = + hipKernelNameRefByPtr(data->args.hipExtLaunchKernel.function_address, + data->args.hipLaunchKernel.stream); break; } default: break; } + if(_name != nullptr) + { + if(get_use_perfetto() || get_use_timemory() || get_use_rocm_smi()) + { + tim::auto_lock_t _lk{ tim::type_mutex() }; + get_roctracer_key_data().emplace(_corr_id, _name); + get_roctracer_tid_data().emplace(_corr_id, _tid); + } + } + + std::tie(_cid, _parent_cid, _depth) = create_cpu_cid_entry(); + if(get_use_perfetto()) { - TRACE_EVENT_BEGIN("device", perfetto::StaticString{ op_name }, - static_cast(_ts)); + TRACE_EVENT_BEGIN( + "host", perfetto::StaticString{ op_name }, static_cast(_ts), + perfetto::Flow::ProcessScoped(_cid), "pcid", _parent_cid, "cid", _cid, + "tid", _tid, "depth", _depth, "corr_id", _corr_id); } if(get_use_timemory()) { - auto itr = get_roctracer_hip_data()->emplace(data->correlation_id, + auto itr = get_roctracer_hip_data()->emplace(_corr_id, roctracer_bundle_t{ op_name }); if(itr.second) { @@ -368,36 +419,37 @@ hip_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* } if(get_use_critical_trace() || get_use_rocm_smi()) { - auto _cid = get_cpu_cid()++; - uint16_t _depth = (get_cpu_cid_stack()->empty()) - ? get_cpu_cid_stack(0)->size() - : get_cpu_cid_stack()->size() - 1; - auto _parent_cid = (get_cpu_cid_stack()->empty()) - ? get_cpu_cid_stack(0)->back() - : get_cpu_cid_stack()->back(); add_critical_trace( - threading::get_id(), _cid, data->correlation_id, _parent_cid, _ts, 0, + _tid, _cid, _corr_id, _parent_cid, _ts, 0, critical_trace::add_hash_id(op_name), _depth); + } + + { tim::auto_lock_t _lk{ tim::type_mutex() }; - get_roctracer_cid_data().emplace(data->correlation_id, + get_roctracer_cid_data().emplace(_corr_id, cid_tuple_t{ _cid, _parent_cid, _depth }); } - hip_exec_activity_callbacks(threading::get_id()); + hip_exec_activity_callbacks(_tid); } else if(data->phase == ACTIVITY_API_PHASE_EXIT) { - hip_exec_activity_callbacks(threading::get_id()); + hip_exec_activity_callbacks(_tid); + + { + tim::auto_lock_t _lk{ tim::type_mutex() }; + std::tie(_cid, _parent_cid, _depth) = get_roctracer_cid_data().at(_corr_id); + } if(get_use_perfetto()) { - TRACE_EVENT_END("device", static_cast(_ts)); + TRACE_EVENT_END("host", static_cast(_ts)); } if(get_use_timemory()) { - auto _stop = [data](int64_t _tid) { + auto _stop = [&_corr_id](int64_t _tid) { auto& _data = get_roctracer_hip_data(_tid); - auto itr = _data->find(data->correlation_id); + auto itr = _data->find(_corr_id); if(itr != get_roctracer_hip_data()->end()) { itr->second.stop(); @@ -406,7 +458,7 @@ hip_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* } return false; }; - if(!_stop(threading::get_id())) + if(!_stop(_tid)) { for(size_t i = 0; i < max_supported_threads; ++i) { @@ -416,16 +468,8 @@ hip_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void* } if(get_use_critical_trace() || get_use_rocm_smi()) { - uint16_t _depth = 0; - uint64_t _cid = 0; - uint64_t _parent_cid = 0; - { - tim::auto_lock_t _lk{ tim::type_mutex() }; - std::tie(_cid, _parent_cid, _depth) = - get_roctracer_cid_data().at(data->correlation_id); - } add_critical_trace( - threading::get_id(), _cid, data->correlation_id, _parent_cid, _ts, _ts, + _tid, _cid, _corr_id, _parent_cid, _ts, _ts, critical_trace::add_hash_id(op_name), _depth); } } @@ -454,8 +498,6 @@ hip_activity_callback(const char* begin, const char* end, void*) const roctracer_record_t* end_record = reinterpret_cast(end); - OMNITRACE_DEBUG("Activity records:\n"); - auto&& _advance_record = [&record]() { ROCTRACER_CALL(roctracer_next_record(record, &record)); }; @@ -465,47 +507,23 @@ hip_activity_callback(const char* begin, const char* end, void*) // make sure every iteration advances regardless of where return point happens scope::destructor _next_dtor{ _advance_record }; + // OMNITRACE_CI will enable these asserts and should fail if something relevant + // changes + assert(HIP_OP_ID_DISPATCH == 0); + assert(HIP_OP_ID_COPY == 1); + assert(HIP_OP_ID_BARRIER == 2); + assert(record->domain == ACTIVITY_DOMAIN_HIP_OPS); + + if(record->domain != ACTIVITY_DOMAIN_HIP_OPS) continue; + if(record->op > HIP_OP_ID_BARRIER) continue; + const char* op_name = - roctracer_op_string(record->domain, record->correlation_id, 0); - if(op_name == nullptr) op_name = hip_api_name(record->correlation_id); + roctracer_op_string(record->domain, record->op, record->kind); - switch(record->kind) - { - case HIP_API_ID_hipLaunchKernel: - case HIP_API_ID_hipLaunchCooperativeKernel: - case HIP_API_ID_hipModuleLaunchKernel: break; - case HIP_API_ID_hipGetLastError: continue; - default: - { - if(op_name != nullptr && strcmp(op_name, "unknown") != 0 && - strcmp(op_name, "InternalMarker") != 0) - { - OMNITRACE_BASIC_VERBOSE_F(2, "[%s] ignoring callback for %s\n", - __FUNCTION__, op_name); - continue; - } - break; - } - } - - auto _dev_id = record->device_id; - auto _thr_id = record->thread_id; - auto _prc_id = record->process_id; - auto _que_id = record->queue_id; - - if(op_name != nullptr) - { - OMNITRACE_DEBUG( - "\t%-30s\tcorrelation_id(%6lu) time_ns(%12lu:%12lu) " - "delta_ns(%12lu) device_id(%d) stream_id(%lu) proc_id(%u) thr_id(%u)\n", - op_name, record->correlation_id, record->begin_ns, record->end_ns, - (record->end_ns - record->begin_ns), _dev_id, _que_id, _prc_id, _thr_id); - } - - auto _begin_ns = record->begin_ns; - auto _end_ns = record->end_ns; - auto _corr_id = record->correlation_id; - static auto _scope = []() { + uint64_t _beg_ns = record->begin_ns + get_clock_skew(); + uint64_t _end_ns = record->end_ns + get_clock_skew(); + auto _corr_id = record->correlation_id; + static auto _scope = []() { auto _v = scope::config{}; if(get_roctracer_timeline_profile()) _v += scope::timeline{}; if(get_roctracer_flat_profile()) _v += scope::flat{}; @@ -536,6 +554,9 @@ hip_activity_callback(const char* begin, const char* end, void*) } } + if(_name == nullptr && op_name == nullptr) continue; + if(_name == nullptr) _name = op_name; + if(_critical_trace) { tim::auto_lock_t _lk{ tim::type_mutex() }; @@ -545,44 +566,51 @@ hip_activity_callback(const char* begin, const char* end, void*) _critical_trace = false; } - auto _func = [_critical_trace, _depth, _tid, _cid, _laps, _begin_ns, _end_ns, + { + static size_t _n = 0; + OMNITRACE_VERBOSE_F( + 2, + "%4zu :: %-20s :: %-20s :: correlation_id(%6lu) time_ns(%12lu:%12lu) " + "delta_ns(%12lu) device_id(%d) stream_id(%lu) proc_id(%u) thr_id(%lu)\n", + _n++, op_name, _name, record->correlation_id, _beg_ns, _end_ns, + (_end_ns - _beg_ns), record->device_id, record->queue_id, + record->process_id, _tid); + } + + // execute this on this thread bc of how perfetto visualization works + if(get_use_perfetto()) + { + static auto _op_id_names = + std::array{ "DISPATCH", "COPY", "BARRIER" }; + + if(_kernel_names.find(_name) == _kernel_names.end()) + _kernel_names.emplace(_name, tim::demangle(_name)); + + assert(_end_ns > _beg_ns); + TRACE_EVENT_BEGIN( + "device", perfetto::StaticString{ _kernel_names.at(_name).c_str() }, + _beg_ns, perfetto::Flow::ProcessScoped(_cid), "corr_id", + record->correlation_id, "device", record->device_id, "queue", + record->queue_id, "op", _op_id_names.at(record->op)); + TRACE_EVENT_END("device", _end_ns); + } + + auto _func = [_critical_trace, _depth, _tid, _cid, _laps, _beg_ns, _end_ns, _corr_id, _name]() { // NOTE #1: we get two measurements for 1 kernel so we need to // tweak the number of laps for the wall-clock component if(_name != nullptr) { - if(get_use_perfetto()) - { - if(_kernel_names.find(_name) == _kernel_names.end()) - _kernel_names.emplace(_name, tim::demangle(_name)); - TRACE_EVENT_BEGIN( - "device", - perfetto::StaticString{ _kernel_names.at(_name).c_str() }, - static_cast(_begin_ns)); - TRACE_EVENT_END("device", static_cast(_end_ns)); - } if(get_use_timemory()) { roctracer_bundle_t _bundle{ _name, _scope }; _bundle.start() .store(std::plus{}, - static_cast(_end_ns - _begin_ns)) + static_cast(_end_ns - _beg_ns)) .stop() .get([&](comp::wall_clock* wc) { - wc->set_value(_end_ns - _begin_ns); - wc->set_accum(_end_ns - _begin_ns); - if(_laps % 2 == 1) - { - // below is a hack bc we get two measurements for 1 kernel - wc->set_laps(0); - - auto itr = wc->get_iterator(); - if(itr && itr->data().get_laps() == 0) - { - wc->set_is_invalid(true); - itr->data().set_is_invalid(true); - } - } + wc->set_value(_end_ns - _beg_ns); + wc->set_accum(_end_ns - _beg_ns); return wc; }); _bundle.pop(); @@ -592,7 +620,7 @@ hip_activity_callback(const char* begin, const char* end, void*) auto _hash = critical_trace::add_hash_id(_name); uint16_t _prio = _laps + 1; // priority add_critical_trace( - _tid, _cid, _corr_id, _cid, _begin_ns, _end_ns, _hash, _depth + 1, + _tid, _cid, _corr_id, _cid, _beg_ns, _end_ns, _hash, _depth + 1, _prio); } } diff --git a/source/lib/src/library/config.cpp b/source/lib/src/library/config.cpp index 3dc22475be..722247fd49 100644 --- a/source/lib/src/library/config.cpp +++ b/source/lib/src/library/config.cpp @@ -29,6 +29,7 @@ #include #include #include +#include #include #include #include @@ -92,15 +93,14 @@ configure_settings() if(_once) return; _once = true; - OMNITRACE_CONDITIONAL_THROW( - get_state() < State::Init, - "config::configure_settings() called before omnitrace_init_library. state = %s", - std::to_string(get_state()).c_str()); - - OMNITRACE_CONDITIONAL_THROW( - get_state() > State::Init, - "config::configure_settings() called after omnitrace was initialized. state = %s", - std::to_string(get_state()).c_str()); + if(get_state() < State::Init) + { + ::tim::print_demangled_backtrace<64>(); + OMNITRACE_CONDITIONAL_THROW(true, + "config::configure_settings() called before " + "omnitrace_init_library. state = %s", + std::to_string(get_state()).c_str()); + } static auto _config = settings::shared_instance(); @@ -114,26 +114,27 @@ configure_settings() if(_omnitrace_debug) tim::set_env("TIMEMORY_DEBUG_SETTINGS", "1", 0); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_USE_PERFETTO", "Enable perfetto backend", - _default_perfetto_v, "backend", "perfetto"); + _default_perfetto_v, "backend", "perfetto", + "instrumentation"); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_USE_TIMEMORY", "Enable timemory backend", !_config->get("OMNITRACE_USE_PERFETTO"), "backend", - "timemory"); + "timemory", "instrumentation", "sampling"); #if defined(OMNITRACE_USE_ROCTRACER) OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_USE_ROCTRACER", "Enable ROCM tracing", true, - "backend", "roctracer"); + "backend", "roctracer", "rocm"); #endif #if defined(OMNITRACE_USE_ROCM_SMI) OMNITRACE_CONFIG_SETTING( bool, "OMNITRACE_USE_ROCM_SMI", "Enable sampling GPU power, temp, utilization, and memory usage", true, "backend", - "rocm-smi"); + "rocm-smi", "rocm"); OMNITRACE_CONFIG_SETTING(std::string, "OMNITRACE_ROCM_SMI_DEVICES", "Devices to query when OMNITRACE_USE_ROCM_SMI=ON", "all", - "backend", "rocm-smi"); + "backend", "rocm-smi", "rocm"); #endif OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_USE_SAMPLING", @@ -146,7 +147,8 @@ configure_settings() "io"); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_USE_KOKKOSP", - "Enable support for Kokkos Tools", false, "kokkos"); + "Enable support for Kokkos Tools", false, "kokkos", + "backend"); OMNITRACE_CONFIG_SETTING(size_t, "OMNITRACE_INSTRUMENTATION_INTERVAL", "Instrumentation only takes measurements once every N " @@ -160,8 +162,9 @@ configure_settings() OMNITRACE_CONFIG_SETTING( double, "OMNITRACE_SAMPLING_DELAY", - "Number of seconds to delay activating the statistical sampling", 0.05, - "sampling"); + "Number of seconds to wait before the first sampling signal is delivered, " + "increasing this value can fix deadlocks during init", + 0.5, "sampling"); auto _backend = tim::get_env_choice( "OMNITRACE_BACKEND", @@ -173,10 +176,11 @@ configure_settings() OMNITRACE_CONFIG_SETTING(std::string, "OMNITRACE_BACKEND", "Specify the perfetto backend to activate. Options are: " "'inprocess', 'system', or 'all'", - _backend, "perfetto"); + _backend, "perfetto", "instrumentation", "sampling"); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_CRITICAL_TRACE", - "Enable generation of the critical trace", false, "feature"); + "Enable generation of the critical trace", false, "backend", + "critical-trace", "instrumentation"); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_FLAT_SAMPLING", "Ignore hierarchy in all statistical sampling entries", @@ -190,30 +194,32 @@ configure_settings() OMNITRACE_CONFIG_SETTING( bool, "OMNITRACE_ROCTRACER_FLAT_PROFILE", "Ignore hierarchy in all kernels entries with timemory backend", - _config->get_flat_profile(), "roctracer", "data_layout"); + _config->get_flat_profile(), "roctracer", "data_layout", "rocm"); OMNITRACE_CONFIG_SETTING( bool, "OMNITRACE_ROCTRACER_TIMELINE_PROFILE", "Create unique entries for every kernel with timemory backend", - _config->get_timeline_profile(), "roctracer", "data_layout"); + _config->get_timeline_profile(), "roctracer", "data_layout", "rocm"); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_ROCTRACER_HSA_ACTIVITY", - "Enable HSA activity tracing support", false, "roctracer"); + "Enable HSA activity tracing support", false, "roctracer", + "rocm"); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_ROCTRACER_HSA_API", - "Enable HSA API tracing support", false, "roctracer"); + "Enable HSA API tracing support", false, "roctracer", + "rocm"); OMNITRACE_CONFIG_SETTING(std::string, "OMNITRACE_ROCTRACER_HSA_API_TYPES", - "HSA API type to collect", "", "roctracer"); + "HSA API type to collect", "", "roctracer", "rocm"); OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_CRITICAL_TRACE_DEBUG", "Enable debugging for critical trace", _omnitrace_debug, - "debugging"); + "debugging", "critical-trace"); OMNITRACE_CONFIG_SETTING( bool, "OMNITRACE_CRITICAL_TRACE_SERIALIZE_NAMES", "Include names in serialization of critical trace (mainly for debugging)", - _omnitrace_debug, "debugging"); + _omnitrace_debug, "debugging", "critical-trace"); OMNITRACE_CONFIG_SETTING(size_t, "OMNITRACE_SHMEM_SIZE_HINT_KB", "Hint for shared-memory buffer size in perfetto (in KB)", @@ -224,26 +230,29 @@ configure_settings() "data"); OMNITRACE_CONFIG_SETTING(int64_t, "OMNITRACE_CRITICAL_TRACE_COUNT", - "Number of critical trace to export (0 == all)", 0, "data"); + "Number of critical trace to export (0 == all)", 0, "data", + "critical-trace"); OMNITRACE_CONFIG_SETTING(uint64_t, "OMNITRACE_CRITICAL_TRACE_BUFFER_COUNT", "Number of critical trace records to store in thread-local " "memory before submitting to shared buffer", - 2000, "data"); + 2000, "data", "critical-trace"); OMNITRACE_CONFIG_SETTING( uint64_t, "OMNITRACE_CRITICAL_TRACE_NUM_THREADS", "Number of threads to use when generating the critical trace", - std::min(8, std::thread::hardware_concurrency()), "parallelism"); + std::min(8, std::thread::hardware_concurrency()), "parallelism", + "critical-trace"); OMNITRACE_CONFIG_SETTING( int64_t, "OMNITRACE_CRITICAL_TRACE_PER_ROW", - "How many critical traces per row in perfetto (0 == all in one row)", 0, "io"); + "How many critical traces per row in perfetto (0 == all in one row)", 0, "io", + "critical-trace"); OMNITRACE_CONFIG_SETTING( std::string, "OMNITRACE_TIMEMORY_COMPONENTS", "List of components to collect via timemory (see timemory-avail)", "wall_clock", - "timemory", "component"); + "timemory", "component", "instrumentation"); OMNITRACE_CONFIG_SETTING(std::string, "OMNITRACE_OUTPUT_FILE", "Perfetto filename", "", "perfetto", "io"); @@ -375,7 +384,6 @@ configure_settings() kill(process::get_id(), nsig); }; signal_settings::set_exit_action(_exit_action); - tim::set_env("SIGNAL_ENABLE_INTERRUPT", "1", 0); signal_settings::check_environment(); auto default_signals = signal_settings::get_default(); for(const auto& itr : default_signals) @@ -612,7 +620,7 @@ get_is_continuous_integration() bool get_debug_init() { - return tim::get_env("OMNITRACE_DEBUG_INIT", false); + return tim::get_env("OMNITRACE_DEBUG_INIT", get_debug_env()); } bool @@ -976,6 +984,36 @@ get_cpu_cid_stack(int64_t _tid, int64_t _parent) (void) _v_copy; } +std::unique_ptr& +get_cpu_cid_parents(int64_t _tid) +{ + struct omnitrace_cpu_cid_stack + {}; + using thread_data_t = thread_data; + static auto& _v = thread_data_t::instances(thread_data_t::construct_on_init{}, + cpu_cid_parent_map_t{}); + return _v.at(_tid); +} + +std::tuple +create_cpu_cid_entry(int64_t _tid) +{ + auto&& _cid = get_cpu_cid()++; + auto&& _parent_cid = (get_cpu_cid_stack(_tid)->empty()) ? get_cpu_cid_stack(0)->back() + : get_cpu_cid_stack()->back(); + uint16_t&& _depth = (get_cpu_cid_stack(_tid)->empty()) + ? get_cpu_cid_stack(0)->size() + : get_cpu_cid_stack()->size() - 1; + get_cpu_cid_parents(_tid)->emplace(_cid, std::make_tuple(_parent_cid, _depth)); + return std::make_tuple(_cid, _parent_cid, _depth); +} + +cpu_cid_pair_t +get_cpu_cid_entry(uint64_t _cid, int64_t _tid) +{ + return get_cpu_cid_parents(_tid)->at(_cid); +} + namespace { void