Miscellaneous fixes (#44)

* Miscellaneous fixes

- handle HSA OnLoad called during omnitrace-avail
- disable setting HSA_ENABLE_INTERRUPT when roctracer not used
- sampler max verbose
- fix roctracer get_clock_skew
- cleanup roctracer debug output
- update timemory submodule with fence
- simplify min-instructions vs. min-address-range specification
- exclude cxx regex updates
- disable HSA_TOOLS_LIB and HSA_ENABLE_INTERRUPT when no roctracer

* git safe.directory

source/lib/omnitrace-dl/dl.cpp

@@ -129,10 +129,10 @@ struct OMNITRACE_HIDDEN_API indirect
             fprintf(stderr, "[omnitrace][dl][pid=%i] libomnitrace.so resolved to '%s'\n",
                     getpid(), m_omnilib.c_str());
         }
-        auto        _omni_hsa_lib = m_omnilib;
-        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);
+#if defined(OMNITRACE_USE_ROCTRACER) && OMNITRACE_USE_ROCTRACER > 0
+        auto _omni_hsa_lib = m_omnilib;
+        setenv("HSA_TOOLS_LIB", _omni_hsa_lib.c_str(), 0);
+#endif
         m_omnihandle = open(m_omnilib);
         m_userhandle = open(m_userlib);
         init();

source/lib/omnitrace/include/library/config.hpp

@@ -42,6 +42,9 @@ namespace omnitrace
 //
 inline namespace config
 {
+bool
+settings_are_configured();
+
 void
 configure_settings(bool _init = true);
 

source/lib/omnitrace/include/library/debug.hpp

@@ -45,6 +45,12 @@ get_debug();
 int
 get_verbose();
 
+bool
+get_debug_env();
+
+int
+get_verbose_env();
+
 bool
 get_is_continuous_integration();
 
@@ -77,14 +83,24 @@ get_chars(T&& _c, std::index_sequence<Idx...>)
 #define OMNITRACE_LINESTR                TIMEMORY_STRINGIZE(__LINE__)
 #define OMNITRACE_VARIABLE(LABEL)        OMNITRACE_VAR_NAME_COMBINE(_omni_var_, LABEL)
 
-#if defined(TIMEMORY_USE_MPI)
-#    define OMNITRACE_PROCESS_IDENTIFIER static_cast<int>(::tim::dmp::rank())
-#elif defined(TIMEMORY_USE_MPI_HEADERS)
-#    define OMNITRACE_PROCESS_IDENTIFIER                                                 \
-        (::tim::dmp::is_initialized()) ? static_cast<int>(::tim::dmp::rank())            \
-                                       : static_cast<int>(::tim::process::get_id())
-#else
-#    define OMNITRACE_PROCESS_IDENTIFIER static_cast<int>(::tim::process::get_id())
+#if !defined(OMNITRACE_DEBUG_BUFFER_LEN)
+#    define OMNITRACE_DEBUG_BUFFER_LEN 2048
+#endif
+
+#if !defined(OMNITRACE_PROCESS_IDENTIFIER)
+#    if defined(TIMEMORY_USE_MPI)
+#        define OMNITRACE_PROCESS_IDENTIFIER static_cast<int>(::tim::dmp::rank())
+#    elif defined(TIMEMORY_USE_MPI_HEADERS)
+#        define OMNITRACE_PROCESS_IDENTIFIER                                             \
+            (::tim::dmp::is_initialized()) ? static_cast<int>(::tim::dmp::rank())        \
+                                           : static_cast<int>(::tim::process::get_id())
+#    else
+#        define OMNITRACE_PROCESS_IDENTIFIER static_cast<int>(::tim::process::get_id())
+#    endif
+#endif
+
+#if !defined(OMNITRACE_THREAD_IDENTIFIER)
+#    define OMNITRACE_THREAD_IDENTIFIER ::tim::threading::get_id()
 #endif
 
 #if defined(__clang__) || (__GNUC__ < 9)
@@ -120,7 +136,7 @@ get_chars(T&& _c, std::index_sequence<Idx...>)
         fflush(stderr);                                                                  \
         tim::auto_lock_t _lk{ tim::type_mutex<decltype(std::cerr)>() };                  \
         fprintf(stderr, "[omnitrace][%i][%li] ", OMNITRACE_PROCESS_IDENTIFIER,           \
-                tim::threading::get_id());                                               \
+                OMNITRACE_THREAD_IDENTIFIER);                                            \
         fprintf(stderr, __VA_ARGS__);                                                    \
         fflush(stderr);                                                                  \
     }
