Rework sampling and colorized logs (#140)

## Overview

This is a significant PR which has 3 very notable characteristics:

1. Omnitrace colorizes most of it's logging
2. Completely reworked the sampling 
  - Samples now record the current instruction pointers instead of strings
    - This _dramatically_ decreases the overhead of taking a sample
  - The collection of metrics during a sample are split out into another component, enabling that data collection to be disabled -- which decreases the sampling overhead even further
  - When both `OMNITRACE_SAMPLING_CPUTIME` and `OMNITRACE_SAMPLING_REALTIME` are ON:
    - `OMNITRACE_SAMPLING_CPUTIME_FREQ` and `OMNITRACE_SAMPLING_REALTIME_FREQ` can be used to individually control the sampling frequency 
  - `OMNITRACE_SAMPLING_CPUTIME_DELAY` and `OMNITRACE_SAMPLING_REALTIME_DELAY` can be used to individually control the delay time before starting
  - Now, omnitrace does not start a real-time sampler on the main thread unless `OMNITRACE_SAMPLING_REALTIME` is ON
    - In the future, an `OMNITRACE_SAMPLING_TIDS` (and real-time, cpu-time variants) configuration variable(s) will allow you to select which threads will be sampled
3. Files produced by `omnitrace` exe -- `available-instr.txt`, `instrumented-instr.txt`, etc. -- now no longer has `-instr` suffix and are placed in `instrumentation/` subfolder, i.e. `available-instr.txt` -> instrumentation/available.txt`
  - This helped de-clutter the output folder

Most of the other edits were reorganization (e.g. internal namespace changes), cleanup, and splitting up functionality.

## Bug Fixes

There is a bug fix with respect to the HSA callbacks which disabled sampling on child threads when an HSA API call was made

## Details

- created thread_info struct for mapping different thread IDs
- reorganized file structure significantly
- added categories.hpp, concepts.hpp
- moved around name trait definitions
- moved all omnitrace components into `omnitrace::component` namespace
  - there was a lot of inconsistency b/t using `tim::component` in some places and `omnitrace::component`
  - added macros like OMNITRACE_DECLARE_COMPONENT in lieu of TIMEMORY_DECLARE_COMPONENT
- OMNITRACE_CRITICAL_TRACE_NUM_THREADS -> OMNITRACE_THREAD_POOL_SIZE
- roctracer and critical_trace use same thread pool
- critical_trace functions do not lock anymore bc of thread-local TaskGroup
- added `component::local_category_region` to support using `component::category_region` without explicitly passing in name
- removed `component::omnitrace` (unused)
- migrated KokkosP and OMPT to use `component::local_category_region`
  - removed `component::user_region` as a result
- migrated omnitrace_{push,pop}_{trace,region}_hidden to use component::category_region
  - removed `component::functors` as a result
- migrated some ppdefs
- `api::omnitrace` -> `project::omnitrace`
- `api::(...)` -> `category::(...)`
- improved recording the execution time of threads
  - migrated this functionality out of pthread_create_gotcha and into thread_info
- moved mpi_gotcha, fork_gotcha, exit_gotcha, rcclp into omnitrace::component namespace
- split backtrace up into backtrace, backtrace_metrics, backtrace_timestamp components
- sampling.cpp handles setup and post-processing that was formerly in backtrace
- updated logging to use colors
- `OMNITRACE_COLORIZED_LOG` config variable
- updated docs on JSON output from timemory
- instrumentation info in instrumentation subfolder
- added testing for KokkosP entries
- added testing for ompt entries
- add_critical_trace function defined in critical_trace.hpp
- disable push_thread_state and pop_thread_state when thread state is Disabled or Completed
- add comp::page_rss to main bundle
- thread_data supports std::optional instead of std::unique_ptr
- thread_data supports tim::identity<T> to avoid unique_ptr or optional
- tracing::record_thread_start_time()
- tracing::push_timemory and tracing::pop_timemory are templated on CategoryT
- removed anonymous namespace from omnitrace::utility
- sampling backtrace stores instruction pointers instead of strings
- component::category_region updates
  - handle disabled thread state
  - handle finalized state
  - fewer debug messages
  - invoke thread_init()
  - invoke thread_init_sampling()
  - handle push/pop count based on category
  - push/pop count only modified when used
- component::cpu_freq
- components/ensure_storage.hpp
- reworked the pthread_create replacement function
- updated parallel-overhead example to report # of times locked
- OMNITRACE_MAX_UNWIND_DEPTH build option
- update timemory submodule
This commit is contained in:
Jonathan R. Madsen
2022-08-31 01:24:31 -05:00
committed by GitHub
parent a1dcd1bc4b
commit 808ea7dfa7
113 changed files with 4284 additions and 2880 deletions
@@ -547,7 +547,6 @@ void
add_hash_id(const hash_ids& _labels)
{
OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
std::unique_lock<std::mutex> _lk{ tasking::critical_trace::get_mutex() };
if(!tasking::critical_trace::get_task_group().pool()) return;
tasking::critical_trace::get_task_group().exec([_labels]() {
static std::mutex _mtx{};
@@ -578,7 +577,6 @@ update(int64_t _tid)
{
if(!get_use_critical_trace() && !get_use_rocm_smi()) return;
OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
std::unique_lock<std::mutex> _lk{ tasking::critical_trace::get_mutex() };
if(!tasking::critical_trace::get_task_group().pool()) return;
call_chain _data{};
std::swap(_data, *critical_trace::get(_tid));
@@ -590,7 +588,6 @@ compute(int64_t _tid)
{
update(_tid);
OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
std::unique_lock<std::mutex> _lk{ tasking::critical_trace::get_mutex() };
if(!tasking::critical_trace::get_task_group().pool()) return;
tasking::critical_trace::get_task_group().exec(compute_critical_trace);
}
@@ -808,13 +805,13 @@ compute_critical_trace()
using perfstats_t =
tim::lightweight_tuple<comp::wall_clock, comp::peak_rss, comp::page_rss>;
perfstats_t _ct_perf{ JOIN("", "[", __FUNCTION__, "]") };
perfstats_t _ct_perf{};
_ct_perf.start();
try
{
OMNITRACE_CT_DEBUG("[%s] initial call chain: %zu entries\n", __FUNCTION__,
complete_call_chain.size());
OMNITRACE_VERBOSE_F(1, "[%s] initial call chain: %zu entries\n", __FUNCTION__,
complete_call_chain.size());
perfstats_t _perf{ get_perf_name(__FUNCTION__) };
_perf.start();
@@ -822,7 +819,7 @@ compute_critical_trace()
std::sort(complete_call_chain.begin(), complete_call_chain.end());
_perf.stop().rekey("Sorting critical trace");
OMNITRACE_CT_DEBUG("%s\n", JOIN("", _perf).c_str());
OMNITRACE_VERBOSE_F(1, "%s\n", JOIN("", _perf).c_str());
_perf.reset().start();
save_call_chain_json(
@@ -830,20 +827,16 @@ compute_critical_trace()
complete_call_chain, true, __FUNCTION__);
_perf.stop().rekey("Save call-chain");
OMNITRACE_CT_DEBUG("%s\n", JOIN("", _perf).c_str());
OMNITRACE_VERBOSE_F(1, "%s\n", JOIN("", _perf).c_str());
} catch(std::exception& e)
{
OMNITRACE_PRINT("Thread exited '%s' with exception: %s\n", __FUNCTION__,
e.what());
OMNITRACE_PRINT_F("Thread exited '%s' with exception: %s\n", __FUNCTION__,
e.what());
TIMEMORY_CONDITIONAL_DEMANGLED_BACKTRACE(true, 32);
}
_ct_perf.stop();
auto _ct_msg = JOIN("", _ct_perf);
auto _ct_pos = _ct_msg.find(">>> ");
if(_ct_pos != std::string::npos) _ct_msg = _ct_msg.substr(_ct_pos + 5);
OMNITRACE_PRINT("%s\n", _ct_msg.c_str());
OMNITRACE_PRINT_F("%s\n", _ct_perf.stop().as_string<false, false>().c_str());
}
} // namespace
@@ -869,8 +862,7 @@ get_entries(int64_t _ts, const std::function<bool(const entry&)>& _eval)
*_targ = _v;
};
OMNITRACE_SCOPED_THREAD_STATE(ThreadState::Internal);
std::unique_lock<std::mutex> _lk{ tasking::critical_trace::get_mutex() };
size_t _n = 0;
size_t _n = 0;
std::vector<std::pair<std::string, entry>> _v{};
if(!tasking::critical_trace::get_task_group().pool()) return _v;
tasking::critical_trace::get_task_group().exec(_func, &_v, &_n);