Various optimizations (#192)

* CDash name prefix {{ repo_owner }}-{{ ref_name }} - remove /merge from CI name * disable using BFD when sampling_include_inlines is OFF - this consumes a lot of memory * Improve finalization of rocprofiler * update timemory submodule - disable OMPT thread begin/end callbacks - support hierarchies in signal handlers - update operation::pop_node debugging - settings_update_type + setting_supported_data_types - fixed parsing args in timemory_init * Improve timemory build time * Remove kokkosp restrictions for perfetto * omnitrace exe signal handler update - configure signal handlers before main to allow libomnitrace to override * Backtrace and timemory submodule updates - Use unwind::cache w/o inline info - update timemory submodule - unwind::cache updates - filepath updates - fix termination_signal_message - fix vsettings::report_change * Update dyninst submodule - updates BinaryEdit::getResolvedLibraryPath * update timemory submodule - update CpuArch support * Cleanup configure warnings * Update examples cmake and workflows - (Mostly) eliminate configuration warnings * omnitrace exe updates - pass environ to BPatch::processCreate - avoid trailing ":" in DYNINST_REWRITER_PATHS * Update dyninst submodule - Add flags to DyninstOptimization.cmake - Remove strtok from BinaryEdit::getResolvedLibraryPath * examples/mpi CMakeLists.txt update - STATUS message about missing MPI during CI, otherwise AUTHOR_WARNING * Dev build and linker flags - use -gsplit-dwarf when OMNITRACE_BUILD_DEVELOPER is ON - disable when OMNITRACE_BUILD_NUMBER > 1 - OMNITRACE_BUILD_LINKER option - add -fuse-ld=${OMNITRACE_BUILD_LINKER} - omnitrace_add_cache_option function * Update workflows to set OMNITRACE_BUILD_NUMBER * Fix generator expressions for -fuse-ld * Suppress some configuration warnings during CI - helps to keep track of real warnings when they arise * Update timemory and dyninst submodules with CMP0135 * Add -V flag to run-ci script [ROCm/rocprofiler-systems commit: f147670a7a]
2022-11-01 17:28:12 -05:00
parent 7b9a527b7e
commit 5a1cec92e8
26 changed files with 346 additions and 137 deletions
@@ -130,6 +130,12 @@ std::unique_ptr<std::ofstream> log_ofs = {};

 namespace
 {
+namespace process = tim::process;
+namespace signals = tim::signals;
+
+using signal_settings = tim::signals::signal_settings;
+using sys_signal      = tim::signals::sys_signal;
+
 bool                                       binary_rewrite       = false;
 bool                                       is_attached          = false;
 bool                                       use_mpi              = false;
@@ -188,9 +194,60 @@ get_cwd();

 void
 find_dyn_api_rt();
-}  // namespace

-namespace process = tim::process;
+void
+activate_signal_handlers(const std::vector<sys_signal>& _signals)
+{
+    for(const auto& itr : _signals)
+        signal_settings::enable(itr);
+
+    static bool _protect     = false;
+    auto        _exit_action = [](int nsig) {
+        if(_protect) return;
+        _protect = true;
+        TIMEMORY_PRINTF_FATAL(
+            stderr, "omnitrace exited with signal %i :: %s\n", nsig,
+            signal_settings::str(static_cast<sys_signal>(nsig)).c_str());
+
+        // print the last log entries
+        print_log_entries(std::cerr, num_log_entries);
+
+        // print any forced entries
+        print_log_entries(
+            std::cerr, -1, [](const auto& _v) { return _v.forced(); },
+            []() {
+                tim::log::stream(std::cerr, tim::log::color::info())
+                    << "\n[omnitrace][exe] Potentially important log entries:\n\n";
+            });
+
+        TIMEMORY_PRINTF_FATAL(stderr, "\n");
+        TIMEMORY_PRINTF_FATAL(
+            stderr,
+            "These were the last %i log entries from omnitrace. You can control the "
+            "number of log entries via the '--log <N>' option or OMNITRACE_LOG_COUNT "
+            "env variable.\n",
+            num_log_entries);
+
+        if(log_ofs) log_ofs->close();
+        log_ofs.reset();
+
+        _protect = false;
+    };
+
+    signal_settings::set_exit_action(_exit_action);
+    signal_settings::check_environment();
+    signals::enable_signal_detection(signal_settings::get_enabled());
+}
+
+// default signals to catch
+auto _activate =
+    (activate_signal_handlers({ sys_signal::Interrupt, sys_signal::FPE, sys_signal::Stop,
+                                sys_signal::Quit, sys_signal::Illegal, sys_signal::Abort,
+                                sys_signal::Bus, sys_signal::SegFault,
+                                sys_signal::FileSize, sys_signal::CPUtime }),
+     true);
+
+}  // namespace

 //======================================================================================//
 //