@@ -143,7 +159,7 @@ get_chars(T&& _c, std::index_sequence<Idx...>)
         fflush(stderr);                                                                  \
         tim::auto_lock_t _lk{ tim::type_mutex<decltype(std::cerr)>() };                  \
         fprintf(stderr, "[omnitrace][%i][%li][%s] ", OMNITRACE_PROCESS_IDENTIFIER,       \
-                tim::threading::get_id(), OMNITRACE_FUNCTION);                           \
+                OMNITRACE_THREAD_IDENTIFIER, OMNITRACE_FUNCTION);                        \
         fprintf(stderr, __VA_ARGS__);                                                    \
         fflush(stderr);                                                                  \
     }
@@ -162,22 +178,23 @@ get_chars(T&& _c, std::index_sequence<Idx...>)
 #define OMNITRACE_CONDITIONAL_THROW(COND, ...)                                           \
     if(COND)                                                                             \
     {                                                                                    \
-        char _msg_buffer[2048];                                                          \
-        snprintf(_msg_buffer, 2048, "[omnitrace][%i][%li][%s] ",                         \
-                 OMNITRACE_PROCESS_IDENTIFIER, tim::threading::get_id(),                 \
+        char _msg_buffer[OMNITRACE_DEBUG_BUFFER_LEN];                                    \
+        snprintf(_msg_buffer, OMNITRACE_DEBUG_BUFFER_LEN, "[omnitrace][%i][%li][%s] ",   \
+                 OMNITRACE_PROCESS_IDENTIFIER, OMNITRACE_THREAD_IDENTIFIER,              \
                  OMNITRACE_FUNCTION);                                                    \
         auto len = strlen(_msg_buffer);                                                  \
-        snprintf(_msg_buffer + len, 2048 - len, __VA_ARGS__);                            \
+        snprintf(_msg_buffer + len, OMNITRACE_DEBUG_BUFFER_LEN - len, __VA_ARGS__);      \
         throw std::runtime_error(_msg_buffer);                                           \
     }
 
 #define OMNITRACE_CONDITIONAL_BASIC_THROW(COND, ...)                                     \
     if(COND)                                                                             \
     {                                                                                    \
-        char _msg_buffer[2048];                                                          \
-        snprintf(_msg_buffer, 2048, "[omnitrace][%s] ", OMNITRACE_FUNCTION);             \
+        char _msg_buffer[OMNITRACE_DEBUG_BUFFER_LEN];                                    \
+        snprintf(_msg_buffer, OMNITRACE_DEBUG_BUFFER_LEN, "[omnitrace][%s] ",            \
+                 OMNITRACE_FUNCTION);                                                    \
         auto len = strlen(_msg_buffer);                                                  \
-        snprintf(_msg_buffer + len, 2048 - len, __VA_ARGS__);                            \
+        snprintf(_msg_buffer + len, OMNITRACE_DEBUG_BUFFER_LEN - len, __VA_ARGS__);      \
         throw std::runtime_error(_msg_buffer);                                           \
     }
 
@@ -247,7 +264,8 @@ get_chars(T&& _c, std::index_sequence<Idx...>)
 
 #define OMNITRACE_BASIC_PRINT(...) OMNITRACE_CONDITIONAL_BASIC_PRINT(true, __VA_ARGS__)
 
-#define OMNITRACE_BASIC_PRINT_F(...) OMNITRACE_CONDITIONAL_BASIC_PRINT(true, __VA_ARGS__)
+#define OMNITRACE_BASIC_PRINT_F(...)                                                     \
+    OMNITRACE_CONDITIONAL_BASIC_PRINT_F(true, __VA_ARGS__)
 
 //--------------------------------------------------------------------------------------//
 //

source/lib/omnitrace/include/library/thread_data.hpp

@@ -53,6 +53,14 @@ struct thread_data
     static std::unique_ptr<Tp>& instance(construct_on_init, Args&&...);
     template <typename... Args>
     static instance_array_t& instances(construct_on_init, Args&&...);
+
+    static constexpr size_t size() { return MaxThreads; }
+
+    decltype(auto) begin() { return instances().begin(); }
+    decltype(auto) end() { return instances().end(); }
+
+    decltype(auto) begin() const { return instances().begin(); }
+    decltype(auto) end() const { return instances().end(); }
 };
 
 template <typename Tp, typename Tag, size_t MaxThreads>

source/lib/omnitrace/src/library.cpp

@@ -114,7 +114,9 @@ ensure_finalization(bool _static_init = false)
         //
         // see:
         // https://github.com/ROCm-Developer-Tools/roctracer/issues/22#issuecomment-572814465
