Skip to content

[PROF-9088] Consider timestamps in comm and fork events #366

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
r1viollet wants to merge 3 commits into
base: main
Choose a base branch
from
+56 −16
Draft

[PROF-9088] Consider timestamps in comm and fork events #366

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
cf03668
Consider timestamps in comm and fork events
r1viollet Jan 23, 2024
b3ee9ad
Consider timestamps in fork and comm events
r1viollet Jan 24, 2024
a521115
Unwind free - Minor API change
r1viollet Jan 26, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions include/dso_hdr.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,6 +118,7 @@ class DsoHdr {
bool maybe_insert_erase_overlap(Dso &&dso, PerfClock::time_point timestamp);

// Clear all dsos and regions associated with this pid
bool pid_free(int pid, PerfClock::time_point timestamp);
void pid_free(int pid);

// Duplicate mapping info from parent_pid into pid
Expand Down
4 changes: 3 additions & 1 deletion include/unwind.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
#pragma once

#include "ddres_def.hpp"
#include "perf_clock.hpp"

#include <sys/types.h>

Expand All @@ -27,6 +28,7 @@ DDRes unwindstate_unwind(UnwindState *us);
void unwind_cycle(UnwindState *us);

// Clear unwinding structures of this pid
void unwind_pid_free(UnwindState *us, pid_t pid);
void unwind_pid_free(UnwindState *us, pid_t pid,
PerfClock::time_point timestamp);

} // namespace ddprof
35 changes: 22 additions & 13 deletions src/ddprof_worker.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -47,7 +47,8 @@ const DDPROF_STATS s_cycled_stats[] = {
const long k_clock_ticks_per_sec = sysconf(_SC_CLK_TCK);

/// Remove all structures related to
DDRes worker_pid_free(DDProfContext &ctx, pid_t el);
DDRes worker_pid_free(DDProfContext &ctx, pid_t el,
PerfClock::time_point timestamp);

DDRes clear_unvisited_pids(DDProfContext &ctx);

Expand Down Expand Up @@ -231,7 +232,7 @@ DDRes ddprof_unwind_sample(DDProfContext &ctx, perf_event_sample *sample,
if (us->_dwfl_wrapper && us->_dwfl_wrapper->_inconsistent) {
// Loaded modules were inconsistent, assume we should flush everything.
LG_WRN("(Inconsistent DWFL/DSOs)%d - Free associated objects", us->pid);
DDRES_CHECK_FWD(worker_pid_free(ctx, us->pid));
Copy link
Collaborator

@nsavoire nsavoire Jan 26, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It weird to have to call PerfClock::now() here, perhaps having two versions of worker_pid_free (with and without timestamp) or having PerfClock::time_point::max() as default value for timestamp in worker_pid_free would be more natural.

DDRES_CHECK_FWD(worker_pid_free(ctx, us->pid, PerfClock::now()));
}
return res;
}
Expand Down Expand Up @@ -303,19 +304,21 @@ DDRes aggregate_live_allocations(DDProfContext &ctx) {
return {};
}

DDRes worker_pid_free(DDProfContext &ctx, pid_t el) {
DDRes worker_pid_free(DDProfContext &ctx, pid_t el,
PerfClock::time_point timestamp) {
DDRES_CHECK_FWD(aggregate_live_allocations_for_pid(ctx, el));
UnwindState *us = ctx.worker_ctx.us;
unwind_pid_free(us, el);
unwind_pid_free(us, el, timestamp);
ctx.worker_ctx.live_allocation.clear_pid(el);
return {};
}

DDRes clear_unvisited_pids(DDProfContext &ctx) {
UnwindState *us = ctx.worker_ctx.us;
const std::vector<pid_t> pids_remove = us->dwfl_hdr.get_unvisited();
const PerfClock::time_point now = PerfClock::now();
for (pid_t const el : pids_remove) {
DDRES_CHECK_FWD(worker_pid_free(ctx, el));
DDRES_CHECK_FWD(worker_pid_free(ctx, el, now));
}
us->dwfl_hdr.reset_unvisited();
return {};
Expand Down Expand Up @@ -584,21 +587,21 @@ void ddprof_pr_lost(DDProfContext &ctx, const perf_event_lost *lost,
}

DDRes ddprof_pr_comm(DDProfContext &ctx, const perf_event_comm *comm,
int watcher_pos) {
int watcher_pos, PerfClock::time_point timestamp) {
// Change in process name (assuming exec) : clear all associated dso
if (comm->header.misc & PERF_RECORD_MISC_COMM_EXEC) {
LG_DBG("<%d>(COMM)%d -> %s", watcher_pos, comm->pid, comm->comm);
DDRES_CHECK_FWD(worker_pid_free(ctx, comm->pid));
DDRES_CHECK_FWD(worker_pid_free(ctx, comm->pid, timestamp));
}
return {};
}

DDRes ddprof_pr_fork(DDProfContext &ctx, const perf_event_fork *frk,
int watcher_pos) {
int watcher_pos, PerfClock::time_point timestamp) {
LG_DBG("<%d>(FORK)%d -> %d/%d", watcher_pos, frk->ppid, frk->pid, frk->tid);
if (frk->ppid != frk->pid) {
// Clear everything and populate at next error or with coming samples
DDRES_CHECK_FWD(worker_pid_free(ctx, frk->pid));
DDRES_CHECK_FWD(worker_pid_free(ctx, frk->pid, timestamp));
ctx.worker_ctx.us->dso_hdr.pid_fork(frk->pid, frk->ppid);
Copy link
Collaborator

@nsavoire nsavoire Jan 26, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be better to only call pid_fork when pid mappings have actually been freed.

}
return {};
Expand Down Expand Up @@ -745,8 +748,11 @@ DDRes ddprof_worker_process_event(const perf_event_header *hdr, int watcher_pos,
break;
case PERF_RECORD_COMM:
if (wpid->pid) {
DDRES_CHECK_FWD(ddprof_pr_comm(
ctx, reinterpret_cast<const perf_event_comm *>(hdr), watcher_pos));
auto timestamp = perf_clock_time_point_from_timestamp(
hdr_time(hdr, watcher->sample_type));
DDRES_CHECK_FWD(
ddprof_pr_comm(ctx, reinterpret_cast<const perf_event_comm *>(hdr),
watcher_pos, timestamp));
}
break;
case PERF_RECORD_EXIT:
Expand All @@ -757,8 +763,11 @@ DDRes ddprof_worker_process_event(const perf_event_header *hdr, int watcher_pos,
break;
case PERF_RECORD_FORK:
if (wpid->pid) {
DDRES_CHECK_FWD(ddprof_pr_fork(
ctx, reinterpret_cast<const perf_event_fork *>(hdr), watcher_pos));
auto timestamp = perf_clock_time_point_from_timestamp(
hdr_time(hdr, watcher->sample_type));
DDRES_CHECK_FWD(
ddprof_pr_fork(ctx, reinterpret_cast<const perf_event_fork *>(hdr),
watcher_pos, timestamp));
}

break;
Expand Down
9 changes: 9 additions & 0 deletions src/dso_hdr.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -404,6 +404,15 @@ DsoHdr::DsoFindRes DsoHdr::dso_find_or_backpopulate(pid_t pid,
return dso_find_or_backpopulate(pid_mapping, pid, addr);
}

bool DsoHdr::pid_free(int pid, PerfClock::time_point timestamp) {
const auto &pid_mapping = _pid_map[pid];
if (timestamp < pid_mapping._backpopulate_state.last_backpopulate_time) {
return false;
}
pid_free(pid);
return true;
}

void DsoHdr::pid_free(int pid) { _pid_map.erase(pid); }

bool DsoHdr::pid_backpopulate(pid_t pid, int &nb_elts_added) {
Expand Down
15 changes: 10 additions & 5 deletions src/unwind.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -123,11 +123,16 @@ DDRes unwindstate_unwind(UnwindState *us) {
return res;
}

void unwind_pid_free(UnwindState *us, pid_t pid) {
us->dso_hdr.pid_free(pid);
us->dwfl_hdr.clear_pid(pid);
us->symbol_hdr.clear(pid);
us->process_hdr.clear(pid);
void unwind_pid_free(UnwindState *us, pid_t pid,
PerfClock::time_point timestamp) {
if (!(us->dso_hdr.pid_free(pid, timestamp))) {
LG_DBG("(PID Free)%d -> avoid free of mappings (%ld)", pid,
timestamp.time_since_epoch().count());
} else {
Copy link
Collaborator Author

@r1viollet r1viollet Jan 26, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if the mappings are good. Does it really mean that the underlying dwfl modules are OK ?
Today we do not really tie the lifetime of the mappings to the lifetimes of the unwinding caches.
So I am not sure about this change. I think it requires more careful thinking.
@nsavoire fyi

Copy link
Collaborator

@nsavoire nsavoire Jan 26, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree

us->dwfl_hdr.clear_pid(pid);
us->symbol_hdr.clear(pid);
us->process_hdr.clear(pid);
}
}

void unwind_cycle(UnwindState *us) {
Expand Down
13 changes: 13 additions & 0 deletions test/dso-ut.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -160,6 +160,19 @@ TEST(DSOTest, erase) {
}
}

TEST(DSOTest, avoid_erase) {
PerfClock::init(); // init otherwise it returns 0
DsoHdr dso_hdr;
PerfClock::time_point old_now = PerfClock::now();
pid_t my_pid = getpid();
usleep(100);
int nb_elts = 0;
dso_hdr.pid_backpopulate(my_pid, nb_elts);
EXPECT_GT(nb_elts, 0);
EXPECT_FALSE(dso_hdr.pid_free(my_pid, old_now));
EXPECT_GE(dso_hdr.get_nb_dso(), nb_elts);
}

TEST(DSOTest, find_same) {
DsoHdr dso_hdr;
fill_mock_hdr(dso_hdr);
Expand Down