@@ -201,56 +258,6 @@ namespace process = tim::process;
 int
 main(int argc, char** argv)
 {
-    {
-        using signal_settings = tim::signals::signal_settings;
-        using sys_signal      = tim::signals::sys_signal;
-
-        // default signals to catch
-        for(const auto& itr :
-            { sys_signal::Interrupt, sys_signal::FPE, sys_signal::Stop, sys_signal::Quit,
-              sys_signal::Illegal, sys_signal::Abort, sys_signal::Bus,
-              sys_signal::SegFault, sys_signal::FileSize, sys_signal::CPUtime })
-            signal_settings::enable(itr);
-
-        static bool _protect     = false;
-        auto        _exit_action = [](int nsig) {
-            if(_protect) return;
-            _protect = true;
-            TIMEMORY_PRINTF_FATAL(
-                stderr, "omnitrace exited with signal %i :: %s\n", nsig,
-                signal_settings::str(static_cast<sys_signal>(nsig)).c_str());
-
-            // print the last log entries
-            print_log_entries(std::cerr, num_log_entries);
-
-            // print any forced entries
-            print_log_entries(
-                std::cerr, -1, [](const auto& _v) { return _v.forced(); },
-                []() {
-                    tim::log::stream(std::cerr, tim::log::color::info())
-                        << "\n[omnitrace][exe] Potentially important log entries:\n\n";
-                });
-
-            TIMEMORY_PRINTF_FATAL(stderr, "\n");
-            TIMEMORY_PRINTF_FATAL(
-                stderr,
-                "These were the last %i log entries from omnitrace. You can control the "
-                "number of log entries via the '--log <N>' option or OMNITRACE_LOG_COUNT "
-                "env variable.\n",
-                num_log_entries);
-
-            if(log_ofs) log_ofs->close();
-            log_ofs.reset();
-
-            kill(process::get_id(), nsig);
-            _protect = false;
-        };
-
-        signal_settings::set_exit_action(_exit_action);
-        signal_settings::check_environment();
-        tim::signals::enable_signal_detection(signal_settings::get_enabled());
-    }
-
    argv0 = argv[0];

    OMNITRACE_ADD_LOG_ENTRY(argv[0]);
@@ -263,7 +270,7 @@ main(int argc, char** argv)
    std::vector<string_t> libname       = {};
    std::vector<string_t> sharedlibname = {};
    std::vector<string_t> staticlibname = {};
-    tim::process::id_t    _pid          = -1;
+    process::id_t         _pid          = -1;

    fixed_module_functions = {
        { &available_module_functions, false },
@@ -881,8 +888,7 @@ main(int argc, char** argv)
            auto _settings = tim::settings::push<omnitrace_env_config_s>();
            for(auto&& iitr : *_settings)
            {
-                iitr.second->set_config_updated(false);
-                iitr.second->set_environ_updated(false);
+                if(iitr.second->get_updated()) iitr.second->set_user_updated();
            }
            _settings->read(itr);
            for(auto&& iitr : *_settings)
@@ -2554,9 +2560,12 @@ find_dyn_api_rt()
                (_file_exists(tim::get_env<string_t>("DYNINSTAPI_RT_LIB", ""))) ? 0 : 1;
            tim::set_env<string_t>("DYNINSTAPI_RT_LIB", _fname, _overwrite);
            _fname = tim::get_env<string_t>("DYNINSTAPI_RT_LIB", _fname);
-            tim::set_env<string_t>("DYNINST_REWRITER_PATHS",
-                                   TIMEMORY_JOIN(':', dirname(_fname), _rewriter_paths),
-                                   1);
+            tim::set_env<string_t>(
+                "DYNINST_REWRITER_PATHS",
+                _rewriter_paths.empty()
+                    ? dirname(_fname)
+                    : TIMEMORY_JOIN(':', dirname(_fname), _rewriter_paths),
+                1);
        };

        auto _resolved = [&](std::string _fname) {
@@ -32,6 +32,7 @@

 #include <string>
 #include <sys/stat.h>
+#include <unistd.h>

 //======================================================================================//

@@ -229,9 +230,11 @@ omnitrace_get_address_space(patch_pointer_t& _bpatch, int _cmdc, char** _cmdv,
        auto _cmd_msg = ss.str();
        if(_cmd_msg.length() > 1) _cmd_msg = _cmd_msg.substr(1);

+        char** _environ = environ;
        verbprintf(1, "Creating process '%s'... ", _cmd_msg.c_str());
        fflush(stderr);
-        mutatee = _bpatch->processCreate(_cmdv[0], (const char**) _cmdv, nullptr);
+        mutatee = _bpatch->processCreate(_cmdv[0], (const char**) _cmdv,
+                                         (const char**) _environ);
        if(!mutatee)
        {
            verbprintf(-1, "Failed to create process: '%s'\n", _cmd_msg.c_str());
@@ -80,9 +80,9 @@ backtrace::get() const
    if(size() == 0) return _v;

    {
-        static auto _cache = cache_type{};
+        static auto _cache = cache_type{ get_sampling_include_inlines() };
        auto_lock_t _lk{ type_mutex<backtrace>() };
-        _v = m_data.get(&_cache, true);
+        _v = m_data.get(&_cache, false);
    }

    // put the bottom of the call-stack on top
@@ -144,6 +144,7 @@ backtrace::filter_and_patch(const std::vector<entry_type>& _data)
    };

    auto _ret = std::vector<entry_type>{};
+    _ret.reserve(_data.size());
    for(const auto& itr : _data)
    {
        auto _name = tim::demangle(_patch_label(itr.name));
@@ -183,7 +184,7 @@ backtrace::sample(int)
 {
    using namespace tim::backtrace;
    constexpr bool   with_signal_frame = false;
-    constexpr size_t ignore_depth      = 3;
+    constexpr size_t ignore_depth      = 4;
    // ignore depth based on:
    // 1. this frame
    // 2. tim::sampling::sampler<...>::sample(...) [always inline]
@@ -321,7 +321,6 @@ extern "C"

    void kokkosp_push_profile_region(const char* name)
    {
-        if(omnitrace::get_use_perfetto()) return;  // perfetto doesn't support regions
        OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
        kokkosp::logger_t{}.mark(1, __FUNCTION__, name);
        kokkosp::get_profiler_stack<kokkosp_region>().push_back(
@@ -331,7 +330,6 @@ extern "C"

    void kokkosp_pop_profile_region()
    {
-        if(omnitrace::get_use_perfetto()) return;  // perfetto doesn't support regions
        OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
        kokkosp::logger_t{}.mark(-1, __FUNCTION__);
        if(kokkosp::get_profiler_stack<kokkosp_region>().empty()) return;
@@ -343,7 +341,6 @@ extern "C"

    void kokkosp_create_profile_section(const char* name, uint32_t* secid)
    {
-        if(omnitrace::get_use_perfetto()) return;  // perfetto doesn't support regions
        OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
        *secid     = kokkosp::get_unique_id();
        auto pname = TIMEMORY_JOIN(" ", "[kokkos]", name);
@@ -352,7 +349,6 @@ extern "C"

    void kokkosp_destroy_profile_section(uint32_t secid)
    {
-        if(omnitrace::get_use_perfetto()) return;  // perfetto doesn't support regions
        OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
        kokkosp::destroy_profiler<kokkosp_region>(secid);
    }
@@ -361,7 +357,6 @@ extern "C"

    void kokkosp_start_profile_section(uint32_t secid)
    {
-        if(omnitrace::get_use_perfetto()) return;  // perfetto doesn't support regions
        OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
        kokkosp::logger_t{}.mark(1, __FUNCTION__, secid);
        kokkosp::start_profiler<kokkosp_region>(secid);
@@ -369,7 +364,6 @@ extern "C"

    void kokkosp_stop_profile_section(uint32_t secid)
    {
-        if(omnitrace::get_use_perfetto()) return;  // perfetto doesn't support regions
        OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
        kokkosp::logger_t{}.mark(-1, __FUNCTION__, secid);
        kokkosp::start_profiler<kokkosp_region>(secid);
@@ -513,6 +513,7 @@ post_process_perfetto()
        for(const auto& itr : _inp)
        {
            if(_ts >= itr->entry && _ts <= itr->exit) _v.emplace_back(itr);
+            if(_ts > itr->exit) break;
        }
        return _v;
    };
@@ -551,11 +552,14 @@ post_process_perfetto()

    for(auto& ditr : _device_range)
    {
-        auto _dev_id = ditr.first;
-        auto _values = std::vector<rocm_feature_value>{};
+        auto _dev_id         = ditr.first;
+        auto _values         = std::vector<rocm_feature_value>{};
+        auto _ts_sorted_data = _device_data[_dev_id];
+        std::sort(_ts_sorted_data.begin(), _ts_sorted_data.end(),
+                  [](auto* _l, auto* _r) { return _l->exit < _r->exit; });
        for(const auto& itr : ditr.second)
        {
-            auto     _v  = _get_events(_device_data[_dev_id], itr);
+            auto     _v  = _get_events(_ts_sorted_data, itr);
            uint64_t _ts = itr;
            for(auto* vitr : _v)
            {
@@ -629,6 +633,13 @@ post_process_timemory()
        _device_data[itr.device_id].emplace_back(&itr);
    }

+    for(auto& itr : _device_data)
+    {
+        // sort according to when it exited
+        std::sort(itr.second.begin(), itr.second.end(),
+                  [](auto* _lhs, auto* _rhs) { return _lhs->exit < _rhs->exit; });
+    }
+
    using storage_type = typename rocm_data_tracker::storage_type;
    using bundle_type  = tim::lightweight_tuple<rocm_data_tracker>;

@@ -646,8 +657,8 @@ post_process_timemory()

    struct local_event
    {
-        rocm_event*              parent   = nullptr;
-        std::vector<local_event> children = {};
+        rocm_event*                      parent   = nullptr;
+        mutable std::vector<local_event> children = {};

        TIMEMORY_DEFAULT_OBJECT(local_event)

@@ -657,17 +668,11 @@ post_process_timemory()

        bool operator()(rocm_event* _v)
        {
-            OMNITRACE_CI_THROW(!parent, "Error! '%s' has nullptr", __PRETTY_FUNCTION__);
-
+            if(!parent) return false;
            if(_v->device_id != parent->device_id) return false;
            if(_v->entry > parent->entry && _v->exit <= parent->exit)
            {
-                for(auto& itr : children)
-                {
-                    if(itr(_v)) return true;
-                }
                children.emplace_back(_v);
-                std::sort(children.begin(), children.end());
                return true;
            }
            return false;
@@ -675,22 +680,20 @@ post_process_timemory()

        bool operator<(const local_event& _v) const
        {
-            OMNITRACE_CI_THROW(!parent, "Error! '%s' has nullptr", __PRETTY_FUNCTION__);
-            OMNITRACE_CI_THROW(!_v.parent, "Error! '%s' passed nullptr",
-                               __PRETTY_FUNCTION__);
-
+            if(!parent && _v.parent) return true;
+            if(parent && !_v.parent) return false;
            return *parent < *_v.parent;
        }

        void operator()(int64_t _index, scope::config _scope) const
        {
-            OMNITRACE_CI_THROW(!parent, "Error! '%s' has nullptr", __PRETTY_FUNCTION__);
-
+            if(!parent) return;
            bundle_type _bundle{ parent->name, _scope };
            _bundle.push(parent->queue_id)
                .start()
                .store(parent->feature_values.at(_index));

+            std::sort(children.begin(), children.end());
            for(const auto& itr : children)
                itr(_index, _scope);

@@ -737,6 +740,8 @@ post_process_timemory()

    for(auto& ditr : _device_data)
    {
+        OMNITRACE_VERBOSE_F(1, "Post-processing %zu entries for device %u...\n",
+                            ditr.second.size(), ditr.first);
        auto _storage = std::vector<local_storage>{};
        for(auto& itr : ditr.second)
        {
@@ -752,22 +757,38 @@ post_process_timemory()
        }

        auto& _local = _local_data[ditr.first];
+        _local.reserve(ditr.second.size());
+        double _avg = 0.0;
        for(auto& itr : ditr.second)
        {
-            for(auto& litr : _local)
+            if(_local.empty() || itr->entry >= _local.back().parent->exit)
            {
-                if(litr(itr))
-                {
-                    goto _bypass_insert;
-                }
+                _local.emplace_back(itr);
+            }
+            else
+            {
+                size_t _n     = 0;
+                bool   _found = false;
+                for(auto litr = _local.rbegin(); litr != _local.rend(); ++litr)
+                {
+                    ++_n;
+                    if((*litr)(itr))
+                    {
+                        _found = true;
+                        break;
+                    }
+                }
+                if(!_found) _local.emplace_back(itr);
+                _avg += _n;
            }
-            _local.emplace_back(itr);
-        _bypass_insert:;
        }

+        OMNITRACE_VERBOSE_F(3, "Average # of iterations before match: %.1f\n",
+                            _avg / ditr.second.size() * 100.0);
+
        for(auto& sitr : _storage)
        {
-            for(auto& itr : _local_data[ditr.first])
+            for(auto& itr : _local)
                sitr(itr, _scope);
        }