+#if defined(OMNITRACE_USE_ROCTRACER)
         tim::set_env("HSA_ENABLE_INTERRUPT", "0", 0);
+#endif
     }
     return scope::destructor{ []() { omnitrace_finalize_hidden(); } };
 }
@@ -502,6 +504,12 @@ omnitrace_init_library_hidden()
 extern "C" bool
 omnitrace_init_tooling_hidden()
 {
+    if(!tim::get_env("OMNITRACE_INIT_TOOLING", true))
+    {
+        omnitrace_init_library_hidden();
+        return false;
+    }
+
     static bool _once       = false;
     static auto _debug_init = get_debug_init();
 

source/lib/omnitrace/src/library/components/backtrace.cpp

@@ -345,6 +345,7 @@ backtrace::configure(bool _setup, int64_t _tid)
         _sampler->set_signals(*_signal_types);
         _sampler->set_flags(SA_RESTART);
         _sampler->set_delay(_delay);
+        _sampler->set_verbose(std::min<size_t>(_sampler->get_verbose(), 1));
         _sampler->set_frequency(_prof_freq, { SIGPROF });
         _sampler->set_frequency(_alrm_freq, { SIGALRM });
 

source/lib/omnitrace/src/library/components/roctracer_callbacks.cpp

@@ -28,8 +28,10 @@
 #include "library/sampling.hpp"
 #include "library/thread_data.hpp"
 
+#include <timemory/backends/cpu.hpp>
 #include <timemory/backends/threading.hpp>
 
+#include <atomic>
 #include <chrono>
 #include <cstdint>
 
@@ -48,30 +50,60 @@ namespace api = tim::api;
 int64_t
 get_clock_skew()
 {
-    static auto _v = []() {
+    static auto _use = tim::get_env("OMNITRACE_USE_ROCTRACER_CLOCK_SKEW", true);
+    static auto _v   = []() {
+        namespace cpu = tim::cpu;
         // 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::nanoseconds>(
-                       std::chrono::steady_clock::now().time_since_epoch())
-                .count();
+        static auto _cpu_now = []() {
+            cpu::fence();
+            return comp::wall_clock::record();
         };
-        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<int64_t>(_cpu_ts) - static_cast<int64_t>(_gpu_ts);
-        OMNITRACE_BASIC_VERBOSE_F(2, "CPU/HIP timestamp skew: %li\n", _diff);
+        static auto _gpu_now = []() {
+            cpu::fence();
+            uint64_t _v = 0;
+            ROCTRACER_CALL(roctracer_get_timestamp(&_v));
+            return _v;
+        };
+
+        do
+        {
+            // warm up cache and allow for any static initialization
+            (void) _cpu_now();
+            (void) _gpu_now();
+        } while(false);
+
+        auto _compute = [](volatile uint64_t& _cpu_ts, volatile uint64_t& _gpu_ts) {
+            _cpu_ts = 0;
+            _gpu_ts = 0;
+            _cpu_ts += _cpu_now() / 2;
+            _gpu_ts += _gpu_now() / 1;
+            _cpu_ts += _cpu_now() / 2;
+            return static_cast<int64_t>(_cpu_ts) - static_cast<int64_t>(_gpu_ts);
+        };
+        constexpr int64_t _n       = 10;
+        int64_t           _cpu_ave = 0;
+        int64_t           _gpu_ave = 0;
+        int64_t           _diff    = 0;
+        for(int64_t i = 0; i < _n; ++i)
+        {
+            volatile uint64_t _cpu_ts = 0;
+            volatile uint64_t _gpu_ts = 0;
+            _diff += _compute(_cpu_ts, _gpu_ts);
+            _cpu_ave += _cpu_ts / _n;
+            _gpu_ave += _gpu_ts / _n;
+        }
+        OMNITRACE_BASIC_VERBOSE(1, "CPU timestamp: %li\n", _cpu_ave);
+        OMNITRACE_BASIC_VERBOSE(1, "HIP timestamp: %li\n", _gpu_ave);
+        OMNITRACE_BASIC_VERBOSE(0, "CPU/HIP timestamp skew: %li (used: %s)\n", _diff,
+                                _use ? "yes" : "no");
+        _diff /= _n;
         return _diff;
     }();
-    return _v;
+    return (_use) ? _v : 0;
 }
 
 std::unordered_set<uint64_t>&
@@ -141,9 +173,10 @@ hsa_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void*
 
     (void) arg;
     const hsa_api_data_t* data = reinterpret_cast<const hsa_api_data_t*>(callback_data);
-    OMNITRACE_DEBUG("<%-30s id(%u)\tcorrelation_id(%lu) %s>\n",
-                    roctracer_op_string(domain, cid, 0), cid, data->correlation_id,
-                    (data->phase == ACTIVITY_API_PHASE_ENTER) ? "on-enter" : "on-exit");
+    OMNITRACE_CONDITIONAL_PRINT_F(
+        get_debug() && get_verbose() > 1, "<%-30s id(%u)\tcorrelation_id(%lu) %s>\n",
+        roctracer_op_string(domain, cid, 0), cid, data->correlation_id,
+        (data->phase == ACTIVITY_API_PHASE_ENTER) ? "on-enter" : "on-exit");
 
     static thread_local int64_t begin_timestamp = 0;
     static auto                 _scope          = []() {
@@ -246,6 +279,8 @@ hsa_activity_callback(uint32_t op, activity_record_t* record, void* arg)
     if(get_state() != State::Active || !trait::runtime_enabled<comp::roctracer>::get())
         return;
 
+    sampling::block_signals();
+
     static const char* copy_op_name     = "hsa_async_copy";
     static const char* dispatch_op_name = "hsa_dispatch";
     static const char* barrier_op_name  = "hsa_barrier";
@@ -321,8 +356,6 @@ hip_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void*
     if(get_state() != State::Active || !trait::runtime_enabled<comp::roctracer>::get())
         return;
 
-    (void) get_clock_skew();
-
     using Device = critical_trace::Device;
     using Phase  = critical_trace::Phase;
 
@@ -347,9 +380,10 @@ hip_api_callback(uint32_t domain, uint32_t cid, const void* callback_data, void*
     }
 
     const hip_api_data_t* data = reinterpret_cast<const hip_api_data_t*>(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");
+    OMNITRACE_CONDITIONAL_PRINT_F(
+        get_debug() && get_verbose() > 1, "<%-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();
@@ -579,8 +613,8 @@ hip_activity_callback(const char* begin, const char* end, void*)
 
         {
             static size_t _n = 0;
-            OMNITRACE_VERBOSE_F(
-                2,
+            OMNITRACE_CONDITIONAL_PRINT_F(
+                get_debug() && get_verbose() > 1,
                 "%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,
@@ -604,6 +638,8 @@ hip_activity_callback(const char* begin, const char* end, void*)
                 record->correlation_id, "device", record->device_id, "queue",
                 record->queue_id, "op", _op_id_names.at(record->op));
             TRACE_EVENT_END("device", _end_ns);
+            // for some reason, this is necessary to make sure very last one ends
+            TRACE_EVENT_END("device", _end_ns);
         }
 
         auto _func = [_critical_trace, _depth, _tid, _cid, _laps, _beg_ns, _end_ns,
@@ -687,13 +723,16 @@ extern "C"
     bool OnLoad(HsaApiTable* table, uint64_t runtime_version, uint64_t failed_tool_count,
                 const char* const* failed_tool_names)
     {
+        if(!tim::get_env("OMNITRACE_INIT_TOOLING", true)) return true;
+
         pthread_gotcha::push_enable_sampling_on_child_threads(false);
         OMNITRACE_CONDITIONAL_BASIC_PRINT_F(get_debug_env() || get_verbose_env() > 0,
                                             "\n");
         tim::consume_parameters(table, runtime_version, failed_tool_count,
                                 failed_tool_names);
 
-        if(get_state() < State::Active) omnitrace_init_tooling_hidden();
+        if(!config::settings_are_configured() && get_state() < State::Active)
+            omnitrace_init_tooling_hidden();
 
         auto _setup = [=]() {
             try
@@ -775,6 +814,8 @@ extern "C"
                 roctracer_disable_op_activity(ACTIVITY_DOMAIN_HSA_OPS, HSA_OP_ID_COPY));
         };
 
+        (void) get_clock_skew();
+
         comp::roctracer::add_setup("hsa", std::move(_setup));
         comp::roctracer::add_shutdown("hsa", std::move(_shutdown));
 

source/lib/omnitrace/src/library/config.cpp

@@ -84,9 +84,30 @@ get_setting_name(std::string _v)
 
 inline namespace config
 {
+namespace
+{
+TIMEMORY_NOINLINE bool&
+_settings_are_configured()
+{
+    static bool _v = false;
+    return _v;
+}
+}  // namespace
+
+bool
+settings_are_configured()
+{
+    volatile bool _v = _settings_are_configured();
+    return _v;
+}
+
 void
 configure_settings(bool _init)
 {
+    volatile bool _v = _settings_are_configured();
+    if(_v) return;
+    _settings_are_configured() = true;
+
     static bool _once = false;
     if(_once) return;
     _once = true;