Skip to content

Commit

Permalink
Minor gtrace timestamp changes
Browse files Browse the repository at this point in the history
PErfetto seems to have changed how it interprets flow event time stamps.
This was detected by testing with the new support for the Iris tasking
runtime.
For that reason, we now add 0.250 us to the start of the flow event
and subtract 0.250 us from the end of the flow event.
the timestamps are adjusted to meet their definition of "enclosing
slice" and "begin >= timestamp of the flow".

Here is what the documentation says:

```
Each flow event phase has a specific type of binding point:
* Flow start (ph='s'): binding point is always "enclosing slice"
* Flow step (ph='t'): binding point is "enclosing slice" (not used by APEX)
* Flow end (ph='f'): binding point is "next slice". If the event contains
bp="e" then the binding point is "enclosing slice."
A bit of detail on "next slice" binding rules: Next slice is defined as the next slice to begin >= the timestamp of the flow. In the case of multiple slices having the same timestamp as the flow event, the earliest event in the trace buffer is chosen.
```

this commit also includes a change to optionally include timers around
the lifetime of the pthread. it's not really necessary so off by default.
  • Loading branch information
khuck committed May 22, 2024
1 parent dbcf633 commit 9bad01e
Show file tree
Hide file tree
Showing 3 changed files with 25 additions and 13 deletions.
21 changes: 11 additions & 10 deletions src/apex/trace_event_listener.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -185,14 +185,15 @@ uint64_t get_flow_id() {
}

void write_flow_event(std::stringstream& ss, double ts, char ph,
std::string cat, uint64_t id, uint64_t pid, uint64_t tid, std::string name) {
std::string cat, uint64_t id, uint64_t pid, uint64_t tid, std::string parent_name,
std::string child_name) {
ss << "{\"ts\":" << ts
<< ",\"ph\":\"" << ph
<< "\",\"cat\":\"" << cat
<< "\",\"id\":" << id
<< ",\"pid\":" << pid
<< ",\"tid\":" << tid
<< ",\"name\":\"" << name << "\"},\n";
<< ",\"name\":\"" << parent_name << " -> " << child_name << "\"},\n";
}

inline void trace_event_listener::_common_stop(std::shared_ptr<profiler> &p) {
Expand All @@ -218,10 +219,10 @@ inline void trace_event_listener::_common_stop(std::shared_ptr<profiler> &p) {
) {
//std::cout << "FLOWING!" << std::endl;
uint64_t flow_id = reversed_node_id + get_flow_id();
write_flow_event(ss, p->tt_ptr->parent->get_flow_us()+0.250, 's', "ControlFlow", flow_id,
saved_node_id, p->tt_ptr->parent->thread_id, p->tt_ptr->parent->task_id->get_name());
write_flow_event(ss, p->get_start_us(), 'f', "ControlFlow", flow_id,
saved_node_id, _tid, p->tt_ptr->parent->task_id->get_name());
write_flow_event(ss, p->tt_ptr->parent->get_flow_us()+0.25, 's', "ControlFlow", flow_id,
saved_node_id, p->tt_ptr->parent->thread_id, p->tt_ptr->parent->task_id->get_name(), p->get_task_id()->get_name());
write_flow_event(ss, p->get_start_us()-0.25, 'f', "ControlFlow", flow_id,
saved_node_id, _tid, p->tt_ptr->parent->task_id->get_name(), p->get_task_id()->get_name());
}
if (p->tt_ptr->explicit_trace_start) {
ss << "{\"name\":\"" << p->get_task_id()->get_name()
Expand Down Expand Up @@ -378,13 +379,13 @@ void trace_event_listener::on_async_event(base_thread_node &node,
if (data.reverse_flow) {
double begin_ts = (p->get_stop_us() + p->get_start_us()) * 0.5;
double end_ts = std::min(p->get_stop_us(), data.parent_ts_stop);
write_flow_event(ss, begin_ts, 's', data.cat, flow_id, saved_node_id, atol(tid.c_str()), data.name);
write_flow_event(ss, end_ts, 't', data.cat, flow_id, saved_node_id, data.parent_tid, data.name);
write_flow_event(ss, begin_ts, 's', data.cat, flow_id, saved_node_id, atol(tid.c_str()), data.name, p->get_task_id()->get_name());
write_flow_event(ss, end_ts, 't', data.cat, flow_id, saved_node_id, data.parent_tid, data.name, p->get_task_id()->get_name());
} else {
double begin_ts = std::min(p->get_start_us(), ((data.parent_ts_stop + data.parent_ts_start) * 0.5));
double end_ts = p->get_start_us();
write_flow_event(ss, begin_ts, 's', data.cat, flow_id, saved_node_id, data.parent_tid, data.name);
write_flow_event(ss, end_ts, 't', data.cat, flow_id, saved_node_id, atol(tid.c_str()), data.name);
write_flow_event(ss, begin_ts, 's', data.cat, flow_id, saved_node_id, data.parent_tid, data.name, p->get_task_id()->get_name());
write_flow_event(ss, end_ts, 't', data.cat, flow_id, saved_node_id, atol(tid.c_str()), data.name, p->get_task_id()->get_name());
}
}
write_to_trace(ss);
Expand Down
7 changes: 6 additions & 1 deletion src/scripts/apex_exec
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,8 @@ where APEX options are zero or more of:
--apex:kokkos-tuning enable Kokkos runtime autotuning support
--apex:kokkos-fence enable Kokkos fences for async kernels
--apex:raja enable RAJA support
--apex:pthread enable pthread wrapper support
--apex:pthread enable pthread wrapper support (default: off)
--apex:track-pthread track pthread lifetime (forces --apex:pthread on)
--apex:gpu-memory enable GPU memory wrapper support
--apex:cpu-memory enable CPU memory wrapper support
--apex:delay-memory delay memory wrapper support until explicitly enabled
Expand Down Expand Up @@ -187,6 +188,10 @@ while (( "$#" )); do
shift
;;
--apex:pthread)
pthread=yes
shift
;;
--apex:track-pthread)
pthread=yes
export APEX_TIME_TOP_LEVEL_OS_THREADS=1
shift
Expand Down
10 changes: 8 additions & 2 deletions src/wrappers/pthread_wrapper_internal.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -106,8 +106,14 @@ class apex_wrapper {
apex_wrapper(start_routine_p func, std::shared_ptr<apex::task_wrapper> parent) :
_wrapped(false), _twp(nullptr), _timing(false) {
apex::register_thread("APEX pthread wrapper", parent);
//_twp = apex::new_task((apex_function_address)func, UINTMAX_MAX, parent);
_twp = apex::new_task((apex_function_address)func);
// if we are tracking thread lifetimes, the top level timer for the thread
// will have the flow event/parent of the pthread_create call, from the
// register_thread timer, above.
if (apex::apex_options::top_level_os_threads()) {
_twp = apex::new_task((apex_function_address)func);
} else {
_twp = apex::new_task((apex_function_address)func, UINTMAX_MAX, parent);
}
_twp->explicit_trace_start = true;
}
~apex_wrapper() {
Expand Down

0 comments on commit 9bad01e

Please sign in to comment.