Sampling use SIGRTMIN + N signals (#104)

* Use SIGRTMIN instead of SIGALRM for sampling * Config options + fully working SIGRTMIN sampling - OMNITRACE_SAMPLING_KEEP_INTERNAL config option - OMNITRACE_PROCESS_SAMPLING_FREQ config option - OMNITRACE_SAMPLING_REALTIME config option - OMNITRACE_SAMPLING_CPUTIME config option - OMNITRACE_SAMPLING_REALTIME_OFFSET config option * Fix omnitrace-avail-regex-negation test - OMNITRACE_PROCESS_SAMPLING_FREQ was causing failure [ROCm/rocprofiler-systems commit: d27f22ea37]
2022-07-22 14:17:27 -05:00
@@ -252,6 +252,7 @@ omnitrace_add_bin_test(
         -r
         _P
         ~PERFETTO
+         ~PROCESS_SAMPLING
         --csv
         --brief
    LABELS "omnitrace-avail"
@@ -28,6 +28,7 @@
 #include "library/debug.hpp"
 #include "library/perfetto.hpp"
 #include "library/ptl.hpp"
+#include "library/runtime.hpp"
 #include "library/sampling.hpp"
 #include "library/tracing.hpp"

@@ -67,6 +68,7 @@
 #include <string>
 #include <string_view>
 #include <type_traits>
+#include <vector>

 #include <pthread.h>
 #include <signal.h>
@@ -117,12 +119,21 @@ using signal_type_instances     = thread_data<std::set<int>, api::sampling>;
 using backtrace_init_instances  = thread_data<backtrace, api::sampling>;
 using sampler_running_instances = thread_data<bool, api::sampling>;
 using papi_vector_instances     = thread_data<hw_counters, api::sampling>;
+using papi_label_instances      = thread_data<std::vector<std::string>, api::sampling>;

 namespace
 {
 struct perfetto_rusage
 {};

+unique_ptr_t<std::vector<std::string>>&
+get_papi_labels(int64_t _tid)
+{
+    static auto& _v =
+        papi_label_instances::instances(papi_label_instances::construct_on_init{});
+    return _v.at(_tid);
+}
+
 unique_ptr_t<hw_counters>&
 get_papi_vector(int64_t _tid)
 {
@@ -167,6 +178,8 @@ backtrace::get() const
        if(strlen(itr) > 0) _v.emplace_back(itr);
    }
    std::reverse(_v.begin(), _v.end());
+    while(!_v.empty() && _v.back() == "funlockfile")
+        _v.pop_back();
    return _v;
 }

@@ -298,7 +311,7 @@ backtrace::sample(int signum)
    m_ctx_swch   = _cache.get_num_priority_context_switch() +
                 _cache.get_num_voluntary_context_switch();
    m_page_flt = _cache.get_num_major_page_faults() + _cache.get_num_minor_page_faults();
-    m_data     = tim::get_unw_backtrace<stack_depth, 2, false>();
+    m_data     = tim::get_unw_backtrace<stack_depth, 3, false>();
    m_size     = m_data.size();

    if constexpr(tim::trait::is_available<hw_counters>::value)
@@ -332,23 +345,32 @@ backtrace::configure(bool _setup, int64_t _tid)
        {
            perfetto_counter_track<hw_counters>::init();
            OMNITRACE_DEBUG("HW COUNTER: starting...\n");
-            if(get_papi_vector(_tid)) get_papi_vector(_tid)->start();
+            if(get_papi_vector(_tid))
+            {
+                using common_type_t = typename hw_counters::common_type;
+                get_papi_vector(_tid)->start();
+                *get_papi_labels(_tid) = comp::papi_common::get_events<common_type_t>();
+            }
        }

-        auto _alrm_freq = 1.0 / std::min<double>(get_sampling_freq(), 20.0);
-        auto _prof_freq = 1.0 / get_sampling_freq();
+        auto _alrm_freq = std::min<double>(get_sampling_freq(), 20.0);
+        auto _prof_freq = get_sampling_freq();
        auto _delay     = std::max<double>(1.0e-3, get_sampling_delay());
+        auto _verbose   = std::min<int>(get_verbose() - 2, 2);
+        if(get_debug_sampling()) _verbose = 2;

        OMNITRACE_DEBUG("Configuring sampler for thread %lu...\n", _tid);
        sampling::sampler_instances::construct("omnitrace", _tid, *_signal_types);
+
        _sampler->set_signals(*_signal_types);
        _sampler->set_flags(SA_RESTART);
-        _sampler->set_delay(_delay);
-        _sampler->set_verbose(std::min<size_t>(_sampler->get_verbose(), 2));
-        if(_signal_types->count(SIGALRM) > 0)
-            _sampler->set_frequency(_alrm_freq, { SIGALRM });
-        if(_signal_types->count(SIGPROF) > 0)
-            _sampler->set_frequency(_prof_freq, { SIGPROF });
+        _sampler->set_delay(_delay, *_signal_types, (_verbose > 1));
+        _sampler->set_verbose(_verbose);
+        if(_signal_types->count(get_realtime_signal()) > 0)
+            _sampler->set_frequency(_alrm_freq, { get_realtime_signal() },
+                                    (_verbose > 1));
+        if(_signal_types->count(get_cputime_signal()) > 0)
+            _sampler->set_frequency(_prof_freq, { get_cputime_signal() }, (_verbose > 1));

        static_assert(tim::trait::buffer_size<sampling::sampler_t>::value > 0,
                      "Error! Zero buffer size");
@@ -358,10 +380,15 @@ backtrace::configure(bool _setup, int64_t _tid)
            "dynamic sampler requires a positive buffer size: %zu",
            _sampler->get_buffer_size());

-        OMNITRACE_DEBUG("Sampler for thread %lu will be triggered %5.1fx per second "
-                        "(every %5.2e seconds)...\n",
-                        _tid, _sampler->get_frequency(units::sec),
-                        _sampler->get_rate(units::sec));
+        for(auto itr : *_signal_types)
+        {
+            const char* _type = (itr == get_realtime_signal()) ? "wall" : "CPU";
+            OMNITRACE_VERBOSE(1,
+                              "[%i] Sampler for thread %lu will be triggered %.1fx per "
+                              "second of %s-time (every %.3f milliseconds)...\n",
+                              itr, _tid, _sampler->get_frequency(units::sec, itr), _type,
+                              _sampler->get_period(units::msec, itr));
+        }

        *_running = true;
        backtrace_init_instances::construct();
@@ -454,26 +481,28 @@ backtrace::post_process(int64_t _tid)
    // check whether the call-stack entry should be used. -1 means break, 0 means continue
    auto _use_label = [](std::string_view _lbl) -> short {
        // debugging feature
-        static bool _keep_internal =
-            tim::get_env<bool>("OMNITRACE_SAMPLING_KEEP_INTERNAL", get_debug_sampling());
-        const auto _npos = std::string::npos;
+        bool       _keep_internal = get_sampling_keep_internal();
+        const auto _npos          = std::string::npos;
        if(_keep_internal) return 1;
-        if(_lbl.find("omnitrace::common::") != _npos) return -1;
-        if(_lbl.find("omnitrace_") != _npos) return -1;
-        if(_lbl.find("roctracer_") != _npos) return -1;
-        if(_lbl.find("perfetto::") != _npos) return -1;
+        if(_lbl.find("omnitrace::common::") != _npos) return 0;
        if(_lbl.find("omnitrace::") != _npos) return 0;
        if(_lbl.find("tim::") != _npos) return 0;
+        if(_lbl.find("DYNINST_") != _npos) return 0;
+        if(_lbl.find("omnitrace_") != _npos) return -1;
+        if(_lbl.find("rocprofiler_") != _npos) return -1;
+        if(_lbl.find("roctracer_") != _npos) return -1;
+        if(_lbl.find("perfetto::") != _npos) return -1;
        if(_lbl == "funlockfile") return 0;
        return 1;
    };

+    bool _keep_suffix = tim::get_env<bool>("OMNITRACE_SAMPLING_KEEP_DYNINST_SUFFIX",
+                                           get_debug_sampling());
+
    // in the dyninst binary rewrite runtime, instrumented functions are appended with
    // "_dyninst", i.e. "main" will show up as "main_dyninst" in the backtrace.
-    auto _patch_label = [](std::string_view _lbl) -> std::string {
+    auto _patch_label = [_keep_suffix](std::string_view _lbl) -> std::string {
        // debugging feature
-        static bool _keep_suffix = tim::get_env<bool>(
-            "OMNITRACE_SAMPLING_KEEP_DYNINST_SUFFIX", get_debug_sampling());
        if(_keep_suffix) return std::string{ _lbl };
        const std::string _dyninst{ "_dyninst" };
        auto              _pos = _lbl.find(_dyninst);
@@ -481,10 +510,7 @@ backtrace::post_process(int64_t _tid)
        return std::string{ _lbl }.replace(_pos, _dyninst.length(), "");
    };

-    using common_type_t = typename hw_counters::common_type;
-    auto _hw_cnt_labels = (get_papi_vector(_tid))
-                              ? comp::papi_common::get_events<common_type_t>()
-                              : std::vector<std::string>{};
+    auto _hw_cnt_labels = *get_papi_labels(_tid);

    auto _process_perfetto_counters = [&](const std::vector<sampling::bundle_t*>& _data) {
        auto _tid_name = JOIN("", '[', _tid, ']');
@@ -33,7 +33,6 @@
 #include <timemory/components/papi/types.hpp>
 #include <timemory/macros/language.hpp>
 #include <timemory/mpl/concepts.hpp>
-#include <timemory/sampling/sampler.hpp>
 #include <timemory/variadic/types.hpp>

 #include <array>
@@ -295,8 +295,8 @@ pthread_create_gotcha::operator()(pthread_t* thread, const pthread_attr_t* attr,

    // block the signals in entire process
    OMNITRACE_DEBUG("blocking signals...\n");
-    tim::sampling::block_signals({ SIGALRM, SIGPROF },
-                                 tim::sampling::sigmask_scope::process);
+    auto _blocked_signals = get_sampling_signals();
+    tim::sampling::block_signals(_blocked_signals, tim::sampling::sigmask_scope::process);

    start_bundle(_bundle);

@@ -316,7 +316,7 @@ pthread_create_gotcha::operator()(pthread_t* thread, const pthread_attr_t* attr,

    // unblock the signals in the entire process
    OMNITRACE_DEBUG("unblocking signals...\n");
-    tim::sampling::unblock_signals({ SIGALRM, SIGPROF },
+    tim::sampling::unblock_signals(_blocked_signals,
                                   tim::sampling::sigmask_scope::process);

    OMNITRACE_DEBUG("returning success...\n");
@@ -25,6 +25,7 @@
 #include "library/defines.hpp"
 #include "library/gpu.hpp"
 #include "library/perfetto.hpp"
+#include "library/runtime.hpp"

 #include <timemory/backends/dmp.hpp>
 #include <timemory/backends/mpi.hpp>
@@ -40,10 +41,12 @@
 #include <timemory/utility/declaration.hpp>
 #include <timemory/utility/signals.hpp>

+#include <algorithm>
 #include <array>
 #include <csignal>
 #include <cstdint>
 #include <cstdlib>
+#include <limits>
 #include <numeric>
 #include <ostream>
 #include <string>
@@ -291,10 +294,16 @@ configure_settings(bool _init)

    OMNITRACE_CONFIG_SETTING(
        double, "OMNITRACE_SAMPLING_DELAY",
-        "Number of seconds to wait before the first sampling signal is delivered, "
+        "Time (in seconds) to wait before the first sampling signal is delivered, "
        "increasing this value can fix deadlocks during init",
        0.5, "sampling", "process_sampling");

+    OMNITRACE_CONFIG_SETTING(
+        double, "OMNITRACE_PROCESS_SAMPLING_FREQ",
+        "Number of measurements per second when OMNITTRACE_USE_PROCESS_SAMPLING=ON. If "
+        "set to zero, uses OMNITRACE_SAMPLING_FREQ value",
+        0.0, "process_sampling");
+
    OMNITRACE_CONFIG_SETTING(
        std::string, "OMNITRACE_SAMPLING_CPUS",
        "CPUs to collect frequency information for. Values should be separated by commas "
@@ -341,6 +350,35 @@ configure_settings(bool _init)
                             "cause deadlocks with ROCm-enabled OpenMPI.",
                             false, "backend", "parallelism", "gotcha");

+    OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_SAMPLING_KEEP_INTERNAL",
+                             "If disabled, omnitrace will attempt to filter out internal "
+                             "routines from the sampling call-stacks",
+                             true, "sampling", "data");
+
+    OMNITRACE_CONFIG_SETTING(
+        bool, "OMNITRACE_SAMPLING_REALTIME",
+        "Enable sampling frequency via a wall-clock timer on child threads. This may "
+        "result in typically idle child threads consuming an unnecessary large amount of "
+        "CPU time. The main thread always has this enabled.",
+        false, "sampling");
+
+    OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_SAMPLING_CPUTIME",
+                             "Enable sampling frequency via a timer that measures both "
+                             "CPU time used by the current process, "
+                             "and CPU time expended on behalf of the process by the "
+                             "system. This is recommended.",
+                             true, "timemory", "sampling");
+
+    auto _sigrt_range = SIGRTMAX - SIGRTMIN;
+
+    OMNITRACE_CONFIG_SETTING(
+        int, "OMNITRACE_SAMPLING_REALTIME_OFFSET",
+        std::string{
+            "Modify this value only if the target process is also using SIGRTMIN. E.g. "
+            "the signal used is SIGRTMIN + <THIS_VALUE>. Value must be <= " } +
+            std::to_string(_sigrt_range),
+        0, "sampling");
+
    OMNITRACE_CONFIG_SETTING(bool, "OMNITRACE_FLAT_SAMPLING",
                             "Ignore hierarchy in all statistical sampling entries",
                             _config->get_flat_profile(), "timemory", "sampling",
@@ -443,6 +481,7 @@ configure_settings(bool _init)
    OMNITRACE_CONFIG_SETTING(std::string, "OMNITRACE_OUTPUT_FILE",
                             "[DEPRECATED] See OMNITRACE_PERFETTO_FILE", std::string{},
                             "perfetto", "io", "filename", "deprecated");
+
    OMNITRACE_CONFIG_SETTING(std::string, "OMNITRACE_PERFETTO_FILE", "Perfetto filename",
                             std::string{ "perfetto-trace.proto" }, "perfetto", "io",
                             "filename");
@@ -694,7 +733,7 @@ configure_signal_handler()
        using sys_signal      = tim::sys_signal;
        tim::disable_signal_detection();
        auto _exit_action = [](int nsig) {
-            tim::sampling::block_signals({ SIGPROF, SIGALRM },
+            tim::sampling::block_signals(get_sampling_signals(),
                                         tim::sampling::sigmask_scope::process);
            OMNITRACE_BASIC_PRINT(
                "Finalizing afer signal %i :: %s\n", nsig,
@@ -1314,6 +1353,34 @@ get_critical_trace_serialize_names()
    return static_cast<tim::tsettings<bool>&>(*_v->second).get();
 }

+bool
+get_sampling_keep_internal()
+{
+    static auto _v = get_config()->find("OMNITRACE_SAMPLING_KEEP_INTERNAL");
+    return static_cast<tim::tsettings<bool>&>(*_v->second).get();
+}
+
+bool
+get_use_sampling_realtime()
+{
+    static auto _v = get_config()->find("OMNITRACE_SAMPLING_REALTIME");
+    return static_cast<tim::tsettings<bool>&>(*_v->second).get();
+}
+
+bool
+get_use_sampling_cputime()
+{
+    static auto _v = get_config()->find("OMNITRACE_SAMPLING_CPUTIME");
+    return static_cast<tim::tsettings<bool>&>(*_v->second).get();
+}
+
+int
+get_sampling_rtoffset()
+{
+    static auto _v = get_config()->find("OMNITRACE_SAMPLING_REALTIME_OFFSET");
+    return static_cast<tim::tsettings<int>&>(*_v->second).get();
+}
+
 bool
 get_timeline_sampling()
 {
@@ -1475,7 +1542,7 @@ get_instrumentation_interval()
    return static_cast<tim::tsettings<size_t>&>(*_v->second).get();
 }

-double&
+double
 get_sampling_freq()
 {
    static auto _v = get_config()->find("OMNITRACE_SAMPLING_FREQ");
@@ -1503,11 +1570,14 @@ get_critical_trace_count()
    return static_cast<tim::tsettings<int64_t>&>(*_v->second).get();
 }

-double&
+double
 get_process_sampling_freq()
 {
-    static auto _v = std::min<double>(get_sampling_freq(), 1000.0);
-    return _v;
+    static auto _v = get_config()->find("OMNITRACE_PROCESS_SAMPLING_FREQ");
+    auto        _val =
+        std::min<double>(static_cast<tim::tsettings<double>&>(*_v->second).get(), 1000.0);
+    if(_val < 1.0e-9) return get_sampling_freq();
+    return _val;
 }

 std::string
@@ -204,6 +204,18 @@ get_use_ompt();
 bool
 get_use_code_coverage();

+bool
+get_sampling_keep_internal();
+
+bool
+get_use_sampling_realtime();
+
+bool
+get_use_sampling_cputime();
+
+int
+get_sampling_rtoffset();
+
 bool
 get_timeline_sampling();

@@ -265,7 +277,7 @@ get_critical_trace_count();
 size_t&
 get_instrumentation_interval();

-double&
+double
 get_sampling_freq();

 double&
@@ -274,7 +286,7 @@ get_sampling_delay();
 std::string
 get_sampling_cpus();

-double&
+double
 get_process_sampling_freq();

 std::string
@@ -51,6 +51,43 @@

 namespace omnitrace
 {
+int
+get_realtime_signal()
+{
+    return SIGRTMIN + config::get_sampling_rtoffset();
+}
+
+int
+get_cputime_signal()
+{
+    return SIGPROF;
+}
+
+std::set<int>
+get_sampling_signals(int64_t _tid)
+{
+    auto _sigreal = get_realtime_signal();
+    auto _sigprof = get_cputime_signal();
+
+    // on the main thread, typically use both real-time and cpu-time
+    // on secondary threads, typically use only cpu-time.
+
+    if(_tid < 1)
+    {
+        if(config::get_use_sampling_cputime()) return std::set<int>{ _sigreal, _sigprof };
+        return std::set<int>{ _sigreal };
+    }
+
+    if(config::get_use_sampling_realtime() && config::get_use_sampling_cputime())
+        return std::set<int>{ _sigreal, _sigprof };
+    else if(config::get_use_sampling_realtime())
+        return std::set<int>{ _sigreal };
+    else if(config::get_use_sampling_cputime())
+        return std::set<int>{ _sigprof };
+
+    return std::set<int>{};
+}
+
 std::atomic<uint64_t>&
 get_cpu_cid()
 {
@@ -34,6 +34,7 @@
 #include "library/timemory.hpp"

 #include <memory>
+#include <set>
 #include <timemory/backends/threading.hpp>
 #include <timemory/macros/language.hpp>

@@ -67,6 +68,15 @@ get_main_bundle();
 std::unique_ptr<gotcha_bundle_t>&
 get_gotcha_bundle();

+int
+get_realtime_signal();
+
+int
+get_cputime_signal();
+
+std::set<int>
+get_sampling_signals(int64_t _tid = 0);
+
 std::atomic<uint64_t>&
 get_cpu_cid() TIMEMORY_HOT;

@@ -25,6 +25,7 @@
 #include "library/config.hpp"
 #include "library/debug.hpp"
 #include "library/ptl.hpp"
+#include "library/runtime.hpp"

 #include <timemory/backends/papi.hpp>
 #include <timemory/backends/threading.hpp>
@@ -124,10 +125,7 @@ unique_ptr_t<std::set<int>>&
 get_signal_types(int64_t _tid)
 {
    static auto& _v = signal_type_instances::instances();
-    // on the main thread, use both SIGALRM and SIGPROF.
-    // on secondary threads, only use SIGPROF.
-    signal_type_instances::construct((_tid == 0) ? std::set<int>{ SIGALRM, SIGPROF }
-                                                 : std::set<int>{ SIGPROF });
+    signal_type_instances::construct(omnitrace::get_sampling_signals(_tid));
    return _v.at(_tid);
 }